commit 6292112eca818eab9fa5056bc4a28092812b291b
author Andy Hung <hunga@google.com> Mon May 18 10:47:31 2020 -0700
committer Andy Hung <hunga@google.com> Wed May 27 11:47:47 2020 -0700
tree 1e37d150cd5325d37b7d1b115c18fc7e4e1c0d0c
parent b4a3b65d297a8436ba48138ce7ce2ba6b7a652b8

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

services/audioflinger/Tracks.cpp

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;
     }
 }