GNOME Bugzilla – Bug 719785
hlssink: does not always adhere to the segment target duration
Last modified: 2018-11-03 13:19:12 UTC
It seems that the force-key-unit events emitted by hlssink are being ignored by the upstream in some cases. This depends on the source file. Executing the pipe: gst-launch-1.0 -v --gst-debug=mpegtsmux:4,hlssink:4,x264enc:4 filesrc location=klovn_1500.mp4 ! decodebin ! queue ! x264enc ! mpegtsmux ! hlssink target-duration=10 result: http://pastebin.com/UTae4KXK The interesting messages are: 0:00:02.083604323 21359 0xc0e8f0 INFO mpegtsmux mpegtsmux.c:937:check_pending_key_unit_event: now 0:00:07.800000000 wanted 0:00:10.000000000 0:00:02.083781840 21359 0xc0e8f0 INFO x264enc gstx264enc.c:1902:gst_x264_enc_encode_frame:<x264enc0> Forcing key frame 0:00:02.093407736 21359 0xc0e8f0 INFO mpegtsmux mpegtsmux.c:937:check_pending_key_unit_event: now 0:00:08.000000000 wanted 0:00:10.000000000 And a few seconds later: 0:00:02.975715319 21359 0xc0e8f0 INFO mpegtsmux mpegtsmux.c:937:check_pending_key_unit_event: now 0:00:09.800000000 wanted 0:00:10.000000000 0:00:02.998043430 21359 0xc0e8f0 INFO mpegtsmux mpegtsmux.c:937:check_pending_key_unit_event: now 0:00:09.880000000 wanted 0:00:10.000000000 0:00:02.998910966 21359 0xc0e8f0 INFO mpegtsmux mpegtsmux.c:806:mpegtsmux_sink_event:<mpegtsmux0> have downstream force-key-unit event on pad sink_65, seqnum 263, running-time 0:00:10.000000000 count 1 0:00:02.998932445 21359 0xc0e8f0 INFO mpegtsmux mpegtsmux.c:810:mpegtsmux_sink_event:<mpegtsmux0> skipping downstream force key unit event as an upstream force key unit is already queued 0:00:02.998955341 21359 0xc0e8f0 INFO mpegtsmux mpegtsmux.c:937:check_pending_key_unit_event: now 0:00:09.920000000 wanted 0:00:10.000000000 0:00:03.000188674 21359 0xc0e8f0 INFO mpegtsmux mpegtsmux.c:937:check_pending_key_unit_event: now 0:00:10.000000000 wanted 0:00:10.000000000 0:00:03.000215625 21359 0xc0e8f0 INFO mpegtsmux mpegtsmux.c:943:check_pending_key_unit_event: pending force key unit, waiting for keyframe 0:00:03.010917966 21359 0xc0e8f0 INFO mpegtsmux mpegtsmux.c:937:check_pending_key_unit_event: now 0:00:09.960000000 wanted 0:00:10.000000000 0:00:03.046916732 21359 0xc0e8f0 INFO mpegtsmux mpegtsmux.c:937:check_pending_key_unit_event: now 0:00:10.080000000 wanted 0:00:10.000000000 0:00:03.046973034 21359 0xc0e8f0 INFO mpegtsmux mpegtsmux.c:943:check_pending_key_unit_event: pending force key unit, waiting for keyframe And more seconds later: 0:00:04.253965353 21359 0xc0e8f0 INFO mpegtsmux mpegtsmux.c:943:check_pending_key_unit_event: pending force key unit, waiting for keyframe 0:00:04.264080154 21359 0xc0e8f0 INFO mpegtsmux mpegtsmux.c:937:check_pending_key_unit_event: now 0:00:12.800000000 wanted 0:00:10.000000000 0:00:04.264115620 21359 0xc0e8f0 INFO mpegtsmux mpegtsmux.c:943:check_pending_key_unit_event: pending force key unit, waiting for keyframe 0:00:04.264906283 21359 0xc0e8f0 INFO mpegtsmux mpegtsmux.c:937:check_pending_key_unit_event: now 0:00:12.920000000 wanted 0:00:10.000000000 0:00:04.264959113 21359 0xc0e8f0 INFO mpegtsmux mpegtsmux.c:1092:mpegtsmux_collected_buffer:<mpegtsmux0> pushing downstream force-key-unit event 234 0:00:12.920000000 count 1 0:00:04.264977565 21359 0xc0e8f0 INFO hlssink gsthlssink.c:530:gst_hls_sink_ghost_event_probe:<hlssink0> event: custom-downstream 0:00:04.264993943 21359 0xc0e8f0 INFO hlssink gsthlssink.c:562:gst_hls_sink_ghost_event_probe:<hlssink0> setting index 1 0:00:04.265520688 21359 0xc0e8f0 INFO hlssink gsthlssink.c:358:gst_hls_sink_handle_message:<hlssink0> COUNT 1 0:00:04.275804950 21359 0xc0e8f0 INFO hlssink gsthlssink.c:588:schedule_next_key_unit:<hlssink0> sending upstream force-key-unit, index 2 now 0:00:12.920000000 target 0:00:22.920000000 0:00:04.275849188 21359 0xc0e8f0 INFO mpegtsmux mpegtsmux.c:862:mpegtsmux_src_event:<mpegtsmux0> received upstream force-key-unit event, seqnum 266 running_time 0:00:22.920000000 all_headers 1 count 2 0:00:04.275869467 21359 0xc0e8f0 INFO mpegtsmux mpegtsmux.c:883:mpegtsmux_src_event:<mpegtsmux0> forwarding to sink_65 0:00:04.275885087 21359 0xc0e8f0 INFO mpegtsmux mpegtsmux.c:885:mpegtsmux_src_event:<mpegtsmux0> result 1 0:00:04.278922057 21359 0xc0e8f0 INFO mpegtsmux mpegtsmux.c:937:check_pending_key_unit_event: now 0:00:13.080000000 wanted 0:00:22.920000000 0:00:04.279804278 21359 0xc0e8f0 INFO mpegtsmux mpegtsmux.c:937:check_pending_key_unit_event: now 0:00:13.000000000 wanted 0:00:22.920000000
Sample file used in testing: http://bigben.oz.com/b/klovnsample.mp4
What seems to happen here is the forced keyframe is generated when DTS matches the requested timestamp. Normally, when transcoding a file that works properly, the keyframe is emitted when PTS matches the requested timestamp.
Further observation. Turning off B-frames, thus putting PTS and DTS into sync has no effect.
Did you ever find a solution to this problem?
After a lot of digging I've managed to narrow this down. The trigger is that for reasons I do not yet understand, none of the buffers coming through the pipeline are keyframes. This in turn triggers this code in mpegtsmux.c: if (flags & GST_BUFFER_FLAG_DELTA_UNIT) { GST_INFO ("pending force key unit, waiting for keyframe"); goto out; } Because no buffers are keyframes, the forced keyframe event is delayed forever, and therefore never reaches hlssink, which never rolls over to the next file. This raises a question - should mpegtsmux be checking for keyframes at all? Obviously we expect a keyframe here, but instead of a straightforward to diagnose bug we get broken hlssink behaviour instead, which is counterintuitive and makes the actual bug very hard to find. I suspect the problem occurs when a file touches one of the following elements containing check_pending_key_unit_event(): pi@towerofpi9:~/packages/gstreamer-master/gst-plugins-bad$ grep -r check_pending_key_unit_event * | grep -v matches gst/videoparsers/gsth265parse.c:check_pending_key_unit_event (GstEvent * pending_event, GstSegment * segment, gst/videoparsers/gsth265parse.c: if ((event = check_pending_key_unit_event (h265parse->force_key_unit_event, gst/videoparsers/gstmpeg4videoparse.c:check_pending_key_unit_event (GstEvent * pending_event, GstSegment * segment, gst/videoparsers/gstmpeg4videoparse.c: if ((event = check_pending_key_unit_event (mp4vparse->force_key_unit_event, gst/videoparsers/gsth264parse.c:check_pending_key_unit_event (GstEvent * pending_event, gst/videoparsers/gsth264parse.c: if ((event = check_pending_key_unit_event (h264parse->force_key_unit_event, gst/mpegtsmux/mpegtsmux.c:check_pending_key_unit_event (GstEvent * pending_event, GstSegment * segment, gst/mpegtsmux/mpegtsmux.c: event = check_pending_key_unit_event (mux->downstream_force_key_unit_event,
This hack patch causes data to flow again: diff --git a/gst/mpegtsmux/mpegtsmux.c b/gst/mpegtsmux/mpegtsmux.c index 67c2b72..e11d075 100644 --- a/gst/mpegtsmux/mpegtsmux.c +++ b/gst/mpegtsmux/mpegtsmux.c @@ -1079,10 +1081,10 @@ check_pending_key_unit_event (GstEvent * pending_event, GstSegment * segment, running_time < pending_key_unit_ts) goto out; - if (flags & GST_BUFFER_FLAG_DELTA_UNIT) { - GST_INFO ("pending force key unit, waiting for keyframe"); - goto out; - } +// if (flags & GST_BUFFER_FLAG_DELTA_UNIT) { +// GST_INFO ("pending force key unit, waiting for keyframe"); +// goto out; +// } stream_time = gst_segment_to_stream_time (segment, GST_FORMAT_TIME, timestamp);
I couldn't reproduce this using a big buck bunny sample and git master. Did you try it with a recent gstreamer version?
I am currently reproducing this with git master. This bug is triggered by stream containing errors, which in my case comes from a live (but unreliable) DVB source. If you use an error-free source you won't see this bug. It looks like the solution is to stop this code from trying to be the keyframe police, that is the job of an encoder. Alternatively, this behaviour should be optional, defaulting to off.
Created attachment 342747 [details] Example of a broken transport stream with no keyframes
The same cut-and-paste code in h264parse causes more mayhem in the transcoding case - if you're trying to transcode something originally h264 encoded to something h264 encoded, this h264parse code kicks in and delays the force-key-unit event until it sees a keyframe of it's own. This ruins the timing of whatever is driving the force-key-unit events.
It is not a good idea to make hlssink start new files at non-keyframe boundaries. That makes that file unplayable until a keyframe is written. If there are no keyframes than you can only begin playing it from the start (assuming there is a keyframe at the beginning). This defeats the whole fragmented purpose of allowing to start on any fragment. Why isn't there a keyframe on the stream? Or the problem is that the parser isn't recognizing and marking the keyframes as such? What exactly is the pipeline that you're using?
> Why isn't there a keyframe on the stream? Or the problem is that > the parser isn't recognizing and marking the keyframes as such? As I said above, the stream in my case is broken, and you'll see that by the attachment I added. In this particular case, something has gone wrong with the encoder, and there a no keyframes. Then this bug kicks in - the hlssink element stops slicing, because all the force-key-unit events are being delayed indefinitely. The segment currently being written to now grows without bounds, until the partition runs out of space, at that point the whole gstreamer pipeline shuts down. Obviously we want keyframes at the HLS boundaries, but that is impossible to achieve when other elements in the pipeline keep delaying the force-key-unit events without being told to do so and moving those boundaries. This bug also causes mayhem on live streams coming from unreliable sources like DVB. The stream runs for hours without a problem, then suddenly out of the blue keyframes stop arriving because of some kind of stream error, and thus bug gets triggered. Segment grows indefinitely, out of space, pipeline shuts down. > What exactly is the pipeline that you're using? The pipeline is a transcoding pipeline, converting h264 back into h264 after resizing. It's the equivalent of "[src] ! [timing-element] ! decodebin ! encodebin ! hlssink". The timing element sends downstream force-key-unit events, which are intercepted by h264parse, which then delays the force-key-unit, ruining the timing. Because h264 is being transcoded to h264 in this case, h264parse appears twice in the pipeline, so it breaks whether the timing is controlled by the src, or whether controlled by the sink.
(In reply to minfrin from comment #12) > > Why isn't there a keyframe on the stream? Or the problem is that > > the parser isn't recognizing and marking the keyframes as such? > > As I said above, the stream in my case is broken, and you'll see that by the > attachment I added. In this particular case, something has gone wrong with > the encoder, and there a no keyframes. This is the real bug. Which encoder is this? We should fix the encoder to generate keyframes again. > > Then this bug kicks in - the hlssink element stops slicing, because all the > force-key-unit events are being delayed indefinitely. The segment currently > being written to now grows without bounds, until the partition runs out of > space, at that point the whole gstreamer pipeline shuts down. > > Obviously we want keyframes at the HLS boundaries, but that is impossible to > achieve when other elements in the pipeline keep delaying the force-key-unit > events without being told to do so and moving those boundaries. > > This bug also causes mayhem on live streams coming from unreliable sources > like DVB. The stream runs for hours without a problem, then suddenly out of > the blue keyframes stop arriving because of some kind of stream error, and > thus bug gets triggered. Segment grows indefinitely, out of space, pipeline > shuts down. Generating segments without a keyframe at the beginning will break the playback of your resulting stream, so we would be fixing the wrong bug. Or trading one bug for another. > > > What exactly is the pipeline that you're using? > > The pipeline is a transcoding pipeline, converting h264 back into h264 after > resizing. > > It's the equivalent of "[src] ! [timing-element] ! decodebin ! encodebin ! > hlssink". > > The timing element sends downstream force-key-unit events, which are > intercepted by h264parse, which then delays the force-key-unit, ruining the > timing. Because h264 is being transcoded to h264 in this case, h264parse > appears twice in the pipeline, so it breaks whether the timing is controlled > by the src, or whether controlled by the sink. So if you have an encoder, it should definitely be generating keyframes every once in a while. We need to track down why does that stop happening.
> This is the real bug. Which encoder is this? We should fix the > encoder to generate keyframes again. Alas no, this is a distraction. The real bug is as described. Right now, gstreamer has been completely impossible to use for processing live streams, as it refuses to last more than a few hours without an error in the stream triggering this bug and then out-of-disk. Given that I've been chasing this bug down for almost 18 months, I am not touching the encoder until this bug has been completely flushed out and fixed.
I have the impression the last answer is slightly going off the rational thinking. I personally agree that for robustness hlssink should prevent from filling up the disk. But you will likely be unhappy with what I think hlssink should do in that situation. hlssink role is to cut a streams into different files. The cut is done on keyframe as this is the recommended method to produce an acceptable HLS stream. At best, hlssink should be configurable to prevent producing file over a certain threshold. Uppon that threshold (e.g. 10 frames passed the expected time), it should simply error out. This will break the current stream, but it will prevent any harm to the server itself. Now, fixing that is probably trivial, unlike the encoder bug. An encoder should always be relatively quick on replying to keyframe request. The delay will depend on the amount of buffering between the encoder and the hlssink. This threshold should be configurable.
I have just re-read something you said: (In reply to minfrin from comment #12) > It's the equivalent of "[src] ! [timing-element] ! decodebin ! encodebin ! > hlssink". > > The timing element sends downstream force-key-unit events, which are > intercepted by h264parse, which then delays the force-key-unit, ruining the > timing. That's unreliable by choice. Most sources don't know what to do with keyframe request. The keyframe request is only handled by video encoders in GStreamer. I think this thread can be closed quickly here, just configure your encoder key frame distance. E.g. x264enc has key-int-max property. If you configure this (depends on which exact encoder you are using), you'll never notice this lack of robustness again. Remember, this is an upstream request, so timing-element cannot reach to your downstream encoder.
-- 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-bad/issues/120.