commit e98dd6f5496aaba009ed27be8e83af1cd10869c5
author Eric Tan <taneric@google.com> Wed Aug 22 18:23:50 2018 -0700
committer Eric Tan <taneric@google.com> Wed Aug 29 15:10:40 2018 -0700
tree 2d3c6b7f683b781d961d22d541d7193ec08f0642
parent 6af1847b8ea55d9f21e75b0f0ed91dc0e8f68c32

NBLog: add latency logging and histogram serialization

ReportPerformance::writeToFile and the recording of PerformanceAnalysis
FastMixer timestamps are disabled for now.

Test: dumpsys media.log -r
Bug: 68148948
Change-Id: I4ba55fc20521ad2278348e6a3f713f9db04d951b

media/libnblog/NBLog.cpp

diff --git a/media/libnblog/NBLog.cpp b/media/libnblog/NBLog.cpp
index d659445..f1d7523 100644
--- a/media/libnblog/NBLog.cpp
+++ b/media/libnblog/NBLog.cpp
@@ -478,12 +478,20 @@
     }
 }
 
+void NBLog::Writer::logLatency(double latencyMs)
+{
+    if (!mEnabled) {
+        return;
+    }
+    log(EVENT_LATENCY, &latencyMs, sizeof(latencyMs));
+}
+
 void NBLog::Writer::logMonotonicCycleTime(uint32_t monotonicNs)
 {
     if (!mEnabled) {
         return;
     }
-    log(EVENT_MONOTONIC_CYCLE_TIME, &monotonicNs, sizeof(&monotonicNs));
+    log(EVENT_MONOTONIC_CYCLE_TIME, &monotonicNs, sizeof(monotonicNs));
 }
 
 void NBLog::Writer::logFormat(const char *fmt, log_hash_t hash, ...)
@@ -713,12 +721,14 @@
         NBLog::Event::EVENT_START_FMT,
         NBLog::Event::EVENT_HISTOGRAM_ENTRY_TS,
         NBLog::Event::EVENT_AUDIO_STATE,
+        NBLog::Event::EVENT_LATENCY,
         NBLog::Event::EVENT_MONOTONIC_CYCLE_TIME
 };
 const std::unordered_set<NBLog::Event> NBLog::Reader::endingTypes   {
         NBLog::Event::EVENT_END_FMT,
         NBLog::Event::EVENT_HISTOGRAM_ENTRY_TS,
         NBLog::Event::EVENT_AUDIO_STATE,
+        NBLog::Event::EVENT_LATENCY,
         NBLog::Event::EVENT_MONOTONIC_CYCLE_TIME
 };
 
@@ -873,6 +883,17 @@
             memcpy(&hash, &(data->hash), sizeof(hash));
             mThreadPerformanceAnalysis[author][0 /*hash*/].handleStateChange();
         } break;
+        case EVENT_LATENCY: {
+            double latencyMs;
+            memcpy(&latencyMs, etr.data, sizeof(latencyMs));
+            mPerformanceData.addLatencyEntry(author, latencyMs);
+        } break;
+        case EVENT_MONOTONIC_CYCLE_TIME: {
+            uint32_t monotonicNs;
+            memcpy(&monotonicNs, etr.data, sizeof(monotonicNs));
+            const double monotonicMs = monotonicNs * 1e-6;
+            mPerformanceData.addCycleTimeEntry(author, monotonicMs);
+        } break;
         case EVENT_END_FMT:
         case EVENT_RESERVED:
         case EVENT_UPPER_BOUND:
@@ -904,6 +925,7 @@
 {
     // TODO: add a mutex around media.log dump
     ReportPerformance::dump(fd, indent, mThreadPerformanceAnalysis);
+    mPerformanceData.dump(fd);
 }
 
 // TODO for future compatibility, would prefer to have a dump() go to string, and then go
@@ -926,7 +948,12 @@
         case EVENT_MONOTONIC_CYCLE_TIME: {
             uint32_t monotonicNs;
             memcpy(&monotonicNs, it->data, sizeof(monotonicNs));
-            body.appendFormat("Thread cycle took %u ns", monotonicNs);
+            body.appendFormat("Thread cycle: %u ns", monotonicNs);
+        } break;
+        case EVENT_LATENCY: {
+            double latencyMs;
+            memcpy(&latencyMs, it->data, sizeof(latencyMs));
+            body.appendFormat("latency: %.3f ms", latencyMs);
         } break;
         case EVENT_END_FMT:
         case EVENT_RESERVED: