Add options to dumpsys media.log and dump visualizations
Other Changes:
- added thread_params_t type to NBLog
- rearranged ordering of macros in TypedLogger.h
Test: dumpsys media.log with --json, --pa, and --plots options
Bug: 68148948
Change-Id: If97714271a085a99bba0ab3ae0c268a9f407f053
diff --git a/media/libnblog/Merger.cpp b/media/libnblog/Merger.cpp
index 5f6e0d1..5e6f79a 100644
--- a/media/libnblog/Merger.cpp
+++ b/media/libnblog/Merger.cpp
@@ -34,9 +34,11 @@
#include <utils/Log.h>
#include <utils/Mutex.h>
#include <utils/RefBase.h>
+#include <utils/String16.h>
#include <utils/String8.h>
-#include <utils/Timers.h>
#include <utils/Thread.h>
+#include <utils/Timers.h>
+#include <utils/Vector.h>
namespace android {
namespace NBLog {
@@ -145,13 +147,12 @@
} 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.threadInfo = info;
} break;
+ case EVENT_THREAD_PARAMS: {
+ const thread_params_t params = it.payload<thread_params_t>();
+ data.threadParams = params;
+ } break;
case EVENT_LATENCY: {
const double latencyMs = it.payload<double>();
data.latencyHist.add(latencyMs);
@@ -211,23 +212,29 @@
}
}
-void MergeReader::dump(int fd, int indent)
+void MergeReader::dump(int fd, const Vector<String16>& args)
{
// TODO: add a mutex around media.log dump
- ReportPerformance::dump(fd, indent, mThreadPerformanceAnalysis);
- Json::Value root(Json::arrayValue);
- for (const auto& item : mThreadPerformanceData) {
- const ReportPerformance::PerformanceData& data = item.second;
- std::unique_ptr<Json::Value> threadData = ReportPerformance::dumpToJson(data);
- if (threadData == nullptr) {
- continue;
+ // Options for dumpsys
+ bool pa = false, json = false, plots = false;
+ for (const auto &arg : args) {
+ if (arg == String16("--pa")) {
+ pa = true;
+ } else if (arg == String16("--json")) {
+ json = true;
+ } else if (arg == String16("--plots")) {
+ plots = true;
}
- (*threadData)["threadNum"] = item.first;
- root.append(*threadData);
}
- Json::StyledWriter writer;
- std::string rootStr = writer.write(root);
- write(fd, rootStr.c_str(), rootStr.size());
+ if (pa) {
+ ReportPerformance::dump(fd, 0 /*indent*/, mThreadPerformanceAnalysis);
+ }
+ if (json) {
+ ReportPerformance::dumpJson(fd, mThreadPerformanceData);
+ }
+ if (plots) {
+ ReportPerformance::dumpPlots(fd, mThreadPerformanceData);
+ }
}
void MergeReader::handleAuthor(const AbstractEntry &entry, String8 *body)
diff --git a/media/libnblog/ReportPerformance.cpp b/media/libnblog/ReportPerformance.cpp
index bf8a1dc..7e40947 100644
--- a/media/libnblog/ReportPerformance.cpp
+++ b/media/libnblog/ReportPerformance.cpp
@@ -40,13 +40,14 @@
namespace android {
namespace ReportPerformance {
-std::unique_ptr<Json::Value> dumpToJson(const PerformanceData& data)
+static 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"] = (Json::Value::Int)data.threadInfo.type;
- root["frameCount"] = (Json::Value::Int)data.threadInfo.frameCount;
- root["sampleRate"] = (Json::Value::Int)data.threadInfo.sampleRate;
+ root["ioHandle"] = data.threadInfo.id;
+ root["type"] = NBLog::threadTypeToString(data.threadInfo.type);
+ root["frameCount"] = (Json::Value::Int)data.threadParams.frameCount;
+ root["sampleRate"] = (Json::Value::Int)data.threadParams.sampleRate;
root["workMsHist"] = data.workHist.toString();
root["latencyMsHist"] = data.latencyHist.toString();
root["warmupMsHist"] = data.warmupHist.toString();
@@ -57,6 +58,61 @@
return rootPtr;
}
+static std::string dumpHistogramsToString(const PerformanceData& data)
+{
+ std::stringstream ss;
+ ss << "==========================================\n";
+ ss << "Thread type=" << NBLog::threadTypeToString(data.threadInfo.type)
+ << " handle=" << data.threadInfo.id
+ << " sampleRate=" << data.threadParams.sampleRate
+ << " frameCount=" << data.threadParams.frameCount << "\n";
+ ss << " Thread work times in ms:\n" << data.workHist.asciiArtString(4 /*indent*/);
+ ss << " Thread latencies in ms:\n" << data.latencyHist.asciiArtString(4 /*indent*/);
+ ss << " Thread warmup times in ms:\n" << data.warmupHist.asciiArtString(4 /*indent*/);
+ return ss.str();
+}
+
+void dumpJson(int fd, const std::map<int, PerformanceData>& threadDataMap)
+{
+ if (fd < 0) {
+ return;
+ }
+
+ Json::Value root(Json::arrayValue);
+ for (const auto& item : threadDataMap) {
+ const ReportPerformance::PerformanceData& data = item.second;
+ // Skip threads that do not have performance data recorded yet.
+ if (data.empty()) {
+ continue;
+ }
+ std::unique_ptr<Json::Value> dataJson = ReportPerformance::dumpToJson(data);
+ if (dataJson == nullptr) {
+ continue;
+ }
+ (*dataJson)["threadNum"] = item.first;
+ root.append(*dataJson);
+ }
+ Json::StyledWriter writer;
+ std::string rootStr = writer.write(root);
+ write(fd, rootStr.c_str(), rootStr.size());
+}
+
+void dumpPlots(int fd, const std::map<int, PerformanceData>& threadDataMap)
+{
+ if (fd < 0) {
+ return;
+ }
+
+ for (const auto &item : threadDataMap) {
+ const ReportPerformance::PerformanceData& data = item.second;
+ if (data.empty()) {
+ continue;
+ }
+ std::string hists = ReportPerformance::dumpHistogramsToString(data);
+ write(fd, hists.c_str(), hists.size());
+ }
+}
+
bool sendToMediaMetrics(const PerformanceData& data)
{
// See documentation for these metrics here:
@@ -72,6 +128,11 @@
static constexpr char kThreadActive[] = "android.media.audiothread.activeMs";
static constexpr char kThreadDuration[] = "android.media.audiothread.durationMs";
+ // Currently, we only allow FastMixer thread data to be sent to Media Metrics.
+ if (data.threadInfo.type != NBLog::FASTMIXER) {
+ return false;
+ }
+
std::unique_ptr<MediaAnalyticsItem> item(new MediaAnalyticsItem("audiothread"));
const Histogram &workHist = data.workHist;
@@ -104,8 +165,8 @@
// Add thread info fields.
const char * const typeString = NBLog::threadTypeToString(data.threadInfo.type);
item->setCString(kThreadType, typeString);
- item->setInt32(kThreadFrameCount, data.threadInfo.frameCount);
- item->setInt32(kThreadSampleRate, data.threadInfo.sampleRate);
+ item->setInt32(kThreadFrameCount, data.threadParams.frameCount);
+ item->setInt32(kThreadSampleRate, data.threadParams.sampleRate);
// Add time info fields.
item->setInt64(kThreadActive, data.active / 1000000);
item->setInt64(kThreadDuration, (systemTime() - data.start) / 1000000);
diff --git a/media/libnblog/include/media/nblog/Events.h b/media/libnblog/include/media/nblog/Events.h
index 9212ce4..aca4fe8 100644
--- a/media/libnblog/include/media/nblog/Events.h
+++ b/media/libnblog/include/media/nblog/Events.h
@@ -19,6 +19,7 @@
#include <stddef.h>
#include <stdint.h>
+#include <system/audio.h>
#include <type_traits>
namespace android {
@@ -62,11 +63,11 @@
EVENT_LATENCY, // difference between frames presented by HAL and frames
// written to HAL output sink, divided by sample rate.
EVENT_OVERRUN, // predicted thread overrun event timestamp
- EVENT_THREAD_INFO, // thread type, frameCount and sampleRate, which give context
- // for the metrics below.
+ EVENT_THREAD_INFO, // see thread_info_t below
EVENT_UNDERRUN, // predicted thread underrun event timestamp
EVENT_WARMUP_TIME, // thread warmup time
EVENT_WORK_TIME, // the time a thread takes to do work, e.g. read, write, etc.
+ EVENT_THREAD_PARAMS, // see thread_params_t below
EVENT_UPPER_BOUND, // to check for invalid events
};
@@ -113,10 +114,22 @@
}
// mapped from EVENT_THREAD_INFO
+// These fields always stay the same throughout a thread's lifetime and
+// should only need to be logged once upon thread initialization.
+// There is currently no recovery mechanism if the log event corresponding
+// to this type is lost.
+// TODO add this information when adding a reader to MediaLogService?
struct thread_info_t {
- ThreadType type;
- size_t frameCount; // number of frames per read or write buffer
- unsigned sampleRate; // in frames per second
+ audio_io_handle_t id = -1; // Thread I/O handle
+ ThreadType type = UNKNOWN; // See enum ThreadType above
+};
+
+// mapped from EVENT_THREAD_PARAMS
+// These fields are not necessarily constant throughout a thread's lifetime and
+// can be logged whenever a thread receives new configurations or parameters.
+struct thread_params_t {
+ size_t frameCount = 0; // number of frames per read or write buffer
+ unsigned sampleRate = 0; // in frames per second
};
template <Event E> struct get_mapped;
@@ -135,6 +148,7 @@
MAP_EVENT_TO_TYPE(EVENT_UNDERRUN, int64_t);
MAP_EVENT_TO_TYPE(EVENT_WARMUP_TIME, double);
MAP_EVENT_TO_TYPE(EVENT_WORK_TIME, int64_t);
+MAP_EVENT_TO_TYPE(EVENT_THREAD_PARAMS, thread_params_t);
} // namespace NBLog
} // namespace android
diff --git a/media/libnblog/include/media/nblog/Merger.h b/media/libnblog/include/media/nblog/Merger.h
index ac63a7e..7da8521 100644
--- a/media/libnblog/include/media/nblog/Merger.h
+++ b/media/libnblog/include/media/nblog/Merger.h
@@ -29,9 +29,12 @@
#include <utils/Mutex.h>
#include <utils/RefBase.h>
#include <utils/Thread.h>
+#include <utils/Timers.h>
+#include <utils/Vector.h>
namespace android {
+class String16;
class String8;
namespace NBLog {
@@ -83,7 +86,7 @@
// the send if it is time to do so.
void checkPushToMediaMetrics();
- void dump(int fd, int indent = 0);
+ void dump(int fd, const Vector<String16>& args);
private:
// FIXME Needs to be protected by a lock,
diff --git a/media/libnblog/include/media/nblog/PerformanceAnalysis.h b/media/libnblog/include/media/nblog/PerformanceAnalysis.h
index 37a30aa..b1e09d7 100644
--- a/media/libnblog/include/media/nblog/PerformanceAnalysis.h
+++ b/media/libnblog/include/media/nblog/PerformanceAnalysis.h
@@ -136,6 +136,9 @@
// also does some additional analyzing of data, while the purpose of this struct is
// to hold data.
struct PerformanceData {
+ // TODO the Histogram::Config numbers below are for FastMixer.
+ // Specify different numbers for other thread types.
+
// 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.};
@@ -148,10 +151,8 @@
// bin size and lower/upper limits.
static constexpr Histogram::Config kWarmupConfig = { 5., 10, 10.};
- // Thread Info
- NBLog::thread_info_t threadInfo{
- NBLog::UNKNOWN /*threadType*/, 0 /*frameCount*/, 0 /*sampleRate*/
- };
+ NBLog::thread_info_t threadInfo{};
+ NBLog::thread_params_t threadParams{};
// Performance Data
Histogram workHist{kWorkConfig};
@@ -174,6 +175,13 @@
active = 0;
start = systemTime();
}
+
+ // Return true if performance data has not been recorded yet, false otherwise.
+ bool empty() const {
+ return workHist.totalCount() == 0 && latencyHist.totalCount() == 0
+ && warmupHist.totalCount() == 0 && underruns == 0 && overruns == 0
+ && active == 0;
+ }
};
//------------------------------------------------------------------------------
diff --git a/media/libnblog/include/media/nblog/ReportPerformance.h b/media/libnblog/include/media/nblog/ReportPerformance.h
index b69ed3b..caad14c 100644
--- a/media/libnblog/include/media/nblog/ReportPerformance.h
+++ b/media/libnblog/include/media/nblog/ReportPerformance.h
@@ -19,22 +19,18 @@
#include <deque>
#include <map>
-#include <memory>
#include <vector>
-namespace Json {
-class Value;
-}
-
namespace android {
namespace ReportPerformance {
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);
+// Dumps performance data in a JSON format.
+void dumpJson(int fd, const std::map<int, PerformanceData>& threadDataMap);
+
+//Dumps performance data as visualized plots.
+void dumpPlots(int fd, const std::map<int, PerformanceData>& threadDataMap);
// Send one thread's data to media metrics, if the performance data is nontrivial (i.e. not
// all zero values). Return true if data was sent, false if there is nothing to write