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), ×tamp, &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