ao/pulse: repeated forward seeking in certain files may mess up

[sfan5]

Important Information

• mpv 45ff209
• Linux/X11
• PulseAudio 16.0 or 16.1

Reproduction steps

1. mpv --no-config --force-window 06.flac
2. Seek between random places in the song about 7 times
3. Seek back to beginning
4. Press and hold the right arrow key

Expected behavior

5. mpv skips through song linearly

Actual behavior

5. mpv occasionally goes backwards (sometimes so often consecutively that you end up back the beginning)

Log file

http://sprunge.us/7995Gl

Sample files

https://0x0.st/oSbK.flac

Further information

Seeking going wrong is also evident in the log file:

[   9.207][v][lavf] queuing seek to 196.001769
[   9.207][v][lavf] execute seek (to 196.001769 flags 32)
[   9.207][v][file] stream level seek from 24131348 to 23458322
[   9.208][v][file] stream level seek from 23654930 to 23455417
[   9.208][v][file] stream level seek from 23652025 to 23378889
[   9.208][v][cplayer] hr-seek, skipping to 196.001769
[   9.208][v][vo/gpu/x11] Enabling screensaver.
[   9.208][v][file] stream level seek from 23641033 to 23420676
[   9.208][v][vd] Decoder format: 640x638 yuv420p bt.601/auto/auto/full/auto CL=mpeg1/jpeg
[   9.208][v][file] stream level seek from 23617284 to 23449547
[   9.208][v][file] stream level seek from 23646155 to 23440375
[   9.208][v][file] stream level seek from 23636983 to 23446536
[   9.209][v][file] stream level seek from 23643144 to 23446127
[   9.209][v][file] stream level seek from 23642735 to 23445720
[   9.209][v][file] stream level seek from 23642328 to 23445719
[   9.209][v][lavf] seek done
[   9.239][v][cplayer] first video frame after restart shown
[   9.240][d][cplayer] Run command: seek, flags=73, args=[target="5.000000", flags="relative", legacy="unused"]
[   9.240][v][cplayer] audio ready
[   9.240][d][cplayer] video EOF (status=4)
[   9.240][v][cplayer] starting audio playback
[   9.240][v][vo/gpu/x11] Disabling screensaver.
[   9.240][v][cplayer] playback restart complete @ 196.001769, audio=playing, video=eof
[   9.240][v][ao/pulse] starting AO
[   9.241][v][lavf] queuing seek to 193.396849

After restarting playback at 196 the next seek should go to 196 + 5 = 201, yet mpv queues a seek to a position even before the starting point.

This also happens with --hr-seek=no (hr-seek is automatically enabled for audio).

This does not happen with --vid=no or --no-audio-display.

This does not happen with --ao=null or --ao=alsa

[sfan5]

This happens because pa_stream_get_latency momentarily returns bogus values, here's an example:

[cplayer] first video frame after restart shown
[cplayer] audio ready
[ao/pulse] delay = 0.000000
[cplayer] = 145.658776 - 1.000000 * 0.265760
[cplayer] starting audio playback
[ao/pulse] delay = 0.000000
[cplayer] = 145.658776 - 1.000000 * 0.265760
[cplayer] current audio pts 145.393016
[ao/pulse] delay = 0.000000
[vo/gpu/x11] Disabling screensaver.
[cplayer] playback restart complete @ 145.393016, audio=playing, video=eof
[ao/pulse] starting AO
[ao/pulse] delay = 7.116190
[cplayer] = 145.658776 - 1.000000 * 7.281950
[cplayer] current audio pts 138.376826
[ao/pulse] delay = 7.116190
[ao/pulse] delay = 0.160249
[cplayer] = 145.763265 - 1.000000 * 0.371927
[cplayer] current audio pts 145.391338
[ao/pulse] delay = 0.160228
[ao/pulse] delay = 0.159251
[cplayer] = 145.763265 - 1.000000 * 0.370929
[cplayer] current audio pts 145.392336
[ao/pulse] delay = 0.158261
[cplayer] = 145.763265 - 1.000000 * 0.369939
[cplayer] current audio pts 145.393326
[ao/pulse] delay = 0.157272
[cplayer] = 145.763265 - 1.000000 * 0.368950
[cplayer] current audio pts 145.394315
[ao/pulse] delay = 0.156274
[cplayer] = 145.763265 - 1.000000 * 0.367952
[cplayer] current audio pts 145.395313

The [cplayer] lines are from how mpv determines the current playback position. The [ao/pulse] one is self-explanatory.
Even though the bogus value is returned just once, when doing consecutive seeks that value will be the one mpv bases its next seek off causing it to go wrong.

Since the latency calculation is wrong, --pulse-latency-hacks=yes unsurprisingly fixes this bug.
@avih suggested that the bug depends on audio output being repeatedly being turned on/off, --audio-stream-silence=yes also gets rid of the bug so that seems to be the root cause.

Finally since I this bug has only started happening to me recently I suspect it's a regression in PulseAudio 16.

[Traneptora]

@sfan5 can you reproduce it with pipewire-pulse?

[sfan5]

I could test this with PipeWire but I don't see how that's any useful.

[Traneptora]

Because then it would allow us to fully determine if it's a PulseAudio bug.

[gourdcaptain]

FYI, I just experienced this bug on Arch Linux with Pulseaudio 16.1, switching to Pipewire 0.3.58 seems to have fixed it.