[pulseaudio-discuss] alsa sink latency - how to account for startup delay

[Georg Chini]

On 02.04.2016 16:10, Tanu Kaskinen wrote:
> On Wed, 2016-03-30 at 22:31 +0200, Georg Chini wrote:
>> On 30.03.2016 18:06, Tanu Kaskinen wrote:
>>> On Tue, 2016-03-29 at 20:29 +0200, Georg Chini wrote:
>>>>
>>>> The starting point is the observation, that with module-loopback and an
>>>> USB sink
>>>> the real end-to-end latency is about 10ms longer than configured. This
>>>> cannot be
>>>> observed with a HDA sink. Let's go through the sequence of events when
>>>> module-loopback is started:
>> The latency that is made up by the contents of the memblockq
>> (and the render memblockq's on the sink input/source output side)
>> can be exactly calculated, so if the resulting overall latency is wrong,
>> the error must be on the source or sink side. In this case it must be
>> the sink side because changing the source has no impact.
>> Nevertheless the sequence below is interesting, because it shows,
>> how the latency is calculated on the alsa side. I'll attach a log with
>> some debugging information, numbers without units are usec.
> I thought that the loopback latency got eventually right, and you only
> had trouble in the beginning. Now it sounds like the latency is wrong
> all the time.

Yes, the latency stabilizes at the wrong value. I don't care too much
about the initial latency, it is sufficient if there is enough silence 
in the
memblockq to avoid underruns. It's nice if it is near the expected
value, but not mandatory.

>> 4) On the alsa side, the preparation has been done. Again, to simplify
>> we assume 2 URB's
>> with 5ms each have been set up and submitted to the USB bus. The first
>> URB starts
>> playing silence to the speakers now.
>>> prepare() has been called. If we assume that the DAC has not yet
>>> consumed anything from the first URB, the "USB bus" latency is 10 ms.
>>> PulseAudio hasn't written anything yet to the ring buffer. Expected
>>> delay: 10 ms.
>> I think the delay is still undefined here. No audio has been sent
>> and the stream is not even started.
> Yes, you're right, the delay is undefined when the stream hasn't been
> started. If we can assume that snd_pcm_start() takes an insignificant
> time, then talking about the delay can still make sense, though, if we
> define delay as the latency for data that is written now if
> snd_pcm_start() is also called now.

That is my definition of the delay.

>
>>>> 5) The pulseaudio sink code takes the first 10ms of audio out of the
>>>> loopback buffer,
>>>> writes it to the alsa buffer and calls snd_pcm_start().
>>> If the sink takes something from the loopback buffer, this means that
>>> the first pop() call has been made. Assuming no time has passed since
>>> the previous step, the USB bus is still full, and so is the ring
>>> buffer. Expected delay: 20 ms.
>> Reported delay is exactly the amount of audio that was written to
>> the buffer.
> That's the bug that I think should be fixed in alsa if possible (and if
> it's impossible, I don't see how it could be fixed in pulseaudio
> either).
It can be fixed (or at least be worked around). If you take a time stamp
at the moment when snd_pcm_start() is called and another when
the first audio has definitely been played (delay < write_count), then
the difference between the time stamps corrected by the amount
of audio that has already been played, gives you exactly that
missing bit of latency.
That was what my original question was about - what should I do with
this extra latency? Currently I am just adding it as an offset to the
"normal" latency. This however means, that if you configure let's say
10ms, you will get in fact around 22ms. (You would get 22ms anyway,
but the reports would show 10ms with the old code.)
For HDA the reported delay is even slightly negative, probably because
the card already starts during the preparation step. Negative delays
are truncated by my code, no real audio should have been played
before snd_pcm_start().

BTW, do you think the debug output of module-loopback is
better now?

> Yes, although if it's logged twice a second, it might be better to
> print the status only if explicitly requested via a module argument.
>
The status is printed once every adjust time and only when debug
logging is enabled. 500ms seems to be a good value for the adjust
time, it is currently my default. If you prefer an additional argument
to enable logging, I can add it.