NBLog: add latency logging and histogram serialization (e98dd6f5) · Commits · e / os / android_frameworks_av

media/libnblog/NBLog.cpp

+29 −2

Original line number	Diff line number	Diff line
		@@ -478,12 +478,20 @@ void NBLog::Writer::logEventHistTs(Event event, log_hash_t hash)
		}
		}

		void NBLog::Writer::logLatency(double latencyMs)
		{
		if (!mEnabled) {
		return;
		}
		log(EVENT_LATENCY, &latencyMs, sizeof(latencyMs));
		}

		void NBLog::Writer::logMonotonicCycleTime(uint32_t monotonicNs)
		{
		if (!mEnabled) {
		return;
		}
		log(EVENT_MONOTONIC_CYCLE_TIME, &monotonicNs, sizeof(&monotonicNs));
		log(EVENT_MONOTONIC_CYCLE_TIME, &monotonicNs, sizeof(monotonicNs));
		}

		void NBLog::Writer::logFormat(const char *fmt, log_hash_t hash, ...)
		@@ -713,12 +721,14 @@ const std::unordered_set<NBLog::Event> NBLog::Reader::startingTypes {
		NBLog::Event::EVENT_START_FMT,
		NBLog::Event::EVENT_HISTOGRAM_ENTRY_TS,
		NBLog::Event::EVENT_AUDIO_STATE,
		NBLog::Event::EVENT_LATENCY,
		NBLog::Event::EVENT_MONOTONIC_CYCLE_TIME
		};
		const std::unordered_set<NBLog::Event> NBLog::Reader::endingTypes {
		NBLog::Event::EVENT_END_FMT,
		NBLog::Event::EVENT_HISTOGRAM_ENTRY_TS,
		NBLog::Event::EVENT_AUDIO_STATE,
		NBLog::Event::EVENT_LATENCY,
		NBLog::Event::EVENT_MONOTONIC_CYCLE_TIME
		};

		@@ -873,6 +883,17 @@ void NBLog::MergeReader::getAndProcessSnapshot(NBLog::Snapshot &snapshot, int au
		memcpy(&hash, &(data->hash), sizeof(hash));
		mThreadPerformanceAnalysis[author][0 /hash/].handleStateChange();
		} break;
		case EVENT_LATENCY: {
		double latencyMs;
		memcpy(&latencyMs, etr.data, sizeof(latencyMs));
		mPerformanceData.addLatencyEntry(author, latencyMs);
		} break;
		case EVENT_MONOTONIC_CYCLE_TIME: {
		uint32_t monotonicNs;
		memcpy(&monotonicNs, etr.data, sizeof(monotonicNs));
		const double monotonicMs = monotonicNs * 1e-6;
		mPerformanceData.addCycleTimeEntry(author, monotonicMs);
		} break;
		case EVENT_END_FMT:
		case EVENT_RESERVED:
		case EVENT_UPPER_BOUND:
		@@ -904,6 +925,7 @@ void NBLog::MergeReader::dump(int fd, int indent)
		{
		// TODO: add a mutex around media.log dump
		ReportPerformance::dump(fd, indent, mThreadPerformanceAnalysis);
		mPerformanceData.dump(fd);
		}

		// TODO for future compatibility, would prefer to have a dump() go to string, and then go
		@@ -926,7 +948,12 @@ void NBLog::DumpReader::dump(int fd, size_t indent)
		case EVENT_MONOTONIC_CYCLE_TIME: {
		uint32_t monotonicNs;
		memcpy(&monotonicNs, it->data, sizeof(monotonicNs));
		body.appendFormat("Thread cycle took %u ns", monotonicNs);
		body.appendFormat("Thread cycle: %u ns", monotonicNs);
		} break;
		case EVENT_LATENCY: {
		double latencyMs;
		memcpy(&latencyMs, it->data, sizeof(latencyMs));
		body.appendFormat("latency: %.3f ms", latencyMs);
		} break;
		case EVENT_END_FMT:
		case EVENT_RESERVED:

media/libnblog/PerformanceAnalysis.cpp

+99 −2

