Merge "NBLog: add retroactive dump and standard printing format"

media/libnblog/Merger.cpp

@@ -167,12 +167,24 @@ void MergeReader::processSnapshot(Snapshot &snapshot, int author)
             const double timeMs = it.payload<double>();
             data.warmupHist.add(timeMs);
         } break;
-        case EVENT_UNDERRUN:
+        case EVENT_UNDERRUN: {
+            const int64_t ts = it.payload<int64_t>();
             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<int64_t>();
             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<String16>& 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<String16>& 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<String16>& args)
     if (plots) {
         ReportPerformance::dumpPlots(fd, mThreadPerformanceData);
     }
+    if (retro) {
+        ReportPerformance::dumpRetro(fd, mThreadPerformanceData);
+    }
 }
 
 void MergeReader::handleAuthor(const AbstractEntry &entry, String8 *body)

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<Snapshot> Reader::getSnapshot()
+std::unique_ptr<Snapshot> Reader::getSnapshot(bool flush)
 {
     if (mFifoReader == NULL) {
         return std::unique_ptr<Snapshot>(new Snapshot());
@@ -146,7 +146,9 @@ std::unique_ptr<Snapshot> 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> snapshot = getSnapshot();
+    std::unique_ptr<Snapshot> 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), &timestamp, &body);
             break;
-        case EVENT_WORK_TIME: {
-            const int64_t monotonicNs = it.payload<int64_t>();
-            body.appendFormat("Thread cycle: %ld ns", (long)monotonicNs);
-        } break;
         case EVENT_LATENCY: {
             const double latencyMs = it.payload<double>();
-            body.appendFormat("latency: %.3f ms", latencyMs);
+            body.appendFormat("EVENT_LATENCY,%.3f", latencyMs);
+        } break;
+        case EVENT_OVERRUN: {
+            const int64_t ts = it.payload<int64_t>();
+            body.appendFormat("EVENT_OVERRUN,%lld", static_cast<long long>(ts));
+        } break;
+        case EVENT_THREAD_INFO: {
+            const thread_info_t info = it.payload<thread_info_t>();
+            body.appendFormat("EVENT_THREAD_INFO,%d,%s", static_cast<int>(info.id),
+                    threadTypeToString(info.type));
+        } break;
+        case EVENT_UNDERRUN: {
+            const int64_t ts = it.payload<int64_t>();
+            body.appendFormat("EVENT_UNDERRUN,%lld", static_cast<long long>(ts));
         } break;
         case EVENT_WARMUP_TIME: {
             const double timeMs = it.payload<double>();
-            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<int64_t>();
+            body.appendFormat("EVENT_WORK_TIME,%lld", static_cast<long long>(monotonicNs));
+        } break;
+        case EVENT_THREAD_PARAMS: {
+            const thread_params_t params = it.payload<thread_params_t>();
+            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:

media/libnblog/ReportPerformance.cpp

@@ -113,6 +113,41 @@ void dumpPlots(int fd, const std::map<int, PerformanceData>& 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<int, PerformanceData>& 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:

media/libnblog/include/media/nblog/PerformanceAnalysis.h

@@ -19,6 +19,7 @@
 
 #include <deque>
 #include <map>
+#include <string>
 #include <utility>
 #include <vector>
 
@@ -159,6 +160,8 @@ struct PerformanceData {
     Histogram latencyHist{kLatencyConfig};
     Histogram warmupHist{kWarmupConfig};
     int64_t underruns = 0;
+    static constexpr size_t kMaxSnapshotsToStore = 256;
+    std::deque<std::pair<NBLog::Event, int64_t /*timestamp*/>> snapshots;
     int64_t overruns = 0;
     nsecs_t active = 0;
     nsecs_t start{systemTime()};

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<Snapshot> getSnapshot();
+    std::unique_ptr<Snapshot> getSnapshot(bool flush = true);
     bool     isIMemory(const sp<IMemory>& 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<Snapshot> Reader::getSnapshot();
+    friend std::unique_ptr<Snapshot> Reader::getSnapshot(bool flush);
 
     uint8_t * const       mData = nullptr;
     size_t                mLost = 0;

media/libnblog/include/media/nblog/ReportPerformance.h

@@ -32,6 +32,9 @@ 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);
 
+// Dumps snapshots at important events in the past.
+void dumpRetro(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
 // or an error occurred while writing.