[pulseaudio-discuss] Problem with latency

[Dan Oscarsson]

Running mplayer under opensuse 11.2 with audio out == pulseaudio gives
latency problems. The current pulseaudio in opensuse is 0.9,.21 with 64
patches added (most I assume is from pulseaudio git).

mplayer uses the latency (the value of pa_stream_get_latency) to
calculate the timestamp of current player audio sample.
It calculates the timestamp of current played sample as:
timestamp of next sample to be written to audio device - latency.

This works well with pulseaudio when audio is flowing continuously.
Not when a pause is done (like when user pauses movie), or a flush of
data (like when user jumps to new place in movie).

I have analysed what happens trying to find the cause. Below is a log.
In it I output timing info when that is sent from server, when write to
stream is done, and when cork and flush is called.
The info for timing info is: time usec since last timing info,
sinc usec, buffer size in bytes and as usec, and transport usec.

You can see that after a cork 1 (pause) the sinc usec varies a little
for a while and then turns to zero, while buffer remains constant.
And after cork 0, audio is out of sync with video and latency is
unstable - that is it give A-V sync values with plus and minus values.

Later on you can se a flush, buffer turns zero but sinc usec remains.

For me it looks like sinc usec is the main problem.
After a cork 1 (pause) both sinc usec and buffer size should remain
constant.
After a flush both sinc usec and buffer size should turn zero. sinc usec
can retain the device latency - but the timing value contains a lot
more.

Trying to understand the core I see that sinc usec is device latency
plus length of thread_info.render_memblockq.
What is render_memblockq? Is it for doing resampling? Even though a
player like mplayer will do resampling to match audio device.
And even if it is a resampling space it should not change after a pause,
and should flush all data at a flush.
In mplayer is works like: decoded-buffer -> resampling-buffer ->
output-buffer -> send to audio-device. A flush will reset all buffers in
mplayer, not just the decoded-buffer that could correspond to the server
buffer in pulseaudio.

As it is now I can even make the defective oss driver under opensuse
11.2 work better then pulseaudio because it at least handles flush
correctly.

Below is my log.

   Dan


TIMING info 34491 sinc usec 1964561 buffer bytes 0 buffer usec 0 transport usec 364
TIMING info 54374 sinc usec 1909166 buffer bytes 0 buffer usec 0 transport usec 198
TIMING info 46495 sinc usec 1862673 buffer bytes 0 buffer usec 0 transport usec 228
WRITE len 48000
WRITE len 32224
TIMING info 37777 sinc usec 206979 buffer bytes 43744 buffer usec 227833 transport usec 3822
TIMING info 6236 sinc usec 200611 buffer bytes 43744 buffer usec 227833 transport usec 107
TIMING info 20265 sinc usec 180363 buffer bytes 43744 buffer usec 227833 transport usec 133
WRITE len 4256
TIMING info 40329 sinc usec 140022 buffer bytes 48000 buffer usec 250000 transport usec 116
TIMING info 82672 sinc usec 208621 buffer bytes 18948 buffer usec 98687 transport usec 2507
WRITE len 29052
TIMING info 160831 sinc usec 208444 buffer bytes 17144 buffer usec 89291 transport usec 2626
WRITE len 30856
WRITE len 36504
TIMING info 320346 sinc usec 208450 buffer bytes 22928 buffer usec 119416 transport usec 2150
WRITE len 25072
WRITE len 36472
WRITE len 36464
WRITE len 36468
TIMING info 638341 sinc usec 139353 buffer bytes 48000 buffer usec 250000 transport usec 220
WRITE len 36504
WRITE len 36496
WRITE len 36644
WRITE len 36536
WRITE len 36504
WRITE len 36500
TIMING info 1280522 sinc usec 190337 buffer bytes 11428 buffer usec 59520 transport usec 108
WRITE len 36572
WRITE len 36504
WRITE len 36532
WRITE len 36504
WRITE len 36536
WRITE len 36500
WRITE len 36504
WRITE len 36536
TIMING info 1503143 sinc usec 206842 buffer bytes 11844 buffer usec 61687 transport usec 2663
WRITE len 36156
WRITE len 36780
WRITE len 36500
WRITE len 36536
WRITE len 36504
WRITE len 36500
WRITE len 36536
WRITE len 36540
TIMING info 1500669 sinc usec 207371 buffer bytes 15716 buffer usec 81854 transport usec 2395
WRITE len 32284
WRITE len 36504
WRITE len 36500

CORK 1 (pause)

