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
