Merge changes I9b1538a8,Ib6ea9676 (5fcd6ca5) · Commits · e / os / android_frameworks_av

media/libnblog/Android.bp

+5 −0

Original line number	Diff line number	Diff line
		@@ -13,9 +13,14 @@ cc_library_shared {
		"libbinder",
		"libcutils",
		"liblog",
		"libmediametrics",
		"libutils",
		],

		static_libs: [
		"libjsoncpp",
		],

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

media/libnblog/NBLog.cpp

+76 −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)
		{
		ReportPerformance::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,20 @@ 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);
		}
		}
		checkPushToMediaMetrics();
		}

		void NBLog::MergeReader::checkPushToMediaMetrics()
		{
		const nsecs_t now = systemTime();
		for (auto& item : mThreadPerformanceData) {
		ReportPerformance::PerformanceData& data = item.second;
		if (now - data.start >= kPeriodicMediaMetricsPush) {
		(void)ReportPerformance::sendToMediaMetrics(data);
		data.reset(); // data is persistent per thread
		}
		}
		}
		@@ -835,7 +875,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 ReportPerformance::PerformanceData& data = item.second;
		std::unique_ptr<Json::Value> threadData = ReportPerformance::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 +908,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 +1009,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

+4 −35

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

		#include <queue>
		#include <utility>

		namespace android {

		namespace ReportPerformance {

		void Histogram::add(double value)
		{
		// TODO Handle domain and range error exceptions?
		@@ -74,7 +77,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,42 +107,8 @@ 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 {

		// Given an audio processing wakeup timestamp, buckets the time interval
		// since the previous timestamp into a histogram, searches for
		// outliers, analyzes the outlier series for unexpectedly

media/libnblog/ReportPerformance.cpp

+84 −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,8 @@
		#include <sys/prctl.h>
		#include <sys/time.h>
		#include <utility>
		#include <json/json.h>
		#include <media/MediaAnalyticsItem.h>
		#include <media/nblog/NBLog.h>
		#include <media/nblog/PerformanceAnalysis.h>
		#include <media/nblog/ReportPerformance.h>
		@@ -37,13 +40,93 @@ 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;
		}

		bool sendToMediaMetrics(const PerformanceData& data)
		{
		// See documentation for these metrics here:
		// docs.google.com/document/d/11--6dyOXVOpacYQLZiaOY5QVtQjUyqNx2zT9cCzLKYE/edit?usp=sharing
		static constexpr char kThreadType[] = "android.media.audiothread.type";
		static constexpr char kThreadFrameCount[] = "android.media.audiothread.framecount";
		static constexpr char kThreadSampleRate[] = "android.media.audiothread.samplerate";
		static constexpr char kThreadWorkHist[] = "android.media.audiothread.workMs.hist";
		static constexpr char kThreadLatencyHist[] = "android.media.audiothread.latencyMs.hist";
		static constexpr char kThreadWarmupHist[] = "android.media.audiothread.warmupMs.hist";
		static constexpr char kThreadUnderruns[] = "android.media.audiothread.underruns";
		static constexpr char kThreadOverruns[] = "android.media.audiothread.overruns";
		static constexpr char kThreadActive[] = "android.media.audiothread.activeMs";
		static constexpr char kThreadDuration[] = "android.media.audiothread.durationMs";

		std::unique_ptr<MediaAnalyticsItem> item(new MediaAnalyticsItem("audiothread"));

		const Histogram &workHist = data.workHist;
		if (workHist.totalCount() > 0) {
		item->setCString(kThreadWorkHist, workHist.toString().c_str());
		}

		const Histogram &latencyHist = data.latencyHist;
		if (latencyHist.totalCount() > 0) {
		item->setCString(kThreadLatencyHist, latencyHist.toString().c_str());
		}

		const Histogram &warmupHist = data.warmupHist;
		if (warmupHist.totalCount() > 0) {
		item->setCString(kThreadWarmupHist, warmupHist.toString().c_str());
		}

		if (data.underruns > 0) {
		item->setInt64(kThreadUnderruns, data.underruns);
		}

		if (data.overruns > 0) {
		item->setInt64(kThreadOverruns, data.overruns);
		}

		// Send to Media Metrics if the record is not empty.
		// The thread and time info are added inside the if statement because
		// we want to send them only if there are performance metrics to send.
		if (item->count() > 0) {
		// Add thread info fields.
		const int type = data.type;
		// TODO have a int-to-string mapping defined somewhere else for other thread types.
		if (type == 2) {
		item->setCString(kThreadType, "FASTMIXER");
		} else {
		item->setCString(kThreadType, "UNKNOWN");
		}
		item->setInt32(kThreadFrameCount, data.frameCount);
		item->setInt32(kThreadSampleRate, data.sampleRate);
		// Add time info fields.
		item->setInt64(kThreadActive, data.active / 1000000);
		item->setInt64(kThreadDuration, (systemTime() - data.start) / 1000000);
		return item->selfrecord();
		}
		return false;
		}

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

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

		// Writes outlier intervals, timestamps, and histograms spanning long time intervals to file.
		// TODO: write data in binary format
		void writeToFile(const std::deque<std::pair<timestamp, Histogram>> &hists,
		void writeToFile(const std::deque<std::pair<timestamp, Hist>> &hists,
		const std::deque<std::pair<msInterval, timestamp>> &outlierData,
		const std::deque<timestamp> &peakTimestamps,
		const char * directory, bool append, int author, log_hash_t hash) {

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

+43 −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.");
		@@ -418,6 +440,7 @@ public:
		void log(Event event, const void *data, size_t length);

		void logvf(const char *fmt, va_list ap);

		// helper functions for logging parts of a formatted entry
		void logStart(const char *fmt);
		void logTimestampFormat();
		@@ -477,10 +500,12 @@ public:
		private:
		// Amount of tries for reader to catch up with writer in getSnapshot().
		static constexpr int kMaxObtainTries = 3;

		// invalidBeginTypes and invalidEndTypes are used to align the Snapshot::begin() and
		// Snapshot::end() EntryIterators to valid entries.
		static const std::unordered_set<Event> invalidBeginTypes;
		static const std::unordered_set<Event> invalidEndTypes;

		// declared as const because audio_utils_fifo() constructor
		sp<IMemory> mIMemory; // ref-counted version, assigned only in constructor

		@@ -539,12 +564,14 @@ public:
		static void appendFloat(String8 body, const void data);
		static void appendPID(String8 body, const void data, size_t length);
		static void appendTimestamp(String8 body, const void data);

		// The bufferDump functions are used for debugging only.
		static String8 bufferDump(const uint8_t *buffer, size_t size);
		static String8 bufferDump(const EntryIterator &it);
		};

		// ---------------------------------------------------------------------------
		// 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.
		@@ -580,11 +607,17 @@ public:
		MergeReader(const void *shared, size_t size, Merger &merger);

		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();

		// check for periodic push of performance data to media metrics, and perform
		// the send if it is time to do so.
		void checkPushToMediaMetrics();

		private:
		// FIXME Needs to be protected by a lock,
		// because even though our use of it is read-only there may be asynchronous updates
		@@ -596,7 +629,12 @@ public:
		// location within each author
		ReportPerformance::PerformanceAnalysisMap mThreadPerformanceAnalysis;

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

		// how often to push data to Media Metrics
		static constexpr nsecs_t kPeriodicMediaMetricsPush = s2ns((nsecs_t)2 * 60 * 60); // 2 hours

		// 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 +683,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