Produce log warning when a glitch occurred.

A glitch is assumed to occur when the sum of the three
latest buffer periods cause CPU time to be unavailable
for the next buffer. For example, if a buffer period
is 4 ms, requires 3 ms of CPU time, and a running sum of
3 consecutive buffer periods is examined, this sum cannot
exceed 13 = 3*4 + (4-3), where 3*4 is the expected total
time and (4-3) is the CPU time left available by one 4 ms
period. Glitch examples:
4 + 4 + 6; 5 + 4 + 5; 2 + 2 + 10

See NBLog::Reader::alertIfGlitch.
Boolean NBLog::Reader::findGlitch should be set to true
for the notification to occur.

Note: this function needs to be developed to track glitch
occurrences over time and notify when a difference in
trend occurs.

Test: dumpsys media.log
      logcat | grep NBLog

Change-Id: Ibf120afd990a71eb40863157a28c3a5a4a610c64
diff --git a/media/libnbaio/NBLog.cpp b/media/libnbaio/NBLog.cpp
index 3888bd9..4516fc4 100644
--- a/media/libnbaio/NBLog.cpp
+++ b/media/libnbaio/NBLog.cpp
@@ -18,7 +18,9 @@
 //#define LOG_NDEBUG 0
 
 #include <climits>
+#include <deque>
 #include <math.h>
+#include <numeric>
 #include <stdarg.h>
 #include <stdint.h>
 #include <stdio.h>
@@ -701,7 +703,8 @@
       mFifo(mShared != NULL ?
         new audio_utils_fifo(size, sizeof(uint8_t),
             mShared->mBuffer, mShared->mRear, NULL /*throttlesFront*/) : NULL),
-      mFifoReader(mFifo != NULL ? new audio_utils_fifo_reader(*mFifo) : NULL)
+      mFifoReader(mFifo != NULL ? new audio_utils_fifo_reader(*mFifo) : NULL),
+      findGlitch(false)
 {
 }
 
@@ -717,6 +720,39 @@
     delete mFifo;
 }
 
