diff --git a/media/libnblog/Merger.cpp b/media/libnblog/Merger.cpp index 5e6f79ac1f..30f6fe3745 100644 --- a/media/libnblog/Merger.cpp +++ b/media/libnblog/Merger.cpp @@ -167,12 +167,24 @@ void MergeReader::processSnapshot(Snapshot &snapshot, int author) const double timeMs = it.payload(); data.warmupHist.add(timeMs); } break; - case EVENT_UNDERRUN: + case EVENT_UNDERRUN: { + const int64_t ts = it.payload(); data.underruns++; - break; - case EVENT_OVERRUN: + data.snapshots.emplace_front(EVENT_UNDERRUN, ts); + // TODO have a data structure to automatically handle resizing + if (data.snapshots.size() > ReportPerformance::PerformanceData::kMaxSnapshotsToStore) { + data.snapshots.pop_back(); + } + } break; + case EVENT_OVERRUN: { + const int64_t ts = it.payload(); data.overruns++; - break; + data.snapshots.emplace_front(EVENT_UNDERRUN, ts); + // TODO have a data structure to automatically handle resizing + if (data.snapshots.size() > ReportPerformance::PerformanceData::kMaxSnapshotsToStore) { + data.snapshots.pop_back(); + } + } break; case EVENT_RESERVED: case EVENT_UPPER_BOUND: ALOGW("warning: unexpected event %d", it->type); @@ -216,7 +228,7 @@ void MergeReader::dump(int fd, const Vector& args) { // TODO: add a mutex around media.log dump // Options for dumpsys - bool pa = false, json = false, plots = false; + bool pa = false, json = false, plots = false, retro = false; for (const auto &arg : args) { if (arg == String16("--pa")) { pa = true; @@ -224,6 +236,8 @@ void MergeReader::dump(int fd, const Vector& args) json = true; } else if (arg == String16("--plots")) { plots = true; + } else if (arg == String16("--retro")) { + retro = true; } } if (pa) { @@ -235,6 +249,9 @@ void MergeReader::dump(int fd, const Vector& args) if (plots) { ReportPerformance::dumpPlots(fd, mThreadPerformanceData); } + if (retro) { + ReportPerformance::dumpRetro(fd, mThreadPerformanceData); + } } void MergeReader::handleAuthor(const AbstractEntry &entry, String8 *body) diff --git a/media/libnblog/Reader.cpp b/media/libnblog/Reader.cpp index f86bb99949..dfad332c57 100644 --- a/media/libnblog/Reader.cpp +++ b/media/libnblog/Reader.cpp @@ -59,7 +59,7 @@ Reader::~Reader() // Copies content of a Reader FIFO into its Snapshot // The Snapshot has the same raw data, but represented as a sequence of entries // and an EntryIterator making it possible to process the data. -std::unique_ptr Reader::getSnapshot() +std::unique_ptr Reader::getSnapshot(bool flush) { if (mFifoReader == NULL) { return std::unique_ptr(new Snapshot()); @@ -146,7 +146,9 @@ std::unique_ptr Reader::getSnapshot() } // advance fifo reader index to after last entry read. - mFifoReader->release(snapshot->mEnd - front); + if (flush) { + mFifoReader->release(snapshot->mEnd - front); + } snapshot->mLost = lost; return snapshot; @@ -221,36 +223,48 @@ const uint8_t *Reader::findLastValidEntry(const uint8_t *front, const uint8_t *b void DumpReader::dump(int fd, size_t indent) { if (fd < 0) return; - std::unique_ptr snapshot = getSnapshot(); + std::unique_ptr snapshot = getSnapshot(false /*flush*/); if (snapshot == nullptr) { return; } String8 timestamp, body; // TODO all logged types should have a printable format. + // TODO can we make the printing generic? for (EntryIterator it = snapshot->begin(); it != snapshot->end(); ++it) { switch (it->type) { case EVENT_FMT_START: it = handleFormat(FormatEntry(it), ×tamp, &body); break; - case EVENT_WORK_TIME: { - const int64_t monotonicNs = it.payload(); - body.appendFormat("Thread cycle: %ld ns", (long)monotonicNs); - } break; case EVENT_LATENCY: { const double latencyMs = it.payload(); - body.appendFormat("latency: %.3f ms", latencyMs); + body.appendFormat("EVENT_LATENCY,%.3f", latencyMs); + } break; + case EVENT_OVERRUN: { + const int64_t ts = it.payload(); + body.appendFormat("EVENT_OVERRUN,%lld", static_cast(ts)); + } break; + case EVENT_THREAD_INFO: { + const thread_info_t info = it.payload(); + body.appendFormat("EVENT_THREAD_INFO,%d,%s", static_cast(info.id), + threadTypeToString(info.type)); + } break; + case EVENT_UNDERRUN: { + const int64_t ts = it.payload(); + body.appendFormat("EVENT_UNDERRUN,%lld", static_cast(ts)); } break; case EVENT_WARMUP_TIME: { const double timeMs = it.payload(); - body.appendFormat("warmup time: %.3f ms", timeMs); + body.appendFormat("EVENT_WARMUP_TIME,%.3f", timeMs); + } break; + case EVENT_WORK_TIME: { + const int64_t monotonicNs = it.payload(); + body.appendFormat("EVENT_WORK_TIME,%lld", static_cast(monotonicNs)); + } break; + case EVENT_THREAD_PARAMS: { + const thread_params_t params = it.payload(); + body.appendFormat("EVENT_THREAD_PARAMS,%zu,%u", params.frameCount, params.sampleRate); } 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: diff --git a/media/libnblog/ReportPerformance.cpp b/media/libnblog/ReportPerformance.cpp index 7e409474da..f632e40d25 100644 --- a/media/libnblog/ReportPerformance.cpp +++ b/media/libnblog/ReportPerformance.cpp @@ -113,6 +113,41 @@ void dumpPlots(int fd, const std::map& threadDataMap) } } +static std::string dumpRetroString(const PerformanceData& data, int64_t now) +{ + std::stringstream ss; + ss << NBLog::threadTypeToString(data.threadInfo.type) << "," << data.threadInfo.id << "\n"; + for (const auto &item : data.snapshots) { + // TODO use an enum to string conversion method. One good idea: + // https://stackoverflow.com/a/238157 + if (item.first == NBLog::EVENT_UNDERRUN) { + ss << "EVENT_UNDERRUN,"; + } else if (item.first == NBLog::EVENT_OVERRUN) { + ss << "EVENT_OVERRUN,"; + } + ss << now - item.second << "\n"; + } + ss << "\n"; + return ss.str(); +} + +void dumpRetro(int fd, const std::map& threadDataMap) +{ + if (fd < 0) { + return; + } + + const nsecs_t now = systemTime(); + for (const auto &item : threadDataMap) { + const ReportPerformance::PerformanceData& data = item.second; + if (data.snapshots.empty()) { + continue; + } + const std::string retroStr = dumpRetroString(data, now); + write(fd, retroStr.c_str(), retroStr.size()); + } +} + bool sendToMediaMetrics(const PerformanceData& data) { // See documentation for these metrics here: diff --git a/media/libnblog/include/media/nblog/PerformanceAnalysis.h b/media/libnblog/include/media/nblog/PerformanceAnalysis.h index b1e09d7636..d7c16b64dc 100644 --- a/media/libnblog/include/media/nblog/PerformanceAnalysis.h +++ b/media/libnblog/include/media/nblog/PerformanceAnalysis.h @@ -19,6 +19,7 @@ #include #include +#include #include #include @@ -159,6 +160,8 @@ struct PerformanceData { Histogram latencyHist{kLatencyConfig}; Histogram warmupHist{kWarmupConfig}; int64_t underruns = 0; + static constexpr size_t kMaxSnapshotsToStore = 256; + std::deque> snapshots; int64_t overruns = 0; nsecs_t active = 0; nsecs_t start{systemTime()}; diff --git a/media/libnblog/include/media/nblog/Reader.h b/media/libnblog/include/media/nblog/Reader.h index bf1c32157c..2495e8c4b3 100644 --- a/media/libnblog/include/media/nblog/Reader.h +++ b/media/libnblog/include/media/nblog/Reader.h @@ -51,7 +51,7 @@ public: ~Reader() override; // get snapshot of readers fifo buffer, effectively consuming the buffer - std::unique_ptr getSnapshot(); + std::unique_ptr getSnapshot(bool flush = true); bool isIMemory(const sp& iMemory) const; const std::string &name() const { return mName; } @@ -99,7 +99,7 @@ public: private: Snapshot() = default; explicit Snapshot(size_t bufferSize) : mData(new uint8_t[bufferSize]) {} - friend std::unique_ptr Reader::getSnapshot(); + friend std::unique_ptr Reader::getSnapshot(bool flush); uint8_t * const mData = nullptr; size_t mLost = 0; diff --git a/media/libnblog/include/media/nblog/ReportPerformance.h b/media/libnblog/include/media/nblog/ReportPerformance.h index caad14c145..64a570145d 100644 --- a/media/libnblog/include/media/nblog/ReportPerformance.h +++ b/media/libnblog/include/media/nblog/ReportPerformance.h @@ -32,6 +32,9 @@ void dumpJson(int fd, const std::map& threadDataMap); //Dumps performance data as visualized plots. void dumpPlots(int fd, const std::map& threadDataMap); +// Dumps snapshots at important events in the past. +void dumpRetro(int fd, const std::map& 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 // or an error occurred while writing.