Original line number	Diff line number	Diff line
		@@ -17,13 +17,15 @@

		#define LOG_TAG "PerformanceAnalysis"
		// #define LOG_NDEBUG 0
		// #define WRITE_TO_FILE

		#include <algorithm>
		#include <climits>
		#include <deque>
		#include <iostream>
		#include <math.h>
		#include <numeric>
		#include <sstream>
		#include <string>
		#include <vector>
		#include <stdarg.h>
		#include <stdint.h>
		@@ -45,6 +47,97 @@

		namespace android {

		void Histogram::add(double value)
		{
		// TODO Handle domain and range error exceptions?
		const int binIndex = lround((value - mLow) / mBinSize);
		if (binIndex < 0) {
		mLowCount++;
		} else if (binIndex >= mNumBins) {
		mHighCount++;
		} else {
		mBins[binIndex]++;
		}
		mTotalCount++;
		}

		void Histogram::clear()
		{
		std::fill(mBins.begin(), mBins.end(), 0);
		mLowCount = 0;
		mHighCount = 0;
		mTotalCount = 0;
		}

		uint64_t Histogram::totalCount() const
		{
		return mTotalCount;
		}

		std::string Histogram::serializeToString() const {
		std::stringstream ss;
		static constexpr char kDivider = '\|';
		ss << mBinSize << "," << mNumBins << "," << mLow << ",{";
		bool first = true;
		if (mLowCount != 0) {
		ss << "-1" << kDivider << mLowCount;
		first = false;
		}
		for (size_t i = 0; i < mNumBins; i++) {
		if (mBins[i] != 0) {
		if (!first) {
		ss << ",";
		}
		ss << i << kDivider << mBins[i];
		first = false;
		}
		}
		if (mHighCount != 0) {
		if (!first) {
		ss << ",";
		}
		ss << mNumBins << kDivider << mHighCount;
		first = false;
		}
		ss << "}";

		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
		@@ -277,7 +370,9 @@ void PerformanceAnalysis::reportPerformance(String8 *body, int author, log_hash_
		// writes summary of performance into specified file descriptor
		void dump(int fd, int indent, PerformanceAnalysisMap &threadPerformanceAnalysis) {
		String8 body;
		#ifdef WRITE_TO_FILE
		const char* const kDirectory = "/data/misc/audioserver/";
		#endif
		for (auto & thread : threadPerformanceAnalysis) {
		for (auto & hash: thread.second) {
		PerformanceAnalysis& curr = hash.second;
		@@ -287,9 +382,11 @@ void dump(int fd, int indent, PerformanceAnalysisMap &threadPerformanceAnalysis)
		dumpLine(fd, indent, body);
		body.clear();
		}
		// write to file
		#ifdef WRITE_TO_FILE
		// write to file. Enable by uncommenting macro at top of file.
		writeToFile(curr.mHists, curr.mOutlierData, curr.mPeakTimestamps,
		kDirectory, false, thread.first, hash.first);
		#endif
		}
		}
		}

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

+3 −0

Original line number	Diff line number	Diff line
		@@ -350,6 +350,7 @@ public:
		virtual void logFormat(const char *fmt, log_hash_t hash, ...);
		virtual void logVFormat(const char *fmt, log_hash_t hash, va_list ap);
		virtual void logEventHistTs(Event event, log_hash_t hash);
		virtual void logLatency(double latencyMs);
		virtual void logMonotonicCycleTime(uint32_t monotonicNs);
		// End of functions that are not in LockedWriter yet.

		@@ -547,6 +548,8 @@ public:
		// location within each author
		ReportPerformance::PerformanceAnalysisMap mThreadPerformanceAnalysis;

		PerformanceData mPerformanceData;

		// handle author entry by looking up the author's name and appending it to the body
		// returns number of bytes read from fmtEntry
		void handleAuthor(const AbstractEntry &fmtEntry, String8 *body);

media/libnblog/include/media/nblog/PerformanceAnalysis.h

+122 −0

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

		#include <deque>
		#include <map>
		#include <unordered_map>
		#include <vector>

		#include <media/nblog/ReportPerformance.h>
		@@ -27,6 +28,127 @@ namespace android {

		class String8;

		// TODO make this a templated class and put it in a separate file.
		// The templated parameters would be bin size and low limit.
		/*
		* Histogram provides a way to store numeric data in histogram format and read it as a serialized
		* string. The terms "bin" and "bucket" are used interchangeably.
		*
		* This class is not thread-safe.
		*/
		class Histogram {
		public:
		struct Config {
		const double binSize; // TODO template type
		const size_t numBins;
		const double low; // TODO template type
		};

		// Histograms are constructed with fixed configuration numbers. Dynamic configuration based
		// the data is possible but complex because
		// - data points are added one by one, not processed as a batch.
		// - Histograms with different configuration parameters are tricky to aggregate, and they
		// will need to be aggregated at the Media Metrics cloud side.
		// - not providing limits theoretically allows for infinite number of buckets.

		/**
		* \brief Creates a Histogram object.
		*
		* \param binSize the width of each bin of the histogram.
		* Units are whatever data the caller decides to store.
		* \param numBins the number of bins desired in the histogram range.
		* \param low the lower bound of the histogram bucket values.
		* Units are whatever data the caller decides to store.
		* Note that the upper bound can be calculated by the following:
		* upper = lower + binSize * numBins.
		*/
		Histogram(double binSize, size_t numBins, double low = 0.)
		: mBinSize(binSize), mNumBins(numBins), mLow(low), mBins(mNumBins) {}

		Histogram(const Config &c)
		: Histogram(c.binSize, c.numBins, c.low) {}

		/**
		* \brief Add a data point to the histogram. The value of the data point
		* is rounded to the nearest multiple of the bin size (before accounting
		* for the lower bound offset, which may not be a multiple of the bin size).
		*
		* \param value the value of the data point to add.
		*/
		void add(double value);

		/**
		* \brief Removes all data points from the histogram.
		*/
		void clear();

		/**
		* \brief Returns the total number of data points added to the histogram.
		*
		* \return the total number of data points in the histogram.
		*/
		uint64_t totalCount() const;

		/**
		* \brief Serializes the histogram into a string. The format is chosen to be compatible with
		* the histogram representation to send to the Media Metrics service.
		*
		* The string is as follows:
		* binSize,numBins,low,{-1\|lowCount,...,binIndex\|count,...,numBins\|highCount}
		*
		* - binIndex is an integer with 0 <= binIndex < numBins.
		* - count is the number of occurrences of the (rounded) value
		* low + binSize * bucketIndex.
		* - lowCount is the number of (rounded) values less than low.
		* - highCount is the number of (rounded) values greater than or equal to
		* low + binSize * numBins.
		* - a binIndex may be skipped if its count is 0.
		*
		* \return the histogram serialized as a string.
		*/
		std::string serializeToString() const;

		private:
		const double mBinSize; // Size of each bucket
		const size_t mNumBins; // Number of buckets in histogram range
		const double mLow; // Lower bound of values
		std::vector<int> mBins; // Data structure to store the actual histogram

		int mLowCount = 0; // Number of values less than mLow
		int mHighCount = 0; // Number of values >= mLow + mBinSize * mNumBins
		uint64_t mTotalCount = 0; // Total number of values recorded
		};

		// TODO For now this is a holder of audio performance metrics. The idea is essentially the same
		// as PerformanceAnalysis, but the design structure is different. There is a PerformanceAnalysis
		// instance for each thread writer (see PerformanceAnalysisMap later in this file), while a
		// PerformanceData instance already takes into account each thread writer in its calculations.
		// Eventually, this class should be merged with PerformanceAnalysis into some single entity.
		/*
		* PerformanceData stores audio performance data from audioflinger threads as histograms,
		* time series, or counts, and outputs them in a machine-readable format.
		*/
		class PerformanceData {
		public:
		void addCycleTimeEntry(int author, double cycleTimeMs);
		void addLatencyEntry(int author, double latencyMs);
		void addWarmupTimeEntry(int author, double warmupTimeMs);
		void addWarmupCyclesEntry(int author, double warmupCycles);
		void dump(int fd, int indent = 0);
		private:
		// Values based on mUnderrunNs and mOverrunNs in FastMixer.cpp for frameCount = 192 and
		// mSampleRate = 48000, which correspond to 2 and 7 seconds.
		static constexpr Histogram::Config kCycleTimeConfig = { 0.25, 20, 2.};
		std::unordered_map<int /author, i.e. thread number/, Histogram> mCycleTimeMsHists;

		// Values based on trial and error logging. Need a better way to determine
		// bin size and lower/upper limits.
		static constexpr Histogram::Config kLatencyConfig = { 2., 10, 10.};
		std::unordered_map<int, Histogram> mLatencyMsHists;
		};

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

		namespace ReportPerformance {

		class PerformanceAnalysis;

services/audioflinger/FastMixer.cpp

+12 −1

Original line number	Diff line number	Diff line
		@@ -340,10 +340,19 @@ void FastMixer::onWork()
		FastMixerDumpState * const dumpState = (FastMixerDumpState *) mDumpState;

		if (mIsWarm) {
		// Logging timestamps for FastMixer is currently disabled to make memory room for logging
		// other statistics in FastMixer.
		// To re-enable, delete the #ifdef FASTMIXER_LOG_HIST_TS lines (and the #endif lines).
		#ifdef FASTMIXER_LOG_HIST_TS
		LOG_HIST_TS();
		#endif
		//ALOGD("Eric FastMixer::onWork() mIsWarm");
		} else {
		dumpState->mTimestampVerifier.discontinuity();
		// See comment in if block.
		#ifdef FASTMIXER_LOG_HIST_TS
		LOG_AUDIO_STATE();
		#endif
		}
		const FastMixerState::Command command = mCommand;
		const size_t frameCount = current->mFrameCount;
		@@ -498,8 +507,10 @@ void FastMixer::onWork()
		timestamp.mTimeNs[ExtendedTimestamp::LOCATION_KERNEL];
		// We don't compensate for server - kernel time difference and
		// only update latency if we have valid info.
		dumpState->mLatencyMs =
		const double latencyMs =
		(double)mNativeFramesWrittenButNotPresented * 1000 / mSampleRate;
		dumpState->mLatencyMs = latencyMs;
		LOG_LATENCY(latencyMs);
		} else {
		// HAL reported that more frames were presented than were written
		mNativeFramesWrittenButNotPresented = 0;