+inline static int deltaMs(int64_t ns1, int64_t ns2) {
+    return (ns2 - ns1) / (1000 * 1000);
+}
+
+// Produces a log warning if the timing of recent buffer periods caused a glitch
+// Computes sum of running window of three buffer periods
+// Checks whether the buffer periods leave enough CPU time for the next one
+// e.g. if a buffer period is expected to be 4 ms and a buffer requires 3 ms of CPU time,
+// here are some glitch cases:
+// 4 + 4 + 6 ; 5 + 4 + 5; 2 + 2 + 10
+// TODO: develop this code to track changes in histogram distribution in addition
+// to / instead of glitches
+void NBLog::Reader::alertIfGlitch(const std::vector<int64_t> &samples) {
+    //TODO: measure kPeriodLen and kRatio from the data as they may change.
+    static const int kPeriodLen = 4; // current period length is ideally 4 ms
+    static const double kRatio = 0.75; // estimate of CPU time as ratio of period length
+    // DAC processing time for 4 ms buffer
+    static const int kPeriodTime = static_cast<int>(round(kPeriodLen * kRatio));
+    static const int kNumBuff = 3; // number of buffers considered in local history
+    std::deque<int> periods(kNumBuff, kPeriodLen);
+    for (size_t i = 2; i < samples.size(); ++i) { // skip first time entry
+        periods.push_front(deltaMs(samples[i - 1], samples[i]));
+        periods.pop_back();
+        // TODO: check that all glitch cases are covered
+        if (std::accumulate(periods.begin(), periods.end(), 0) > kNumBuff * kPeriodLen +
+            kPeriodLen - kPeriodTime) {
+                ALOGW("A glitch occurred");
+                periods.assign(kNumBuff, kPeriodLen);
+        }
+    }
+    return;
+}
+
 const uint8_t *NBLog::Reader::findLastEntryOfTypes(const uint8_t *front, const uint8_t *back,
                                             const std::set<Event> &types) {
     while (back + Entry::kPreviousLengthOffset >= front) {
@@ -800,10 +836,6 @@
 
 }
 
-inline static int deltaMs(int64_t t1, int64_t t2) {
-    return (t2 - t1) / (1000 * 1000);
-}
-
 void NBLog::Reader::dump(int fd, size_t indent, NBLog::Reader::Snapshot &snapshot)
 {
 #if 0
@@ -917,7 +949,6 @@
             break;
 #endif
         case EVENT_START_FMT:
-            // right now, this is the only supported case
             entry = handleFormat(FormatEntry(entry), &timestamp, &body);
             break;
         case EVENT_HISTOGRAM_ENTRY_TS: {
@@ -938,16 +969,24 @@
         case EVENT_HISTOGRAM_FLUSH: {
             HistogramEntry histEntry(entry);
             // Log timestamp
+            // Timestamp of call to drawHistogram, not when audio was generated
             const int64_t ts = histEntry.timestamp();
             timestamp.clear();
             timestamp.appendFormat("[%d.%03d]", (int) (ts / (1000 * 1000 * 1000)),
                             (int) ((ts / (1000 * 1000)) % 1000));
             // Log histograms
+            setFindGlitch(true);
             body.appendFormat("Histogram flush - ");
             handleAuthor(histEntry, &body);
+            int debug = 0;
             for (auto hist = mHists.begin(); hist != mHists.end();) {
+                // TODO: "debug" is always 0. Is a for loop necessary here?
+                ALOGW("EVENT_HISTOGRAM_FLUSH case hist: %d", debug++);
                 if (hist->first.second == histEntry.author()) {
                     body.appendFormat("%X", (int)hist->first.first);
+                    if (findGlitch) {
+                        alertIfGlitch(hist->second);
+                    }
                     drawHistogram(&body, hist->second, true, indent);
                     hist = mHists.erase(hist);
                 } else {
@@ -1000,6 +1039,16 @@
     return iMemory != 0 && mIMemory != 0 && iMemory->pointer() == mIMemory->pointer();
 }
 
+void NBLog::Reader::setFindGlitch(bool s)
+{
+    findGlitch = s;
+}
+
+bool NBLog::Reader::isFindGlitch() const
+{
+    return findGlitch;
+}
+
 // ---------------------------------------------------------------------------
 
 void NBLog::appendTimestamp(String8 *body, const void *data) {
@@ -1147,6 +1196,7 @@
     // TODO allow buckets of variable resolution
     std::map<int, int> buckets;
     for (size_t i = 1; i < samples.size(); ++i) {
+        // ALOGW("sample %d ", deltaMs(samples[i - 1], samples[i]));
         ++buckets[deltaMs(samples[i - 1], samples[i])];
     }
     return buckets;
diff --git a/media/libnbaio/include/NBLog.h b/media/libnbaio/include/NBLog.h
index 19232ff..d1d9387 100644
--- a/media/libnbaio/include/NBLog.h
+++ b/media/libnbaio/include/NBLog.h
@@ -424,7 +424,6 @@
         // iterator to end of readable segment of snapshot
         EntryIterator end() { return mEnd; }
 
-
     private:
         friend class Reader;
         uint8_t              *mData;
@@ -440,6 +439,8 @@
 
     virtual ~Reader();
 
+    void alertIfGlitch(const std::vector<int64_t> &samples);
+
     // get snapshot of readers fifo buffer, effectively consuming the buffer
     std::unique_ptr<Snapshot> getSnapshot();
     // dump a particular snapshot of the reader
@@ -447,6 +448,9 @@
     // dump the current content of the reader's buffer
     void     dump(int fd, size_t indent = 0);
     bool     isIMemory(const sp<IMemory>& iMemory) const;
+    // if findGlitch is true, log warning when buffer periods caused glitch
+    void     setFindGlitch(bool s);
+    bool     isFindGlitch() const;
 
 private:
     static const std::set<Event> startingTypes;
@@ -480,6 +484,8 @@
                                          const std::set<Event> &types);
 
     static const size_t kSquashTimestamp = 5; // squash this many or more adjacent timestamps
+
+    bool findGlitch; // alert if a local buffer period sequence caused an audio glitch
 };
 
 // Wrapper for a reader with a name. Contains a pointer to the reader and a pointer to the name