[pulseaudio-discuss] [PATCH v6 12/25] loopback: Implement underrun protection

[Tanu Kaskinen]

On Thu, 2016-08-11 at 16:17 +0200, Georg Chini wrote:
> On 10.08.2016 23:41, Tanu Kaskinen wrote:
> > 
> > On Sun, 2016-06-05 at 21:05 +0200, Georg Chini wrote:
> > > > > > +        else
> > > +            u->extra_latency += 5 * PA_USEC_PER_MSEC;
> > > +        pa_log_warn("Too many underruns, increasing latency to %0.2f ms", (double)(u->extra_latency + u->minimum_latency) / PA_USEC_PER_MSEC);
> > > +        u->underrun_counter = 0;
> > > +    }
> > > +
> > > +    /* Allow one underrun per hour */
> > > +    if (u->iteration_counter * u->adjust_time / PA_USEC_PER_SEC / 3600 > hours) {
> > > +        pa_log_info("Underrun counter: %u", u->underrun_counter);
> > > +        u->underrun_counter = PA_CLIP_SUB(u->underrun_counter, 1u);
> > If you print the counter just before adjusting it, the log will be
> > misleading. If a line appears in the console saying "Underrun counter:
> > 2", I don't think the natural thought process goes like "a-ha! the
> > counter value was 2 at the time of printing that message, so now it
> > clearly has to be 1!"
> 
> This is just printing the counter each hour and therefore giving
> you something like the observed underrun rate. The advantage
> of printing it before it is decremented is that you can still see if
> there is one underrun per hour, otherwise you would not notice it.
> I could remove the log message completely if you prefer.

Removing the message is fine, but I'd prefer showing the counter in the
log. The problem of not noticing once-per-hour underrunds can be solved
by logging the same message when the counter is incremented.

> > > 
> > >   }
> > >   
> > >   /* Called from main thread */
> > > @@ -585,9 +619,14 @@ static void update_source_requested_latency_cb(pa_source_output *i) {
> > >       if (source_latency > u->configured_source_latency) {
> > >           /* The minimum latency has changed to a value larger than the configured latency */
> > >           pa_log_warn("Source latency increased to %0.2f ms", (double)source_latency / PA_USEC_PER_MSEC);
> > > +        u->extra_latency = PA_CLIP_SUB(u->extra_latency, source_latency - u->configured_source_latency);
> > >           u->configured_source_latency = source_latency;
> > >           u->min_source_latency = source_latency;
> > >           update_minimum_latency(u);
> > > +        if (!u->source_sink_changed) {
> > > +            u->iteration_counter = 0;
> > > +            u->underrun_counter = 0;
> > > +        }
> > Send a message about the source latency increase to the main thread and
> > update the variables there.
> 
> Don't understand, isn't that already called from the main thread?

Certainly not. Maybe you're confused because of the "Called from main
thread" comment that is visible at the end of the previous patch hunk?

> > > @@ -611,7 +650,8 @@ 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)
> > > +            pa_log_info("Could not peek into queue");
> > What's the purpose of this change?
> 
> This is to suppress unnecessary log messages after startup or when
> source or sink changes. See also comment at the bottom.

At what point does it become necessary to log the messages?
source_sink_changed is set to false in adjust_rates(), and I don't
think that's a relevant event in this case. The first call to
source_output_push_cb() would seem like more relevant trigger.

> > > @@ -667,14 +707,18 @@ static int sink_input_process_msg_cb(pa_msgobject *obj, int code, void *data, in
> > >   
> > >               /* Is this the end of an underrun? Then let's start things
> > >                * right-away */
> > > -            if (!u->in_pop &&
> > > -                u->sink_input->thread_info.underrun_for > 0 &&
> > > +            if (u->sink_input->thread_info.underrun_for > 0 &&
> > >                   pa_memblockq_is_readable(u->memblockq)) {
> > >   
> > > -                pa_log_debug("Requesting rewind due to end of underrun.");
> > > -                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);
> > > +                if (!u->source_sink_changed)
> > > +                    u->underrun_counter +=1;
> > underrun_counter is used in the main thread, so you shouldn't access it
> > from the IO thread. Send a message to notify the main thread of the
> > underrun.
> 
> One question: It is only unsafe if both threads try to modify a
> variable, correct? So is it OK if one threads sets a variable while
> the other only reads it? Or do I have to take into account that
> one thread may read the variable while the other modifies it at
> the same time?

AFAIK, the compiler is allowed to cache variable values on per-thread
basis, so when another thread changes the value, that doesn't
necessarily propagate to the other thread, at least immediately. The
"volatile" keyword can be used to mark variables so that they must
always be read from the RAM when accessed. But rather than trying to
understand all the details, I think it's best to never access variables
that can be concurrently changed in another thread.

-- 
Tanu