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

[Tanu Kaskinen]

On Wed, 2015-02-25 at 19:43 +0100, Georg Chini wrote:
> 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 */

Why do you count the number of peek failures? Why isn't it enough to
count underruns?

> +    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);

This seems buggy (also without your patch). This code is guarded by "if
(!in_pop)". The message queue is drained in the beginning of the pop
callback, and if the POST message that ends an underrun is processed in
the pop callback, then the rewind is not done, and the underrun won't
be counted in u->underruns.

Neither of the problems is particularly serious, so we could ignore
them, but the fix seems simple to me: it should be safe to just remove
the message queue draining from the pop callback. It would mean that if
the memblockq is empty, and a POST message is ready for processing when
the pop callback is called, the audio in the message won't be used, and
an unnecessary underrun will occur. I believe that's not a real
problem, however. The memblockq should be empty only when the sink and
source buffers are full, and if the sink buffer is full, the pop
callback won't be called.

-- 
Tanu