Underflow when seeking forward in gstreamer-based applications
- PipeWire version (
pipewire --version): 0.3.43 - Distribution and distribution version (
PRETTY_NAMEfrom/etc/os-release): Fedora 35 - Desktop Environment: KDE Plasma 5.23.3
- Kernel version (
uname -r): 5.15.12 - USB audio devices:
Bus 002 Device 004: ID 20b1:306a XMOS Ltd m9XX - gstreamer version: gstreamer1-1.19.3
Description of Problem:
Seeking forward in applications that use gstreamer results in an underflow which causes a small skip in the audio playback.
How Reproducible:
Always.
Steps to Reproduce:
- Play audio file using a gstreamer-based application (e.g. lollypop or Elisa)
- Seek forward
Actual Results:
There is an audible skip immediately after seeking forward.
Expected Results:
Seamless audio playback after seeking forward.
Additional Information:
@pobrn has looked into this issue in more detail while troubleshooting #1956 (closed) which is a different (and now fixed) bug.
I have copied the content of their original comment below:
gstreamer seems to "rewind" the stream somewhat hence almost every seek in Lollypop leads to an underflow, that is what can be heard, as far as I can tell.
The first memblock after the flush causes lots of samples to be dropped, inevitably leading to the underflow.
handle_memblock(stream=0x618000003880): (seek=1, offs=728056, diff=0)
handle_memblock(stream=0x618000003880): received 9216 bytes
handle_memblock(stream=0x618000003880): (w=737272, r=662552, delta=74720)
handle_memblock(stream=0x618000003880): (req=2896, miss=0)
handle_memblock(stream=0x618000003880): done
[I][77306.121347] mod.protocol-pulse | [ pulse-server.c: 2503 do_cork_stream()] [Lollypop] CORK_PLAYBACK_STREAM tag:68 channel:0 cork:yes
[I][77306.122745] mod.protocol-pulse | [ pulse-server.c: 2534 do_flush_trigger_prebuf_stream()] [Lollypop] FLUSH_PLAYBACK_STREAM tag:71 channel:0
[I][77306.122973] pw.stream | [ stream.c: 550 impl_send_command()] 0x62100003fd00: command Spa:Pod:Object:Command:Node:Flush
stream_pop_missing(stream=0x618000003880): stream->missing=35912
stream_send_request(stream=0x618000003880): size = 35912
[I][77306.123960] pw.stream | [ stream.c: 550 impl_send_command()] 0x62100003fd00: command Spa:Pod:Object:Command:Node:Pause
[I][77306.124421] pw.node | [ impl-node.c: 377 node_update_state()] (Lollypop-0) running -> idle
handle_memblock(stream=0x618000003880): (seek=1, offs=614536, diff=-48016)
handle_memblock(stream=0x618000003880): received 9216 bytes
handle_memblock(stream=0x618000003880): (w=623752, r=662552, delta=-38800)
handle_memblock(stream=0x618000003880): (req=29592, miss=48016)
handle_memblock(stream=0x618000003880): donempv also does cork-flush-uncork when seeking (it uses relative seeking, though), however, in mpv's case the diff remains zero; and no underflow.
gstreamer logs show the following:
0:00:06.398894825 0x55c6c0801ea0 LOG pulse pulsesink.c:1615:gst_pulseringbuffer_commit:<autoaudiosink0-actual-sink-pulse> writing 1152 samples at offset 728056
0:00:06.398931669 0x55c6c0801ea0 LOG pulse pulsesink.c:1668:gst_pulseringbuffer_commit:<autoaudiosink0-actual-sink-pulse> flushing 1152 samples at offset 728056
0:00:06.398975928 0x55c6c0801ea0 LOG pulse pulsesink.c:1713:gst_pulseringbuffer_commit:<autoaudiosink0-actual-sink-pulse> wrote 1152 samples
0:00:06.399144760 0x55c6c0801ea0 DEBUG pulse pulsesink.c:1488:gst_pulseringbuffer_commit:<autoaudiosink0-actual-sink-pulse> entering commit
0:00:06.399183139 0x55c6c0801ea0 DEBUG pulse pulsesink.c:1506:gst_pulseringbuffer_commit:<autoaudiosink0-actual-sink-pulse> in 1151, out 1151
0:00:06.399220177 0x55c6c0801ea0 LOG pulse pulsesink.c:1527:gst_pulseringbuffer_commit:<autoaudiosink0-actual-sink-pulse> need to write 1152 samples at offset 737272
0:00:06.399247570 0x55c6c0801ea0 LOG pulse pulsesink.c:1585:gst_pulseringbuffer_commit:<autoaudiosink0-actual-sink-pulse> waiting for free space
0:00:06.439454912 0x55c6bfdfdc30 DEBUG pulse pulsesink.c:1266:gst_pulseringbuffer_pause:<autoaudiosink0-actual-sink-pulse> pausing and corking
0:00:06.439506809 0x55c6bfdfdc30 DEBUG pulse pulsesink.c:1131:gst_pulsering_set_corked:<autoaudiosink0-actual-sink-pulse> setting corked state to 1
0:00:06.440038372 0x55c6c07ac4f0 LOG pulse pulsesink.c:753:gst_pulsering_stream_latency_cb:<autoaudiosink0-actual-sink-pulse> latency_update, 1640812874375693000, 0:737272, 0:662552, 85333, 90000
0:00:06.440202457 0x55c6c07ac4f0 LOG pulse pulsesink.c:753:gst_pulsering_stream_latency_cb:<autoaudiosink0-actual-sink-pulse> latency_update, 1640812874375811000, 0:737272, 0:662552, 85333, 90000
0:00:06.440264258 0x55c6c0801ea0 LOG pulse pulsesink.c:1745:gst_pulseringbuffer_commit:<autoaudiosink0-actual-sink-pulse> we are paused
0:00:06.440335494 0x55c6c0801ea0 LOG pulse pulsesink.c:1713:gst_pulseringbuffer_commit:<autoaudiosink0-actual-sink-pulse> wrote 0 samples
0:00:06.440498868 0x55c6bfdfdc30 LOG pulse pulsesink.c:2041:gst_pulsesink_get_time:<autoaudiosink0-actual-sink-pulse> current time is 0:00:01.741884000
0:00:06.440918644 0x55c6bfdfdc30 DEBUG pulse pulsesink.c:1180:gst_pulseringbuffer_clear:<autoaudiosink0-actual-sink-pulse> clearing
0:00:06.441670990 0x55c6c07ac4f0 LOG pulse pulsesink.c:753:gst_pulsering_stream_latency_cb:<autoaudiosink0-actual-sink-pulse> latency_update, 1640812874377087000, 1:737272, 0:662552, 85333, 90000
0:00:06.441789499 0x55c6c07ac4f0 LOG pulse pulsesink.c:685:gst_pulsering_stream_request_cb:<autoaudiosink0-actual-sink-pulse> got request for length 38808
0:00:06.441954520 0x55c6c07ac4f0 LOG pulse pulsesink.c:753:gst_pulsering_stream_latency_cb:<autoaudiosink0-actual-sink-pulse> latency_update, 1640812874377463000, 0:662552, 0:662552, 85333, 90000
0:00:06.442072559 0x55c6c0982e40 LOG pulse pulsesink.c:2041:gst_pulsesink_get_time:<autoaudiosink0-actual-sink-pulse> current time is 0:00:01.741884000
0:00:06.442835241 0x55c6c0801ea0 DEBUG pulse pulsesink.c:1481:gst_pulseringbuffer_commit:<pulseringbuffer1> start!
0:00:06.442894682 0x55c6c0801ea0 DEBUG pulse pulsesink.c:1226:gst_pulseringbuffer_start:<autoaudiosink0-actual-sink-pulse> starting
0:00:06.442930773 0x55c6c0801ea0 DEBUG pulse pulsesink.c:1488:gst_pulseringbuffer_commit:<autoaudiosink0-actual-sink-pulse> entering commit
0:00:06.442968036 0x55c6c0801ea0 DEBUG pulse pulsesink.c:1506:gst_pulseringbuffer_commit:<autoaudiosink0-actual-sink-pulse> in 1151, out 1151
0:00:06.443004518 0x55c6c0801ea0 LOG pulse pulsesink.c:1527:gst_pulseringbuffer_commit:<autoaudiosink0-actual-sink-pulse> need to write 1152 samples at offset 614536
0:00:06.443040764 0x55c6c0801ea0 LOG pulse pulsesink.c:1532:gst_pulseringbuffer_commit:<autoaudiosink0-actual-sink-pulse> discontinuity, offset is 614536, last offset was 737272
0:00:06.443077002 0x55c6c0801ea0 LOG pulse pulsesink.c:1597:gst_pulseringbuffer_commit:<autoaudiosink0-actual-sink-pulse> requesting 9216 bytes of shared memory
0:00:06.443114150 0x55c6c0801ea0 LOG pulse pulsesink.c:1606:gst_pulseringbuffer_commit:<autoaudiosink0-actual-sink-pulse> got 9216 bytes of shared memory
0:00:06.443136814 0x55c6c0801ea0 LOG pulse pulsesink.c:1615:gst_pulseringbuffer_commit:<autoaudiosink0-actual-sink-pulse> writing 1152 samples at offset 614536
0:00:06.443158733 0x55c6c0801ea0 LOG pulse pulsesink.c:1668:gst_pulseringbuffer_commit:<autoaudiosink0-actual-sink-pulse> flushing 1152 samples at offset 614536
0:00:06.443202688 0x55c6c0801ea0 LOG pulse pulsesink.c:1688:gst_pulseringbuffer_commit:<autoaudiosink0-actual-sink-pulse> read_index at 662552, offset 623752
0:00:06.443238965 0x55c6c0801ea0 LOG pulse pulsesink.c:1713:gst_pulseringbuffer_commit:<autoaudiosink0-actual-sink-pulse> wrote 1152 samplesgstreamer says
0:00:06.443040764 [...] discontinuity, offset is 614536, last offset was 737272I do not know where the problem is; it could be pipewire, gstreamer, or even lollypop.