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

[Georg Chini]

On 06.12.2015 22:38, Tanu Kaskinen wrote:
> 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?

First, sorry for the late reply. I have been very busy the last weeks 
and also
worked on a new controller version.
There are situations where I observe large latency changes when only the
peek failures are visible and no underruns are reported. Maybe that is a
consequence of the problem you point out below.

>
>> +    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.
>
I will test what happens when I remove the message queue draining
from the pop callback, but I fear this might significantly impact the
latency calculations.