GNOME Bugzilla – Bug 764120
audiosink: doesn't wait for ringbuffer to drain on EOS with sync=false
Last modified: 2018-11-03 11:45:58 UTC
Created attachment 324653 [details] concat cuttoff last part of second source Concat element somehow cuts off 2 seconds of end of second input. This can be triggered out by analysing output of this pipeline: gst-launch-1.0 concat name=c audiotestsrc num-buffers=200 ! queue ! c. audiotestsrc num-buffers=200 volume=0.5 ! queue ! c. c. ! alsasink buffer-time=1000000 sync=false The bug is easily reproducible and it happens every time. I use branch 1.6 from 15.3 (gstreamer - commit c5ad081b9 about baseparse) I recorded output of soundcard with audacity and I see that last part of second source (with volume 0.5) is much shorter than first source. Both audiotestsrc has num-buffers=200 so they should be equal.
The bug is reproducible on master as well. Did checkout and compile just now.
Ideally you could add a unit test for this in tests/check/elements/concat.c :) Without audiotestsrc though, just manually created buffers and segments as the other tests there.
I just found out that this is not caused by concat but by alsasink itself. It is reproducible with this pipeline: gst-launch-1.0 filesrc location=/tmp/t.wav ! wavparse ! queue name=qsink ! identity silent=false name=insink ! alsasink -v buffer-time=1000000 sync=false Or this simpler pipeline (but harder to check if the cutoff happend): gst-launch-1.0 audiotestsrc num-buffers=200 ! queue name=qsink ! identity silent=false name=insink ! alsasink -v buffer-time=1000000 sync=false This is the end of processing pipeline (identity debug logs). We see that last buffer was 05.00 the pipeline however played only for ~ 3 seconds: /GstPipeline:pipeline0/GstIdentity:insink: last-message = chain ******* (insink:sink) (4096 bytes, dts: none, pts:0:00:04.620770975, duration: 0:00:00.023219954, offset: 203776, offset_end: 204800, flags: 00000000 ) 0x7f52c80168f0 /GstPipeline:pipeline0/GstIdentity:insink: last-message = event ******* (insink:sink) E (type: eos (28174), ) 0x237a6e0 Got EOS from element "pipeline0". Execution ended after 0:00:02.911121411 Setting pipeline to PAUSED ... Setting pipeline to READY ... Setting pipeline to NULL ... Freeing pipeline ... I see in logs that the buffers were commited into ringbuffer, but suddenly the ringbuffer was "starting ringbuffer" and the elements were going to pause state. 0:00:02.956686797 29179 0x2382190 DEBUG audiobasesink gstaudiobasesink.c:2174:gst_audio_base_sink_render:<alsasink0> wrote 1024 of 1024 0:00:04.620770975 0:00:02.956692797 29179 0x2382190 DEBUG audiobasesink gstaudiobasesink.c:2206:gst_audio_base_sink_render:<alsasink0> next sample expected at 216274 0:00:02.956739505 29179 0x2382190 DEBUG ringbuffer gstaudioringbuffer.c:912:gst_audio_ring_buffer_start:<audiosinkringbuffer0> starting ringbuffer 0:00:02.956743747 29179 0x2382190 DEBUG ringbuffer gstaudioringbuffer.c:929:gst_audio_ring_buffer_start:<audiosinkringbuffer0> was not stopped, try paused 0:00:02.956746429 29179 0x2382190 DEBUG ringbuffer gstaudioringbuffer.c:937:gst_audio_ring_buffer_start:<audiosinkringbuffer0> was not paused, must have been started 0:00:02.956750747 29179 0x2382190 DEBUG ringbuffer gstaudioringbuffer.c:912:gst_audio_ring_buffer_start:<audiosinkringbuffer0> starting ringbuffer 0:00:02.956753360 29179 0x2382190 DEBUG ringbuffer gstaudioringbuffer.c:929:gst_audio_ring_buffer_start:<audiosinkringbuffer0> was not stopped, try paused 0:00:02.956755822 29179 0x2382190 DEBUG ringbuffer gstaudioringbuffer.c:937:gst_audio_ring_buffer_start:<audiosinkringbuffer0> was not paused, must have been started 0:00:02.956772776 29179 0x2382190 INFO task gsttask.c:315:gst_task_func:<qsink:src> Task going to paused 0:00:02.956834841 29179 0x2174e00 DEBUG audiobasesink gstaudiobasesink.c:575:gst_audio_base_sink_get_time:<alsasink0> processed samples: raw 172872, delay 44381, real 128491, time 0:00:02.913 628117 0:00:02.956855473 29179 0x2174e00 INFO GST_STATES gstbin.c:2243:gst_bin_element_set_state:<alsasink0> current PLAYING pending VOID_PENDING, desired next PAUSED 0:00:02.956866248 29179 0x2174e00 LOG ringbuffer gstaudioringbuffer.c:1951:gst_audio_ring_buffer_may_start:<audiosinkringbuffer0> may start: 0 0:00:02.956870062 29179 0x2174e00 DEBUG ringbuffer gstaudioringbuffer.c:991:gst_audio_ring_buffer_pause_unlocked:<audiosinkringbuffer0> pausing ringbuffer 0:00:02.956872926 29179 0x2174e00 DEBUG ringbuffer gstaudioringbuffer.c:1001:gst_audio_ring_buffer_pause_unlocked:<audiosinkringbuffer0> signal waiter 0:00:02.956875665 29179 0x2174e00 DEBUG audiosink gstaudiosink.c:553:gst_audio_sink_ring_buffer_pause:<alsasink0> reset...
Created attachment 324662 [details] testing audio with marks on beginning&end Adding testing file for reproducing the bug.
Created attachment 324665 [details] log of mentioned pipeline The log was created with pipe: GST_DEBUG_FILE=asink_cutoff.log GST_DEBUG=4,ringbuffer:7,audiobasesink:7,queue:7,queue_dataflow:5,audiosink:7 gst-launch-1.0 audiotestsrc num-buffers=200 ! queue name=qsink ! identity silent=false name=insink ! alsasink -v buffer-time=1000000 sync=false At the end it is visible that the ringbuffer goes suddenly into "starting ringbuffer" at 0:00:03.116732688
Waiting for the time needed to drain the ring buffer waits an additional ~1 second, but this isn't enough. There seems to be two seconds' worth of missing audio in the first place, so there's stil one second missing after the change, and I'm not sure where that is coming from.
Created attachment 330197 [details] [review] fix missing samples at EOS with sync=0 Got it.
-- GitLab Migration Automatic Message -- This bug has been migrated to freedesktop.org's GitLab instance and has been closed from further activity. You can subscribe and participate further through the new bug through this link to our GitLab instance: https://gitlab.freedesktop.org/gstreamer/gst-plugins-base/issues/262.