NBLog: log and store warmup times, underruns, overruns, and thread info
Test: dumpsys media.log
Bug: 68148948
Change-Id: Ib6ea96760f7886cba47c8e2f0334114237a2434b
diff --git a/services/audioflinger/FastMixer.cpp b/services/audioflinger/FastMixer.cpp
index fd784a4..f650b66 100644
--- a/services/audioflinger/FastMixer.cpp
+++ b/services/audioflinger/FastMixer.cpp
@@ -195,6 +195,9 @@
// to avoid blocking here and to prevent possible priority inversion
mMixer = new AudioMixer(frameCount, mSampleRate);
// FIXME See the other FIXME at FastMixer::setNBLogWriter()
+ // TODO define an int to thread type mapping for the "2" below.
+ const NBLog::thread_info_t info = { 2 /*FastMixer*/, frameCount, mSampleRate };
+ LOG_THREAD_INFO(info);
const size_t mixerFrameSize = mSinkChannelCount
* audio_bytes_per_sample(mMixerBufferFormat);
mMixerBufferSize = mixerFrameSize * frameCount;
diff --git a/services/audioflinger/FastThread.cpp b/services/audioflinger/FastThread.cpp
index 6f223df..09101d9 100644
--- a/services/audioflinger/FastThread.cpp
+++ b/services/audioflinger/FastThread.cpp
@@ -22,6 +22,7 @@
#include "Configuration.h"
#include <linux/futex.h>
#include <sys/syscall.h>
+#include <audio_utils/clock.h>
#include <cutils/atomic.h>
#include <utils/Log.h>
#include <utils/Trace.h>
@@ -260,6 +261,9 @@
mIsWarm = true;
mDumpState->mMeasuredWarmupTs = mMeasuredWarmupTs;
mDumpState->mWarmupCycles = mWarmupCycles;
+ const double measuredWarmupMs = (mMeasuredWarmupTs.tv_sec * 1e3) +
+ (mMeasuredWarmupTs.tv_nsec * 1e-6);
+ LOG_WARMUP_TIME(measuredWarmupMs);
}
}
mSleepNs = -1;
@@ -270,6 +274,7 @@
ALOGV("underrun: time since last cycle %d.%03ld sec",
(int) sec, nsec / 1000000L);
mDumpState->mUnderruns++;
+ LOG_UNDERRUN(audio_utils_ns_from_timespec(&newTs));
mIgnoreNextOverrun = true;
} else if (nsec < mOverrunNs) {
if (mIgnoreNextOverrun) {
@@ -279,6 +284,7 @@
ALOGV("overrun: time since last cycle %d.%03ld sec",
(int) sec, nsec / 1000000L);
mDumpState->mOverruns++;
+ LOG_OVERRUN(audio_utils_ns_from_timespec(&newTs));
}
// This forces a minimum cycle time. It:
// - compensates for an audio HAL with jitter due to sample rate conversion
diff --git a/services/audioflinger/TypedLogger.h b/services/audioflinger/TypedLogger.h
index 6677470..dd2e7c9 100644
--- a/services/audioflinger/TypedLogger.h
+++ b/services/audioflinger/TypedLogger.h
@@ -107,6 +107,23 @@
#define LOG_LATENCY(ms) do { NBLog::Writer *x = tlNBLogWriter; if (x != nullptr) \
x->log<NBLog::EVENT_LATENCY>(ms); } while (0)
+// Record thread warmup time in milliseconds. Parameter ms is of type double.
+#define LOG_WARMUP_TIME(ms) do { NBLog::Writer *x = tlNBLogWriter; if (x != nullptr) \
+ x->log<NBLog::EVENT_WARMUP_TIME>(ms); } while (0)
+
+// Record thread underrun event nanosecond timestamp. Parameter ns is an int64_t.
+#define LOG_UNDERRUN(ns) do { NBLog::Writer *x = tlNBLogWriter; if (x != nullptr) \
+ x->log<NBLog::EVENT_UNDERRUN>(ns); } while (0)
+
+// Record thread overrun event nanosecond timestamp. Parameter ns is an int64_t.
+#define LOG_OVERRUN(ns) do { NBLog::Writer *x = tlNBLogWriter; if (x != nullptr) \
+ x->log<NBLog::EVENT_OVERRUN>(ns); } while (0)
+
+// Record thread info. This currently includes type, frameCount, and sampleRate.
+// Parameter type is thread_info_t as defined in NBLog.h.
+#define LOG_THREAD_INFO(info) do { NBLog::Writer *x = tlNBLogWriter; \
+ if (x != nullptr) x->log<NBLog::EVENT_THREAD_INFO>(info); } while (0)
+
namespace android {
extern "C" {
extern thread_local NBLog::Writer *tlNBLogWriter;