[pulseaudio-discuss] How to control latency with CLI?

[Steven Wawryk]

> Message: 3 Date: Sat, 14 Oct 2017 01:43:42 +0300 From: Tanu Kaskinen 
> <tanuk at iki.fi> To: General PulseAudio Discussion 
> <pulseaudio-discuss at lists.freedesktop.org> Subject: Re: 
> [pulseaudio-discuss] How to control latency with CLI? Message-ID: 
> <1507934622.7449.10.camel at iki.fi> Content-Type: text/plain; 
> charset="UTF-8" On Fri, 2017-10-13 at 19:09 +1030, Steven Wawryk wrote:
>> Today I noticed that there seems to be about 5minutes delay in
>> module-remap-source on the workstation rather than in module-loopback on
>> the embedded system.
>>
>> With the following CLI script items (selecting 1 of the 12 channels of
>> digitised audio from the embedded system):
>>
>>       ...
>>
>>       load-module module-null-sink sink_name=rtp_in_sink1
>> sink_properties=device.description=RTP_in1 format=ulaw rate=8000
>> channels=12
>> channel_map=aux0,aux1,aux2,aux3,aux4,aux5,aux6,aux7,aux8,aux9,aux10,aux11
>>       ...
>>
>>       load-module module-rtp-recv sink=rtp_in_sink1
>> sap_address=224.0.0.81 latency_msec=10
>>       ...
>>
>>       load-module module-remap-source source_name=voip_source
>> master=rtp_in_sink1.monitor
>> source_properties=device.description=VoIPSource format=ulaw rate=8000
>> channels=1 master_channel_map=aux4 channel_map=front-left remix=no
>>
>>       ...
>>
>> ... and observing with pavucontrol, when I tapped or spoke into the
>> microphone, there was signal with no noticeable delay at rtp_in_sink1
>> and rtp_in_sink1.monitor, but the signal could not be seen on
>> voip_source until about 5minutes later.  I can't see any obvious reason
>> in the module-remap-source source code.
>>
>> I will investigate further on Monday (including logs), but have I messed
>> up the above CLI statements?
> I don't see anything wrong with the CLI commands.
>
> The latency in module-remap-source is weird. The module itself doesn't
> do any buffering. module-remap-source connects to the master source
> using a pa_source_output, and pa_source_output contains
> delay_memblockq, which is a buffer. Maybe the delay_memblockq is
> involved in the huge latency? The purpose (or at least one purpose) of
> delay_memblockq is to keep enough data buffered in monitor sources to
> deal with the possibility of data getting changed in the unplayed
> portion of the sink playback buffer. The sink in your case (or in any
> other case) doesn't have a playback buffer of 5 minutes, so if the
> delay_memblockq holds 5 minutes worth of data, there's some bug. Maybe
> adding some extra logging to pa_source_output_push() will shed some
> light on the matter.

I've *finally* managed to get PulseAudio running on the test workstation 
with extra logging in pa_source_output_push()!

I've attached a copy of pa_source_output_push() with the extra log 
statements to show where they are.  Also, about 1second of gzipped 
output is attached (because otherwise there's a *lot* of output).

I don't fully understand what's going on, but here are a few things I 
noticed, which may be suspicious:

     * There seems to be a number of source-outputs logging output, but 
I assume the relevant one for module-remap-source is the one with the 
PA_RESAMPLER_NO_REMIX ("flags=0x04") flag set because of the "remix=no" 
parameter I gave it.

     * Whenever this source-output calls this function (outputting 
"rsmplr=30, flags=0x4" in the while loop), there seems to always be 
another immediately following call (outputting "limit=2304000bytes (1)" 
at the start of the function) with the *large* 2304000bytes limit that 
never executes the following "if" and "while" statement bodies.  Hence 
it never calls o->push().

     * At some point in the "Oct 25 05:31:07" second, the above 
behaviour switches from 1 to 2 immediately following calls with 
"limit=2304000bytes (1)" logged.

That's as far as I got today.  In the absence of any feedback or 
guidance on this email, I'll investigate further tomorrow and hope I'm 
not too far off track.


-------------- next part --------------
A non-text attachment was scrubbed...
Name: logging.c
Type: text/x-csrc
Size: 4904 bytes
Desc: not available
URL: <https://lists.freedesktop.org/archives/pulseaudio-discuss/attachments/20171025/04721ce3/attachment-0001.c>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: palog.gz
Type: application/gzip
Size: 42791 bytes
Desc: not available
URL: <https://lists.freedesktop.org/archives/pulseaudio-discuss/attachments/20171025/04721ce3/attachment-0001.gz>