NBLog: log and store warmup times, underruns, overruns, and thread info (fefe3165) · Commits · e / os / android_frameworks_av

media/libnblog/Android.bp

+4 −0

Original line number	Diff line number	Diff line
		@@ -16,6 +16,10 @@ cc_library_shared {
		"libutils",
		],

		static_libs: [
		"libjsoncpp",
		],

		cflags: [
		"-Werror",
		"-Wall",

media/libnblog/NBLog.cpp

+63 −14

Original line number	Diff line number	Diff line
		@@ -21,6 +21,7 @@
		#include <algorithm>
		#include <climits>
		#include <math.h>
		#include <memory>
		#include <unordered_set>
		#include <vector>
		#include <stdarg.h>
		@@ -31,12 +32,14 @@
		#include <time.h>
		#include <new>
		#include <audio_utils/roundup.h>
		#include <json/json.h>
		#include <media/nblog/NBLog.h>
		#include <media/nblog/PerformanceAnalysis.h>
		#include <media/nblog/ReportPerformance.h>
		#include <utils/CallStack.h>
		#include <utils/Log.h>
		#include <utils/String8.h>
		#include <utils/Timers.h>

		#include <queue>
		#include <utility>
		@@ -417,7 +420,7 @@ void NBLog::Writer::logTimestampFormat()
		if (!mEnabled) {
		return;
		}
		int64_t ts = get_monotonic_ns();
		const nsecs_t ts = systemTime();
		if (ts > 0) {
		log(EVENT_FMT_TIMESTAMP, &ts, sizeof(ts));
		} else {
		@@ -432,7 +435,7 @@ void NBLog::Writer::logEventHistTs(Event event, log_hash_t hash)
		}
		HistTsEntry data;
		data.hash = hash;
		data.ts = get_monotonic_ns();
		data.ts = systemTime();
		if (data.ts > 0) {
		log(event, &data, sizeof(data));
		} else {
		@@ -780,15 +783,17 @@ std::unique_ptr<NBLog::Snapshot> NBLog::Reader::getSnapshot()
		return snapshot;
		}

		// TODO separate this method from the rest of NBLog
		// Takes raw content of the local merger FIFO, processes log entries, and
		// writes the data to a map of class PerformanceAnalysis, based on their thread ID.
		void NBLog::MergeReader::getAndProcessSnapshot(NBLog::Snapshot &snapshot, int author)
		void NBLog::MergeReader::processSnapshot(NBLog::Snapshot &snapshot, int author)
		{
		PerformanceData& data = mThreadPerformanceData[author];
		// We don't do "auto it" because it reduces readability in this case.
		for (EntryIterator it = snapshot.begin(); it != snapshot.end(); ++it) {
		switch (it->type) {
		case EVENT_HISTOGRAM_ENTRY_TS: {
		HistTsEntry payload = it.payload<HistTsEntry>();
		const HistTsEntry payload = it.payload<HistTsEntry>();
		// TODO: hash for histogram ts and audio state need to match
		// and correspond to audio production source file location
		mThreadPerformanceAnalysis[author][0 /hash/].logTsEntry(payload.ts);
		@@ -796,15 +801,37 @@ void NBLog::MergeReader::getAndProcessSnapshot(NBLog::Snapshot &snapshot, int au
		case EVENT_AUDIO_STATE: {
		mThreadPerformanceAnalysis[author][0 /hash/].handleStateChange();
		} break;
		case EVENT_THREAD_INFO: {
		const thread_info_t info = it.payload<thread_info_t>();
		// TODO make PerformanceData hold a type of thread_info_t.
		// Currently, thread_info_t is defined in NBLog.h, which includes
		// PerformanceAnalysis.h. PerformanceData is defined in PerformanceAnalysis.h,
		// where including NBLog.h would result in circular includes. The organization
		// of files will need to change to avoid this problem.
		data.type = info.type;
		data.frameCount = info.frameCount;
		data.sampleRate = info.sampleRate;
		} break;
		case EVENT_LATENCY: {
		double latencyMs = it.payload<double>();
		mPerformanceData.addLatencyEntry(author, latencyMs);
		const double latencyMs = it.payload<double>();
		data.latencyHist.add(latencyMs);
		} break;
		case EVENT_WORK_TIME: {
		uint64_t monotonicNs = it.payload<uint64_t>();
		const int64_t monotonicNs = it.payload<int64_t>();
		const double monotonicMs = monotonicNs * 1e-6;
		mPerformanceData.addCycleTimeEntry(author, monotonicMs);
		data.workHist.add(monotonicMs);
		data.active += monotonicNs;
		} break;
		case EVENT_WARMUP_TIME: {
		const double timeMs = it.payload<double>();
		data.warmupHist.add(timeMs);
		} break;
		case EVENT_UNDERRUN:
		data.underruns++;
		break;
		case EVENT_OVERRUN:
		data.overruns++;
		break;
		case EVENT_RESERVED:
		case EVENT_UPPER_BOUND:
		ALOGW("warning: unexpected event %d", it->type);
		@@ -826,7 +853,7 @@ void NBLog::MergeReader::getAndProcessSnapshot()
		// TODO unlock lock here
		for (size_t i = 0; i < nLogs; i++) {
		if (snapshots[i] != nullptr) {
		getAndProcessSnapshot(*(snapshots[i]), i);
		processSnapshot(*(snapshots[i]), i);
		}
		}
		}
		@@ -835,7 +862,19 @@ void NBLog::MergeReader::dump(int fd, int indent)
		{
		// TODO: add a mutex around media.log dump
		ReportPerformance::dump(fd, indent, mThreadPerformanceAnalysis);
		mPerformanceData.dump(fd);
		Json::Value root(Json::arrayValue);
		for (const auto& item : mThreadPerformanceData) {
		const PerformanceData& data = item.second;
		std::unique_ptr<Json::Value> threadData = dumpToJson(data);
		if (threadData == nullptr) {
		continue;
		}
		(*threadData)["threadNum"] = item.first;
		root.append(*threadData);
		}
		Json::StyledWriter writer;
		std::string rootStr = writer.write(root);
		dprintf(fd, "%s", rootStr.c_str());
		}

		// TODO for future compatibility, would prefer to have a dump() go to string, and then go
		@@ -856,13 +895,23 @@ void NBLog::DumpReader::dump(int fd, size_t indent)
		it = handleFormat(FormatEntry(it), &timestamp, &body);
		break;
		case EVENT_WORK_TIME: {
		uint64_t monotonicNs = it.payload<uint64_t>();
		body.appendFormat("Thread cycle: %lu ns", (unsigned long)monotonicNs);
		const int64_t monotonicNs = it.payload<int64_t>();
		body.appendFormat("Thread cycle: %ld ns", (long)monotonicNs);
		} break;
		case EVENT_LATENCY: {
		double latencyMs = it.payload<double>();
		const double latencyMs = it.payload<double>();
		body.appendFormat("latency: %.3f ms", latencyMs);
		} break;
		case EVENT_WARMUP_TIME: {
		const double timeMs = it.payload<double>();
		body.appendFormat("warmup time: %.3f ms", timeMs);
		} break;
		case EVENT_UNDERRUN:
		body.appendFormat("underrun");
		break;
		case EVENT_OVERRUN:
		body.appendFormat("overrun");
		break;
		case EVENT_FMT_END:
		case EVENT_RESERVED:
		case EVENT_UPPER_BOUND:
		@@ -947,7 +996,7 @@ NBLog::EntryIterator NBLog::DumpReader::handleFormat(const FormatEntry &fmtEntry
		String8 *body)
		{
		// log timestamp
		int64_t ts = fmtEntry.timestamp();
		const int64_t ts = fmtEntry.timestamp();
		timestamp->clear();
		timestamp->appendFormat("[%d.%03d]", (int) (ts / (1000 * 1000 * 1000)),
		(int) ((ts / (1000 * 1000)) % 1000));

media/libnblog/PerformanceAnalysis.cpp

+2 −33

Original line number	Diff line number	Diff line
		@@ -41,6 +41,7 @@
		#include <media/nblog/ReportPerformance.h>
		#include <utils/Log.h>
		#include <utils/String8.h>
		#include <utils/Timers.h>

		#include <queue>
		#include <utility>
		@@ -74,7 +75,7 @@ uint64_t Histogram::totalCount() const
		return mTotalCount;
		}

		std::string Histogram::serializeToString() const {
		std::string Histogram::toString() const {
		std::stringstream ss;
		static constexpr char kDivider = '\|';
		ss << mBinSize << "," << mNumBins << "," << mLow << ",{";
		@@ -104,38 +105,6 @@ std::string Histogram::serializeToString() const {
		return ss.str();
		}

		// TODO make a hash map from Event type to std::pair<HistConfig, unordered_map<int, Histogram>>
		// so that we don't have to create a "add histogram entry" method for every different metric.
		void PerformanceData::addCycleTimeEntry(int author, double cycleTimeMs)
		{
		if (mCycleTimeMsHists.count(author) == 0) {
		mCycleTimeMsHists.emplace(author, Histogram(kCycleTimeConfig));
		}
		mCycleTimeMsHists.at(author).add(cycleTimeMs);
		}

		void PerformanceData::addLatencyEntry(int author, double latencyMs)
		{
		if (mLatencyMsHists.count(author) == 0) {
		mLatencyMsHists.emplace(author, Histogram(kLatencyConfig));
		}
		mLatencyMsHists.at(author).add(latencyMs);
		}

		void PerformanceData::dump(int fd, int indent __unused)
		{
		// TODO add thread metadata for better context.
		// Also output in a more machine-readable friendly format.
		dprintf(fd, "Thread cycle time histograms:\n");
		for (const auto &item : mCycleTimeMsHists) {
		dprintf(fd, " Thread %d: %s\n", item.first, item.second.serializeToString().c_str());
		}
		dprintf(fd, "Latency histograms:\n");
		for (const auto &item : mLatencyMsHists) {
		dprintf(fd, " Thread %d: %s\n", item.first, item.second.serializeToString().c_str());
		}
		}

		//------------------------------------------------------------------------------

		namespace ReportPerformance {

media/libnblog/ReportPerformance.cpp

+21 −1

Original line number	Diff line number	Diff line
		@@ -18,6 +18,7 @@

		#include <fstream>
		#include <iostream>
		#include <memory>
		#include <queue>
		#include <stdarg.h>
		#include <stdint.h>
		@@ -27,6 +28,7 @@
		#include <sys/prctl.h>
		#include <sys/time.h>
		#include <utility>
		#include <json/json.h>
		#include <media/nblog/NBLog.h>
		#include <media/nblog/PerformanceAnalysis.h>
		#include <media/nblog/ReportPerformance.h>
		@@ -35,8 +37,26 @@

		namespace android {

		namespace ReportPerformance {
		std::unique_ptr<Json::Value> dumpToJson(const PerformanceData& data)
		{
		std::unique_ptr<Json::Value> rootPtr = std::make_unique<Json::Value>(Json::objectValue);
		Json::Value& root = *rootPtr;
		root["type"] = data.type;
		root["frameCount"] = (Json::Value::Int)data.frameCount;
		root["sampleRate"] = (Json::Value::Int)data.sampleRate;
		root["workMsHist"] = data.workHist.toString();
		root["latencyMsHist"] = data.latencyHist.toString();
		root["warmupMsHist"] = data.warmupHist.toString();
		root["underruns"] = (Json::Value::Int64)data.underruns;
		root["overruns"] = (Json::Value::Int64)data.overruns;
		root["activeMs"] = (Json::Value::Int64)ns2ms(data.active);
		root["durationMs"] = (Json::Value::Int64)ns2ms(systemTime() - data.start);
		return rootPtr;
		}

		//------------------------------------------------------------------------------

		namespace ReportPerformance {

		// TODO: use a function like this to extract logic from writeToFile
		// https://stackoverflow.com/a/9279620

media/libnblog/include/media/nblog/NBLog.h

+29 −14

Original line number	Diff line number	Diff line
		@@ -20,6 +20,7 @@
		#define ANDROID_MEDIA_NBLOG_H

		#include <map>
		#include <memory>
		#include <type_traits>
		#include <unordered_set>
		#include <vector>
		@@ -30,6 +31,7 @@
		#include <media/nblog/ReportPerformance.h>
		#include <utils/Mutex.h>
		#include <utils/threads.h>
		#include <utils/Timers.h>

		namespace android {

		@@ -39,7 +41,7 @@ class NBLog {

		public:

		using log_hash_t = ReportPerformance::log_hash_t;
		using log_hash_t = uint64_t;

		// FIXME Everything needed for client (writer API and registration) should be isolated
		// from the rest of the implementation.
		@@ -78,13 +80,29 @@ public:
		EVENT_AUDIO_STATE, // audio on/off event: logged on FastMixer::onStateChange call

		// Types representing audio performance metrics
		EVENT_THREAD_INFO, // thread type, frameCount and sampleRate, which give context
		// for the metrics below.
		EVENT_LATENCY, // difference between frames presented by HAL and frames
		// written to HAL output sink, divided by sample rate.
		EVENT_WORK_TIME, // the time a thread takes to do work, e.g. read, write, etc.
		EVENT_WARMUP_TIME, // thread warmup time
		EVENT_UNDERRUN, // predicted thread underrun event timestamp
		EVENT_OVERRUN, // predicted thread overrun event timestamp

		EVENT_UPPER_BOUND, // to check for invalid events
		};

		// NBLog custom-defined structs. Some NBLog Event types map to these structs.

		// mapped from EVENT_THREAD_INFO
		struct thread_info_t {
		// TODO make type an enum
		int type; // Thread type: 0 for MIXER, 1 for CAPTURE,
		// 2 for FASTMIXER, 3 for FASTCAPTURE
		size_t frameCount; // number of frames per read or write buffer
		unsigned sampleRate; // in frames per second
		};

		template <Event E> struct get_mapped;
		#define MAP_EVENT_TO_TYPE(E, T) \
		template<> struct get_mapped<E> { \
		@@ -95,8 +113,12 @@ public:
		}

		// Maps an NBLog Event type to a C++ POD type.
		MAP_EVENT_TO_TYPE(EVENT_THREAD_INFO, thread_info_t);
		MAP_EVENT_TO_TYPE(EVENT_LATENCY, double);
		MAP_EVENT_TO_TYPE(EVENT_WORK_TIME, uint64_t);
		MAP_EVENT_TO_TYPE(EVENT_WORK_TIME, int64_t);
		MAP_EVENT_TO_TYPE(EVENT_WARMUP_TIME, double);
		MAP_EVENT_TO_TYPE(EVENT_UNDERRUN, int64_t);
		MAP_EVENT_TO_TYPE(EVENT_OVERRUN, int64_t);

		private:

		@@ -154,7 +176,7 @@ private:
		}
		#else
		template<typename T>
		inline T payload() {
		inline T payload() const {
		static_assert(std::is_trivially_copyable<T>::value
		&& !std::is_pointer<T>::value,
		"NBLog::EntryIterator payload must be trivially copyable, non-pointer type.");
		@@ -545,6 +567,7 @@ public:
		};

		// ---------------------------------------------------------------------------
		// TODO move Merger, MergeReader, and MergeThread to a separate file.

		// This class is used to read data from each thread's individual FIFO in shared memory
		// and write it to a single FIFO in local memory.
		@@ -581,7 +604,7 @@ public:

		void dump(int fd, int indent = 0);
		// process a particular snapshot of the reader
		void getAndProcessSnapshot(Snapshot &snap, int author);
		void processSnapshot(Snapshot &snap, int author);
		// call getSnapshot of the content of the reader's buffer and process the data
		void getAndProcessSnapshot();

		@@ -596,7 +619,8 @@ public:
		// location within each author
		ReportPerformance::PerformanceAnalysisMap mThreadPerformanceAnalysis;

		PerformanceData mPerformanceData;
		// compresses and stores audio performance data from each thread's buffers.
		std::map<int /author, i.e. thread index/, PerformanceData> mThreadPerformanceData;

		// handle author entry by looking up the author's name and appending it to the body
		// returns number of bytes read from fmtEntry
		@@ -645,15 +669,6 @@ public:

		}; // class NBLog

		// TODO put somewhere else
		static inline int64_t get_monotonic_ns() {
		timespec ts;
		if (clock_gettime(CLOCK_MONOTONIC, &ts) == 0) {
		return (uint64_t) ts.tv_sec * 1000 * 1000 * 1000 + ts.tv_nsec;
		}
		return 0; // should not happen.
		}

		} // namespace android

		#endif // ANDROID_MEDIA_NBLOG_H