commit 241e36f4686595f62a4bd64704a53e0323ba157c
author Andy Hung <hunga@google.com> Tue Feb 19 12:00:38 2019 -0800
committer Andy Hung <hunga@google.com> Tue Feb 19 17:05:31 2019 -0800
tree a09b77c802c9d1a04a30f1491c625d8d026251b8
parent 572633eea9caf5017daac9d707b58dcadf50860a

Add startup time from idle statistics

Test: audioflinger dumpsys
Bug: 124765214
Change-Id: I443f18fc80595810cf10d990a237139f8d35241c

hal/audio_hw.c

diff --git a/hal/audio_hw.c b/hal/audio_hw.c
index 5a1ae4d..4f2f3dc 100644
--- a/hal/audio_hw.c
+++ b/hal/audio_hw.c
@@ -2668,6 +2668,11 @@
     simple_stats_to_string(&out->fifo_underruns, buffer, sizeof(buffer));
     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);
     }
@@ -3214,6 +3219,8 @@
     const bool was_in_standby = out->standby;
     if (out->standby) {
         out->standby = false;
+        const int64_t startNs = systemTime(SYSTEM_TIME_MONOTONIC);
+
         pthread_mutex_lock(&adev->lock);
         ret = start_output_stream(out);
 
@@ -3230,6 +3237,9 @@
         send_gain_dep_calibration_l();
         pthread_mutex_unlock(&adev->lock);
 
+        // log startup time in ms.
+        simple_stats_log(
+                &out->start_latency_ms, (systemTime(SYSTEM_TIME_MONOTONIC) - startNs) * 1e-6);
         out->last_fifo_valid = false; // we're coming out of standby, last_fifo isn't valid.
     }
 
@@ -3839,6 +3849,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);
     }
@@ -4040,6 +4056,8 @@
     }
 
     if (in->standby) {
+        const int64_t startNs = systemTime(SYSTEM_TIME_MONOTONIC);
+
         pthread_mutex_lock(&adev->lock);
         ret = start_input_stream(in);
         pthread_mutex_unlock(&adev->lock);
@@ -4047,6 +4065,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);
     }
 
     // errors that occur here are read errors.

hal/audio_hw.h

diff --git a/hal/audio_hw.h b/hal/audio_hw.h
index 820436c..3fc1577 100644
--- a/hal/audio_hw.h
+++ b/hal/audio_hw.h
@@ -265,6 +265,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 {
@@ -305,6 +306,8 @@
     uint32_t supported_sample_rates[MAX_SUPPORTED_SAMPLE_RATES + 1];
 
     error_log_t *error_log;
+
+    simple_stats_t start_latency_ms;
 };
 
 typedef enum usecase_type_t {