Tracks: Stabilize the latency/startup metrics for BT
Use kernel timestamps instead of server timestamps.
Postpone latency / startup collection until later
to ensure BT is stabilized.
Test: adb shell dumpsys media.metrics
Bug: 149850236
Change-Id: Ie4e0658cedec13000f7b713407630e273df391b7
diff --git a/services/audioflinger/TrackBase.h b/services/audioflinger/TrackBase.h
index 15c66fb..01d5345 100644
--- a/services/audioflinger/TrackBase.h
+++ b/services/audioflinger/TrackBase.h
@@ -373,10 +373,15 @@
bool mIsInvalid; // non-resettable latch, set by invalidate()
// It typically takes 5 threadloop mix iterations for latency to stabilize.
- static inline constexpr int32_t LOG_START_COUNTDOWN = 8;
- int32_t mLogStartCountdown = 0;
- int64_t mLogStartTimeNs = 0;
- int64_t mLogStartFrames = 0;
+ // However, this can be 12+ iterations for BT.
+ // To be sure, we wait for latency to dip (it usually increases at the start)
+ // to assess stability and then log to MediaMetrics.
+ // Rapid start / pause calls may cause inaccurate numbers.
+ static inline constexpr int32_t LOG_START_COUNTDOWN = 12;
+ int32_t mLogStartCountdown = 0; // Mixer period countdown
+ int64_t mLogStartTimeNs = 0; // Monotonic time at start()
+ int64_t mLogStartFrames = 0; // Timestamp frames at start()
+ double mLogLatencyMs = 0.; // Track the last log latency
TrackMetrics mTrackMetrics;
diff --git a/services/audioflinger/Tracks.cpp b/services/audioflinger/Tracks.cpp
index 73a40d3..9386a42 100644
--- a/services/audioflinger/Tracks.cpp
+++ b/services/audioflinger/Tracks.cpp
@@ -978,7 +978,8 @@
mLogStartCountdown = LOG_START_COUNTDOWN;
mLogStartTimeNs = systemTime();
mLogStartFrames = mAudioTrackServerProxy->getTimestamp()
- .mPosition[ExtendedTimestamp::LOCATION_SERVER];
+ .mPosition[ExtendedTimestamp::LOCATION_KERNEL];
+ mLogLatencyMs = 0.;
}
if (status == NO_ERROR || status == ALREADY_EXISTS) {
@@ -1514,23 +1515,31 @@
mServerLatencyFromTrack.store(useTrackTimestamp);
mServerLatencyMs.store(latencyMs);
- if (mLogStartCountdown > 0) {
- if (--mLogStartCountdown == 0) {
+ if (mLogStartCountdown > 0
+ && local.mTimeNs[ExtendedTimestamp::LOCATION_KERNEL] > 0
+ && local.mPosition[ExtendedTimestamp::LOCATION_KERNEL] > 0)
+ {
+ if (mLogStartCountdown > 1) {
+ --mLogStartCountdown;
+ } else if (latencyMs < mLogLatencyMs) { // wait for latency to stabilize (dip)
+ mLogStartCountdown = 0;
// startup is the difference in times for the current timestamp and our start
double startUpMs =
- (local.mTimeNs[ExtendedTimestamp::LOCATION_SERVER] - mLogStartTimeNs) * 1e-6;
+ (local.mTimeNs[ExtendedTimestamp::LOCATION_KERNEL] - mLogStartTimeNs) * 1e-6;
// adjust for frames played.
- startUpMs -= (local.mPosition[ExtendedTimestamp::LOCATION_SERVER] - mLogStartFrames)
- * 1e3 / mSampleRate;
- ALOGV("%s: logging localTime:%lld, startTime:%lld"
- " localPosition:%lld, startPosition:%lld",
- __func__,
- (long long)local.mTimeNs[ExtendedTimestamp::LOCATION_SERVER],
+ startUpMs -= (local.mPosition[ExtendedTimestamp::LOCATION_KERNEL] - mLogStartFrames)
+ * 1e3 / mSampleRate;
+ ALOGV("%s: latencyMs:%lf startUpMs:%lf"
+ " localTime:%lld startTime:%lld"
+ " localPosition:%lld startPosition:%lld",
+ __func__, latencyMs, startUpMs,
+ (long long)local.mTimeNs[ExtendedTimestamp::LOCATION_KERNEL],
(long long)mLogStartTimeNs,
- (long long)local.mPosition[ExtendedTimestamp::LOCATION_SERVER],
+ (long long)local.mPosition[ExtendedTimestamp::LOCATION_KERNEL],
(long long)mLogStartFrames);
mTrackMetrics.logLatencyAndStartup(latencyMs, startUpMs);
}
+ mLogLatencyMs = latencyMs;
}
}