aaudio: add histogram to clock model
Measure distribution of MMAP timestamp lateness.
This is used to discover the actual DSP timing behavior.
Turn histogram log on or off using a property.
Test: adb root
Test: adb shell setprop aaudio.log_mask 1
Test: run an AAudio MMAP program
Test: adb logcat | grep ClockModel
Change-Id: I910831d1feee43c59d1af2ac3135a910fef36fb2
diff --git a/media/libaaudio/src/client/IsochronousClockModel.cpp b/media/libaaudio/src/client/IsochronousClockModel.cpp
index 07b6ad0..bd46d05 100644
--- a/media/libaaudio/src/client/IsochronousClockModel.cpp
+++ b/media/libaaudio/src/client/IsochronousClockModel.cpp
@@ -18,18 +18,30 @@
//#define LOG_NDEBUG 0
#include <log/log.h>
+#define __STDC_FORMAT_MACROS
+#include <inttypes.h>
#include <stdint.h>
#include <algorithm>
#include "utility/AudioClock.h"
+#include "utility/AAudioUtilities.h"
#include "IsochronousClockModel.h"
using namespace aaudio;
+using namespace android::audio_utils;
+
#ifndef ICM_LOG_DRIFT
#define ICM_LOG_DRIFT 0
#endif // ICM_LOG_DRIFT
+// To enable the timestamp histogram, enter this before opening the stream:
+// adb root
+// adb shell setprop aaudio.log_mask 1
+// A histogram of the lateness of the timestamps will be cleared when the stream is started.
+// It will be updated when the model is stable and receives a timestamp,
+// and dumped to the log when the stream is stopped.
+
IsochronousClockModel::IsochronousClockModel()
: mMarkerFramePosition(0)
, mMarkerNanoTime(0)
@@ -39,6 +51,10 @@
, mLatenessForDriftNanos(kInitialLatenessForDriftNanos)
, mState(STATE_STOPPED)
{
+ if ((AAudioProperty_getLogMask() & AAUDIO_LOG_CLOCK_MODEL_HISTOGRAM) != 0) {
+ mHistogramMicros = std::make_unique<Histogram>(kHistogramBinCount,
+ kHistogramBinWidthMicros);
+ }
}
IsochronousClockModel::~IsochronousClockModel() {
@@ -54,6 +70,9 @@
ALOGV("start(nanos = %lld)\n", (long long) nanoTime);
mMarkerNanoTime = nanoTime;
mState = STATE_STARTING;
+ if (mHistogramMicros) {
+ mHistogramMicros->clear();
+ }
}
void IsochronousClockModel::stop(int64_t nanoTime) {
@@ -63,6 +82,9 @@
setPositionAndTime(convertTimeToPosition(nanoTime), nanoTime);
// TODO should we set position?
mState = STATE_STOPPED;
+ if (mHistogramMicros) {
+ dumpHistogram();
+ }
}
bool IsochronousClockModel::isStarting() const {
@@ -113,6 +135,9 @@
}
break;
case STATE_RUNNING:
+ if (mHistogramMicros) {
+ mHistogramMicros->add(latenessNanos / AAUDIO_NANOS_PER_MICROSECOND);
+ }
// Modify estimated position based on lateness.
// This affects the "early" side of the window, which controls output glitches.
if (latenessNanos < 0) {
@@ -121,10 +146,9 @@
// Or we may be drifting due to a fast HW clock.
setPositionAndTime(framePosition, nanoTime);
#if ICM_LOG_DRIFT
- int microsDelta = (int) (nanosDelta / 1000);
- int expectedMicrosDelta = (int) (expectedNanosDelta / 1000);
+ int earlyDeltaMicros = (int) ((expectedNanosDelta - nanosDelta)/ 1000);
ALOGD("%s() - STATE_RUNNING - #%d, %4d micros EARLY",
- __func__, mTimestampCount, expectedMicrosDelta - microsDelta);
+ __func__, mTimestampCount, earlyDeltaMicros);
#endif
} else if (latenessNanos > mLatenessForDriftNanos) {
// When we are on the late side, it may be because of preemption in the kernel,
@@ -242,10 +266,19 @@
}
void IsochronousClockModel::dump() const {
- ALOGD("mMarkerFramePosition = %16lld", (long long) mMarkerFramePosition);
- ALOGD("mMarkerNanoTime = %16lld", (long long) mMarkerNanoTime);
- ALOGD("mSampleRate = %8d", mSampleRate);
- ALOGD("mFramesPerBurst = %8d", mFramesPerBurst);
- ALOGD("mState = %8d", mState);
- ALOGD("max lateness nanos = %8d", mMaxMeasuredLatenessNanos);
+ ALOGD("mMarkerFramePosition = %" PRIu64, mMarkerFramePosition);
+ ALOGD("mMarkerNanoTime = %" PRIu64, mMarkerNanoTime);
+ ALOGD("mSampleRate = %6d", mSampleRate);
+ ALOGD("mFramesPerBurst = %6d", mFramesPerBurst);
+ ALOGD("mMaxMeasuredLatenessNanos = %6d", mMaxMeasuredLatenessNanos);
+ ALOGD("mState = %6d", mState);
+}
+
+void IsochronousClockModel::dumpHistogram() const {
+ if (!mHistogramMicros) return;
+ std::istringstream istr(mHistogramMicros->dump());
+ std::string line;
+ while (std::getline(istr, line)) {
+ ALOGD("lateness, %s", line.c_str());
+ }
}
diff --git a/media/libaaudio/src/client/IsochronousClockModel.h b/media/libaaudio/src/client/IsochronousClockModel.h
index a86d264..40f066b 100644
--- a/media/libaaudio/src/client/IsochronousClockModel.h
+++ b/media/libaaudio/src/client/IsochronousClockModel.h
@@ -18,6 +18,9 @@
#define ANDROID_AAUDIO_ISOCHRONOUS_CLOCK_MODEL_H
#include <stdint.h>
+
+#include <audio_utils/Histogram.h>
+
#include "utility/AudioClock.h"
namespace aaudio {
@@ -122,6 +125,8 @@
void dump() const;
+ void dumpHistogram() const;
+
private:
int32_t getLateTimeOffsetNanos() const;
@@ -140,6 +145,9 @@
// Initial small threshold for causing a drift later in time.
static constexpr int32_t kInitialLatenessForDriftNanos = 10 * 1000;
+ static constexpr int32_t kHistogramBinWidthMicros = 50;
+ static constexpr int32_t kHistogramBinCount = 128;
+
int64_t mMarkerFramePosition; // Estimated HW position.
int64_t mMarkerNanoTime; // Estimated HW time.
int32_t mSampleRate;
@@ -153,6 +161,9 @@
int32_t mTimestampCount = 0; // For logging.
+ // distribution of timestamps relative to earliest
+ std::unique_ptr<android::audio_utils::Histogram> mHistogramMicros;
+
void update();
};
diff --git a/media/libaaudio/src/utility/AAudioUtilities.cpp b/media/libaaudio/src/utility/AAudioUtilities.cpp
index 0ff6333..c2f7fd0 100644
--- a/media/libaaudio/src/utility/AAudioUtilities.cpp
+++ b/media/libaaudio/src/utility/AAudioUtilities.cpp
@@ -359,6 +359,10 @@
return AAudioProperty_getMMapOffsetMicros(__func__, AAUDIO_PROP_OUTPUT_MMAP_OFFSET_USEC);
}
+int32_t AAudioProperty_getLogMask() {
+ return property_get_int32(AAUDIO_PROP_LOG_MASK, 0);
+}
+
aaudio_result_t AAudio_isFlushAllowed(aaudio_stream_state_t state) {
aaudio_result_t result = AAUDIO_OK;
switch (state) {
diff --git a/media/libaaudio/src/utility/AAudioUtilities.h b/media/libaaudio/src/utility/AAudioUtilities.h
index 55824f7..5dcddf3 100644
--- a/media/libaaudio/src/utility/AAudioUtilities.h
+++ b/media/libaaudio/src/utility/AAudioUtilities.h
@@ -162,6 +162,20 @@
int32_t AAudioProperty_getOutputMMapOffsetMicros();
#define AAUDIO_PROP_OUTPUT_MMAP_OFFSET_USEC "aaudio.out_mmap_offset_usec"
+// These are powers of two that can be combined as a bit mask.
+// AAUDIO_LOG_CLOCK_MODEL_HISTOGRAM must be enabled before the stream is opened.
+#define AAUDIO_LOG_CLOCK_MODEL_HISTOGRAM 1
+#define AAUDIO_LOG_RESERVED_2 2
+#define AAUDIO_LOG_RESERVED_4 4
+#define AAUDIO_LOG_RESERVED_8 8
+
+/**
+ * Use a mask to enable various logs in AAudio.
+ * @return mask that enables various AAudio logs, such as AAUDIO_LOG_CLOCK_MODEL_HISTOGRAM
+ */
+int32_t AAudioProperty_getLogMask();
+#define AAUDIO_PROP_LOG_MASK "aaudio.log_mask"
+
/**
* Is flush allowed for the given state?
* @param state