Log audio information to ensure complete delivery

Test: Audio playback
Bug: 30572472
Change-Id: Ibad6fc202692cd3480ae726627252afdead083f3
diff --git a/services/audioflinger/Threads.h b/services/audioflinger/Threads.h
index 5235cde..e28c947 100644
--- a/services/audioflinger/Threads.h
+++ b/services/audioflinger/Threads.h
@@ -861,6 +861,78 @@
     uint32_t                mScreenState;   // cached copy of gScreenState
     static const size_t     kFastMixerLogSize = 4 * 1024;
     sp<NBLog::Writer>       mFastMixerNBLogWriter;
+
+    // Do not call from a sched_fifo thread as it uses a system time call
+    // and obtains a local mutex.
+    class LocalLog {
+    public:
+        void log(const char *fmt, ...) {
+            va_list val;
+            va_start(val, fmt);
+
+            // format to buffer
+            char buffer[512];
+            int length = vsnprintf(buffer, sizeof(buffer), fmt, val);
+            if (length >= (signed)sizeof(buffer)) {
+                length = sizeof(buffer) - 1;
+            }
+
+            // strip out trailing newline
+            while (length > 0 && buffer[length - 1] == '\n') {
+                buffer[--length] = 0;
+            }
+
+            // store in circular array
+            AutoMutex _l(mLock);
+            mLog.emplace_back(
+                    std::make_pair(systemTime(SYSTEM_TIME_REALTIME), std::string(buffer)));
+            if (mLog.size() > kLogSize) {
+                mLog.pop_front();
+            }
+
+            va_end(val);
+        }
+
+        void dump(int fd, const Vector<String16>& args, const char *prefix = "") {
+            if (!AudioFlinger::dumpTryLock(mLock)) return; // a local lock, shouldn't happen
+            if (mLog.size() > 0) {
+                bool dumpAll = false;
+                for (const auto &arg : args) {
+                    if (arg == String16("--locallog")) {
+                        dumpAll = true;
+                    }
+                }
+
+                dprintf(fd, "Local Log:\n");
+                auto it = mLog.begin();
+                if (!dumpAll && mLog.size() > kLogPrint) {
+                    it += (mLog.size() - kLogPrint);
+                }
+                for (; it != mLog.end(); ++it) {
+                    const int64_t ns = it->first;
+                    const int ns_per_sec = 1000000000;
+                    const time_t sec = ns / ns_per_sec;
+                    struct tm tm;
+                    localtime_r(&sec, &tm);
+
+                    dprintf(fd, "%s%02d-%02d %02d:%02d:%02d.%03d %s\n",
+                            prefix,
+                            tm.tm_mon + 1, // localtime_r uses months in 0 - 11 range
+                            tm.tm_mday, tm.tm_hour, tm.tm_min, tm.tm_sec,
+                            (int)(ns % ns_per_sec / 1000000),
+                            it->second.c_str());
+                }
+            }
+            mLock.unlock();
+        }
+
+    private:
+        Mutex mLock;
+        static const size_t kLogSize = 256; // full history
+        static const size_t kLogPrint = 32; // default print history
+        std::deque<std::pair<int64_t, std::string>> mLog;
+    } mLocalLog;
+
 public:
     virtual     bool        hasFastMixer() const = 0;
     virtual     FastTrackUnderruns getFastTrackUnderruns(size_t fastIndex __unused) const