NBLog: log and store warmup times, underruns, overruns, and thread info
Test: dumpsys media.log
Bug: 68148948
Change-Id: Ib6ea96760f7886cba47c8e2f0334114237a2434b
diff --git a/media/libnblog/Android.bp b/media/libnblog/Android.bp
index 74aaf77..b15e79b 100644
--- a/media/libnblog/Android.bp
+++ b/media/libnblog/Android.bp
@@ -16,6 +16,10 @@
"libutils",
],
+ static_libs: [
+ "libjsoncpp",
+ ],
+
cflags: [
"-Werror",
"-Wall",
diff --git a/media/libnblog/NBLog.cpp b/media/libnblog/NBLog.cpp
index f73e2ae..cd967e4 100644
--- a/media/libnblog/NBLog.cpp
+++ b/media/libnblog/NBLog.cpp
@@ -21,6 +21,7 @@
#include <algorithm>
#include <climits>
#include <math.h>
+#include <memory>
#include <unordered_set>
#include <vector>
#include <stdarg.h>
@@ -31,12 +32,14 @@
#include <time.h>
#include <new>
#include <audio_utils/roundup.h>
+#include <json/json.h>
#include <media/nblog/NBLog.h>
#include <media/nblog/PerformanceAnalysis.h>
#include <media/nblog/ReportPerformance.h>
#include <utils/CallStack.h>
#include <utils/Log.h>
#include <utils/String8.h>
+#include <utils/Timers.h>
#include <queue>
#include <utility>
@@ -417,7 +420,7 @@
if (!mEnabled) {
return;
}
- int64_t ts = get_monotonic_ns();
+ const nsecs_t ts = systemTime();
if (ts > 0) {
log(EVENT_FMT_TIMESTAMP, &ts, sizeof(ts));
} else {
@@ -432,7 +435,7 @@
}
HistTsEntry data;
data.hash = hash;
- data.ts = get_monotonic_ns();
+ data.ts = systemTime();
if (data.ts > 0) {
log(event, &data, sizeof(data));
} else {
@@ -780,15 +783,17 @@
return snapshot;
}
+// TODO separate this method from the rest of NBLog
// Takes raw content of the local merger FIFO, processes log entries, and
// writes the data to a map of class PerformanceAnalysis, based on their thread ID.
-void NBLog::MergeReader::getAndProcessSnapshot(NBLog::Snapshot &snapshot, int author)
+void NBLog::MergeReader::processSnapshot(NBLog::Snapshot &snapshot, int author)
{
+ PerformanceData& data = mThreadPerformanceData[author];
// We don't do "auto it" because it reduces readability in this case.
for (EntryIterator it = snapshot.begin(); it != snapshot.end(); ++it) {
switch (it->type) {
case EVENT_HISTOGRAM_ENTRY_TS: {
- HistTsEntry payload = it.payload<HistTsEntry>();
+ const HistTsEntry payload = it.payload<HistTsEntry>();
// TODO: hash for histogram ts and audio state need to match
// and correspond to audio production source file location
mThreadPerformanceAnalysis[author][0 /*hash*/].logTsEntry(payload.ts);
@@ -796,15 +801,37 @@
case EVENT_AUDIO_STATE: {
mThreadPerformanceAnalysis[author][0 /*hash*/].handleStateChange();
} break;
+ case EVENT_THREAD_INFO: {
+ const thread_info_t info = it.payload<thread_info_t>();
+ // TODO make PerformanceData hold a type of thread_info_t.
+ // Currently, thread_info_t is defined in NBLog.h, which includes
+ // PerformanceAnalysis.h. PerformanceData is defined in PerformanceAnalysis.h,
+ // where including NBLog.h would result in circular includes. The organization
+ // of files will need to change to avoid this problem.
+ data.type = info.type;
+ data.frameCount = info.frameCount;
+ data.sampleRate = info.sampleRate;
+ } break;
case EVENT_LATENCY: {
- double latencyMs = it.payload<double>();
- mPerformanceData.addLatencyEntry(author, latencyMs);
+ const double latencyMs = it.payload<double>();
+ data.latencyHist.add(latencyMs);
} break;
case EVENT_WORK_TIME: {
- uint64_t monotonicNs = it.payload<uint64_t>();
+ const int64_t monotonicNs = it.payload<int64_t>();
const double monotonicMs = monotonicNs * 1e-6;
- mPerformanceData.addCycleTimeEntry(author, monotonicMs);
+ data.workHist.add(monotonicMs);
+ data.active += monotonicNs;
} break;
+ case EVENT_WARMUP_TIME: {
+ const double timeMs = it.payload<double>();
+ data.warmupHist.add(timeMs);
+ } break;
+ case EVENT_UNDERRUN:
+ data.underruns++;
+ break;
+ case EVENT_OVERRUN:
+ data.overruns++;
+ break;
case EVENT_RESERVED:
case EVENT_UPPER_BOUND:
ALOGW("warning: unexpected event %d", it->type);
@@ -826,7 +853,7 @@
// TODO unlock lock here
for (size_t i = 0; i < nLogs; i++) {
if (snapshots[i] != nullptr) {
- getAndProcessSnapshot(*(snapshots[i]), i);
+ processSnapshot(*(snapshots[i]), i);
}
}
}
@@ -835,7 +862,19 @@
{
// TODO: add a mutex around media.log dump
ReportPerformance::dump(fd, indent, mThreadPerformanceAnalysis);
- mPerformanceData.dump(fd);
+ Json::Value root(Json::arrayValue);
+ for (const auto& item : mThreadPerformanceData) {
+ const PerformanceData& data = item.second;
+ std::unique_ptr<Json::Value> threadData = dumpToJson(data);
+ if (threadData == nullptr) {
+ continue;
+ }
+ (*threadData)["threadNum"] = item.first;
+ root.append(*threadData);
+ }
+ Json::StyledWriter writer;
+ std::string rootStr = writer.write(root);
+ dprintf(fd, "%s", rootStr.c_str());
}
// TODO for future compatibility, would prefer to have a dump() go to string, and then go
@@ -856,13 +895,23 @@
it = handleFormat(FormatEntry(it), ×tamp, &body);
break;
case EVENT_WORK_TIME: {
- uint64_t monotonicNs = it.payload<uint64_t>();
- body.appendFormat("Thread cycle: %lu ns", (unsigned long)monotonicNs);
+ const int64_t monotonicNs = it.payload<int64_t>();
+ body.appendFormat("Thread cycle: %ld ns", (long)monotonicNs);
} break;
case EVENT_LATENCY: {
- double latencyMs = it.payload<double>();
+ const double latencyMs = it.payload<double>();
body.appendFormat("latency: %.3f ms", latencyMs);
} break;
+ case EVENT_WARMUP_TIME: {
+ const double timeMs = it.payload<double>();
+ body.appendFormat("warmup time: %.3f ms", timeMs);
+ } break;
+ case EVENT_UNDERRUN:
+ body.appendFormat("underrun");
+ break;
+ case EVENT_OVERRUN:
+ body.appendFormat("overrun");
+ break;
case EVENT_FMT_END:
case EVENT_RESERVED:
case EVENT_UPPER_BOUND:
@@ -947,7 +996,7 @@
String8 *body)
{
// log timestamp
- int64_t ts = fmtEntry.timestamp();
+ const int64_t ts = fmtEntry.timestamp();
timestamp->clear();
timestamp->appendFormat("[%d.%03d]", (int) (ts / (1000 * 1000 * 1000)),
(int) ((ts / (1000 * 1000)) % 1000));
diff --git a/media/libnblog/PerformanceAnalysis.cpp b/media/libnblog/PerformanceAnalysis.cpp
index ce9e22a..999b22a 100644
--- a/media/libnblog/PerformanceAnalysis.cpp
+++ b/media/libnblog/PerformanceAnalysis.cpp
@@ -41,6 +41,7 @@
#include <media/nblog/ReportPerformance.h>
#include <utils/Log.h>
#include <utils/String8.h>
+#include <utils/Timers.h>
#include <queue>
#include <utility>
@@ -74,7 +75,7 @@
return mTotalCount;
}
-std::string Histogram::serializeToString() const {
+std::string Histogram::toString() const {
std::stringstream ss;
static constexpr char kDivider = '|';
ss << mBinSize << "," << mNumBins << "," << mLow << ",{";
@@ -104,38 +105,6 @@
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 {
diff --git a/media/libnblog/ReportPerformance.cpp b/media/libnblog/ReportPerformance.cpp
index 827e731..98e11cd 100644
--- a/media/libnblog/ReportPerformance.cpp
+++ b/media/libnblog/ReportPerformance.cpp
@@ -18,6 +18,7 @@
#include <fstream>
#include <iostream>
+#include <memory>
#include <queue>
#include <stdarg.h>
#include <stdint.h>
@@ -27,6 +28,7 @@
#include <sys/prctl.h>
#include <sys/time.h>
#include <utility>
+#include <json/json.h>
#include <media/nblog/NBLog.h>
#include <media/nblog/PerformanceAnalysis.h>
#include <media/nblog/ReportPerformance.h>
@@ -35,8 +37,26 @@
namespace android {
-namespace ReportPerformance {
+std::unique_ptr<Json::Value> dumpToJson(const PerformanceData& data)
+{
+ std::unique_ptr<Json::Value> rootPtr = std::make_unique<Json::Value>(Json::objectValue);
+ Json::Value& root = *rootPtr;
+ root["type"] = data.type;
+ root["frameCount"] = (Json::Value::Int)data.frameCount;
+ root["sampleRate"] = (Json::Value::Int)data.sampleRate;
+ root["workMsHist"] = data.workHist.toString();
+ root["latencyMsHist"] = data.latencyHist.toString();
+ root["warmupMsHist"] = data.warmupHist.toString();
+ root["underruns"] = (Json::Value::Int64)data.underruns;
+ root["overruns"] = (Json::Value::Int64)data.overruns;
+ root["activeMs"] = (Json::Value::Int64)ns2ms(data.active);
+ root["durationMs"] = (Json::Value::Int64)ns2ms(systemTime() - data.start);
+ return rootPtr;
+}
+//------------------------------------------------------------------------------
+
+namespace ReportPerformance {
// TODO: use a function like this to extract logic from writeToFile
// https://stackoverflow.com/a/9279620
diff --git a/media/libnblog/include/media/nblog/NBLog.h b/media/libnblog/include/media/nblog/NBLog.h
index 561e8c7..d6403d3 100644
--- a/media/libnblog/include/media/nblog/NBLog.h
+++ b/media/libnblog/include/media/nblog/NBLog.h
@@ -20,6 +20,7 @@
#define ANDROID_MEDIA_NBLOG_H
#include <map>
+#include <memory>
#include <type_traits>
#include <unordered_set>
#include <vector>
@@ -30,6 +31,7 @@
#include <media/nblog/ReportPerformance.h>
#include <utils/Mutex.h>
#include <utils/threads.h>
+#include <utils/Timers.h>
namespace android {
@@ -39,7 +41,7 @@
public:
- using log_hash_t = ReportPerformance::log_hash_t;
+ using log_hash_t = uint64_t;
// FIXME Everything needed for client (writer API and registration) should be isolated
// from the rest of the implementation.
@@ -78,13 +80,29 @@
EVENT_AUDIO_STATE, // audio on/off event: logged on FastMixer::onStateChange call
// Types representing audio performance metrics
+ EVENT_THREAD_INFO, // thread type, frameCount and sampleRate, which give context
+ // for the metrics below.
EVENT_LATENCY, // difference between frames presented by HAL and frames
// written to HAL output sink, divided by sample rate.
EVENT_WORK_TIME, // the time a thread takes to do work, e.g. read, write, etc.
+ EVENT_WARMUP_TIME, // thread warmup time
+ EVENT_UNDERRUN, // predicted thread underrun event timestamp
+ EVENT_OVERRUN, // predicted thread overrun event timestamp
EVENT_UPPER_BOUND, // to check for invalid events
};
+ // NBLog custom-defined structs. Some NBLog Event types map to these structs.
+
+ // mapped from EVENT_THREAD_INFO
+ struct thread_info_t {
+ // TODO make type an enum
+ int type; // Thread type: 0 for MIXER, 1 for CAPTURE,
+ // 2 for FASTMIXER, 3 for FASTCAPTURE
+ size_t frameCount; // number of frames per read or write buffer
+ unsigned sampleRate; // in frames per second
+ };
+
template <Event E> struct get_mapped;
#define MAP_EVENT_TO_TYPE(E, T) \
template<> struct get_mapped<E> { \
@@ -95,8 +113,12 @@
}
// Maps an NBLog Event type to a C++ POD type.
+ MAP_EVENT_TO_TYPE(EVENT_THREAD_INFO, thread_info_t);
MAP_EVENT_TO_TYPE(EVENT_LATENCY, double);
- MAP_EVENT_TO_TYPE(EVENT_WORK_TIME, uint64_t);
+ MAP_EVENT_TO_TYPE(EVENT_WORK_TIME, int64_t);
+ MAP_EVENT_TO_TYPE(EVENT_WARMUP_TIME, double);
+ MAP_EVENT_TO_TYPE(EVENT_UNDERRUN, int64_t);
+ MAP_EVENT_TO_TYPE(EVENT_OVERRUN, int64_t);
private:
@@ -154,7 +176,7 @@
}
#else
template<typename T>
- inline T payload() {
+ inline T payload() const {
static_assert(std::is_trivially_copyable<T>::value
&& !std::is_pointer<T>::value,
"NBLog::EntryIterator payload must be trivially copyable, non-pointer type.");
@@ -545,6 +567,7 @@
};
// ---------------------------------------------------------------------------
+ // TODO move Merger, MergeReader, and MergeThread to a separate file.
// This class is used to read data from each thread's individual FIFO in shared memory
// and write it to a single FIFO in local memory.
@@ -581,7 +604,7 @@
void dump(int fd, int indent = 0);
// process a particular snapshot of the reader
- void getAndProcessSnapshot(Snapshot &snap, int author);
+ void processSnapshot(Snapshot &snap, int author);
// call getSnapshot of the content of the reader's buffer and process the data
void getAndProcessSnapshot();
@@ -596,7 +619,8 @@
// location within each author
ReportPerformance::PerformanceAnalysisMap mThreadPerformanceAnalysis;
- PerformanceData mPerformanceData;
+ // compresses and stores audio performance data from each thread's buffers.
+ std::map<int /*author, i.e. thread index*/, PerformanceData> mThreadPerformanceData;
// handle author entry by looking up the author's name and appending it to the body
// returns number of bytes read from fmtEntry
@@ -645,15 +669,6 @@
}; // class NBLog
-// TODO put somewhere else
-static inline int64_t get_monotonic_ns() {
- timespec ts;
- if (clock_gettime(CLOCK_MONOTONIC, &ts) == 0) {
- return (uint64_t) ts.tv_sec * 1000 * 1000 * 1000 + ts.tv_nsec;
- }
- return 0; // should not happen.
-}
-
} // namespace android
#endif // ANDROID_MEDIA_NBLOG_H
diff --git a/media/libnblog/include/media/nblog/PerformanceAnalysis.h b/media/libnblog/include/media/nblog/PerformanceAnalysis.h
index f2c3a48..6677cde 100644
--- a/media/libnblog/include/media/nblog/PerformanceAnalysis.h
+++ b/media/libnblog/include/media/nblog/PerformanceAnalysis.h
@@ -19,10 +19,11 @@
#include <deque>
#include <map>
-#include <unordered_map>
+#include <utility>
#include <vector>
#include <media/nblog/ReportPerformance.h>
+#include <utils/Timers.h>
namespace android {
@@ -106,7 +107,7 @@
*
* \return the histogram serialized as a string.
*/
- std::string serializeToString() const;
+ std::string toString() const;
private:
const double mBinSize; // Size of each bucket
@@ -119,32 +120,50 @@
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;
+// This is essentially the same as class PerformanceAnalysis, but PerformanceAnalysis
+// also does some additional analyzing of data, while the purpose of this struct is
+// to hold data.
+struct PerformanceData {
+ // 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 kWorkConfig = { 0.25, 20, 2.};
// 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;
+
+ // Values based on trial and error logging. Need a better way to determine
+ // bin size and lower/upper limits.
+ static constexpr Histogram::Config kWarmupConfig = { 5., 10, 10.};
+
+ // Thread Info
+ // TODO make type an enum
+ int type = -1; // Thread type: 0 for MIXER, 1 for CAPTURE,
+ // 2 for FASTMIXER, 3 for FASTCAPTURE
+ size_t frameCount = 0;
+ unsigned sampleRate = 0;
+
+ // Performance Data
+ Histogram workHist{kWorkConfig};
+ Histogram latencyHist{kLatencyConfig};
+ Histogram warmupHist{kWarmupConfig};
+ int64_t underruns = 0;
+ int64_t overruns = 0;
+ nsecs_t active = 0;
+ nsecs_t start{systemTime()};
+
+ // Reset the performance data. This does not represent a thread state change.
+ // Thread info is not reset here because the data is meant to be a continuation of the thread
+ // that struct PerformanceData is associated with.
+ void reset() {
+ workHist.clear();
+ latencyHist.clear();
+ warmupHist.clear();
+ underruns = 0;
+ overruns = 0;
+ active = 0;
+ start = systemTime();
+ }
};
//------------------------------------------------------------------------------
diff --git a/media/libnblog/include/media/nblog/ReportPerformance.h b/media/libnblog/include/media/nblog/ReportPerformance.h
index 1b11197..da0c7ca 100644
--- a/media/libnblog/include/media/nblog/ReportPerformance.h
+++ b/media/libnblog/include/media/nblog/ReportPerformance.h
@@ -19,10 +19,22 @@
#include <deque>
#include <map>
+#include <memory>
#include <vector>
+namespace Json {
+class Value;
+}
+
namespace android {
+struct PerformanceData;
+
+// Dumps performance data to a JSON format.
+// Return by pointer instead of by value to avoid dependency side effects of including
+// the header of an external library.
+std::unique_ptr<Json::Value> dumpToJson(const PerformanceData& data);
+
namespace ReportPerformance {
constexpr int kMsPerSec = 1000;