Develop histogram logging
Add date to WriteToFile filenames and simplify
file format. Add timestamp logging to
NormalMixer. Change histogram resolution
dynamically based on logarithmic distance
from the distribution center. Add context
information: thread, hash and time.
Example of right end of a histogram with
rounding for values >= 27:
1 1 2 1 1 1 2 2 1
| | |
| | | | | | | | |
_____________________________________________
21.1 21.2 22.9 23.0 23.3 27.0 34.0 37.0 38.0 ms
Test: dumpsys media.log
Change-Id: I255e2d28d76a1c7a06d48e7c3eacdf2f846a7ea3
diff --git a/media/libnbaio/PerformanceAnalysis.cpp b/media/libnbaio/PerformanceAnalysis.cpp
index 8c2104c..e5e444e 100644
--- a/media/libnbaio/PerformanceAnalysis.cpp
+++ b/media/libnbaio/PerformanceAnalysis.cpp
@@ -46,16 +46,6 @@
namespace ReportPerformance {
-static int widthOf(int x) {
- int width = 0;
- while (x > 0) {
- ++width;
- x /= 10;
- }
- return width;
-}
-
-
// Given a the most recent timestamp of a series of audio processing
// wakeup timestamps,
// buckets the time interval into a histogram, searches for
@@ -75,8 +65,6 @@
const int diffJiffy = deltaJiffy(mBufferPeriod.mPrevTs, ts);
-
- // update buffer period distribution
// old versus new weight ratio when updating the buffer period mean
static constexpr double exponentialWeight = 0.999;
// update buffer period mean with exponential weighting
@@ -200,6 +188,8 @@
// 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).
+// TODO: learn what timestamp sequences correlate with glitches instead of
+// manually designing a heuristic.
bool PerformanceAnalysis::detectAndStoreOutlier(const msInterval diffMs) {
bool isOutlier = false;
if (diffMs >= mBufferPeriod.mOutlier) {
@@ -219,32 +209,73 @@
return isOutlier;
}
+static int widthOf(int x) {
+ int width = 0;
+ if (x < 0) {
+ width++;
+ x = x == INT_MIN ? INT_MAX : -x;
+ }
+ // assert (x >= 0)
+ do {
+ ++width;
+ x /= 10;
+ } while (x > 0);
+ return width;
+}
+
// computes the column width required for a specific histogram value
-inline int numberWidth(int number, int leftPadding) {
- return std::max(std::max(widthOf(number) + 4, 3), leftPadding + 2);
+inline int numberWidth(double number, int leftPadding) {
+ // Added values account for whitespaces needed around numbers, and for the
+ // dot and decimal digit not accounted for by widthOf
+ return std::max(std::max(widthOf(static_cast<int>(number)) + 3, 2), leftPadding + 1);
+}
+
+// rounds value to precision based on log-distance from mean
+inline double logRound(double x, double mean) {
+ // Larger values increase range of high resolution
+ constexpr double kBase = 2;
+ const double power = floor(
+ log(abs(x - mean) / mean) / log(kBase)) + 1;
+ // do not round values close to the mean
+ if (power < 1) {
+ return x;
+ }
+ const int factor = static_cast<int>(pow(10, power));
+ return (static_cast<int>(x) * factor) / factor;
}
// TODO Make it return a std::string instead of modifying body
-// TODO: move this to ReportPerformance, probably make it a friend function of PerformanceAnalysis
-void PerformanceAnalysis::reportPerformance(String8 *body, int maxHeight) {
+// TODO: move this to ReportPerformance, probably make it a friend function
+// of PerformanceAnalysis
+void PerformanceAnalysis::reportPerformance(String8 *body, int author, log_hash_t hash,
+ int maxHeight) {
if (mHists.empty()) {
return;
}
- std::map<int, int> buckets;
+ // ms of active audio in displayed histogram
+ double elapsedMs = 0;
+ // starting timestamp of histogram
+ timestamp startingTs = mHists[0].first;
+
+ // histogram which stores .1 precision ms counts instead of Jiffy multiple counts
+ // TODO: when there is more data, print many histograms, possibly separated at peaks
+ std::map<double, int> buckets;
for (const auto &shortHist: mHists) {
for (const auto &countPair : shortHist.second) {
- buckets[countPair.first] += countPair.second;
+ const double ms = static_cast<double>(countPair.first) / kJiffyPerMs;
+ buckets[logRound(ms, mBufferPeriod.mMean)] += countPair.second;
+ elapsedMs += ms;
}
}
// underscores and spaces length corresponds to maximum width of histogram
- static const int kLen = 100;
+ static const int kLen = 200;
std::string underscores(kLen, '_');
std::string spaces(kLen, ' ');
auto it = buckets.begin();
- int maxDelta = it->first;
+ double maxDelta = it->first;
int maxCount = it->second;
// Compute maximum values
while (++it != buckets.end()) {
@@ -264,13 +295,16 @@
scalingFactor = (height + maxHeight) / maxHeight;
height /= scalingFactor;
}
- // TODO: print reader (author) ID
- body->appendFormat("\n%*s", leftPadding + 11, "Occurrences");
+ body->appendFormat("\n%*s %3.2f %s", leftPadding + 11,
+ "Occurrences in", (elapsedMs / kMsPerSec), "seconds of audio:");
+ body->appendFormat("\n%*s%d, %lld, %lld\n", leftPadding + 11,
+ "Thread, hash, starting timestamp: ", author,
+ static_cast<long long int>(hash), static_cast<long long int>(startingTs));
// write histogram label line with bucket values
body->appendFormat("\n%s", " ");
body->appendFormat("%*s", leftPadding, " ");
for (auto const &x : buckets) {
- const int colWidth = numberWidth(x.first / kJiffyPerMs, leftPadding);
+ const int colWidth = numberWidth(x.first, leftPadding);
body->appendFormat("%*d", colWidth, x.second);
}
// write histogram ascii art
@@ -279,7 +313,7 @@
const int value = 1 << row;
body->appendFormat("%.*s", leftPadding, spaces.c_str());
for (auto const &x : buckets) {
- const int colWidth = numberWidth(x.first / kJiffyPerMs, leftPadding);
+ const int colWidth = numberWidth(x.first, leftPadding);
body->appendFormat("%.*s%s", colWidth - 1,
spaces.c_str(), x.second < value ? " " : "|");
}
@@ -294,43 +328,19 @@
// write footer with bucket labels
body->appendFormat("%*s", leftPadding, " ");
for (auto const &x : buckets) {
- const int colWidth = numberWidth(x.first / kJiffyPerMs, leftPadding);
- body->appendFormat("%*.*f", colWidth, 1,
- static_cast<double>(x.first) / kJiffyPerMs);
+ const int colWidth = numberWidth(x.first, leftPadding);
+ body->appendFormat("%*.*f", colWidth, 1, x.first);
}
body->appendFormat("%.*s%s", bucketWidth, spaces.c_str(), "ms\n");
// Now report glitches
- body->appendFormat("\ntime elapsed between glitches and glitch timestamps\n");
+ body->appendFormat("\ntime elapsed between glitches and glitch timestamps:\n");
for (const auto &outlier: mOutlierData) {
body->appendFormat("%lld: %lld\n", static_cast<long long>(outlier.first),
static_cast<long long>(outlier.second));
}
}
-// TODO: learn what timestamp sequences correlate with glitches instead of
-// manually designing a heuristic. Ultimately, detect glitches directly from audio.
-// Produces a log warning if the timing of recent buffer periods caused a glitch
-// Computes sum of running window of three buffer periods
-// Checks whether the buffer periods leave enough CPU time for the next one
-// e.g. if a buffer period is expected to be 4 ms and a buffer requires 3 ms of CPU time,
-// here are some glitch cases:
-// 4 + 4 + 6 ; 5 + 4 + 5; 2 + 2 + 10
-
-// void PerformanceAnalysis::alertIfGlitch(const std::vector<int64_t> &samples) {
-// std::deque<int> periods(kNumBuff, kPeriodMs);
-// for (size_t i = 2; i < samples.size(); ++i) { // skip first time entry
-// periods.push_front(deltaMs(samples[i - 1], samples[i]));
-// periods.pop_back();
-// // TODO: check that all glitch cases are covered
-// if (std::accumulate(periods.begin(), periods.end(), 0) > kNumBuff * kPeriodMs +
-// kPeriodMs - kPeriodMsCPU) {
-// periods.assign(kNumBuff, kPeriodMs);
-// }
-// }
-// return;
-//}
-
//------------------------------------------------------------------------------
// writes summary of performance into specified file descriptor
@@ -341,7 +351,7 @@
for (auto & hash: thread.second) {
PerformanceAnalysis& curr = hash.second;
// write performance data to console
- curr.reportPerformance(&body);
+ curr.reportPerformance(&body, thread.first, hash.first);
if (!body.isEmpty()) {
dumpLine(fd, indent, body);
body.clear();
diff --git a/media/libnbaio/ReportPerformance.cpp b/media/libnbaio/ReportPerformance.cpp
index 813df94..e64a6d3 100644
--- a/media/libnbaio/ReportPerformance.cpp
+++ b/media/libnbaio/ReportPerformance.cpp
@@ -25,6 +25,7 @@
#include <string.h>
#include <sstream>
#include <sys/prctl.h>
+#include <sys/time.h>
#include <utility>
#include <media/nbaio/NBLog.h>
#include <media/nbaio/PerformanceAnalysis.h>
@@ -36,13 +37,16 @@
namespace ReportPerformance {
-// Writes outlier intervals, timestamps, and histograms spanning long time intervals to a file.
-// TODO: format the data efficiently and write different types of data to different files
+// 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,
const std::deque<std::pair<msInterval, timestamp>> &outlierData,
const std::deque<timestamp> &peakTimestamps,
const char * directory, bool append, int author, log_hash_t hash) {
- if (outlierData.empty() || hists.empty()) {
+
+ // TODO: remove old files, implement rotating files as in AudioFlinger.cpp
+
+ if (outlierData.empty() && hists.empty() && peakTimestamps.empty()) {
ALOGW("No data, returning.");
return;
}
@@ -51,9 +55,21 @@
std::stringstream histogramName;
std::stringstream peakName;
- histogramName << directory << "histograms_" << author << "_" << hash;
- outlierName << directory << "outliers_" << author << "_" << hash;
- peakName << directory << "peaks_" << author << "_" << hash;
+ // get current time
+ char currTime[16]; //YYYYMMDDHHMMSS + '\0' + one unused
+ struct timeval tv;
+ gettimeofday(&tv, NULL);
+ struct tm tm;
+ localtime_r(&tv.tv_sec, &tm);
+ strftime(currTime, sizeof(currTime), "%Y%m%d%H%M%S", &tm);
+
+ // generate file names
+ std::stringstream common;
+ common << author << "_" << hash << "_" << currTime << ".csv";
+
+ histogramName << directory << "histograms_" << common.str();
+ outlierName << directory << "outliers_" << common.str();
+ peakName << directory << "peaks_" << common.str();
std::ofstream hfs;
hfs.open(histogramName.str(), append ? std::ios::app : std::ios::trunc);
@@ -61,16 +77,16 @@
ALOGW("couldn't open file %s", histogramName.str().c_str());
return;
}
- hfs << "Histogram data\n";
+ // each histogram is written as a line where the first value is the timestamp and
+ // subsequent values are pairs of buckets and counts. Each value is separated
+ // by a comma, and each histogram is separated by a newline.
for (const auto &hist : hists) {
- hfs << "\ttimestamp\n";
- hfs << hist.first << "\n";
- hfs << "\tbuckets (in ms) and counts\n";
+ hfs << hist.first << ", ";
for (const auto &bucket : hist.second) {
hfs << bucket.first / static_cast<double>(kJiffyPerMs)
- << ": " << bucket.second << "\n";
+ << ", " << bucket.second << ", ";
}
- hfs << "\n"; // separate histograms with a newline
+ hfs << "\n";
}
hfs.close();
@@ -80,9 +96,10 @@
ALOGW("couldn't open file %s", outlierName.str().c_str());
return;
}
- ofs << "Outlier data: interval and timestamp\n";
+ // outliers are written as pairs separated by newlines, where each
+ // pair's values are separated by a comma
for (const auto &outlier : outlierData) {
- ofs << outlier.first << ": " << outlier.second << "\n";
+ ofs << outlier.first << ", " << outlier.second << "\n";
}
ofs.close();
@@ -92,9 +109,9 @@
ALOGW("couldn't open file %s", peakName.str().c_str());
return;
}
- pfs << "Peak data: timestamp\n";
+ // peaks are simply timestamps separated by commas
for (const auto &peak : peakTimestamps) {
- pfs << peak << "\n";
+ pfs << peak << ", ";
}
pfs.close();
}
diff --git a/media/libnbaio/include/media/nbaio/PerformanceAnalysis.h b/media/libnbaio/include/media/nbaio/PerformanceAnalysis.h
index 97b2c92..a673151 100644
--- a/media/libnbaio/include/media/nbaio/PerformanceAnalysis.h
+++ b/media/libnbaio/include/media/nbaio/PerformanceAnalysis.h
@@ -14,9 +14,6 @@
* limitations under the License.
*/
-// Non-blocking event logger intended for safe communication between
-// processes via shared memory
-
#ifndef ANDROID_MEDIA_PERFORMANCEANALYSIS_H
#define ANDROID_MEDIA_PERFORMANCEANALYSIS_H
@@ -78,12 +75,8 @@
// Generates a string of analysis of the buffer periods and prints to console
// TODO: WIP write more detailed analysis
// FIXME: move this data visualization to a separate class. Model/view/controller
- void reportPerformance(String8 *body, int maxHeight = 10);
-
- // This function detects glitches in a time series.
- // TODO: learn what timestamp sequences correlate with glitches instead of
- // manually designing a heuristic. Ultimately, detect glitches directly from audio.
- // void alertIfGlitch(const std::vector<timestamp_raw> &samples);
+ void reportPerformance(String8 *body, int author, log_hash_t hash,
+ int maxHeight = 10);
private:
@@ -108,15 +101,6 @@
timestamp mPrevTs = -1; // previous timestamp
} mBufferPeriod;
- // TODO: delete values below if unused or add them to the BufferPeriod struct
- // FIXME: decide whether to make kPeriodMs static.
- // static const int kNumBuff = 3; // number of buffers considered in local history
- // int kPeriodMs; // current period length is ideally 4 ms
- // static const int kOutlierMs = 7; // values greater or equal to this cause glitches
- // DAC processing time for 4 ms buffer
- // static constexpr double kRatio = 0.75; // estimate CPU time as ratio of period
- // int kPeriodMsCPU; // compute based on kPeriodLen and kRatio
-
// capacity allocated to data structures
// TODO: make these values longer when testing is finished
struct MaxLength {
diff --git a/services/audioflinger/Threads.cpp b/services/audioflinger/Threads.cpp
index 459e4fb..6378a14 100644
--- a/services/audioflinger/Threads.cpp
+++ b/services/audioflinger/Threads.cpp
@@ -2636,6 +2636,7 @@
// shared by MIXER and DIRECT, overridden by DUPLICATING
ssize_t AudioFlinger::PlaybackThread::threadLoop_write()
{
+ LOG_HIST_TS();
mInWrite = true;
ssize_t bytesWritten;
const size_t offset = mCurrentWriteLength - mBytesRemaining;
@@ -3114,6 +3115,10 @@
threadLoop_standby();
+ // This is where we go into standby
+ if (!mStandby) {
+ LOG_AUDIO_STATE();
+ }
mStandby = true;
}
@@ -5429,7 +5434,7 @@
mPausedWriteLength(0), mPausedBytesRemaining(0), mKeepWakeLock(true),
mOffloadUnderrunPosition(~0LL)
{
- //FIXME: mStandby should be set to true by ThreadBase constructor
+ //FIXME: mStandby should be set to true by ThreadBase constructo
mStandby = true;
mKeepWakeLock = property_get_bool("ro.audio.offload_wakelock", true /* default_value */);
}
diff --git a/services/audioflinger/Threads.h b/services/audioflinger/Threads.h
index 32f2bc4..613d08c 100644
--- a/services/audioflinger/Threads.h
+++ b/services/audioflinger/Threads.h
@@ -485,6 +485,7 @@
// Updated by updateSuspendedSessions_l() only.
KeyedVector< audio_session_t, KeyedVector< int, sp<SuspendedSessionDesc> > >
mSuspendedSessions;
+ // TODO: add comment and adjust size as needed
static const size_t kLogSize = 4 * 1024;
sp<NBLog::Writer> mNBLogWriter;
bool mSystemReady;
@@ -984,6 +985,7 @@
sp<NBAIO_Source> mTeeSource;
#endif
uint32_t mScreenState; // cached copy of gScreenState
+ // TODO: add comment and adjust size as needed
static const size_t kFastMixerLogSize = 8 * 1024;
sp<NBLog::Writer> mFastMixerNBLogWriter;
@@ -1456,6 +1458,7 @@
// If a fast capture is present, the Pipe as IMemory, otherwise clear
sp<IMemory> mPipeMemory;
+ // TODO: add comment and adjust size as needed
static const size_t kFastCaptureLogSize = 4 * 1024;
sp<NBLog::Writer> mFastCaptureNBLogWriter;