TIMING info 591739 sinc usec 186062 buffer bytes 11500 buffer usec 59895 transport usec 176
TIMING info 345 sinc usec 185904 buffer bytes 11500 buffer usec 59895 transport usec 305
TIMING info 10184 sinc usec 175530 buffer bytes 11500 buffer usec 59895 transport usec 83
TIMING info 20231 sinc usec 155320 buffer bytes 11500 buffer usec 59895 transport usec 111
TIMING info 40325 sinc usec 115018 buffer bytes 11500 buffer usec 59895 transport usec 169
TIMING info 80365 sinc usec 209708 buffer bytes 11500 buffer usec 59895 transport usec 197
TIMING info 160450 sinc usec 209641 buffer bytes 11500 buffer usec 59895 transport usec 206
TIMING info 320633 sinc usec 209801 buffer bytes 11500 buffer usec 59895 transport usec 215
TIMING info 640910 sinc usec 139666 buffer bytes 11500 buffer usec 59895 transport usec 169
TIMING info 1280635 sinc usec 190999 buffer bytes 11500 buffer usec 59895 transport usec 164
TIMING info 1501087 sinc usec 209963 buffer bytes 11500 buffer usec 59895 transport usec 243
TIMING info 948182 sinc usec 0 buffer bytes 11500 buffer usec 59895 transport usec 50
TIMING info 10198 sinc usec 0 buffer bytes 11500 buffer usec 59895 transport usec 85
TIMING info 20192 sinc usec 0 buffer bytes 11500 buffer usec 59895 transport usec 85
TIMING info 40261 sinc usec 0 buffer bytes 11500 buffer usec 59895 transport usec 132
TIMING info 80328 sinc usec 0 buffer bytes 11500 buffer usec 59895 transport usec 154
TIMING info 160386 sinc usec 0 buffer bytes 11500 buffer usec 59895 transport usec 137
TIMING info 320337 sinc usec 0 buffer bytes 11500 buffer usec 59895 transport usec 138
TIMING info 640868 sinc usec 0 buffer bytes 11500 buffer usec 59895 transport usec 138
TIMING info 1281131 sinc usec 0 buffer bytes 11500 buffer usec 59895 transport usec 140
TIMING info 1500990 sinc usec 0 buffer bytes 11500 buffer usec 59895 transport usec 133
TIMING info 1501739 sinc usec 0 buffer bytes 11500 buffer usec 59895 transport usec 141
TIMING info 1501747 sinc usec 0 buffer bytes 11500 buffer usec 59895 transport usec 142
TIMING info 1501529 sinc usec 0 buffer bytes 11500 buffer usec 59895 transport usec 136
TIMING info 1501729 sinc usec 0 buffer bytes 11500 buffer usec 59895 transport usec 139
TIMING info 1501268 sinc usec 0 buffer bytes 11500 buffer usec 59895 transport usec 137

CORK 0 (resume)

TIMING info 517365 sinc usec 0 buffer bytes 11500 buffer usec 59895 transport usec 209
TIMING info 10208 sinc usec 209818 buffer bytes 11500 buffer usec 59895 transport usec 9939
TIMING info 36 sinc usec 209666 buffer bytes 11500 buffer usec 59895 transport usec 83
WRITE len 36500

A:6.509862 V:6.172833 A-V:  0.337
   -- unstable and out of sync --

TIMING info 10668 sinc usec 198636 buffer bytes 48000 buffer usec 250000 transport usec 50
TIMING info 20186 sinc usec 178464 buffer bytes 48000 buffer usec 250000 transport usec 79
TIMING info 40210 sinc usec 138258 buffer bytes 48000 buffer usec 250000 transport usec 99
TIMING info 61500 sinc usec 208292 buffer bytes 22744 buffer usec 118458 transport usec 73
TIMING info 10175 sinc usec 198116 buffer bytes 22744 buffer usec 118458 transport usec 67
WRITE len 25256
TIMING info 20546 sinc usec 177567 buffer bytes 48000 buffer usec 250000 transport usec 72
TIMING info 40204 sinc usec 137357 buffer bytes 48000 buffer usec 250000 transport usec 91
TIMING info 80996 sinc usec 188002 buffer bytes 22716 buffer usec 118312 transport usec 80
WRITE len 25284
TIMING info 160941 sinc usec 161748 buffer bytes 22120 buffer usec 115208 transport usec 86
WRITE len 22716
WRITE len 25284
WRITE len 22116
TIMING info 320879 sinc usec 181967 buffer bytes 26688 buffer usec 139000 transport usec 168
WRITE len 21312
WRITE len 21912

A:7.006400 V:7.007000 A-V: -0.001
   -- stable here --

WRITE len 22148
WRITE len 18740
WRITE len 20864
WRITE len 22080

 - log data deleted -

TIMING info 1500798 sinc usec 207318 buffer bytes 15364 buffer usec 80020 transport usec 2708
WRITE len 32636
WRITE len 36500

FLUSH

TIMING info 340126 sinc usec 207877 buffer bytes 19092 buffer usec 99437 transport usec 2197
TIMING info 300 sinc usec 207701 buffer bytes 0 buffer usec 0 transport usec 2337
WRITE len 48000
TIMING info 7760 sinc usec 199804 buffer bytes 48000 buffer usec 250000 transport usec 80
TIMING info 21707 sinc usec 178095 buffer bytes 48000 buffer usec 250000 transport usec 1588
TIMING info 39284 sinc usec 138820 buffer bytes 48000 buffer usec 250000 transport usec 152

A:28.892986 V:28.945583 A-V: -0.053
  - out of sync -

TIMING info 82350 sinc usec 207805 buffer bytes 18948 buffer usec 98687 transport usec 2180
WRITE len 29052
TIMING info 160388 sinc usec 207798 buffer bytes 17212 buffer usec 89645 transport usec 2314
WRITE len 30788
WRITE len 36500
TIMING info 320439 sinc usec 207942 buffer bytes 22956 buffer usec 119562 transport usec 2125
WRITE len 25044
WRITE len 36504
WRITE len 36532

A:29.865042 V:29.863167 A-V:  0.002
  - stable here -

WRITE len 36504
TIMING info 638912 sinc usec 139563 buffer bytes 48000 buffer usec 250000 transport usec 148
WRITE len 36500
WRITE len 36504
WRITE len 36536