commit c6bfd4a64813929641ee2e22e3f77325aea93774
author Andy Hung <hunga@google.com> Mon Jul 01 18:26:00 2019 -0700
committer George Gao <georgao@codeaurora.org> Wed Apr 08 15:03:11 2020 -0700
tree 1b7edb6739c5498a07f0fda312fa7ea36b7e39e2
parent a1f48fa465945784e249abd471301d5fafc3d212

Add startup time from idle statistics

Test: audioflinger dumpsys
Bug: 135729709
Bug: 124765214
Change-Id: I443f18fc80595810cf10d990a237139f8d35241c
(cherry picked from commit 81f79936b6dce64f6f7630a3b5cf8270f270d260)
Signed-off-by: Aniket Kumar Lata <alata@codeaurora.org>

hal/audio_hw.c

diff --git a/hal/audio_hw.c b/hal/audio_hw.c
index 8bd8992..18cd05d 100644
--- a/hal/audio_hw.c
+++ b/hal/audio_hw.c
@@ -4549,6 +4549,11 @@
         dprintf(fd, "      Fifo frame underruns: %s\n", buffer);
     }
 
+    if (out->start_latency_ms.n > 0) {
+        simple_stats_to_string(&out->start_latency_ms, buffer, sizeof(buffer));
+        dprintf(fd, "      Start latency ms: %s\n", buffer);
+    }
+
     if (locked) {
         pthread_mutex_unlock(&out->lock);
     }
@@ -5705,6 +5710,8 @@
 
     if (out->standby) {
         out->standby = false;
+        const int64_t startNs = systemTime(SYSTEM_TIME_MONOTONIC);
+
         pthread_mutex_lock(&adev->lock);
         if (out->usecase == USECASE_COMPRESS_VOIP_CALL)
             ret = voice_extn_compress_voip_start_output_stream(out);
@@ -5732,6 +5739,10 @@
         }
         if (out->set_dual_mono)
             audio_extn_send_dual_mono_mixing_coefficients(out);
+
+        // log startup time in ms.
+        simple_stats_log(
+                &out->start_latency_ms, (systemTime(SYSTEM_TIME_MONOTONIC) - startNs) * 1e-6);
     }
 
     if (adev->is_channel_status_set == false &&
@@ -6646,6 +6657,12 @@
     dprintf(fd, "      Frames read: %lld\n", (long long)in->frames_read);
     dprintf(fd, "      Frames muted: %lld\n", (long long)in->frames_muted);
 
+    char buffer[256]; // for statistics formatting
+    if (in->start_latency_ms.n > 0) {
+        simple_stats_to_string(&in->start_latency_ms, buffer, sizeof(buffer));
+        dprintf(fd, "      Start latency ms: %s\n", buffer);
+    }
+
     if (locked) {
         pthread_mutex_unlock(&in->lock);
     }
@@ -6908,6 +6925,8 @@
     }
 
     if (in->standby) {
+        const int64_t startNs = systemTime(SYSTEM_TIME_MONOTONIC);
+
         pthread_mutex_lock(&adev->lock);
         if (in->usecase == USECASE_COMPRESS_VOIP_CALL)
             ret = voice_extn_compress_voip_start_input_stream(in);
@@ -6922,6 +6941,10 @@
             goto exit;
         }
         in->standby = 0;
+
+        // log startup time in ms.
+        simple_stats_log(
+                &in->start_latency_ms, (systemTime(SYSTEM_TIME_MONOTONIC) - startNs) * 1e-6);
     }
 
     /* Avoid read if capture_stopped is set */

hal/audio_hw.h

diff --git a/hal/audio_hw.h b/hal/audio_hw.h
index bd88f86..5e3c1cb 100644
--- a/hal/audio_hw.h
+++ b/hal/audio_hw.h
@@ -465,6 +465,7 @@
     int64_t      last_fifo_time_ns;
 
     simple_stats_t fifo_underruns;  // TODO: keep a list of the last N fifo underrun times.
+    simple_stats_t start_latency_ms;
 };
 
 struct stream_in {
@@ -518,6 +519,8 @@
     int64_t frames_muted; /* total frames muted, not cleared when entering standby */
 
     error_log_t *error_log;
+
+    simple_stats_t start_latency_ms;
 };
 
 typedef enum {