[pulseaudio-discuss] 61ms delay in pa_simple_write()

[Wu Fengguang]

On Fri, Sep 24, 2010 at 01:17:29PM +0800, Wu Fengguang wrote:
> Greetings,
> 
> We are debugging a new QEMU USB audio model that works fine with alsa
> backend but drops samples from time to time with pulseaudio backend.
> 
> Traces show that the pa_simple_write() call normally does its job
> quickly, but sometimes takes ~60ms to return (the last write=XXms
> field):
> 
>     L1    qpa_thread_out rpos = 1499, pa->decr = 1155, decr = 1155, pa->live = 0, write=0ms
>     L2    qpa_thread_out rpos = 605, pa->decr = 1154, decr = 1154, pa->live = 0, write=0ms
>     L3    qpa_thread_out rpos = 1670, pa->decr = 1065, decr = 1065, pa->live = 0, write=1ms
>     L4    qpa_thread_out rpos = 736, pa->decr = 1114, decr = 1114, pa->live = 0, write=0ms
>     L5    qpa_thread_out rpos = 1850, pa->decr = 1114, decr = 1114, pa->live = 0, write=0ms
>     L6    qpa_thread_out rpos = 957, pa->decr = 1155, decr = 1155, pa->live = 0, write=0ms
>     L7    qpa_thread_out rpos = 15, pa->decr = 1106, decr = 1106, pa->live = 0, write=0ms
> ==> L8    qpa_thread_out rpos = 1127, pa->decr = 1112, decr = 1112, pa->live = 936, write=61ms
> ==> L9    qpa_thread_out rpos = 1127, pa->decr = 2048, decr = 2048, pa->live = 0, write=0ms
> 
> The 61ms delay in L8 overruns the ring buffer inside qemu (note the
> decr=2048 in L9; I ran qemu with QEMU_PA_SAMPLES=2048).
> 
> Skimming through the pulseaudio code, my wild guess is there are two
> possible source of delays (I excluded kernel problems since ALSA works
> fine):
> 1) memory allocation
> 2) pulseaudio internal lock
> 3) blockable syscall

With "strace -Tp `pidof pulseaudio`", I do see several ppoll()
syscalls that take up to 59ms:

        (sorted by time spent in the syscall)

==>     0.059522 ppoll
==>     0.059478 ppoll
==>     0.056892 ppoll
        0.035356 ppoll
        0.028646 ppoll
        0.028407 ppoll
        0.027576 ppoll
        ...
         
> I'm mainly suspecting (1). Basically any latency sensible application
> should do pre-allocation and to _absolutely avoid_ memory allocation
> during audio streaming. However I do see the pa_simple_write() calls
> into pa_stream_write() which in turn _might_ call malloc() in the end.
> 
> I'm not sure if the pa_memblock_new[_user]() API takes care to
> preallocate _enough_ memory before playback. Can anyone kindly confirm
> that?

Hmm it seems there are zero memory allocation delays, so it's at least
not the root cause of the qemu delays in my case.

        $ getdelays -dip `pidof pulseaudio`
        print delayacct stats ON
        printing IO accounting
        PID     7412


        CPU             count     real total  virtual total    delay total
                        81186     9808613000     9692671654     4396396593
        IO              count    delay total
                           91      483460900
(note: the above line does not change during playback, so don't care)
        SWAP            count    delay total
                            0              0
==>     RECLAIM         count    delay total
==>                         0              0
        pulseaudio: read=1019904, write=4096, cancelled_write=0

Thanks,
Fengguang