GNOME Bugzilla – Bug 774600
omx: Pipeline premature EOS after discontinuity on lossy transport stream
Last modified: 2016-12-22 12:48:24 UTC
When an attempt is made to transcode the following transport stream from h264 and back to h264 again for HLS encoding, the pipeline runs for approximately 1:33 or so before freezing / hanging on a Raspberry Pi 3: http://www.sharp.fm/glitch1.ts The above file is an MPEG transport stream containing h264 video that originates from DVB-T2, and am trying to transcode this with an element that has the effect of “decodebin ! encodebin”. The stream is demuxed and decoded with omxh264dec, and then reencoded with omxh264enc and remuxed before being written to an HLS stream. Raising the debug level seems to change when the freeze occurs. When it freezes the pipeline, omxh264enc says the following and then goes silent: 0:05:26.921029963 2774 0x73101d50 DEBUG omxvideoenc gstomxvideoenc.c:1692:gst_omx_video_enc_drain:<omxh264enc-omxh264enc0> Draining component 0:05:26.921240325 2774 0x73101d50 DEBUG omxvideoenc gstomxvideoenc.c:1738:gst_omx_video_enc_drain:<omxh264enc-omxh264enc0> Waiting until component is drained 0:05:26.922070629 2774 0x75714ac0 DEBUG omxvideodec gstomxvideodec.c:2178:gst_omx_video_dec_handle_frame:<omxh264dec-omxh264dec0> Handling frame 0:05:26.924129253 2774 0x73145400 DEBUG omxvideoenc gstomxvideoenc.c:753:gst_omx_video_enc_loop:<omxh264enc-omxh264enc0> Handling buffer: 0x00000480 0 0:05:26.924239825 2774 0x75714ac0 DEBUG omxvideodec gstomxvideodec.c:2178:gst_omx_video_dec_handle_frame:<omxh264dec-omxh264dec0> Handling frame 0:05:26.924242950 2774 0x73145400 DEBUG omxvideoenc gstomxvideoenc.c:762:gst_omx_video_enc_loop:<omxh264enc-omxh264enc0> Finished frame: ok 0:05:26.924531385 2774 0x73145400 DEBUG omxvideoenc gstomxvideoenc.c:770:gst_omx_video_enc_loop:<omxh264enc-omxh264enc0> Read frame from component 0:05:26.924573780 2774 0x73145400 DEBUG omxvideoenc gstomxvideoenc.c:753:gst_omx_video_enc_loop:<omxh264enc-omxh264enc0> Handling buffer: 0x00000490 0 0:05:26.924627790 2774 0x73145400 DEBUG omxvideoenc gstomxvideoenc.c:762:gst_omx_video_enc_loop:<omxh264enc-omxh264enc0> Finished frame: ok 0:05:26.924861589 2774 0x73145400 DEBUG omxvideoenc gstomxvideoenc.c:770:gst_omx_video_enc_loop:<omxh264enc-omxh264enc0> Read frame from component 0:05:26.924899402 2774 0x73145400 DEBUG omxvideoenc gstomxvideoenc.c:753:gst_omx_video_enc_loop:<omxh264enc-omxh264enc0> Handling buffer: 0x00000430 1482599921 0:05:26.924961536 2774 0x73145400 DEBUG omxvideoenc gstomxvideoenc.c:586:gst_omx_video_enc_handle_output_frame:<omxh264enc-omxh264enc0> Handling output data 0:05:26.925675123 2774 0x73145400 DEBUG omxvideoenc gstomxvideoenc.c:762:gst_omx_video_enc_loop:<omxh264enc-omxh264enc0> Finished frame: ok 0:05:26.926104754 2774 0x73145400 DEBUG omxvideoenc gstomxvideoenc.c:770:gst_omx_video_enc_loop:<omxh264enc-omxh264enc0> Read frame from component 0:05:26.926179857 2774 0x73145400 DEBUG omxvideoenc gstomxvideoenc.c:753:gst_omx_video_enc_loop:<omxh264enc-omxh264enc0> Handling buffer: 0x00000001 1482639921 0:05:26.926242565 2774 0x73145400 DEBUG omxvideoenc gstomxvideoenc.c:762:gst_omx_video_enc_loop:<omxh264enc-omxh264enc0> Finished frame: ok 0:05:26.926448604 2774 0x73145400 DEBUG omxvideoenc gstomxvideoenc.c:770:gst_omx_video_enc_loop:<omxh264enc-omxh264enc0> Read frame from component 0:05:26.926489698 2774 0x73145400 DEBUG omxvideoenc gstomxvideoenc.c:810:gst_omx_video_enc_loop:<omxh264enc-omxh264enc0> Drained 0:05:26.926540010 2774 0x73101d50 DEBUG omxvideoenc gstomxvideoenc.c:1740:gst_omx_video_enc_drain:<omxh264enc-omxh264enc0> Drained component omxh264dec keeps running, until eventually, sometimes within a second, sometimes many seconds later, omxh264dec also freezes and goes silent as follows: 0:06:05.580576707 2581 0x75614ac0 DEBUG omxvideodec gstomxvideodec.c:2178:gst_omx_video_dec_handle_frame:<omxh264dec-omxh264dec0> Handling frame 0:06:05.583004391 2581 0x75614ac0 DEBUG omxvideodec gstomxvideodec.c:2178:gst_omx_video_dec_handle_frame:<omxh264dec-omxh264dec0> Handling frame 0:06:05.585423220 2581 0x75614ac0 DEBUG omxvideodec gstomxvideodec.c:2178:gst_omx_video_dec_handle_frame:<omxh264dec-omxh264dec0> Handling frame 0:06:05.587669864 2581 0x75614ac0 DEBUG omxvideodec gstomxvideodec.c:2178:gst_omx_video_dec_handle_frame:<omxh264dec-omxh264dec0> Handling frame 0:06:05.591000038 2581 0x75614ac0 DEBUG omxvideodec gstomxvideodec.c:2178:gst_omx_video_dec_handle_frame:<omxh264dec-omxh264dec0> Handling frame 0:06:05.591114776 2581 0x75614ac0 DEBUG omxvideodec gstomxvideodec.c:2185:gst_omx_video_dec_handle_frame:<omxh264dec-omxh264dec0> Starting task 0:06:05.591252691 2581 0x74d018f0 DEBUG omxvideodec gstomxvideodec.c:1570:gst_omx_video_dec_loop:<omxh264dec-omxh264dec0> Component signalled EOS 0:06:05.591313316 2581 0x74d018f0 DEBUG omxvideodec gstomxvideodec.c:1590:gst_omx_video_dec_loop:<omxh264dec-omxh264dec0> EOS 0:06:05.605895926 2581 0x75614ac0 DEBUG omxvideodec gstomxvideodec.c:2178:gst_omx_video_dec_handle_frame:<omxh264dec-omxh264dec0> Handling frame 0:06:05.606009936 2581 0x75614ac0 DEBUG omxvideodec gstomxvideodec.c:2185:gst_omx_video_dec_handle_frame:<omxh264dec-omxh264dec0> Starting task 0:06:05.606143997 2581 0x74d018f0 DEBUG omxvideodec gstomxvideodec.c:1570:gst_omx_video_dec_loop:<omxh264dec-omxh264dec0> Component signalled EOS 0:06:05.606203319 2581 0x74d018f0 DEBUG omxvideodec gstomxvideodec.c:1590:gst_omx_video_dec_loop:<omxh264dec-omxh264dec0> EOS 0:06:05.606916541 2581 0x75614ac0 DEBUG omxvideodec gstomxvideodec.c:2178:gst_omx_video_dec_handle_frame:<omxh264dec-omxh264dec0> Handling frame 0:06:05.609172247 2581 0x75614ac0 DEBUG omxvideodec gstomxvideodec.c:2457:gst_omx_video_dec_drain:<omxh264dec-omxh264dec0> Draining component 0:06:05.609289433 2581 0x75614ac0 DEBUG omxvideodec gstomxvideodec.c:2462:gst_omx_video_dec_drain:<omxh264dec-omxh264dec0> Component not started yet
0:01:35.201549213 14697 0x74301db0 DEBUG videodecoder gstvideodecoder.c:2703:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> no valid PTS, using oldest DTS 0:07:14.952708481 Placing a breakpoint at this point and taking a look at the frame that triggered this message, we find this: 0:01:40.252680427 351 0x74e021b0 DEBUG videodecoder gstvideodecoder.c:2654:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> sync timestamp 0:07:15.792708481 diff -0:07:15.792708481 0:01:40.253014642 351 0x74e021b0 DEBUG videodecoder gstvideodecoder.c:3174:gst_video_decoder_clip_and_push_buf:<omxh264dec-omxh264dec0> pushing buffer 0x6c7bb3e0 of size 470016, PTS 0:07:15.792708481, dur 0:00:00.040000000 0:01:40.254921651 351 0x73144ec0 DEBUG videodecoder gstvideodecoder.c:1728:gst_video_decoder_src_query:<omxh264dec-omxh264dec0> received query 5123, duration 0:01:40.255264043 351 0x73144ec0 DEBUG tsdemux tsdemux.c:516:gst_ts_demux_srcpad_query: query duration 0:01:40.255315657 351 0x73144ec0 DEBUG tsdemux tsdemux.c:527:gst_ts_demux_srcpad_query:<tsdemux0> only query duration on TIME is supported [Switching to Thread 0x6dfff460 (LWP 366)] Breakpoint 1, gst_video_decoder_prepare_finish_frame (decoder=0x74e28190, frame=0x7314e950, dropping=1) at gstvideodecoder.c:2700 2700 frame->pts = min_ts + priv->pts_delta; (gdb) print frame->pts $1 = 18446744073709551615 (gdb) print priv->reordered_output $2 = 0 (gdb) print *frame $3 = {ref_count = 2, flags = 0, system_frame_number = 3456, decode_frame_number = 3456, presentation_frame_number = 0, dts = 139992708481, pts = 18446744073709551615, duration = 40000000, distance_from_sync = 3456, input_buffer = 0x6e1d38d0, output_buffer = 0x0, deadline = 18446744073709551615, events = 0x0, user_data = 0x0, user_data_destroy_notify = 0x0, abidata = {ABI = { ts = 434912708481, ts2 = 18446744073709551615}, padding = {0x42d14781, 0x65, 0xffffffff, 0xffffffff, 0x0 <repeats 16 times>}}} (gdb) Specifically, the PTS on this frame is 18446744073709551615 (GST_CLOCK_TIME_NONE), as is the “deadline” and the “ts2”. This triggers the code that replaces the bogus PTS with DTS, which is in the future compared to the frames that follow, leading to this: 0:01:35.202174569 14697 0x74301db0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:14.952708481 < 0:07:15.792708481) 0:01:35.202333421 14697 0x74301db0 DEBUG videodecoder gstvideodecoder.c:2847:gst_video_decoder_drop_frame:<omxh264dec-omxh264dec0> dropping frame 0:07:15.792708481 The videodecoder starts dropping all frames, and shortly afterwards the pipeline freezes up completely.
This looks like it a) needs some checks for invalid times in GstVideoDecoder and then do something more sensible, and b) we need to find out where they come from to begin with. Can you create a patch for a) already?
Unfortunately I don't understand the reasoning behind the current behaviour of GstVideoDecoder, and so can't practically provide a patch. What I was hoping for is confirmation of what the videodecoder expects from upstream, I have no idea what is normal and what isn't alas. Removing the part where the invalid PTS is set to DTS makes no difference to the stream, we still hang: diff --git a/gst-libs/gst/video/gstvideodecoder.c b/gst-libs/gst/video/gstvideodecoder.c index fdbc7d2..db15514 100644 --- a/gst-libs/gst/video/gstvideodecoder.c +++ b/gst-libs/gst/video/gstvideodecoder.c @@ -2697,7 +2697,7 @@ gst_video_decoder_prepare_finish_frame (GstVideoDecoder * if (!priv->reordered_output && !GST_CLOCK_TIME_IS_VALID (frame->pts) && !seen_none && GST_CLOCK_TIME_IS_VALID (priv->pts_delta)) { - frame->pts = min_ts + priv->pts_delta; +// frame->pts = min_ts + priv->pts_delta; GST_DEBUG_OBJECT (decoder, "no valid PTS, using oldest DTS %" GST_TIME_FORMAT, GST_TIME_ARGS (frame->pts)); It appears that the videodecoder suddenly starts receiving packets in a corrupted order, which eventually freezes up the decoded completely. The PTS values below are all over the show, they run backwards, then jump forwards, then run backwards again. minfrin@towerofpi9:/var/www/html/stream $ GST_TRACE="live" G_DEBUG="fatal-warnings" LD_LIBRARY_PATH=/usr/local/lib gst-launch-1.0 --gst-debug=1,videotag:1,souphttpclientsink:2,pixelsample:1,mpegtsbase:0,tdttsparse:5,transcoder:5,omxvideodec:1,omxvideoenc:1,tsdemux:5,encodebin:1,videodecoder:5 filesrc location=/mnt/stream/raw.ts ! progressreport update-freq=5 ! tsdemux ! queue ! h264parse ! omxh264dec ! omxh264enc ! h264parse ! mpegtsmux ! hlssink target-duration=0 2>&1 | grep "decreasing timestamp" 0:01:30.313825356 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:15.632708481 < 0:07:15.832708481) 0:01:30.316706261 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:15.552708481 < 0:07:15.832708481) 0:01:30.318355305 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:15.512708481 < 0:07:15.832708481) 0:01:30.319121754 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:15.592708481 < 0:07:15.832708481) 0:01:30.320096587 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:15.712708481 < 0:07:15.832708481) 0:01:30.321267303 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:15.672708481 < 0:07:15.832708481) 0:01:30.322132397 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:15.752708481 < 0:07:15.832708481) 0:01:30.324218728 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:15.952708481 < 0:07:16.112708481) 0:01:30.325133405 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:15.872708481 < 0:07:16.112708481) 0:01:30.326079071 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:15.832708481 < 0:07:16.112708481) 0:01:30.326970520 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:15.912708481 < 0:07:16.112708481) 0:01:30.327863218 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:16.032708481 < 0:07:16.112708481) 0:01:30.328728677 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:15.992708481 < 0:07:16.112708481) 0:01:30.329690749 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:16.072708481 < 0:07:16.112708481) 0:01:30.331694425 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:16.272708481 < 0:07:16.432708481) 0:01:30.332536863 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:16.192708481 < 0:07:16.432708481) 0:01:30.333387218 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:16.152708481 < 0:07:16.432708481) 0:01:30.334488091 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:16.232708481 < 0:07:16.432708481) 0:01:30.335555110 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:16.352708481 < 0:07:16.432708481) 0:01:30.336482860 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:16.312708481 < 0:07:16.432708481) 0:01:30.337385558 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:16.392708481 < 0:07:16.432708481) 0:01:30.343763923 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:16.512708481 < 0:07:16.592708481) 0:01:30.344523342 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:16.472708481 < 0:07:16.592708481) 0:01:30.345333593 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:16.552708481 < 0:07:16.592708481) 0:01:30.347091490 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:16.632708481 < 0:07:16.672708481) 0:01:30.349699169 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:16.912708481 < 0:07:17.072708481) 0:01:30.350496555 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:16.832708481 < 0:07:17.072708481) 0:01:30.351306182 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:16.792708481 < 0:07:17.072708481) 0:01:30.352110547 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:16.872708481 < 0:07:17.072708481) 0:01:30.352951319 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:16.992708481 < 0:07:17.072708481) 0:01:30.353880996 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:16.952708481 < 0:07:17.072708481) 0:01:30.354788434 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:17.032708481 < 0:07:17.072708481) 0:01:30.356623465 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:17.232708481 < 0:07:17.392708481) 0:01:30.357527465 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:17.152708481 < 0:07:17.392708481) 0:01:30.358418289 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:17.112708481 < 0:07:17.392708481) 0:01:30.359328903 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:17.192708481 < 0:07:17.392708481) 0:01:30.360204570 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:17.312708481 < 0:07:17.392708481) 0:01:30.361147581 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:17.272708481 < 0:07:17.392708481) 0:01:30.361996113 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:17.352708481 < 0:07:17.392708481) 0:01:30.363952184 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:17.552708481 < 0:07:17.712708481) 0:01:30.364770039 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:17.472708481 < 0:07:17.712708481) 0:01:30.365663936 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:17.432708481 < 0:07:17.712708481) 0:01:30.366567988 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:17.512708481 < 0:07:17.712708481) 0:01:30.367426311 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:17.632708481 < 0:07:17.712708481) 0:01:30.368308906 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:17.592708481 < 0:07:17.712708481) 0:01:30.369254624 30367 0x208def0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:17.672708481 < 0:07:17.712708481) Am I right in understanding that for the videodecoder to work properly, it must receive PTS values that are monotonically increasing? If this is true, then I need to be searching for the bug upstream of videodecoder.
Looking upstream of videodecoder, I have found this line from tsdemux: 0:01:21.758812742 30550 0x1aa8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:15.632708481 REFPTS:0:07:15.792708481 Gap:5124095:34:33.549551616 nb_buffers: 10864 (ref:10864) 0:01:21.758879720 30550 0x1aa8f0 DEBUG tsdemux tsdemux.c:2441:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> Stream needs update. Pushing GAP event to TS 0:07:13.901125185 Am I right in assuming that tsdemux is requesting that the pipeline inserts a gap of 5124095:34:33.549551616, or 584 years?
Zooming in further to this tsdemux behaviour, we find PTS increasing monotonically... 0:01:29.048908085 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:03.552708481 REFPTS:0:07:02.032708481 Gap:0:00:01.520000000 nb_buffers: 10562 (ref:10520) 0:01:29.485388521 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:05.792708481 REFPTS:0:07:03.552708481 Gap:0:00:02.240000000 nb_buffers: 10614 (ref:10562) 0:01:29.864504383 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:07.712708481 REFPTS:0:07:05.792708481 Gap:0:00:01.920000000 nb_buffers: 10661 (ref:10614) 0:01:30.128882086 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:08.832708481 REFPTS:0:07:07.712708481 Gap:0:00:01.120000000 nb_buffers: 10693 (ref:10661) 0:01:30.527394140 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:10.872708481 REFPTS:0:07:08.832708481 Gap:0:00:02.040000000 nb_buffers: 10741 (ref:10693) 0:01:30.675514325 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:11.392708481 REFPTS:0:07:10.872708481 Gap:0:00:00.520000000 nb_buffers: 10758 (ref:10741) 0:01:31.100338328 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:13.632708481 REFPTS:0:07:11.392708481 Gap:0:00:02.240000000 nb_buffers: 10810 (ref:10758) 0:01:31.546484855 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:15.792708481 REFPTS:0:07:13.632708481 Gap:0:00:02.160000000 nb_buffers: 10864 (ref:10810) ...until here, where we jump backwards PTS:0:07:15.792708481 -> PTS:0:07:15.632708481, and where the nb_buffers don't move at all ref:10864 -> nb_buffers: 10864... 0:01:31.548391553 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:15.632708481 REFPTS:0:07:15.792708481 Gap:5124095:34:33.549551616 nb_buffers: 10864 (ref:10864) 0:01:31.548606394 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2441:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> Stream needs update. Pushing GAP event to TS 0:07:13.901125185 ...we seem to send a GAP event, and then we continue with PTS monotomically increasing again... 0:01:31.692513501 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:17.712708481 REFPTS:0:07:15.632708481 Gap:0:00:02.080000000 nb_buffers: 10912 (ref:10864) 0:01:31.742448575 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:19.192708481 REFPTS:0:07:17.712708481 Gap:0:00:01.480000000 nb_buffers: 10948 (ref:10912) 0:01:31.795789079 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:21.432708481 REFPTS:0:07:19.192708481 Gap:0:00:02.240000000 nb_buffers: 11004 (ref:10948) 0:01:31.796739277 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:21.432708481 REFPTS:0:07:21.432708481 Gap:0:00:00.000000000 nb_buffers: 11004 (ref:11004) 0:01:31.850065823 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:23.672708481 REFPTS:0:07:21.432708481 Gap:0:00:02.240000000 nb_buffers: 11060 (ref:11004) 0:01:31.901809053 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:25.592708481 REFPTS:0:07:23.672708481 Gap:0:00:01.920000000 nb_buffers: 11115 (ref:11060) 0:01:31.950385860 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:27.552708481 REFPTS:0:07:25.592708481 Gap:0:00:01.960000000 nb_buffers: 11165 (ref:11115) 0:01:31.998760481 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:29.872708481 REFPTS:0:07:27.552708481 Gap:0:00:02.320000000 nb_buffers: 11216 (ref:11165) 0:01:32.047631087 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:31.632708481 REFPTS:0:07:29.872708481 Gap:0:00:01.760000000 nb_buffers: 11264 (ref:11216) 0:01:32.102307618 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:33.872708481 REFPTS:0:07:31.632708481 Gap:0:00:02.240000000 nb_buffers: 11316 (ref:11264) 0:01:32.120249034 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:34.352708481 REFPTS:0:07:33.872708481 Gap:0:00:00.480000000 nb_buffers: 11332 (ref:11316) 0:01:32.171216752 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:36.432708481 REFPTS:0:07:34.352708481 Gap:0:00:02.080000000 nb_buffers: 11380 (ref:11332) 0:01:32.223584194 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:38.432708481 REFPTS:0:07:36.432708481 Gap:0:00:02.000000000 nb_buffers: 11429 (ref:11380) 0:01:32.260117853 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:39.472708481 REFPTS:0:07:38.432708481 Gap:0:00:01.040000000 nb_buffers: 11463 (ref:11429) 0:01:32.307605297 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:41.632708481 REFPTS:0:07:39.472708481 Gap:0:00:02.160000000 nb_buffers: 11510 (ref:11463) 0:01:32.366178816 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:43.872708481 REFPTS:0:07:41.632708481 Gap:0:00:02.240000000 nb_buffers: 11566 (ref:11510) 0:01:32.394022362 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:44.592708481 REFPTS:0:07:43.872708481 Gap:0:00:00.720000000 nb_buffers: 11591 (ref:11566) 0:01:32.441511629 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:46.752708481 REFPTS:0:07:44.592708481 Gap:0:00:02.160000000 nb_buffers: 11637 (ref:11591) 0:01:32.488095229 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:48.232708481 REFPTS:0:07:46.752708481 Gap:0:00:01.480000000 nb_buffers: 11679 (ref:11637) 0:01:32.537061563 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:50.312708481 REFPTS:0:07:48.232708481 Gap:0:00:02.080000000 nb_buffers: 11727 (ref:11679) 0:01:32.568993345 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:51.352708481 REFPTS:0:07:50.312708481 Gap:0:00:01.040000000 nb_buffers: 11757 (ref:11727) 0:01:32.620744805 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:53.192708481 REFPTS:0:07:51.352708481 Gap:0:00:01.840000000 nb_buffers: 11805 (ref:11757) 0:01:32.673234641 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:55.472708481 REFPTS:0:07:53.192708481 Gap:0:00:02.280000000 nb_buffers: 11856 (ref:11805) 0:01:32.700631838 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:56.272708481 REFPTS:0:07:55.472708481 Gap:0:00:00.800000000 nb_buffers: 11880 (ref:11856) 0:01:32.751099978 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:07:58.352708481 REFPTS:0:07:56.272708481 Gap:0:00:02.080000000 nb_buffers: 11928 (ref:11880) 0:01:32.804416264 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:08:00.032708481 REFPTS:0:07:58.352708481 Gap:0:00:01.680000000 nb_buffers: 11977 (ref:11928) 0:01:32.848966761 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:08:02.032708481 REFPTS:0:08:00.032708481 Gap:0:00:02.000000000 nb_buffers: 12019 (ref:11977) 0:01:32.899401308 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:08:03.512708481 REFPTS:0:08:02.032708481 Gap:0:00:01.480000000 nb_buffers: 12064 (ref:12019) 0:01:32.947163957 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:08:05.672708481 REFPTS:0:08:03.512708481 Gap:0:00:02.160000000 nb_buffers: 12111 (ref:12064) 0:01:32.996450548 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:08:07.592708481 REFPTS:0:08:05.672708481 Gap:0:00:01.920000000 nb_buffers: 12158 (ref:12111) 0:01:33.049822458 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:08:09.512708481 REFPTS:0:08:07.592708481 Gap:0:00:01.920000000 nb_buffers: 12206 (ref:12158) 0:01:33.110353351 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:08:11.392708481 REFPTS:0:08:09.512708481 Gap:0:00:01.880000000 nb_buffers: 12261 (ref:12206) 0:01:33.146211497 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:08:13.032708481 REFPTS:0:08:11.392708481 Gap:0:00:01.640000000 nb_buffers: 12294 (ref:12261) 0:01:33.205552924 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:08:15.272708481 REFPTS:0:08:13.032708481 Gap:0:00:02.240000000 nb_buffers: 12350 (ref:12294) 0:01:33.232068829 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:08:16.072708481 REFPTS:0:08:15.272708481 Gap:0:00:00.800000000 nb_buffers: 12375 (ref:12350) 0:01:33.274404819 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:08:17.832708481 REFPTS:0:08:16.072708481 Gap:0:00:01.760000000 nb_buffers: 12414 (ref:12375) 0:01:33.333989004 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:08:20.072708481 REFPTS:0:08:17.832708481 Gap:0:00:02.240000000 nb_buffers: 12470 (ref:12414) 0:01:33.386457435 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:08:21.992708481 REFPTS:0:08:20.072708481 Gap:0:00:01.920000000 nb_buffers: 12518 (ref:12470) 0:01:33.411714968 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:08:22.952708481 REFPTS:0:08:21.992708481 Gap:0:00:00.960000000 nb_buffers: 12542 (ref:12518) 0:01:33.464255533 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:08:24.712708481 REFPTS:0:08:22.952708481 Gap:0:00:01.760000000 nb_buffers: 12591 (ref:12542) 0:01:33.480399678 30875 0x131a8f0 DEBUG tsdemux tsdemux.c:2433:gst_ts_demux_check_and_sync_streams:<tsdemux0:video_0_1d4d> 0x1d4d, PTS:0:08:25.512708481 REFPTS:0:08:24.712708481 Gap:0:00:00.800000000 nb_buffers: 12606 (ref:12591) ...then we hang. Possibly because videodecoder choked on the PTS that went backwards?
Digging further, I am able to reproduce the hang using just the tsdemux element alone, like this: gst-launch-1.0 filesrc location=/mnt/stream/raw.ts ! progressreport update-freq=5 ! tsdemux ! fakesink When it hangs, the backtrace of all threads looks like this: 0:00:07.177036844 26676 0x19dac0 DEBUG tsdemux tsdemux.c:2562:gst_ts_demux_push_pending_data:<tsdemux0:subpicture_0_1d51> stream:0x75b20750, pid:0x1d51 stream_type:6 state:0 ^C Program received signal SIGINT, Interrupt. 0x76bf5b80 in poll () at ../sysdeps/unix/syscall-template.S:81 81 ../sysdeps/unix/syscall-template.S: No such file or directory. (gdb) thread apply all backtrace
+ Trace 236865
Thread 2 (Thread 0x7645c460 (LWP 26683))
$1 = {object = {object = {g_type_instance = {g_class = 0x3a528}, ref_count = 2, qdata = 0x0}, lock = {p = 0x0, i = {0, 0}}, name = 0x75b00c98 "tsdemux0:sink", parent = 0x0, flags = 0, control_bindings = 0x0, control_rate = 100000000, last_sync = 18446744073709551615, _gst_reserved = 0x0}, state = GST_TASK_PAUSED, cond = {p = 0x0, i = {1, 0}}, lock = 0x184474, func = 0x7671f5dc <mpegts_base_loop>, user_data = 0x18e188, notify = 0x0, running = 1, thread = 0x19dac0, priv = 0x1a1800, _gst_reserved = {0x0, 0x0, 0x0, 0x0}} Does this code look right? We seem to start the task before unlocking base->sinkpad, is this correct? done: if (flush_event) gst_event_unref (flush_event); gst_pad_start_task (base->sinkpad, (GstTaskFunction) mpegts_base_loop, base, NULL); GST_PAD_STREAM_UNLOCK (base->sinkpad); return ret == GST_FLOW_OK;
This code looks fine to me at first glance. The pad task will take the pad stream lock when it loops from the started thread, so it will just wait until the UNLOCK is done here, if needed. Doesn't look like there are locking order problems with any other locks either. The paused thread you identify seems to belong to a taskpool, so that need not indicate anything unusual either, and may just be waiting to be started/used. The mpegts_base_loop task must be started but then stopped streaming for some reason. The reason is probably found in the debug log, or you can put some strategic printfs into the task function, to see if it gets started and pauses or is never started in the first place.
Alas the reason isn't in the debug log. The addition of a single printf prevents the start of all streaming, we freeze before processing any data. This looks like a memory corruption issue of some kind.
Some progress. The hang turned out to be a patch I had added to stop gst-launch-1.0 from exiting without it being asked to. What was really happening was the pipeline was returning EOS on the live stream and exiting early before being asked to. When a stream comes to EOS, gst_omx_video_dec_drain() is called to request the graphics card empties all outstanding buffers. To drain the card, the OMX_BUFFERFLAG_EOS flag is set on the buffers entering the card. This in turn causes the GST_OMX_ACQUIRE_BUFFER_EOS status to be returned from gst_omx_port_acquire_buffer(), which causes the code to follow a path that on first invocation returns GST_FLOW_OK, but on subsequent invocations returns GST_FLOW_EOS. However, in the live streaming of unreliable streams case where a discontinuity is encountered, we also call gst_omx_video_dec_drain() to empty the graphics card before trying to start decoding from scratch after the discontinuity. On this code path there is obviously no intention to shut the stream down with EOS, but that’s ultimately what is happening. After a discontinuity, during gst_omx_video_dec_drain(), the code is returning GST_FLOW_EOS when it should not, causing the stream to be shut down prematurely. The workaround is this: diff --git a/omx/gstomxvideodec.c b/omx/gstomxvideodec.c index 6baaa48..5a5998c 100644 --- a/omx/gstomxvideodec.c +++ b/omx/gstomxvideodec.c @@ -1568,7 +1569,8 @@ eos: gst_pad_pause_task (GST_VIDEO_DECODER_SRC_PAD (self)); } else { GST_DEBUG_OBJECT (self, "Component signalled EOS"); - flow_ret = GST_FLOW_EOS; + flow_ret = GST_FLOW_OK; +// flow_ret = GST_FLOW_EOS; } g_mutex_unlock (&self->drain_lock); I am looking for some guidance on the real fix. Am I right in understand that GST_FLOW_EOS is the job of the parent video encoder class, and that gstomxvideodec.c has no business trying to return a GST_FLOW_EOS of it’s own?
I have seen this issue last week also. Drain request is called from the videodecoderclass when receiving a DISCONT buffer. This issue is in OMX. When draining the component, the buffer flag OMX_BUFFERFLAG_EOS set port->eos to TRUE in gstomx.c This remains to TRUE forever. I don't know what is the best way to fix the issue. Find a way to set port->eos to FALSE or add a new flag to handle the drain correctly.
So this is a gst-omx bug instead? The problem here seems to be that the draining does not work properly. When draining, the element remembers that it does that currently and is not supposed to send EOS downstream / return GST_FLOW_EOS. For some reason this part of the code did not work as expected for you though and that will have to be debugged and fixed. The intention here is to ignore EOS when draining (and otherwise not ignore it), and to signal the condition variable that is waiting for draining to finish.
Created attachment 341779 [details] [review] Prevent early EOS by resetting eos flag once GST_OMX_ACQUIRE_BUFFER_EOS is triggered. Prevent early EOS by resetting eos flag once GST_OMX_ACQUIRE_BUFFER_EOS is triggered. Log clearly when EOS is handled.
Review of attachment 341779 [details] [review]: Is this maybe related to https://bugzilla.gnome.org/show_bug.cgi?id=741856 ? ::: omx/gstomx.c @@ +1263,3 @@ if (port->flushing) { + GST_DEBUG_OBJECT (comp->parent, "Component %s port %d is flushing", + comp->name, port->index); Can you put all the new debug output into a separate patch? That would definitely be good and useful to merge ASAP @@ +1333,2 @@ ret = GST_OMX_ACQUIRE_BUFFER_EOS; + port->eos = FALSE; How would that help here? We would return EOS from acquire_buffer, which would shut down the caller. And if it doesn't, we would call back in here again and wait forever (the component usually gives you nothing new after EOS).
Created attachment 341807 [details] [review] Add clear debug logging on all the paths out of gst_omx_port_acquire_buffer() Debug patch as requested.
Created attachment 341808 [details] [review] Prevent early EOS by resetting eos flag once GST_OMX_ACQUIRE_BUFFER_EOS is triggered. Split out the eos flag change.
> How would that help here? We would return EOS from acquire_buffer, > which would shut down the caller. And if it doesn't, we would call > back in here again and wait forever (the component usually gives > you nothing new after EOS). You're mixing up the gstreamer's view on EOS with OMX's implementation of EOS. Inside OMX, the OMX_BUFFERFLAG_EOS flag's job is to tell you which packet coming out of the codec corresponds with the packet with that same flag that went into the codec, and that's it. There is no expectation in OMX that the stream will be terminated. Gstreamer uses the OMX EOS mechanism to implement drain, and while drain is called just once at the end of a program stream, it will be called multiple times in a live transport stream, specifically after each discontinuity in the stream. What makes things complicated is that we have a pending_buffers queue, and if we just returned GST_OMX_ACQUIRE_BUFFER_EOS straight away, we would be returning the flag too early. As a result we have an eos flag. As soon as we see OMX_BUFFERFLAG_EOS we set the eos flag, then return buffers from the pending_buffers queue until the queue is empty, then and only then do we send the GST_OMX_ACQUIRE_BUFFER_EOS back to drain to signal we're done, and we need to reset the eos flag at this point so we're back to our initial state where drain can be called again. If we don't set this back to false again, the drain mechanism works exactly once. Directly after the drain is successfully completed we come around for the next packet, eos is still true, GST_OMX_ACQUIRE_BUFFER_EOS is sent again (this time in error), and given that the draining flag is false now, we simply follow the exit path by returning GST_FLOW_EOS.
Oops indeed, sorry :) Makes sense then Do you see any connection to https://bugzilla.gnome.org/show_bug.cgi?id=741856 though?
I don't see any connection, no. That bug is about OMX_BUFFERFLAG_EOS being triggered too early, this bug is about triggering OMX_BUFFERFLAG_EOS too often.
commit 8716c23e2b0553db2982eb84c437f493c974385e Author: Graham Leggett <minfrin@sharp.fm> Date: Mon Dec 12 11:12:48 2016 +0000 Prevent early EOS by resetting eos flag once GST_OMX_ACQUIRE_BUFFER_EOS is triggered https://bugzilla.gnome.org/show_bug.cgi?id=774600 commit 5d5fbcd8f6704a805faf9dbcefb7f5fd977c447f Author: Graham Leggett <minfrin@sharp.fm> Date: Mon Dec 12 11:09:15 2016 +0000 Add clear debug logging on all the paths out of gst_omx_port_acquire_buffer() https://bugzilla.gnome.org/show_bug.cgi?id=774600