Fixed timestamp outlier bug
Test: dumpsys media.log
Change-Id: I8b03feed956100d4cec0a2d9683a8a436323d171
diff --git a/media/libnbaio/NBLog.cpp b/media/libnbaio/NBLog.cpp
index 08f0944..c73632c 100644
--- a/media/libnbaio/NBLog.cpp
+++ b/media/libnbaio/NBLog.cpp
@@ -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,10 +756,11 @@
// ---------------------------------------------------------------------------
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};
+ NBLog::Event::EVENT_HISTOGRAM_ENTRY_TS,
+ NBLog::Event::EVENT_AUDIO_STATE};
NBLog::Reader::Reader(const void *shared, size_t size)
: mFd(-1), mIndent(0), mLost(0),
@@ -903,7 +897,9 @@
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 @@
// 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::dump(int fd, int indent) {
+ // TODO: add a mutex around media.log dump
ReportPerformance::dump(fd, indent, mThreadPerformanceAnalysis);
}
diff --git a/media/libnbaio/PerformanceAnalysis.cpp b/media/libnbaio/PerformanceAnalysis.cpp
index e9212e6..c9ca99d 100644
--- a/media/libnbaio/PerformanceAnalysis.cpp
+++ b/media/libnbaio/PerformanceAnalysis.cpp
@@ -62,73 +62,58 @@
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()) {
+// 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;
}
- // TODO: add mPrev ts depending on whether or not handleStateChange was called
- for (size_t i = 1; i < mTimeStampSeries.size(); i++) {
- // Check whether the current timestamp is an outlier
- const bool isOutlier = detectAndStoreOutlier(mTimeStampSeries[i]);
- // If an outlier was found, check whether it was a peak
- if (isOutlier) {
- /*bool isPeak =*/ detectAndStorePeak(
- mOutlierData[0].first, mOutlierData[0].second);
- }
- // 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.
- // Also insert a new empty histogram if a change in behavior (peak)
+ // 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
- if (mHists.empty() || deltaMs(mHists[0].first, mTimeStampSeries[i]) >=
- kMaxLength.HistTimespanMs) {
- mHists.emplace_front(static_cast<uint64_t>(mTimeStampSeries[i]),
- 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);
- }
- }
- // add current time intervals to histogram
- ++mHists[0].second[deltaMs(mTimeStampSeries[i-1], mTimeStampSeries[i])];
}
- // clear the timestamps
- mTimeStampSeries.clear();
- // reset outlier values
- mOutlierDistribution.mPrevNs = -1;
+ // 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);
+ }
+ }
+ // add current time intervals to histogram
+ ++mHists[0].second[deltaMs(mOutlierDistribution.mPrevTs, ts)];
+ // update previous timestamp
+ mOutlierDistribution.mPrevTs = ts;
}
+
// 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();
- }
-}
// Checks whether the time interval between two outliers is far enough from
// a typical delta to be considered a peak.
@@ -140,7 +125,6 @@
bool PerformanceAnalysis::detectAndStorePeak(outlierInterval diff, timestamp ts) {
bool isPeak = false;
if (mOutlierData.empty()) {
- ALOGD("mOutlierData is empty");
return false;
}
// Update mean of the distribution
@@ -173,7 +157,7 @@
const double kDelta2 = diff - mOutlierDistribution.mMean;
mOutlierDistribution.mM2 += kDelta * kDelta2;
mOutlierDistribution.mSd = (mOutlierDistribution.mN < 2) ? 0 :
- mOutlierDistribution.mM2 / (mOutlierDistribution.mN - 1);
+ 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
@@ -196,25 +180,19 @@
return isPeak;
}
+
// 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).
bool PerformanceAnalysis::detectAndStoreOutlier(const int64_t ts) {
- // first pass: need to initialize
- if (mOutlierDistribution.mPrevNs == -1) {
- mOutlierDistribution.mPrevNs = ts;
- }
bool isOutlier = false;
- const uint64_t diffMs = static_cast<uint64_t>(deltaMs(mOutlierDistribution.mPrevNs, ts));
- // ALOGD("%d\t", static_cast<int>(diffMs));
- if (diffMs >= static_cast<uint64_t>(kOutlierMs)) {
+ const int64_t diffMs = static_cast<int64_t>(deltaMs(mOutlierDistribution.mPrevTs, ts));
+ if (diffMs >= static_cast<int64_t>(kOutlierMs)) {
isOutlier = true;
- //ALOGD("outlier outlier %d %d", static_cast<int>(diffMs),
- // static_cast<int>(mOutlierDistribution.mElapsed));
mOutlierData.emplace_front(mOutlierDistribution.mElapsed,
- static_cast<uint64_t>(mOutlierDistribution.mPrevNs));
+ static_cast<uint64_t>(mOutlierDistribution.mPrevTs));
// Remove oldest value if the vector is full
// TODO: turn this into a circular buffer
// TODO: make sure kShortHistSize is large enough that that data will never be lost
@@ -225,10 +203,10 @@
mOutlierDistribution.mElapsed = 0;
}
mOutlierDistribution.mElapsed += diffMs;
- mOutlierDistribution.mPrevNs = ts;
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
@@ -237,7 +215,6 @@
ALOGD("reportPerformance: mHists is empty");
return;
}
- ALOGD("reportPerformance: hists size %d", static_cast<int>(mHists.size()));
std::map<int, int> buckets;
for (const auto &shortHist: mHists) {
@@ -312,6 +289,7 @@
}
}
+
// 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.
@@ -329,7 +307,6 @@
// 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);
}
}
@@ -341,14 +318,10 @@
// writes summary of performance into specified file descriptor
void dump(int fd, int indent, PerformanceAnalysisMap &threadPerformanceAnalysis) {
String8 body;
- int i = 0; // TODO: delete
const char* const kDirectory = "/data/misc/audioserver/";
for (auto & thread : threadPerformanceAnalysis) {
for (auto & hash: thread.second) {
- ALOGD("hash number %d", i++);
PerformanceAnalysis& curr = hash.second;
- // Add any new data
- curr.processAndFlushTimeStampSeries();
// write performance data to console
curr.reportPerformance(&body);
if (!body.isEmpty()) {
@@ -362,6 +335,7 @@
}
}
+
// Writes a string into specified file descriptor
void dumpLine(int fd, int indent, const String8 &body) {
dprintf(fd, "%.*s%s \n", indent, "", body.string());
diff --git a/media/libnbaio/include/media/nbaio/NBLog.h b/media/libnbaio/include/media/nbaio/NBLog.h
index bd17674..059d3f6 100644
--- a/media/libnbaio/include/media/nbaio/NBLog.h
+++ b/media/libnbaio/include/media/nbaio/NBLog.h
@@ -252,8 +252,6 @@
int author;
}; //TODO __attribute__((packed));
- using StateTsEntryWithAuthor = HistTsEntryWithAuthor;
-
struct HistIntEntry {
log_hash_t hash;
int value;
diff --git a/media/libnbaio/include/media/nbaio/PerformanceAnalysis.h b/media/libnbaio/include/media/nbaio/PerformanceAnalysis.h
index 77fa23a..3f03d4b 100644
--- a/media/libnbaio/include/media/nbaio/PerformanceAnalysis.h
+++ b/media/libnbaio/include/media/nbaio/PerformanceAnalysis.h
@@ -100,10 +100,6 @@
// 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
@@ -130,11 +126,13 @@
// 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 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 mPrevNs = -1; // previous timestamp
+ 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
diff --git a/services/audioflinger/FastMixer.cpp b/services/audioflinger/FastMixer.cpp
index c10fa05..ace586c 100644
--- a/services/audioflinger/FastMixer.cpp
+++ b/services/audioflinger/FastMixer.cpp
@@ -138,8 +138,6 @@
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::onWork()
{
- LOG_HIST_TS();
+ // 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;