Merge changes I8b03feed,I642555f2 (5a76cab2) · Commits · e / os / android_frameworks_av

media/libnbaio/NBLog.cpp

+25 −25

Original line number	Diff line number	Diff line
		@@ -69,26 +69,19 @@
		* class instances, where the wakeup() intervals are stored as histograms
		* and analyzed.
		*
		* 3) reading the data from private buffer
		* MediaLogService::dump
		* calls NBLog::Reader::dump(CONSOLE)
		* The private buffer contains all logs for all readers in shared memory
		* NBLog::Reader::dump(int)
		* calls getSnapshot on the current reader
		* calls dump(int, size_t, Snapshot)
		* NBLog::Reader::dump(int, size, snapshot)
		* iterates through snapshot's events and switches based on their type
		* (string, timestamp, etc...)
		* In the case of EVENT_HISTOGRAM_ENTRY_TS, adds a list of timestamp sequences
		* (histogram entry) to NBLog::mHists
		* TODO: add every HISTOGRAM_ENTRY_TS to two
		* circular buffers: one short-term and one long-term (can add even longer-term
		* structures in the future). When dump is called, print everything currently
		* in the buffer.
		* NBLog::drawHistogram
		* input: timestamp array
		* buckets this to a histogram and prints
		*
		* 3) Dumpsys media.log call to report the data
		* MediaLogService::dump in MediaLogService.cpp
		* calls NBLog::Reader::dump, which calls ReportPerformance::dump
		* ReportPerformance::dump
		* calls PerformanceAnalysis::ReportPerformance
		* and ReportPerformance::WriteToFile
		* PerformanceAnalysis::ReportPerformance
		* for each thread/source file location instance of PerformanceAnalysis data,
		* combines all histograms into a single one and prints it to the console
		* along with outlier data
		* ReportPerformance::WriteToFile
		* writes histogram, outlier, and peak information to file separately for each
		* instance of PerformanceAnalysis data.
		*/

		#define LOG_TAG "NBLog"
		@@ -763,7 +756,8 @@ bool NBLog::LockedWriter::setEnabled(bool enabled)
		// ---------------------------------------------------------------------------

		const std::set<NBLog::Event> NBLog::Reader::startingTypes {NBLog::Event::EVENT_START_FMT,
		NBLog::Event::EVENT_HISTOGRAM_ENTRY_TS};
		NBLog::Event::EVENT_HISTOGRAM_ENTRY_TS,
		NBLog::Event::EVENT_AUDIO_STATE};
		const std::set<NBLog::Event> NBLog::Reader::endingTypes {NBLog::Event::EVENT_END_FMT,
		NBLog::Event::EVENT_HISTOGRAM_ENTRY_TS,
		NBLog::Event::EVENT_AUDIO_STATE};
		@@ -903,7 +897,9 @@ void NBLog::MergeReader::getAndProcessSnapshot(NBLog::Reader::Snapshot &snapshot
		memcpy(&hash, &(data->hash), sizeof(hash));
		int64_t ts;
		memcpy(&ts, &data->ts, sizeof(ts));
		mThreadPerformanceAnalysis[data->author][hash].logTsEntry(ts);
		// TODO: hash for histogram ts and audio state need to match
		// and correspond to audio production source file location
		mThreadPerformanceAnalysis[data->author][0 /hash/].logTsEntry(ts);
		++entry;
		break;
		}
		@@ -913,7 +909,10 @@ void NBLog::MergeReader::getAndProcessSnapshot(NBLog::Reader::Snapshot &snapshot
		// There's probably a more efficient way to do it
		log_hash_t hash;
		memcpy(&hash, &(data->hash), sizeof(hash));
		mThreadPerformanceAnalysis[data->author][hash].handleStateChange();
		// TODO: remove ts if unused
		int64_t ts;
		memcpy(&ts, &data->ts, sizeof(ts));
		mThreadPerformanceAnalysis[data->author][0 /hash/].handleStateChange();
		++entry;
		break;
		}
		@@ -942,6 +941,7 @@ void NBLog::MergeReader::getAndProcessSnapshot()
		}

		void NBLog::MergeReader::dump(int fd, int indent) {
		// TODO: add a mutex around media.log dump
		ReportPerformance::dump(fd, indent, mThreadPerformanceAnalysis);
		}

