pulsesink underflow after GAP buffers
Describe your issue
i'm using a pipeline similar to:
gst-launch-1.0 audiotestsrc ! audioconvert ! volume mute=true ! autoaudiosink
in the real-world application, the mute
property is changed by users, the audio sink is pulseaudio. when the stream is muted, GAP buffers are delivered, however the pulseaudio stream is not stopped, causing buffer underruns:
0:00:01.163764186 104820 0x51d00007c920 DEBUG audiobasesink gstaudiobasesink.c:1898:gst_audio_base_sink_render:<audiosink> Received GAP or ignoring audio for trickplay. Dropping contents
0:00:01.163840218 104820 0x51d00007c920 DEBUG audiobasesink gstaudiobasesink.c:1898:gst_audio_base_sink_render:<audiosink> Received GAP or ignoring audio for trickplay. Dropping contents
0:00:01.163877567 104820 0x51d00007c920 DEBUG audiobasesink gstaudiobasesink.c:1898:gst_audio_base_sink_render:<audiosink> Received GAP or ignoring audio for trickplay. Dropping contents
0:00:01.176157033 104820 0x51900013b320 LOG pulse pulsesink.c:686:gst_pulsering_stream_request_cb:<audiosink> got request for length 102144
0:00:01.176184555 104820 0x51900013b320 LOG pulse pulsesink.c:686:gst_pulsering_stream_request_cb:<audiosink> got request for length 126720
0:00:01.176327014 104820 0x51900013b320 WARN pulse pulsesink.c:704:gst_pulsering_stream_underflow_cb:<audiosink> Got underflow
0:00:01.176340212 104820 0x51900013b320 LOG pulse pulsesink.c:686:gst_pulsering_stream_request_cb:<audiosink> got request for length 144792
after un-muting the stream, the audio still doesn't restart, i'm seeing these logs after unmuting:
0:00:02.054182925 104820 0x51900013b320 LOG pulse pulsesink.c:686:gst_pulsering_stream_request_cb:<audiosink> got request for length 1153512
0:00:02.055447484 104820 0x51d00007c920 DEBUG audiobasesink gstaudiobasesink.c:1915:gst_audio_base_sink_render:<audiosink> time 0:00:23.509333333, start 0:00:00.000000000, samples 1024
0:00:02.055555508 104820 0x51d00007c920 DEBUG audiobasesink gstaudiobasesink.c:1952:gst_audio_base_sink_render:<audiosink> sync-offset +0:00:00.130000000, render-delay 0:00:00.000000000, ts-offset +0:00:00.000000000
0:00:02.055636138 104820 0x51d00007c920 DEBUG audiobasesink gstaudiobasesink.c:2017:gst_audio_base_sink_render:<audiosink> running: start 0:00:23.509333333 - stop 0:00:23.530666666
0:00:02.055669802 104820 0x51d00007c920 DEBUG audiobasesink gstaudiobasesink.c:2032:gst_audio_base_sink_render:<audiosink> compensating for sync-offset 0:00:00.130000000
0:00:02.055699969 104820 0x51d00007c920 DEBUG audiobasesink gstaudiobasesink.c:2039:gst_audio_base_sink_render:<audiosink> adding base_time 23:30:57.206706165
0:00:02.055754512 104820 0x51d00007c920 LOG pulse pulsesink.c:2043:gst_pulsesink_get_time:<audiosink> current time is 0:00:01.310718000
0:00:02.055832376 104820 0x51d00007c920 DEBUG audiobasesink gstaudiobasesink.c:1440:gst_audio_base_sink_skew_slaving:<audiosink> internal 0:00:01.310718000 external 23:30:58.547219106 cinternal 0:00:00.000000000 cexternal 23:30:57.226706165
0:00:02.055899044 104820 0x51d00007c920 DEBUG audiobasesink gstaudiobasesink.c:1461:gst_audio_base_sink_skew_slaving:<audiosink> internal 0:00:01.310718000 external 0:00:01.320512941 skew -0:00:00.009794941 avg -0:00:00.003105518
0:00:02.055950885 104820 0x51d00007c920 DEBUG audiobasesink gstaudiobasesink.c:2059:gst_audio_base_sink_render:<audiosink> final timestamps: start 0:00:23.619333333 - stop 0:00:23.640666666
0:00:02.055973724 104820 0x51d00007c920 DEBUG audiobasesink gstaudiobasesink.c:2128:gst_audio_base_sink_render:<audiosink> no align possible: no previous sample position known
0:00:02.056016744 104820 0x51d00007c920 DEBUG audiobasesink gstaudiobasesink.c:2157:gst_audio_base_sink_render:<audiosink> rendering at 1133727 1024/1024
0:00:02.056041526 104820 0x51d00007c920 DEBUG pulse pulsesink.c:1489:gst_pulseringbuffer_commit:<audiosink> entering commit
0:00:02.056067644 104820 0x51d00007c920 DEBUG pulse pulsesink.c:1507:gst_pulseringbuffer_commit:<audiosink> in 1023, out 1023
0:00:02.056113439 104820 0x51d00007c920 LOG pulse pulsesink.c:1530:gst_pulseringbuffer_commit:<audiosink> need to write 1024 samples at offset 27209448
0:00:02.056141119 104820 0x51d00007c920 LOG pulse pulsesink.c:1534:gst_pulseringbuffer_commit:<audiosink> discontinuity, offset is 27209448, last offset was 593664
0:00:02.056166455 104820 0x51d00007c920 LOG pulse pulsesink.c:1599:gst_pulseringbuffer_commit:<audiosink> requesting 24576 bytes of shared memory
0:00:02.056194909 104820 0x51d00007c920 LOG pulse pulsesink.c:1608:gst_pulseringbuffer_commit:<audiosink> got 24576 bytes of shared memory
0:00:02.056220691 104820 0x51d00007c920 LOG pulse pulsesink.c:1617:gst_pulseringbuffer_commit:<audiosink> writing 1024 samples at offset 27209448
0:00:02.056254005 104820 0x51d00007c920 LOG pulse pulsesink.c:1670:gst_pulseringbuffer_commit:<audiosink> flushing 1024 samples at offset 27209448
0:00:02.056306651 104820 0x51d00007c920 LOG pulse pulsesink.c:1714:gst_pulseringbuffer_commit:<audiosink> wrote 1024 samples
0:00:02.056333299 104820 0x51d00007c920 DEBUG audiobasesink gstaudiobasesink.c:2168:gst_audio_base_sink_render:<audiosink> wrote 1024 of 1024
0:00:02.056355874 104820 0x51d00007c920 DEBUG audiobasesink gstaudiobasesink.c:2200:gst_audio_base_sink_render:<audiosink> next sample expected at 1134751
0:00:02.056615922 104820 0x51d00007c920 DEBUG audiobasesink gstaudiobasesink.c:1915:gst_audio_base_sink_render:<audiosink> time 0:00:23.530666666, start 0:00:00.000000000, samples 1024
0:00:02.056669625 104820 0x51d00007c920 DEBUG audiobasesink gstaudiobasesink.c:1952:gst_audio_base_sink_render:<audiosink> sync-offset +0:00:00.130000000, render-delay 0:00:00.000000000, ts-offset +0:00:00.000000000
0:00:02.056712577 104820 0x51d00007c920 DEBUG audiobasesink gstaudiobasesink.c:2017:gst_audio_base_sink_render:<audiosink> running: start 0:00:23.530666666 - stop 0:00:23.551999999
0:00:02.056741251 104820 0x51d00007c920 DEBUG audiobasesink gstaudiobasesink.c:2032:gst_audio_base_sink_render:<audiosink> compensating for sync-offset 0:00:00.130000000
0:00:02.056748130 104820 0x51900013b320 WARN pulse pulsesink.c:716:gst_pulsering_stream_overflow_cb:<audiosink> Got overflow
0:00:02.056781653 104820 0x51d00007c920 DEBUG audiobasesink gstaudiobasesink.c:2039:gst_audio_base_sink_render:<audiosink> adding base_time 23:30:57.206706165
0:00:02.056851418 104820 0x51d00007c920 LOG pulse pulsesink.c:2043:gst_pulsesink_get_time:<audiosink> current time is 0:00:01.311823000
0:00:02.056899751 104820 0x51d00007c920 DEBUG audiobasesink gstaudiobasesink.c:1440:gst_audio_base_sink_skew_slaving:<audiosink> internal 0:00:01.311823000 external 23:30:58.548328319 cinternal 0:00:00.000000000 cexternal 23:30:57.226706165
0:00:02.057021571 104820 0x51d00007c920 DEBUG audiobasesink gstaudiobasesink.c:1461:gst_audio_base_sink_skew_slaving:<audiosink> internal 0:00:01.311823000 external 0:00:01.321622154 skew -0:00:00.009799154 avg -0:00:00.003314694
0:00:02.057066906 104820 0x51d00007c920 DEBUG audiobasesink gstaudiobasesink.c:2059:gst_audio_base_sink_render:<audiosink> final timestamps: start 0:00:23.640666666 - stop 0:00:23.661999999
0:00:02.057094870 104820 0x51d00007c920 DEBUG audiobasesink gstaudiobasesink.c:1793:gst_audio_base_sink_get_alignment:<audiosink> align with prev sample, ABS (0) < 1920
0:00:02.057122421 104820 0x51d00007c920 DEBUG audiobasesink gstaudiobasesink.c:2157:gst_audio_base_sink_render:<audiosink> rendering at 1134751 1024/1024
0:00:02.057145790 104820 0x51d00007c920 DEBUG pulse pulsesink.c:1489:gst_pulseringbuffer_commit:<audiosink> entering commit
0:00:02.057170722 104820 0x51d00007c920 DEBUG pulse pulsesink.c:1507:gst_pulseringbuffer_commit:<audiosink> in 1023, out 1023
0:00:02.057196645 104820 0x51d00007c920 LOG pulse pulsesink.c:1530:gst_pulseringbuffer_commit:<audiosink> need to write 1024 samples at offset 27234024
0:00:02.057221311 104820 0x51d00007c920 LOG pulse pulsesink.c:1599:gst_pulseringbuffer_commit:<audiosink> requesting 24576 bytes of shared memory
0:00:02.057247065 104820 0x51d00007c920 LOG pulse pulsesink.c:1608:gst_pulseringbuffer_commit:<audiosink> got 24576 bytes of shared memory
0:00:02.057272050 104820 0x51d00007c920 LOG pulse pulsesink.c:1617:gst_pulseringbuffer_commit:<audiosink> writing 1024 samples at offset 27234024
0:00:02.057303191 104820 0x51d00007c920 LOG pulse pulsesink.c:1670:gst_pulseringbuffer_commit:<audiosink> flushing 1024 samples at offset 27234024
0:00:02.057335389 104820 0x51d00007c920 LOG pulse pulsesink.c:1714:gst_pulseringbuffer_commit:<audiosink> wrote 1024 samples
0:00:02.057419933 104820 0x51d00007c920 DEBUG audiobasesink gstaudiobasesink.c:2168:gst_audio_base_sink_render:<audiosink> wrote 1024 of 1024
0:00:02.057446944 104820 0x51d00007c920 DEBUG audiobasesink gstaudiobasesink.c:2200:gst_audio_base_sink_render:<audiosink> next sample expected at 1135775
0:00:02.059073518 104820 0x51900013b320 LOG pulse pulsesink.c:759:gst_pulsering_stream_latency_cb:<audiosink> latency_update, 1710207379174291000, 0:27258600, 0:1624224, 96972, 90000
0:00:02.059190111 104820 0x51900013b320 WARN pulse pulsesink.c:716:gst_pulsering_stream_overflow_cb:<audiosink> Got overflow
0:00:02.059578777 104820 0x51900013b320 LOG pulse pulsesink.c:759:gst_pulsering_stream_latency_cb:<audiosink> latency_update, 1710207379174821000, 0:27258600, 0:1624224, 96405, 90000
0:00:02.070257356 104820 0x51900013b320 LOG pulse pulsesink.c:759:gst_pulsering_stream_latency_cb:<audiosink> latency_update, 1710207379185474000, 0:27258600, 0:1624224, 85806, 90000
0:00:02.090887548 104820 0x51900013b320 LOG pulse pulsesink.c:759:gst_pulsering_stream_latency_cb:<audiosink> latency_update, 1710207379206127000, 0:27258600, 0:1624224, 65158, 90000
0:00:02.096729165 104820 0x51d00007c920 DEBUG audiobasesink gstaudiobasesink.c:1915:gst_audio_base_sink_render:<audiosink> time 0:00:23.552000000, start 0:00:00.000000000, samples 1024
0:00:02.096791441 104820 0x51d00007c920 DEBUG audiobasesink gstaudiobasesink.c:1952:gst_audio_base_sink_render:<audiosink> sync-offset +0:00:00.130000000, render-delay 0:00:00.000000000, ts-offset +0:00:00.000000000
0:00:02.096856520 104820 0x51d00007c920 DEBUG audiobasesink gstaudiobasesink.c:2017:gst_audio_base_sink_render:<audiosink> running: start 0:00:23.552000000 - stop 0:00:23.573333333
0:00:02.096885293 104820 0x51d00007c920 DEBUG audiobasesink gstaudiobasesink.c:2032:gst_audio_base_sink_render:<audiosink> compensating for sync-offset 0:00:00.130000000
0:00:02.096905315 104820 0x51d00007c920 DEBUG audiobasesink gstaudiobasesink.c:2039:gst_audio_base_sink_render:<audiosink> adding base_time 23:30:57.206706165
0:00:02.096940180 104820 0x51d00007c920 LOG pulse pulsesink.c:2043:gst_pulsesink_get_time:<audiosink> current time is 0:00:01.351951000
most notably there are gst_pulsering_stream_overflow_cb
warnings, as probably data is delivered too late.
Expected Behavior
Muted
streams should probably feed silence into the pulseaudio sink, or pause/cork(?) the sink.
Observed Behavior
Once the pulsesink is muted, it cannot be unmuted anymore.
Setup
- Ubuntu 22.04
- GStreamer 1.23.2
Steps to reproduce the bug
reproducer attached to https://bugreports.qt.io/browse/QTBUG-123180
How reproducible is the bug?
Always reproducible when mute/unmute is toggled every second. when toggled every 10s, the issue disappears (probably the pulseaudio backend will consider the stream dead after a specific period and restart it?)
Solutions you have tried
Setting a sufficiently small volume to be below 24bit resolution rather than mute / volume=0 on volume