Missing EOS with qtdemux
Describe your issue
A pipeline qtdemux -> queue -> mp4mux
can get stuck in scenarios where the audio video track lengths are not equal. (Not sure what a good title would be here)
Expected Behavior
Pipeline should not stall irrespective of the input stream
Observed Behavior
Pipeline stalls depending on input stream
Setup
- Operating System: Arch Linux
- Device: Computer
- GStreamer Version: 1.20.1
-
Command line:
gst-inspect-1.0 --version
Steps to reproduce the bug
Generate a test video with
gst-launch-1.0 -e -v mp4mux name=m ! filesink location=video-qtdemux.mp4 sync=true \
videotestsrc ! video/x-raw,width=1920,height=1080,framerate=20/1 ! queue ! videorate ! x264enc bframes=0 ! video/x-h264,framerate=20/1 ! h264parse ! m.video_0 \
audiotestsrc ! queue ! fdkaacenc ! audio/mpeg,rate=48000,channels=2,stream-format=raw ! aacparse ! m.audio_0
Now run the below pipeline. The below pipeline hangs unless max-size-time=0
is set on the video_queue
.
GST_DEBUG=3 gst-launch-1.0 -e \
filesrc location=video-qtdemux.mp4 ! qtdemux name=d \
mp4mux name=m ! filesink location=video-qtdemux-fixed.mp4 \
d.video_0 ! queue name=video_queue ! h264parse ! m.video_0 \
d.audio_0 ! queue name=audio_queue ! aacparse ! m.audio_0
Testing with latest main
and attaching with GDB shows
- The
mux
source thread stuck ingst_aggregator_wait_and_check:841
-
qtdemux
stuck ingst_qtdemux_loop:6682
having pushed through and stuck ingst_queue_chain_buffer_or_list:1251
- Audio queue is stuck in
gst_queue_loop
and is empty - Video queue stuck with back trace
gst_queue_loop:1541 (...) gst_aggregator_pad_chain_internal:3072
. It is not empty and has the stats
cur_level = {
buffers = 20,
bytes = 257902,
time = 1000000000
},
max_size = {
buffers = 200,
bytes = 10485760,
time = 1000000000
},
and being considered full due to time.
How reproducible is the bug?
Consistent.
Screenshots if relevant
Excerpt from the log where it stalls
0:00:01.982514010 114822 0x55d8b6164580 LOG qtdemux qtdemux.c:5197:gst_qtdemux_prepare_current_sample:<d> segment active, index = 4259 of 4292
0:00:01.982516856 114822 0x55d8b6164580 LOG qtdemux qtdemux.c:9634:qtdemux_parse_samples:<d> parsing samples for stream fourcc avc1, pad video_0
0:00:01.982519120 114822 0x55d8b6164580 LOG qtdemux qtdemux.c:10029:qtdemux_parse_samples:<d> Tried to parse up to sample 4259 but this sample has already been parsed
0:00:01.982526323 114822 0x55d8b6164580 DEBUG qtdemux qtdemux.c:6469:gst_qtdemux_loop_state_movie:<d> pushing from track-id 1, empty 0 offset 63038656, size 12436, dts=0:03:32.950000000, pts=0:03:32.950000000, duration 0:00:00.050000000
0:00:01.982528848 114822 0x55d8b6164580 LOG qtdemux qtdemux.c:6573:gst_qtdemux_loop_state_movie:<d> reading 12436 bytes @ 63038656
0:00:01.982542785 114822 0x55d8b6164580 LOG qtdemux qtdemux.c:5377:gst_qtdemux_sync_streams:<d> current position: 0:03:32.950000000, stream end: 0:03:31.797500000, demux seg pos: 0:03:32.950000000
0:00:01.982547293 114822 0x55d8b6164580 LOG qtdemux qtdemux.c:5869:gst_qtdemux_push_buffer:<d> Pushing buffer with dts 0:03:32.950000000, pts 0:03:32.950000000, duration 0:00:00.050000000 on pad video_0
0:00:01.982551521 114822 0x55d8b6164580 LOG queue_dataflow gstqueue.c:1204:gst_queue_chain_buffer_or_list:<video_queue> received buffer 0x7fb57804eb40 of size 12436, time 0:03:32.950000000, duration 0:00:00.050000000
0:00:01.982554968 114822 0x55d8b6164580 DEBUG queue_dataflow gstqueue.c:1245:gst_queue_chain_buffer_or_list:<video_queue> queue is full, waiting for free space
0:00:01.982559917 114822 0x55d8b6164580 LOG queue_dataflow gstqueue.c:1251:gst_queue_chain_buffer_or_list:<video_queue> (video_queue:sink) wait for DEL: 20 of 0-200 buffers, 257902 of 0-10485760 bytes, 1000000000 of 0-1000000000 ns, 20 items
In the case when max-size-time=0
is used on the video queue, the EOS can be seen for the audio stream. Note the difference in active segment index here and above.
0:00:02.080051516 114985 0x55fece49b180 LOG qtdemux qtdemux.c:5197:gst_qtdemux_prepare_current_sample:<d> segment active, index = 4276 of 4292
0:00:02.080053419 114985 0x55fece49b180 LOG qtdemux qtdemux.c:9634:qtdemux_parse_samples:<d> parsing samples for stream fourcc avc1, pad video_0
0:00:02.080054862 114985 0x55fece49b180 LOG qtdemux qtdemux.c:10029:qtdemux_parse_samples:<d> Tried to parse up to sample 4276 but this sample has already been parsed
0:00:02.080058639 114985 0x55fece49b180 DEBUG qtdemux qtdemux.c:6469:gst_qtdemux_loop_state_movie:<d> pushing from track-id 1, empty 0 offset 63260745, size 12412, dts=0:03:33.800000000, pts=0:03:33.800000000, duration 0:00:00.050000000
0:00:02.080060282 114985 0x55fece49b180 LOG qtdemux qtdemux.c:6573:gst_qtdemux_loop_state_movie:<d> reading 12412 bytes @ 63260745
0:00:02.080070982 114985 0x55fece49b180 LOG qtdemux qtdemux.c:5377:gst_qtdemux_sync_streams:<d> current position: 0:03:33.800000000, stream end: 0:03:31.797500000, demux seg pos: 0:03:33.800000000
0:00:02.080072936 114985 0x55fece49b180 DEBUG qtdemux qtdemux.c:5385:gst_qtdemux_sync_streams:<d> sending EOS for stream audio_0
Solutions you have tried
Setting max-size-time=0
fixes it. Is it recommended having max-size-*
property disabled for cases like this?
Related non-duplicate issues
Additional Information
It seems due to the below condition
if (GST_CLOCK_TIME_IS_VALID (end_time)
&& (end_time + 2 * GST_SECOND < demux->segment.position)) {
there is a window of time before the EOS is sent out for the audio stream in the test case above, but by then the downstream queue
has already stalled. EDIT: Checking with git blame
this seems to have been introduced with 3360f449 and describes the exact issue we are running into here. Changing the above condition to use a gap of 1 second, also makes the test pipeline work.