NBLog: add latency logging and histogram serialization
ReportPerformance::writeToFile and the recording of PerformanceAnalysis
FastMixer timestamps are disabled for now.
Test: dumpsys media.log -r
Bug: 68148948
Change-Id: I4ba55fc20521ad2278348e6a3f713f9db04d951b
diff --git a/media/libnblog/NBLog.cpp b/media/libnblog/NBLog.cpp
index d659445..f1d7523 100644
--- a/media/libnblog/NBLog.cpp
+++ b/media/libnblog/NBLog.cpp
@@ -478,12 +478,20 @@
}
}
+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 @@
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 @@
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 @@
{
// 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 @@
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:
diff --git a/media/libnblog/PerformanceAnalysis.cpp b/media/libnblog/PerformanceAnalysis.cpp
index 3418dc0..ce9e22a 100644
--- a/media/libnblog/PerformanceAnalysis.cpp
+++ b/media/libnblog/PerformanceAnalysis.cpp
@@ -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 @@
// 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 @@
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
}
}
}
diff --git a/media/libnblog/include/media/nblog/NBLog.h b/media/libnblog/include/media/nblog/NBLog.h
index c9bfaae..763d743 100644
--- a/media/libnblog/include/media/nblog/NBLog.h
+++ b/media/libnblog/include/media/nblog/NBLog.h
@@ -350,6 +350,7 @@
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 @@
// 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);
diff --git a/media/libnblog/include/media/nblog/PerformanceAnalysis.h b/media/libnblog/include/media/nblog/PerformanceAnalysis.h
index 56e0ea6..f2c3a48 100644
--- a/media/libnblog/include/media/nblog/PerformanceAnalysis.h
+++ b/media/libnblog/include/media/nblog/PerformanceAnalysis.h
@@ -19,6 +19,7 @@
#include <deque>
#include <map>
+#include <unordered_map>
#include <vector>
#include <media/nblog/ReportPerformance.h>
@@ -27,6 +28,127 @@
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;
diff --git a/services/audioflinger/FastMixer.cpp b/services/audioflinger/FastMixer.cpp
index a42d6b3..fd784a4 100644
--- a/services/audioflinger/FastMixer.cpp
+++ b/services/audioflinger/FastMixer.cpp
@@ -340,10 +340,19 @@
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 @@
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;
diff --git a/services/audioflinger/TypedLogger.h b/services/audioflinger/TypedLogger.h
index 0fea42a..736ac60 100644
--- a/services/audioflinger/TypedLogger.h
+++ b/services/audioflinger/TypedLogger.h
@@ -102,6 +102,9 @@
#define LOG_MONOTONIC_CYCLE_TIME(ns) do { NBLog::Writer *x = tlNBLogWriter; if (x != nullptr) \
x->logMonotonicCycleTime(ns); } while (0)
+#define LOG_LATENCY(ms) do { NBLog::Writer *x = tlNBLogWriter; if (x != nullptr) \
+ x->logLatency(ms); } while (0)
+
namespace android {
extern "C" {
extern thread_local NBLog::Writer *tlNBLogWriter;