Unexplained freeze/hang from gst-omx omxh264enc on Raspberry Pi 3
Graham Leggett
minfrin at sharp.fm
Tue Nov 15 22:36:17 UTC 2016
On 15 Nov 2016, at 3:34 AM, Graham Leggett <minfrin at sharp.fm> wrote:
> I am having some strange behaviour from gst-omx and the omxh264dec/omxh264enc elements that I am trying to get to the bottom of, the pipeline seems to hang at random points and I am trying to get to the bottom of why.
>
> I have recorded 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.
>
> My problem is that each time this recorded MPEG transport stream is transcoded, the pipeline freezes/hangs at a different point in time. I would expect the file to freeze/hang in the same place, but it doesn’t do so.
>
> When it freezes the pipeline, omxh264enc says the following and then goes silent:
Looking closer at the decoder part of the pipeline, I see frames being received by omxvideodec, decoded successfully and then pushed downstream like so:
0:01:35.176680217 14697 0x74301db0 DEBUG videodecoder gstvideodecoder.c:2654:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> sync timestamp 0:07:15.432708481 diff -0:07:15.200555555
0:01:35.177353593 14697 0x74301db0 DEBUG videodecoder gstvideodecoder.c:3174:gst_video_decoder_clip_and_push_buf:<omxh264dec-omxh264dec0> pushing buffer 0x6c288550 of size 470016, PTS 0:07:15.432708481, dur 0:00:00.040000000
0:01:35.177826764 14697 0x74301db0 DEBUG omxvideodec gstomxvideodec.c:1506:gst_omx_video_dec_loop:<omxh264dec-omxh264dec0> Read frame from component
0:01:35.177896190 14697 0x74301db0 DEBUG omxvideodec gstomxvideodec.c:1508:gst_omx_video_dec_loop:<omxh264dec-omxh264dec0> Finished frame: ok
0:01:35.184288346 14697 0x74301db0 DEBUG omxvideodec gstomxvideodec.c:1370:gst_omx_video_dec_loop:<omxh264dec-omxh264dec0> Handling buffer: 0x00030010 435472708
0:01:35.184847193 14697 0x74301db0 DEBUG videodecoder gstvideodecoder.c:2654:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> sync timestamp 0:07:15.472708481 diff -0:07:15.240555555
0:01:35.185655619 14697 0x74301db0 DEBUG videodecoder gstvideodecoder.c:3174:gst_video_decoder_clip_and_push_buf:<omxh264dec-omxh264dec0> pushing buffer 0x6c2885f0 of size 470016, PTS 0:07:15.472708481, dur 0:00:00.040000000
0:01:35.186402953 14697 0x74301db0 DEBUG omxvideodec gstomxvideodec.c:1506:gst_omx_video_dec_loop:<omxh264dec-omxh264dec0> Read frame from component
0:01:35.186516962 14697 0x74301db0 DEBUG omxvideodec gstomxvideodec.c:1508:gst_omx_video_dec_loop:<omxh264dec-omxh264dec0> Finished frame: ok
0:01:35.195746841 14697 0x74301db0 DEBUG omxvideodec gstomxvideodec.c:1370:gst_omx_video_dec_loop:<omxh264dec-omxh264dec0> Handling buffer: 0x00030010 435792708
0:01:35.196601882 14697 0x74301db0 DEBUG videodecoder gstvideodecoder.c:2654:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> sync timestamp 0:07:15.792708481 diff -0:07:15.560555555
0:01:35.197258852 14697 0x74301db0 DEBUG videodecoder gstvideodecoder.c:3174:gst_video_decoder_clip_and_push_buf:<omxh264dec-omxh264dec0> pushing buffer 0x6c288690 of size 470016, PTS 0:07:15.792708481, dur 0:00:00.040000000
0:01:35.197735357 14697 0x74301db0 DEBUG omxvideodec gstomxvideodec.c:1506:gst_omx_video_dec_loop:<omxh264dec-omxh264dec0> Read frame from component
0:01:35.197983166 14697 0x74301db0 DEBUG omxvideodec gstomxvideodec.c:1508:gst_omx_video_dec_loop:<omxh264dec-omxh264dec0> Finished frame: ok
0:01:35.200984064 14697 0x74301db0 DEBUG omxvideodec gstomxvideodec.c:1370:gst_omx_video_dec_loop:<omxh264dec-omxh264dec0> Handling buffer: 0x00000001 435832708
Then suddenly, omxvideodec stops accepted frames, but carries on sending frames as the decoder buffer is emptied as follows:
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
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
0:01:35.203420490 14697 0x74301db0 DEBUG omxvideodec gstomxvideodec.c:1506:gst_omx_video_dec_loop:<omxh264dec-omxh264dec0> Read frame from component
0:01:35.203530749 14697 0x74301db0 DEBUG omxvideodec gstomxvideodec.c:1508:gst_omx_video_dec_loop:<omxh264dec-omxh264dec0> Finished frame: ok
0:01:35.240920831 14697 0x74301db0 DEBUG omxvideodec gstomxvideodec.c:1564:gst_omx_video_dec_loop:<omxh264dec-omxh264dec0> Drained
0:01:35.241111505 14697 0x75713bb0 DEBUG omxvideodec gstomxvideodec.c:2517:gst_omx_video_dec_drain:<omxh264dec-omxh264dec0> Drained component
The omxvideodec codec receives an GST_EVENT_GAP event, not sure yet from where. The omxvideoenc element stops accepting frames, not sure why, and so omxvideodec seems to drop all remaining frames.
0:01:35.241288326 14697 0x75713bb0 DEBUG videodecoder gstvideodecoder.c:1220:gst_video_decoder_sink_event_default:<omxh264dec-omxh264dec0> Pushing all pending serialized events before the gap
0:01:35.241400043 14697 0x75713bb0 DEBUG videodecoder gstvideodecoder.c:869:gst_video_decoder_push_event:<omxh264dec-omxh264dec0> pushing event gap
0:01:35.242264980 14697 0x75713bb0 DEBUG videodecoder gstvideodecoder.c:3381:gst_video_decoder_decode_frame:<omxh264dec-omxh264dec0> decoder frame list getting long: 17 frames,possible internal leaking?
progressreport0 (00:01:35): 85464800 / 91982760 bytes (92.9 %)
0:01:35.252898434 14697 0x75713bb0 DEBUG omxvideodec gstomxvideodec.c:2178:gst_omx_video_dec_handle_frame:<omxh264dec-omxh264dec0> Handling frame
0:01:35.253051349 14697 0x75713bb0 DEBUG videodecoder gstvideodecoder.c:2654:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> sync timestamp 0:07:15.632708481 diff -0:07:15.400555555
0:01:35.253199888 14697 0x75713bb0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:15.632708481 < 0:07:15.792708481)
0:01:35.253320876 14697 0x75713bb0 DEBUG videodecoder gstvideodecoder.c:2847:gst_video_decoder_drop_frame:<omxh264dec-omxh264dec0> dropping frame 0:07:15.792708481
0:01:35.254169146 14697 0x75713bb0 DEBUG videodecoder gstvideodecoder.c:3381:gst_video_decoder_decode_frame:<omxh264dec-omxh264dec0> decoder frame list getting long: 17 frames,possible internal leaking?
0:01:35.254307113 14697 0x75713bb0 DEBUG omxvideodec gstomxvideodec.c:2178:gst_omx_video_dec_handle_frame:<omxh264dec-omxh264dec0> Handling frame
0:01:35.254382112 14697 0x75713bb0 DEBUG videodecoder gstvideodecoder.c:2654:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> sync timestamp 0:07:15.552708481 diff -0:07:15.320555555
0:01:35.254519194 14697 0x75713bb0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:07:15.552708481 < 0:07:15.792708481)
0:01:35.254630703 14697 0x75713bb0 DEBUG videodecoder gstvideodecoder.c:2847:gst_video_decoder_drop_frame:<omxh264dec-omxh264dec0> dropping frame 0:07:15.792708481
0:01:35.255431994 14697 0x75713bb0 DEBUG videodecoder gstvideodecoder.c:3381:gst_video_decoder_decode_frame:<omxh264dec-omxh264dec0> decoder frame list getting long: 17 frames,possible internal leaking?
0:01:35.255566524 14697 0x75713bb0 DEBUG omxvideodec gstomxvideodec.c:2178:gst_omx_video_dec_handle_frame:<omxh264dec-omxh264dec0> Handling frame
Eventually the decoder runs out of frames and we get this:
0:01:35.717327853 14697 0x75713bb0 DEBUG videodecoder gstvideodecoder.c:3381:gst_video_decoder_decode_frame:<omxh264dec-omxh264dec0> decoder frame list getting long: 44 frames,possible internal leaking?
0:01:35.717407279 14697 0x75713bb0 DEBUG omxvideodec gstomxvideodec.c:2178:gst_omx_video_dec_handle_frame:<omxh264dec-omxh264dec0> Handling frame
0:01:35.717455612 14697 0x75713bb0 DEBUG videodecoder gstvideodecoder.c:2654:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> sync timestamp 0:08:27.712708481 diff -0:08:27.480555555
0:01:35.717524778 14697 0x75713bb0 WARN videodecoder gstvideodecoder.c:2767:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> decreasing timestamp (0:08:27.712708481 < 0:08:27.752708481)
0:01:35.717578683 14697 0x75713bb0 DEBUG videodecoder gstvideodecoder.c:2847:gst_video_decoder_drop_frame:<omxh264dec-omxh264dec0> dropping frame 0:08:27.752708481
0:01:35.718894082 14697 0x75713bb0 DEBUG videodecoder gstvideodecoder.c:3366:gst_video_decoder_decode_frame:<omxh264dec-omxh264dec0> PTS delta 400 ms
0:01:35.718990279 14697 0x75713bb0 DEBUG videodecoder gstvideodecoder.c:3381:gst_video_decoder_decode_frame:<omxh264dec-omxh264dec0> decoder frame list getting long: 44 frames,possible internal leaking?
0:01:35.719030747 14697 0x75713bb0 DEBUG omxvideodec gstomxvideodec.c:2178:gst_omx_video_dec_handle_frame:<omxh264dec-omxh264dec0> Handling frame
0:01:35.719060434 14697 0x75713bb0 DEBUG omxvideodec gstomxvideodec.c:2185:gst_omx_video_dec_handle_frame:<omxh264dec-omxh264dec0> Starting task
0:01:35.719112413 14697 0x75713bb0 DEBUG videodecoder gstvideodecoder.c:3391:gst_video_decoder_decode_frame:<omxh264dec-omxh264dec0> flow error eos
0:01:35.719369024 14697 0x74301db0 DEBUG omxvideodec gstomxvideodec.c:1570:gst_omx_video_dec_loop:<omxh264dec-omxh264dec0> Component signalled EOS
0:01:35.719425638 14697 0x74301db0 DEBUG omxvideodec gstomxvideodec.c:1590:gst_omx_video_dec_loop:<omxh264dec-omxh264dec0> EOS
0:01:35.719957506 14697 0x75713bb0 DEBUG videodecoder gstvideodecoder.c:3381:gst_video_decoder_decode_frame:<omxh264dec-omxh264dec0> decoder frame list getting long: 45 frames,possible internal leaking?
0:01:35.720032088 14697 0x75713bb0 DEBUG omxvideodec gstomxvideodec.c:2178:gst_omx_video_dec_handle_frame:<omxh264dec-omxh264dec0> Handling frame
0:01:35.720079588 14697 0x75713bb0 DEBUG videodecoder gstvideodecoder.c:2654:gst_video_decoder_prepare_finish_frame:<omxh264dec-omxh264dec0> sync timestamp 0:08:27.912708481 diff -0:08:27.680555555
0:01:35.720149222 14697 0x75713bb0 DEBUG videodecoder gstvideodecoder.c:2847:gst_video_decoder_drop_frame:<omxh264dec-omxh264dec0> dropping frame 0:08:27.912708481
0:01:35.720464635 14697 0x75713bb0 DEBUG videodecoder gstvideodecoder.c:1396:gst_video_decoder_sink_event:<omxh264dec-omxh264dec0> received event 28174, eos
0:01:35.720536196 14697 0x75713bb0 DEBUG omxvideodec gstomxvideodec.c:2457:gst_omx_video_dec_drain:<omxh264dec-omxh264dec0> Draining component
0:01:35.720566769 14697 0x75713bb0 DEBUG omxvideodec gstomxvideodec.c:2462:gst_omx_video_dec_drain:<omxh264dec-omxh264dec0> Component not started yet
0:01:35.720596821 14697 0x75713bb0 DEBUG videodecoder gstvideodecoder.c:869:gst_video_decoder_push_event:<omxh264dec-omxh264dec0> pushing event eos
At this point the pipeline hangs completely and is silent from this point on, until a CTL-C triggers a graceful shutdown.
Some further questions:
- Things seems to start going wrong when we see the following: "no valid PTS, using oldest DTS 0:07:14.952708481” and "decreasing timestamp (0:07:14.952708481 < 0:07:15.792708481)” followed by "dropping frame 0:07:15.792708481” - have we got frames out of order?
- When things go wrong, either before or after we process the following: "Pushing all pending serialized events before the gap”. This is caused by us having received a GST_EVENT_GAP. What does this mean?
Can anyone see anything in the logs above that would explain a hang?
I have an example TS that shows the problem.
Regards,
Graham
—
-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 3240 bytes
Desc: not available
URL: <https://lists.freedesktop.org/archives/gstreamer-devel/attachments/20161116/ad759fac/attachment.bin>
More information about the gstreamer-devel
mailing list