Merge changes from topic "audio stat"
* changes:
Add startup time from idle statistics
Track alsa buffer underruns
diff --git a/hal/audio_hw.c b/hal/audio_hw.c
index 24d726f..4d69362 100644
--- a/hal/audio_hw.c
+++ b/hal/audio_hw.c
@@ -40,6 +40,7 @@
#include <cutils/str_parms.h>
#include <cutils/properties.h>
#include <cutils/atomic.h>
+#include <utils/Timers.h> // systemTime
#include <hardware/audio_effect.h>
#include <hardware/audio_alsaops.h>
@@ -2743,6 +2744,15 @@
dprintf(fd, " Standby: %s\n", out->standby ? "yes" : "no");
dprintf(fd, " Frames written: %lld\n", (long long)out->written);
+ char buffer[256]; // for statistics formatting
+ 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);
}
@@ -3286,8 +3296,11 @@
}
}
+ 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);
@@ -3303,6 +3316,11 @@
ALOGD("%s: retry previous failed cal level set", __func__);
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.
}
if (out->usecase == USECASE_AUDIO_PLAYBACK_OFFLOAD) {
@@ -3322,6 +3340,13 @@
if (avail == 0) {
ret = 0;
} else {
+ // check for compressed format underrun, essentially an empty buffer check
+ // for a lack of better measurement.
+ if (!was_in_standby && avail == out->kernel_buffer_size) {
+ ALOGW("%s: compressed buffer empty (underrun)", __func__);
+ simple_stats_log(&out->fifo_underruns, 1.); // Note: log one frame for compressed.
+ }
+
if (avail > bytes) {
avail = bytes;
}
@@ -3368,7 +3393,29 @@
}
bytes_to_write /= 2;
}
- ALOGVV("%s: writing buffer (%zu bytes) to pcm device", __func__, bytes_to_write);
+
+ // Note: since out_get_presentation_position() is called alternating with out_write()
+ // by AudioFlinger, we can check underruns using the prior timestamp read.
+ // (Alternately we could check if the buffer is empty using pcm_get_htimestamp().
+ if (out->last_fifo_valid) {
+ // compute drain to see if there is an underrun.
+ const int64_t current_ns = systemTime(SYSTEM_TIME_MONOTONIC); // sys call
+ const int64_t frames_by_time =
+ (current_ns - out->last_fifo_time_ns) * out->config.rate / NANOS_PER_SECOND;
+ const int64_t underrun = frames_by_time - out->last_fifo_frames_remaining;
+
+ if (underrun > 0) {
+ simple_stats_log(&out->fifo_underruns, underrun);
+
+ ALOGW("%s: underrun(%lld) "
+ "frames_by_time(%lld) > out->last_fifo_frames_remaining(%lld)",
+ __func__,
+ (long long)out->fifo_underruns.n,
+ (long long)frames_by_time,
+ (long long)out->last_fifo_frames_remaining);
+ }
+ out->last_fifo_valid = false; // we're writing below, mark fifo info as stale.
+ }
long ns = (frames * (int64_t) NANOS_PER_SECOND) / out->config.rate;
request_out_focus(out, ns);
@@ -3549,8 +3596,27 @@
if (out->pcm) {
unsigned int avail;
if (pcm_get_htimestamp(out->pcm, &avail, timestamp) == 0) {
- size_t kernel_buffer_size = out->config.period_size * out->config.period_count;
- int64_t signed_frames = out->written - kernel_buffer_size + avail;
+
+ // pcm_get_htimestamp() computes the available frames by comparing
+ // the alsa driver hw_ptr and the appl_ptr levels.
+ // In underrun, the hw_ptr may keep running and report an excessively
+ // large number available number.
+ if (avail > out->kernel_buffer_size) {
+ ALOGW("%s: avail:%u > kernel_buffer_size:%zu clamping!",
+ __func__, avail, out->kernel_buffer_size);
+ avail = out->kernel_buffer_size;
+ out->last_fifo_frames_remaining = 0;
+ } else {
+ out->last_fifo_frames_remaining = out->kernel_buffer_size - avail;
+ }
+ out->last_fifo_valid = true;
+ out->last_fifo_time_ns = audio_utils_ns_from_timespec(timestamp);
+
+ int64_t signed_frames = out->written - out->last_fifo_frames_remaining;
+
+ ALOGVV("%s: frames:%lld avail:%u kernel_buffer_size:%zu",
+ __func__, (long long)signed_frames, avail, out->kernel_buffer_size);
+
// This adjustment accounts for buffering after app processor.
// It is based on estimated DSP latency per use case, rather than exact.
signed_frames -=
@@ -3929,6 +3995,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);
}
@@ -4130,6 +4202,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);
@@ -4137,6 +4211,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.
@@ -5053,6 +5131,8 @@
else
out->af_period_multiplier = 1;
+ out->kernel_buffer_size = out->config.period_size * out->config.period_count;
+
out->standby = 1;
/* out->muted = false; by calloc() */
/* out->written = 0; by calloc() */
diff --git a/hal/audio_hw.h b/hal/audio_hw.h
index f28505d..0026373 100644
--- a/hal/audio_hw.h
+++ b/hal/audio_hw.h
@@ -26,6 +26,7 @@
#include <audio_route/audio_route.h>
#include <audio_utils/ErrorLog.h>
+#include <audio_utils/Statistics.h>
#include "voice.h"
// dlopen() does not go through default library path search if there is a "/" in the library name.
@@ -256,6 +257,16 @@
error_log_t *error_log;
struct stream_app_type_cfg app_type_cfg;
+
+ size_t kernel_buffer_size; // cached value of the alsa buffer size, const after open().
+
+ // last out_get_presentation_position() cached info.
+ bool last_fifo_valid;
+ unsigned int last_fifo_frames_remaining;
+ 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 {
@@ -296,6 +307,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 {