[PATCH 08/13] loopback: Track underruns and cant-peek events

[georg@xxxxxxxx (Georg Chini)]

React by adjusting buffer latency.
---
 src/modules/module-loopback.c | 38 ++++++++++++++++++++++++++++++++++++--
 1 file changed, 36 insertions(+), 2 deletions(-)

diff --git a/src/modules/module-loopback.c b/src/modules/module-loopback.c
index 09f2f58..cbd0ac9 100644
--- a/src/modules/module-loopback.c
+++ b/src/modules/module-loopback.c
@@ -84,6 +84,8 @@ struct userdata {
     int64_t send_counter;
     uint32_t sink_adjust_counter;
     uint32_t source_adjust_counter;
+    uint32_t underruns;
+    uint32_t no_peeks;
 
     pa_usec_t latency;
     pa_usec_t buffer_latency;
@@ -200,7 +202,7 @@ static uint32_t rate_controller(
 /* Called from main context */
 static void adjust_rates(struct userdata *u) {
     size_t buffer;
-    uint32_t old_rate, base_rate, new_rate;
+    uint32_t old_rate, base_rate, new_rate, hours;
     pa_usec_t final_latency, source_sink_latency, current_buffer_latency, current_latency, corrected_latency;
     int32_t latency_difference;
     pa_usec_t snapshot_delay;
@@ -208,6 +210,8 @@ static void adjust_rates(struct userdata *u) {
     pa_assert(u);
     pa_assert_ctl_context();
 
+    /* Runtime and counters since last change of source or sink */
+    hours = PA_MIN(u->sink_adjust_counter, u->source_adjust_counter) * u->adjust_time / PA_USEC_PER_SEC / 3600;
     u->sink_adjust_counter +=1;
     u->source_adjust_counter +=1;
 
@@ -215,6 +219,21 @@ static void adjust_rates(struct userdata *u) {
     u->source_latency_sum += u->latency_snapshot.source_latency;
     u->sink_latency_sum += u->latency_snapshot.sink_latency;
 
+    /* If we are seeing underruns or cannot peek into the queue during pop then the latency is too small */
+    if (u->underruns > 2 || u->no_peeks > 30) {
+       u->buffer_latency += 5 * PA_USEC_PER_MSEC;
+       pa_log_warn("Too many underruns, increasing buffer latency to %0.2f ms", (double) u->buffer_latency / PA_USEC_PER_MSEC);
+       u->underruns = 0;
+       u->no_peeks = 0;
+    }
+
+    /* Allow one underrun and 15 no peek messages per hour */
+    if (PA_MIN(u->sink_adjust_counter, u->source_adjust_counter) * u->adjust_time / PA_USEC_PER_SEC / 3600 > hours) {
+       pa_log_info("Underrun counters: %u, %u", u->underruns, u->no_peeks);
+       u->underruns = PA_CLIP_SUB(u->underruns, 1u);
+       u->no_peeks = PA_CLIP_SUB(u->no_peeks, 15u);
+    }
+
     /* Rates and latencies*/
     old_rate = u->sink_input->sample_spec.rate;
     base_rate = u->source_output->sample_spec.rate;
@@ -450,6 +469,8 @@ static void source_output_detach_cb(pa_source_output *o) {
    u->source_sink_changed = true;
    u->source_latency_sum = 0;
    u->source_adjust_counter = 0;
+   u->underruns = 0;
+   u->no_peeks = 0;
    u->buffer_latency = u->initial_buffer_latency;
 }
 
@@ -570,6 +591,8 @@ static void update_source_requested_latency_cb(pa_source_output *i) {
        if (!u->source_sink_changed) {
           u->source_adjust_counter = 0;
           u->source_latency_sum = 0;
+          u->underruns = 0;
+          u->no_peeks = 0;
        }
     }
 }
@@ -590,7 +613,10 @@ static int sink_input_pop_cb(pa_sink_input *i, size_t nbytes, pa_memchunk *chunk
     u->in_pop = false;
 
     if (pa_memblockq_peek(u->memblockq, chunk) < 0) {
-        pa_log_info("Could not peek into queue");
+        if (!u->source_sink_changed) {
+           u->no_peeks +=1;
+           pa_log_info("Could not peek into queue");
+        }
         return -1;
     }
 
@@ -648,6 +674,8 @@ static int sink_input_process_msg_cb(pa_msgobject *obj, int code, void *data, in
                 pa_memblockq_is_readable(u->memblockq)) {
 
                 pa_log_debug("Requesting rewind due to end of underrun.");
+                if (!u->source_sink_changed)
+                   u->underruns +=1;
                 pa_sink_input_request_rewind(u->sink_input,
                                              (size_t) (u->sink_input->thread_info.underrun_for == (size_t) -1 ? 0 : u->sink_input->thread_info.underrun_for),
                                              false, true, false);
@@ -747,6 +775,8 @@ static void sink_input_detach_cb(pa_sink_input *i) {
     u->pop_called = false;
     u->sink_latency_sum = 0;
     u->sink_adjust_counter = 0;
+    u->underruns = 0;
+    u->no_peeks = 0;
     u->buffer_latency = u->initial_buffer_latency;
 }
 
@@ -888,6 +918,8 @@ static void update_sink_requested_latency_cb(pa_sink_input *i) {
        if (!u->source_sink_changed) {
           u->sink_adjust_counter = 0;
           u->sink_latency_sum = 0;
+          u->underruns = 0;
+          u->no_peeks = 0;
        }
     }
 }
@@ -1003,6 +1035,8 @@ int pa__init(pa_module *m) {
     u->sink_latency_sum = 0;
     u->source_latency_sum = 0;
     u->pop_called = false;
+    u->underruns = 0;
+    u->no_peeks = 0;
     u->source_sink_changed = true;
 
     adjust_time_sec = DEFAULT_ADJUST_TIME_USEC / PA_USEC_PER_SEC;
-- 
2.1.4