media/libnbaio/PerformanceAnalysis.cpp

+115 −137

Original line number	Diff line number	Diff line
		@@ -62,181 +62,160 @@ static int widthOf(int x) {
		return width;
		}

		// Given a series of audio processing wakeup timestamps,
		// buckets the time intervals into a histogram, searches for

		// Given a the most recent timestamp of a series of audio processing
		// wakeup timestamps,
		// buckets the time interval into a histogram, searches for
		// outliers, analyzes the outlier series for unexpectedly
		// small or large values and stores these as peaks, and flushes
		// the timestamp series from memory.
		void PerformanceAnalysis::processAndFlushTimeStampSeries() {
		if (mTimeStampSeries.empty()) {
		ALOGD("Timestamp series is empty");
		// small or large values and stores these as peaks
		void PerformanceAnalysis::logTsEntry(int64_t ts) {
		// after a state change, start a new series and do not
		// record time intervals in-between
		if (mOutlierDistribution.mPrevTs == 0) {
		mOutlierDistribution.mPrevTs = ts;
		return;
		}

		// mHists is empty if thread/hash pair is sending data for the first time
		if (mHists.empty()) {
		mHists.emplace_front(static_cast<uint64_t>(mTimeStampSeries[0]),
		std::map<int, int>());
		}

		// 1) analyze the series to store all outliers and their exact timestamps:
		storeOutlierData(mTimeStampSeries);

		// 2) detect peaks in the outlier series
		detectPeaks();

		// if the current histogram has spanned its maximum time interval,
		// insert a new empty histogram to the front of mHists
		if (deltaMs(mHists[0].first, mTimeStampSeries[0]) >= kMaxLength.HistTimespanMs) {
		mHists.emplace_front(static_cast<uint64_t>(mTimeStampSeries[0]),
		std::map<int, int>());
		// Check whether the time interval between the current timestamp
		// and the previous one is long enough to count as an outlier
		const bool isOutlier = detectAndStoreOutlier(ts);
		// If an outlier was found, check whether it was a peak
		if (isOutlier) {
		/bool isPeak =/ detectAndStorePeak(
		mOutlierData[0].first, mOutlierData[0].second);
		// TODO: decide whether to insert a new empty histogram if a peak
		// TODO: remove isPeak if unused to avoid "unused variable" error
		// occurred at the current timestamp
		}

		// Insert a histogram to mHists if it is empty, or
		// close the current histogram and insert a new empty one if
		// if the current histogram has spanned its maximum time interval.
		if (mHists.empty() \|\|
		deltaMs(mHists[0].first, ts) >= kMaxLength.HistTimespanMs) {
		mHists.emplace_front(static_cast<uint64_t>(ts), std::map<int, int>());
		// When memory is full, delete oldest histogram
		// TODO: use a circular buffer
		if (mHists.size() >= kMaxLength.Hists) {
		mHists.resize(kMaxLength.Hists);
		}
		}

		// 3) add current time intervals to histogram
		for (size_t i = 1; i < mTimeStampSeries.size(); ++i) {
		++mHists[0].second[deltaMs(
		mTimeStampSeries[i - 1], mTimeStampSeries[i])];
		// add current time intervals to histogram
		++mHists[0].second[deltaMs(mOutlierDistribution.mPrevTs, ts)];
		// update previous timestamp
		mOutlierDistribution.mPrevTs = ts;
		}

		// clear the timestamps
		mTimeStampSeries.clear();
		}

		// forces short-term histogram storage to avoid adding idle audio time interval
		// to buffer period data
		void PerformanceAnalysis::handleStateChange() {
		ALOGD("handleStateChange");
		processAndFlushTimeStampSeries();
		mOutlierDistribution.mPrevTs = 0;
		return;
		}

		// Takes a single buffer period timestamp entry information and stores it in a
		// temporary series of timestamps. Once the series is full, the data is analyzed,
		// stored, and emptied.
		void PerformanceAnalysis::logTsEntry(int64_t ts) {
		// TODO might want to filter excessively high outliers, which are usually caused
		// by the thread being inactive.
		// Store time series data for each reader in order to bucket it once there
		// is enough data. Then, write to recentHists as a histogram.
		mTimeStampSeries.push_back(ts);
		// if length of the time series has reached kShortHistSize samples,
		// analyze the data and flush the timestamp series from memory
		if (mTimeStampSeries.size() >= kMaxLength.TimeStamps) {
		processAndFlushTimeStampSeries();
		}
		}

		// Given a series of outlier intervals (mOutlier data),
		// Checks whether the time interval between two outliers is far enough from
		// a typical delta to be considered a peak.
		// looks for changes in distribution (peaks), which can be either positive or negative.
		// The function sets the mean to the starting value and sigma to 0, and updates
		// them as long as no peak is detected. When a value is more than 'threshold'
		// standard deviations from the mean, a peak is detected and the mean and sigma
		// are set to the peak value and 0.
		void PerformanceAnalysis::detectPeaks() {
		bool PerformanceAnalysis::detectAndStorePeak(outlierInterval diff, timestamp ts) {
		bool isPeak = false;
		if (mOutlierData.empty()) {
		return;
		}

		// compute mean of the distribution. Used to check whether a value is large
		const double kTypicalDiff = std::accumulate(
		mOutlierData.begin(), mOutlierData.end(), 0,
		[](auto &a, auto &b){return a + b.first;}) / mOutlierData.size();
		// ALOGD("typicalDiff %f", kTypicalDiff);

		// iterator at the beginning of a sequence, or updated to the most recent peak
		std::deque<std::pair<uint64_t, uint64_t>>::iterator start = mOutlierData.begin();
		// the mean and standard deviation are updated every time a peak is detected
		// initialize first time. The mean from the previous sequence is stored
		// for the next sequence. Here, they are initialized for the first time.
		if (mOutlierDistribution.Mean < 0) {
		mOutlierDistribution.Mean = static_cast<double>(start->first);
		mOutlierDistribution.Sd = 0;
		}
		auto sqr = [](auto x){ return x * x; };
		for (auto it = mOutlierData.begin(); it != mOutlierData.end(); ++it) {
		// no surprise occurred:
		// the new element is a small number of standard deviations from the mean
		if ((fabs(it->first - mOutlierDistribution.Mean) <
		mOutlierDistribution.kMaxDeviation * mOutlierDistribution.Sd) \|\|
		// or: right after peak has been detected, the delta is smaller than average
		(mOutlierDistribution.Sd == 0 &&
		fabs(it->first - mOutlierDistribution.Mean) < kTypicalDiff)) {
		// update the mean and sd:
		// count number of elements (distance between start interator and current)
		const int kN = std::distance(start, it) + 1;
		// usual formulas for mean and sd
		mOutlierDistribution.Mean = std::accumulate(start, it + 1, 0.0,
		[](auto &a, auto &b){return a + b.first;}) / kN;
		mOutlierDistribution.Sd = sqrt(std::accumulate(start, it + 1, 0.0,
		[=](auto &a, auto &b){
		return a + sqr(b.first - mOutlierDistribution.Mean);})) /
		((kN > 1)? kN - 1 : kN); // kN - 1: mean is correlated with variance
		}
		// surprising value: store peak timestamp and reset mean, sd, and start iterator
		else {
		mPeakTimestamps.emplace_front(it->second);
		return false;
		}
		// Update mean of the distribution
		// TypicalDiff is used to check whether a value is unusually large
		// when we cannot use standard deviations from the mean because the sd is set to 0.
		mOutlierDistribution.mTypicalDiff = (mOutlierDistribution.mTypicalDiff *
		(mOutlierData.size() - 1) + diff) / mOutlierData.size();

		// Initialize short-term mean at start of program
		if (mOutlierDistribution.mMean == 0) {
		mOutlierDistribution.mMean = static_cast<double>(diff);
		}
		// Update length of current sequence of outliers
		mOutlierDistribution.mN++;

		// If statement checks whether a large deviation from the mean occurred.
		// If the standard deviation has been reset to zero, the comparison is
		// instead to the mean of the full mOutlierInterval sequence.
		if ((fabs(static_cast<double>(diff) - mOutlierDistribution.mMean) <
		mOutlierDistribution.kMaxDeviation * mOutlierDistribution.mSd) \|\|
		(mOutlierDistribution.mSd == 0 &&
		fabs(diff - mOutlierDistribution.mMean) <
		mOutlierDistribution.mTypicalDiff)) {
		// update the mean and sd using online algorithm
		// https://en.wikipedia.org/wiki/
		// Algorithms_for_calculating_variance#Online_algorithm
		mOutlierDistribution.mN++;
		const double kDelta = diff - mOutlierDistribution.mMean;
		mOutlierDistribution.mMean += kDelta / mOutlierDistribution.mN;
		const double kDelta2 = diff - mOutlierDistribution.mMean;
		mOutlierDistribution.mM2 += kDelta * kDelta2;
		mOutlierDistribution.mSd = (mOutlierDistribution.mN < 2) ? 0 :
		sqrt(mOutlierDistribution.mM2 / (mOutlierDistribution.mN - 1));
		} else {
		// new value is far from the mean:
		// store peak timestamp and reset mean, sd, and short-term sequence
		isPeak = true;
		mPeakTimestamps.emplace_front(ts);
		// if mPeaks has reached capacity, delete oldest data
		// Note: this means that mOutlierDistribution values do not exactly
		// match the data we have in mPeakTimestamps, but this is not an issue
		// in practice for estimating future peaks.
		// TODO: turn this into a circular buffer
		if (mPeakTimestamps.size() >= kMaxLength.Peaks) {
		mPeakTimestamps.resize(kMaxLength.Peaks);
		}
		mOutlierDistribution.Mean = static_cast<double>(it->first);
		mOutlierDistribution.Sd = 0;
		start = it;
		mOutlierDistribution.mMean = 0;
		mOutlierDistribution.mSd = 0;
		mOutlierDistribution.mN = 0;
		mOutlierDistribution.mM2 = 0;
		}
		}
		return;
		ALOGD("outlier distr %f %f", mOutlierDistribution.mMean, mOutlierDistribution.mSd);
		return isPeak;
		}

		// Called by LogTsEntry. The input is a vector of timestamps.
		// Finds outliers and writes to mOutlierdata.
		// Each value in mOutlierdata consists of: <outlier timestamp,
		// time elapsed since previous outlier>.

		// Determines whether the difference between a timestamp and the previous
		// one is beyond a threshold. If yes, stores the timestamp as an outlier
		// and writes to mOutlierdata in the following format:
		// Time elapsed since previous outlier: Timestamp of start of outlier
		// e.g. timestamps (ms) 1, 4, 5, 16, 18, 28 will produce pairs (4, 5), (13, 18).
		// This function is applied to the time series before it is converted into a histogram.
		void PerformanceAnalysis::storeOutlierData(const std::vector<int64_t> &timestamps) {
		if (timestamps.size() < 1) {
		return;
		}
		// first pass: need to initialize
		if (mOutlierDistribution.Elapsed == 0) {
		mOutlierDistribution.PrevNs = timestamps[0];
		}
		for (const auto &ts: timestamps) {
		const uint64_t diffMs = static_cast<uint64_t>(deltaMs(mOutlierDistribution.PrevNs, ts));
		if (diffMs >= static_cast<uint64_t>(kOutlierMs)) {
		mOutlierData.emplace_front(mOutlierDistribution.Elapsed,
		static_cast<uint64_t>(mOutlierDistribution.PrevNs));
		bool PerformanceAnalysis::detectAndStoreOutlier(const int64_t ts) {
		bool isOutlier = false;
		const int64_t diffMs = static_cast<int64_t>(deltaMs(mOutlierDistribution.mPrevTs, ts));
		if (diffMs >= static_cast<int64_t>(kOutlierMs)) {
		isOutlier = true;
		mOutlierData.emplace_front(mOutlierDistribution.mElapsed,
		static_cast<uint64_t>(mOutlierDistribution.mPrevTs));
		// Remove oldest value if the vector is full
		// TODO: remove pop_front once circular buffer is in place
		// FIXME: make sure kShortHistSize is large enough that that data will never be lost
		// TODO: turn this into a circular buffer
		// TODO: make sure kShortHistSize is large enough that that data will never be lost
		// before being written to file or to a FIFO
		if (mOutlierData.size() >= kMaxLength.Outliers) {
		mOutlierData.resize(kMaxLength.Outliers);
		}
		mOutlierDistribution.Elapsed = 0;
		}
		mOutlierDistribution.Elapsed += diffMs;
		mOutlierDistribution.PrevNs = ts;
		mOutlierDistribution.mElapsed = 0;
		}
		mOutlierDistribution.mElapsed += diffMs;
		return isOutlier;
		}


		// TODO Make it return a std::string instead of modifying body --> is this still relevant?
		// TODO consider changing all ints to uint32_t or uint64_t
		// TODO: move this to ReportPerformance, probably make it a friend function of PerformanceAnalysis
		void PerformanceAnalysis::reportPerformance(String8 *body, int maxHeight) {
		// Add any new data
		processAndFlushTimeStampSeries();

		if (mHists.empty()) {
		ALOGD("reportPerformance: mHists is empty");
		return;
		}
		ALOGD("reportPerformance: hists size %d", static_cast<int>(mHists.size()));
		// TODO: more elaborate data analysis

		std::map<int, int> buckets;
		for (const auto &shortHist: mHists) {
		for (const auto &countPair : shortHist.second) {
		@@ -308,9 +287,9 @@ void PerformanceAnalysis::reportPerformance(String8 *body, int maxHeight) {
		body->appendFormat("%lld: %lld\n", static_cast<long long>(outlier.first),
		static_cast<long long>(outlier.second));
		}

		}


		// TODO: decide whether to use this or whether it is overkill, and it is enough
		// to only treat as glitches single wakeup call intervals which are too long.
		// Ultimately, glitch detection will be directly on the audio signal.
		@@ -328,7 +307,6 @@ void PerformanceAnalysis::alertIfGlitch(const std::vector<int64_t> &samples) {
		// TODO: check that all glitch cases are covered
		if (std::accumulate(periods.begin(), periods.end(), 0) > kNumBuff * kPeriodMs +
		kPeriodMs - kPeriodMsCPU) {
		ALOGW("A glitch occurred");
		periods.assign(kNumBuff, kPeriodMs);
		}
		}
		@@ -344,20 +322,20 @@ void dump(int fd, int indent, PerformanceAnalysisMap &threadPerformanceAnalysis)
		for (auto & thread : threadPerformanceAnalysis) {
		for (auto & hash: thread.second) {
		PerformanceAnalysis& curr = hash.second;
		curr.processAndFlushTimeStampSeries();
		// write performance data to console
		curr.reportPerformance(&body);
		if (!body.isEmpty()) {
		dumpLine(fd, indent, body);
		body.clear();
		}
		// write to file
		writeToFile(curr.mHists, curr.mOutlierData, curr.mPeakTimestamps,
		kDirectory, false, thread.first, hash.first);
		}
		}
		if (!body.isEmpty()) {
		dumpLine(fd, indent, body);
		body.clear();
		}
		}


		// Writes a string into specified file descriptor
		void dumpLine(int fd, int indent, const String8 &body) {
		dprintf(fd, "%.*s%s \n", indent, "", body.string());

media/libnbaio/include/media/nbaio/NBLog.h

+0 −2

Original line number	Diff line number	Diff line
		@@ -252,8 +252,6 @@ private:
		int author;
		}; //TODO __attribute__((packed));

		using StateTsEntryWithAuthor = HistTsEntryWithAuthor;

		struct HistIntEntry {
		log_hash_t hash;
		int value;

media/libnbaio/include/media/nbaio/PerformanceAnalysis.h

+16 −13

Original line number	Diff line number	Diff line
		@@ -67,12 +67,12 @@ public:
		// Input: mOutlierData. Looks at time elapsed between outliers
		// finds significant changes in the distribution
		// writes timestamps of significant changes to mPeakTimestamps
		void detectPeaks();
		bool detectAndStorePeak(outlierInterval delta, timestamp ts);

		// runs analysis on timestamp series before it is converted to a histogram
		// finds outliers
		// writes to mOutlierData <time elapsed since previous outlier, outlier timestamp>
		void storeOutlierData(const std::vector<timestamp_raw> &timestamps);
		bool detectAndStoreOutlier(const timestamp_raw timestamp);

		// input: series of short histograms. Generates a string of analysis of the buffer periods
		// TODO: WIP write more detailed analysis
		@@ -87,21 +87,19 @@ public:

		private:

		// stores outlier analysis: <elapsed time between outliers in ms, outlier timestamp>
		// TODO use a circular buffer for the deques and vectors below

		// stores outlier analysis:
		// <elapsed time between outliers in ms, outlier beginning timestamp>
		std::deque<std::pair<outlierInterval, timestamp>> mOutlierData;

		// stores each timestamp at which a peak was detected
		// a peak is a moment at which the average outlier interval changed significantly
		std::deque<timestamp> mPeakTimestamps;

		// stores stores buffer period histograms with timestamp of first sample
		// TODO use a circular buffer
		// stores buffer period histograms with timestamp of first sample
		std::deque<std::pair<timestamp, Histogram>> mHists;

		// vector of timestamps, collected from NBLog for a specific thread
		// when a vector reaches its maximum size, the data is processed and flushed
		std::vector<timestamp_raw> mTimeStampSeries;

		// Parameters used when detecting outliers
		// TODO: learn some of these from the data, delete unused ones
		// TODO: put used variables in a struct
		@@ -128,13 +126,18 @@ private:

		// these variables are stored in-class to ensure continuity while analyzing the timestamp
		// series one short sequence at a time: the variables are not re-initialized every time.
		// TODO: use m prefix
		// TODO: change this to a running variance/mean class
		struct OutlierDistribution {
		double Mean = -1;
		double Sd = -1;
		uint64_t Elapsed = 0;
		int64_t PrevNs = -1;
		double mMean = 0; // sample mean since previous peak
		double mSd = 0; // sample sd since previous peak
		outlierInterval mElapsed = 0; // time since previous detected outlier
		int64_t mPrevTs = -1; // previous timestamp
		// number of standard deviations from mean considered a significant change
		const int kMaxDeviation = 5;
		double mTypicalDiff = 0; // global mean of outliers
		double mN = 0; // length of sequence since the last peak
		double mM2 = 0;
		} mOutlierDistribution;
		};

services/audioflinger/FastMixer.cpp

+7 −3

Original line number	Diff line number	Diff line
		@@ -138,8 +138,6 @@ bool FastMixer::isSubClassCommand(FastThreadState::Command command)

		void FastMixer::onStateChange()
		{
		// log that audio was turned on/off
		LOG_AUDIO_STATE();
		const FastMixerState * const current = (const FastMixerState *) mCurrent;
		const FastMixerState * const previous = (const FastMixerState *) mPrevious;
		FastMixerDumpState * const dumpState = (FastMixerDumpState *) mDumpState;
		@@ -336,7 +334,13 @@ void FastMixer::onStateChange()

		void FastMixer::onWork()
		{
		// TODO: pass an ID parameter to indicate which time series we want to write to in NBLog.cpp
		// Or: pass both of these into a single call with a boolean
		if (mIsWarm) {
		LOG_HIST_TS();
		} else {
		LOG_AUDIO_STATE();
		}
		const FastMixerState * const current = (const FastMixerState *) mCurrent;
		FastMixerDumpState * const dumpState = (FastMixerDumpState *) mDumpState;
		const FastMixerState::Command command = mCommand;