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
diff --git a/services/audioflinger/FastMixer.cpp b/services/audioflinger/FastMixer.cpp
index d7b7fe8..d15841f 100644
--- a/services/audioflinger/FastMixer.cpp
+++ b/services/audioflinger/FastMixer.cpp
@@ -195,8 +195,10 @@
// to avoid blocking here and to prevent possible priority inversion
mMixer = new AudioMixer(frameCount, mSampleRate);
// FIXME See the other FIXME at FastMixer::setNBLogWriter()
- const NBLog::thread_info_t info = { NBLog::FASTMIXER, frameCount, mSampleRate };
- LOG_THREAD_INFO(info);
+ NBLog::thread_params_t params;
+ params.frameCount = frameCount;
+ params.sampleRate = mSampleRate;
+ LOG_THREAD_PARAMS(params);
const size_t mixerFrameSize = mSinkChannelCount
* audio_bytes_per_sample(mMixerBufferFormat);
mMixerBufferSize = mixerFrameSize * frameCount;
diff --git a/services/audioflinger/Threads.cpp b/services/audioflinger/Threads.cpp
index 811f09a..cf3a65a 100644
--- a/services/audioflinger/Threads.cpp
+++ b/services/audioflinger/Threads.cpp
@@ -4033,6 +4033,11 @@
sq->end();
sq->push(FastMixerStateQueue::BLOCK_UNTIL_PUSHED);
+ NBLog::thread_info_t info;
+ info.id = mId;
+ info.type = NBLog::FASTMIXER;
+ mFastMixerNBLogWriter->log<NBLog::EVENT_THREAD_INFO>(info);
+
// start the fast mixer
mFastMixer->run("FastMixer", PRIORITY_URGENT_AUDIO);
pid_t tid = mFastMixer->getTid();
diff --git a/services/audioflinger/TypedLogger.h b/services/audioflinger/TypedLogger.h
index dd2e7c9..6ef19bf 100644
--- a/services/audioflinger/TypedLogger.h
+++ b/services/audioflinger/TypedLogger.h
@@ -97,24 +97,11 @@
#define LOG_AUDIO_STATE() do { NBLog::Writer *x = tlNBLogWriter; if (x != nullptr) \
x->logEventHistTs(NBLog::EVENT_AUDIO_STATE, hash(__FILE__, __LINE__)); } while(0)
-// Record a typed entry that represents a thread's work time in nanoseconds.
-// Parameter ns should be of type uint32_t.
-#define LOG_WORK_TIME(ns) do { NBLog::Writer *x = tlNBLogWriter; if (x != nullptr) \
- x->log<NBLog::EVENT_WORK_TIME>(ns); } while (0)
-
// Log the difference bewteen frames presented by HAL and frames written to HAL output sink,
// divided by the sample rate. Parameter ms is of type double.
#define LOG_LATENCY(ms) do { NBLog::Writer *x = tlNBLogWriter; if (x != nullptr) \
x->log<NBLog::EVENT_LATENCY>(ms); } while (0)
-// Record thread warmup time in milliseconds. Parameter ms is of type double.
-#define LOG_WARMUP_TIME(ms) do { NBLog::Writer *x = tlNBLogWriter; if (x != nullptr) \
- x->log<NBLog::EVENT_WARMUP_TIME>(ms); } while (0)
-
-// Record thread underrun event nanosecond timestamp. Parameter ns is an int64_t.
-#define LOG_UNDERRUN(ns) do { NBLog::Writer *x = tlNBLogWriter; if (x != nullptr) \
- x->log<NBLog::EVENT_UNDERRUN>(ns); } while (0)
-
// Record thread overrun event nanosecond timestamp. Parameter ns is an int64_t.
#define LOG_OVERRUN(ns) do { NBLog::Writer *x = tlNBLogWriter; if (x != nullptr) \
x->log<NBLog::EVENT_OVERRUN>(ns); } while (0)
@@ -124,8 +111,28 @@
#define LOG_THREAD_INFO(info) do { NBLog::Writer *x = tlNBLogWriter; \
if (x != nullptr) x->log<NBLog::EVENT_THREAD_INFO>(info); } while (0)
+#define LOG_THREAD_PARAMS(params) do {NBLog::Writer *x = tlNBLogWriter; \
+ if (x != nullptr) x->log<NBLog::EVENT_THREAD_PARAMS>(params); } while (0)
+
+// Record thread underrun event nanosecond timestamp. Parameter ns is an int64_t.
+#define LOG_UNDERRUN(ns) do { NBLog::Writer *x = tlNBLogWriter; if (x != nullptr) \
+ x->log<NBLog::EVENT_UNDERRUN>(ns); } while (0)
+
+// Record thread warmup time in milliseconds. Parameter ms is of type double.
+#define LOG_WARMUP_TIME(ms) do { NBLog::Writer *x = tlNBLogWriter; if (x != nullptr) \
+ x->log<NBLog::EVENT_WARMUP_TIME>(ms); } while (0)
+
+// Record a typed entry that represents a thread's work time in nanoseconds.
+// Parameter ns should be of type uint32_t.
+#define LOG_WORK_TIME(ns) do { NBLog::Writer *x = tlNBLogWriter; if (x != nullptr) \
+ x->log<NBLog::EVENT_WORK_TIME>(ns); } while (0)
+
namespace android {
extern "C" {
+// TODO consider adding a thread_local NBLog::Writer tlDummyNBLogWriter and then
+// initialize below tlNBLogWriter to &tlDummyNBLogWriter to remove the need to
+// check for nullptr every time. Also reduces the need to add a new logging macro above
+// each time we want to log a new type.
extern thread_local NBLog::Writer *tlNBLogWriter;
}
} // namespace android
diff --git a/services/medialog/MediaLogService.cpp b/services/medialog/MediaLogService.cpp
index 0598ce7..902af66 100644
--- a/services/medialog/MediaLogService.cpp
+++ b/services/medialog/MediaLogService.cpp
@@ -119,7 +119,6 @@
} else {
ALOGW("%s:", result.string());
}
- // TODO should we instead proceed to mMergeReader.dump? does it need lock?
return NO_ERROR;
}
@@ -132,9 +131,10 @@
}
}
mLock.unlock();
+ } else {
+ mMergeReader.dump(fd, args);
}
}
- mMergeReader.dump(fd);
return NO_ERROR;
}