From c6bfd4a64813929641ee2e22e3f77325aea93774 Mon Sep 17 00:00:00 2001
From: Andy Hung <hunga@google.com>
Date: Mon, 1 Jul 2019 18:26:00 -0700
Subject: [PATCH] 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 | 23 +++++++++++++++++++++++
 hal/audio_hw.h |  3 +++
 2 files changed, 26 insertions(+)

diff --git a/hal/audio_hw.c b/hal/audio_hw.c
index 8bd8992f..18cd05d4 100644
--- a/hal/audio_hw.c
+++ b/hal/audio_hw.c
@@ -4549,6 +4549,11 @@ static int out_dump(const struct audio_stream *stream, int fd)
         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 @@ static ssize_t out_write(struct audio_stream_out *stream, const void *buffer,
 
     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 @@ static ssize_t out_write(struct audio_stream_out *stream, const void *buffer,
         }
         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 @@ static int in_dump(const struct audio_stream *stream,
     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 @@ static ssize_t in_read(struct audio_stream_in *stream, void *buffer,
     }
 
     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 @@ static ssize_t in_read(struct audio_stream_in *stream, void *buffer,
             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 */
diff --git a/hal/audio_hw.h b/hal/audio_hw.h
index bd88f862..5e3c1cb9 100644
--- a/hal/audio_hw.h
+++ b/hal/audio_hw.h
@@ -465,6 +465,7 @@ struct stream_out {
     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 @@ struct stream_in {
     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 {