GNOME Bugzilla – Bug 743363
tsdemux: push segment that cause sink to think it's late
Last modified: 2015-02-13 19:26:44 UTC
I stream a video over wifi with rtp/udp and when, I think, some discontinuities occurs, the playback become jerky and video sink complains about frames being too late. I try to debug the thing and I end up in the tsdemux segment related stuff. In my current understanding, when the stream start, a new segment is created: creating segment event time segment start=0:00:00.000000000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1,000000, applied_rate=1,000000, flags=0x00, time=0:00:00.000000000, base=0:00:00.000000000, position 0:00:00.000000000, duration 99:99:99.999999999 and propagated downstream. tsdemux push buffers with pts starting from 0 and when the sink synchronize to the clock, it check buffers running time using segment by doing basically with current configured segment: buffer.timestamp - segment.start and compare it to current pipeline running time. At this moment, everything is good. But when discontinuity happens, I notice that tsdemux streams are flushed and when data come again, tsdemux output a new segment using the first ts found in new created stream. For instance: creating segment event time segment start=0:00:10.833594372, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1,000000, applied_rate=1,000000, flags=0x00, time=0:00:00.000000000, base=0:00:00.000000000, position 0:00:10.833594372, duration 99:99:99.999999999 At this moment when buffers reach the sink, their running-time are B.timestamp - S.start with B.timestamp starting from 0:00:10.833594372. So for the first buffer which have the timestamp set to the same as segment.start, ie 0:00:10.833594372, its running-time is 0 but pipeline running-time is 10s beyond causing the sink to complain and think it's too late. As a result, I think the involved code is http://cgit.freedesktop.org/gstreamer/gst-plugins-bad/tree/gst/mpegtsdemux/tsdemux.c#n1999 Since this 'use case' works on 1.2, my first try was to remove this code to use the old behavior. It make the playback work, but I don't think it's the way to go :) Then I look more closely to GstSegment and times formula and see that segment.base is in the one used to get buffer running-time. According to design documentation, segment.base is the total elapsed running-time of any previous segment. Hence I try to track position in the current defined segment, and when a new one is defined, set segment.base using gst_segment_to_running_time(previous-segment, GST_FORMAT_TIME, previous-segment-position); It works better but after a while, issue happens again, maybe due to some drift. For records, I also tried some foolish things like setting segment.base to current element running-time or segment.start. It's work in my case but I'm pretty sure it's not the way to fix this and it breaks many things. So I'm quite lost and need some help to solve this issue. Is my understanding right ? Which is the preferred way to solve it ? To help debugging it, I dump a stream received over network by using gdppay so this issue can be easily reproduced with the following pipeline: gst-launch-1.0 filesrc location=dump.ts ! gdpdepay ! tsdemux ! video/x-h264 ! fakesink sync=true qos=true max-lateness=20000000 I used a fakesink here to reduce number of element involved, but video can be decoded as well and I used following debug for my analysis: basesink:5,tsdemux:5,GST_EVENT:5 The dump file can be downloaded here: http://www.darkosphere.fr/tmp/tsdemux-segment-issue/dump.gdp (sorry for slow Internet connection). P.S: I set severity to major since it's work on 1.2, but feel free to lower it.
(In reply to comment #0) > Then I look more closely to GstSegment and times formula and see that > segment.base is in the one used to get buffer running-time. According to design > documentation, segment.base is the total elapsed running-time of any previous > segment. > Hence I try to track position in the current defined segment, and when a new > one is defined, set segment.base using > gst_segment_to_running_time(previous-segment, GST_FORMAT_TIME, > previous-segment-position); > It works better but after a while, issue happens again, maybe due to some > drift. This is correct, did you try to debug why it happens again? > > For records, I also tried some foolish things like setting segment.base to > current element running-time or segment.start. It's work in my case but I'm > pretty sure it's not the way to fix this and it breaks many things. > How is this different from the approach you stated above?
(In reply to comment #1) > (In reply to comment #0) > > Then I look more closely to GstSegment and times formula and see that > > segment.base is in the one used to get buffer running-time. According to design > > documentation, segment.base is the total elapsed running-time of any previous > > segment. > > Hence I try to track position in the current defined segment, and when a new > > one is defined, set segment.base using > > gst_segment_to_running_time(previous-segment, GST_FORMAT_TIME, > > previous-segment-position); > > It works better but after a while, issue happens again, maybe due to some > > drift. > > This is correct, did you try to debug why it happens again? Yes, in my understanding, it is due to the fact that when I lost some packets, the tsdemux obviously stop outputting buffers, hence segment.position is not updated anymore. But pipeline clock keeps running. When new data come again, tsdemux create a new segment and since I calculate segment.base using the last known position, result could be far from elapsed running-time. For instance let assume following scenario. We begin with following segment: start=0, stop=GST_CLOCK_TIME_NONE, base=0 Signal is good, tsdemux outputs buffers and tsdemux->segment.position is updated each time. And running-time increase accordingly from 0. Then some packets are lost. Before the gap, we pushed a buffer with PTS=ts1 so tsdemux->segment.position=ts1 and running-time is rt1. After a time 'tg', data comes again. At this moment running-time is rt2 = rt1 + tg and first PTS after gap is roughly ts2 = ts1 + tg. So we reach the point tsdemux calculate a new segment. So with my calculation: segment.base = gst_segment_to_running_time(segment, GST_FORMAT_TIME, ts1) = somewhere around rt1 = rt1' with rt1' < rt2. segment.start = segment.position = ts2 segment.stop = GST_CLOCK_TIME_NONE When buffer with PTS ts2 reach the sink, it's running time will be: brt = ts2 - segment.start + segment.base = ts2 - ts2 + rt1' = rt1' > > > > > For records, I also tried some foolish things like setting segment.base to > > current element running-time or segment.start. It's work in my case but I'm > > pretty sure it's not the way to fix this and it breaks many things. > > > > How is this different from the approach you stated above? I just set segment.base to current running-time, I didn't track position at all. But my doing this, I avoid the issue described above.
*** Bug 743740 has been marked as a duplicate of this bug. ***
Had a quick chat about this on IRC: <thiagoss> bilboed, https://bugzilla.gnome.org/show_bug.cgi?id=743363 do you know the proper way to fix this? The question is "when mpegts gets a discont, how should the new segment look like to keep running-time going?" <stormer> I wonder if a lost packet should affect the segment <stormer> I would have expected the depayloader to send a gap, not a set discount <__tim> there's no need to generate a new segment event just because there's some data loss <__tim> if the input is live, the clock will continue running, the new data will be timestamped based on the running clock and all will be well again <thiagoss> Couldn't the stream/program have completely changed after the discont? <azanelli> tsdemux flushed the streams, then create new ones I think <__tim> (everything else normal) <thiagoss> The current implementation is that a flush will push all pending data and the streams will be reset (and be marked for creating a new segment) <__tim> uh <__tim> maybe discont has been "overloaded" by hls etc? <thiagoss> __tim, I agree that a new segment isn't needed. But isn't there a corner case where the upstream signal could be completely different after the discont and would really need a new segment? <wtay> that would be stream-start <thiagoss> __tim, afaik hls would only send a discont when it switches bitrates, and even so, it creates a new pad <__tim> thiagoss, maybe, but I'm assuming it's an otherwise continuous stream for now, it seems a bit over the top to do a big reset just because there was some packet loss <wtay> discont is just a missing packet <thiagoss> wtay, *nod* <thiagoss> Will comment on the bug for the reporter to update his fix <__tim> if data comes from hls (e.g. bitrate switch) it might be completely different streams of course <wtay> or after a seek or so, the stream is the same but the packet does not follow the previous packet for some reason <__tim> but that should be detected otherwise <wtay> with stream-start IMHO === So, it seems that a buffer marked with a discont flag is causing the streams to be flushed and marked as needing a new segment. It shouldn't be marked for a new segment just for a discont. This should fix the issue for you. Would be willing to write a patch for this?
I think this is where it happens: http://cgit.freedesktop.org/gstreamer/gst-plugins-bad/tree/gst/mpegtsdemux/mpegtsbase.c#n1129
(In reply to comment #4) > Had a quick chat about this on IRC: > > <thiagoss> bilboed, https://bugzilla.gnome.org/show_bug.cgi?id=743363 do you > know the proper way to fix this? The question is "when mpegts gets a discont, > how should the new segment look like to keep running-time going?" > <stormer> I wonder if a lost packet should affect the segment > <stormer> I would have expected the depayloader to send a gap, not a set > discount > <__tim> there's no need to generate a new segment event just because there's > some data loss > <__tim> if the input is live, the clock will continue running, the new data > will be timestamped based on the running clock and all will be well again > <thiagoss> Couldn't the stream/program have completely changed after the > discont? > <azanelli> tsdemux flushed the streams, then create new ones I think > <__tim> (everything else normal) > <thiagoss> The current implementation is that a flush will push all pending > data and the streams will be reset (and be marked for creating a new segment) > <__tim> uh > <__tim> maybe discont has been "overloaded" by hls etc? > <thiagoss> __tim, I agree that a new segment isn't needed. But isn't there a > corner case where the upstream signal could be completely different after the > discont and would really need a new segment? > <wtay> that would be stream-start > <thiagoss> __tim, afaik hls would only send a discont when it switches > bitrates, and even so, it creates a new pad > <__tim> thiagoss, maybe, but I'm assuming it's an otherwise continuous stream > for now, it seems a bit over the top to do a big reset just because there was > some packet loss > <wtay> discont is just a missing packet > <thiagoss> wtay, *nod* > <thiagoss> Will comment on the bug for the reporter to update his fix > <__tim> if data comes from hls (e.g. bitrate switch) it might be completely > different streams of course > <wtay> or after a seek or so, the stream is the same but the packet does not > follow the previous packet for some reason > <__tim> but that should be detected otherwise > <wtay> with stream-start IMHO > > === > So, it seems that a buffer marked with a discont flag is causing the streams to > be flushed and marked as needing a new segment. It shouldn't be marked for a > new segment just for a discont. This should fix the issue for you. > > Would be willing to write a patch for this? Yes, I could give a try
Created attachment 295838 [details] [review] tsdemux: don't mark streams as needing a new segment on flush Proposal patch to fix this issue :) It remove the mark for a new segment when flushing streams. Instead, it add new functions to completely reset the streams. Moreover, while it is not really needed in the flush case to free stream->data, I move it to the new reset function. Since I'm not 100% percent sur about what I've done, please review it carefully.
Review of attachment 295838 [details] [review]: The patch seems to fix the issue for me that I reported in the duplicate. Remember to use rtpjitterbuffer when testing! But I have no idea if the fix itself is correct; that has to be confirmed by one of gstreamer devs.
Created attachment 296021 [details] [review] tsdemux: don't mark streams as needing a new segment on flush Can you try this version of your patch? It does the same, but I just propagated the 'hard' flag that is already used on the original flush() function instead of adding a new one. The resulting patch should have the same effect but is simpler
(In reply to comment #9) > Created an attachment (id=296021) [details] [review] > tsdemux: don't mark streams as needing a new segment on flush > > Can you try this version of your patch? It does the same, but I just > propagated the 'hard' flag that is already used on the original > flush() function instead of adding a new one. The resulting patch > should have the same effect but is simpler It works. The simpler version is ok for me.
The updated patch works for me too.
Thanks for the quick tests. Pushed. commit d0a50be26d2b325825b32965299ed1aa707ff9d0 Author: Aurélien Zanelli <aurelien.zanelli@darkosphere.fr> Date: Tue Feb 3 10:59:16 2015 -0300 tsdemux: don't mark streams as needing a new segment on flush The flush is called on discont and we shouldn't output a new segment each time a discont happens. So this commit remove the mark for a new segment when flushing streams by propagating the 'hard' flag passed on the flusing from the base class. https://bugzilla.gnome.org/show_bug.cgi?id=743363
Will this be pushed to 1.4 branch as well?
Pushed to 1.4: 1ce3260a638d97d8a2447140d88e1bce156aa40e
With that new patches I am getting: $ wget http://people.collabora.com/~tsaunier/samples/00020.MTS $ ges-launch-1.0 00020.MTS 0 0 Adding clip file:///home/thiblahute/devel/pitivi/1.0-uninstalled/gst-plugins-bad/00020.MTS inpoint:0:00:00.000000000 duration:0:02:45.171494259 (ges-launch-1.0:4387): GStreamer-WARNING **: gstpad.c:4063:gst_pad_push_data:<tsdemux1:subpicture_1200> Got data flow before segment event (ges-launch-1.0:4387): GStreamer-WARNING **: gstpad.c:4063:gst_pad_push_data:<tsdemux1:video_1011> Got data flow before segment event (ges-launch-1.0:4387): GStreamer-WARNING **: gstpad.c:3829:gst_pad_chain_data_unchecked:<multiqueue2:sink_0> Got data flow before segment event (ges-launch-1.0:4387): GStreamer-WARNING **: gstpad.c:4063:gst_pad_push_data:<multiqueue2:src_0> Got data flow before segment event (ges-launch-1.0:4387): GStreamer-WARNING **: gstpad.c:3829:gst_pad_chain_data_unchecked:<h264parse2:sink> Got data flow before segment event (ges-launch-1.0:4387): GStreamer-WARNING **: gstpad.c:4063:gst_pad_push_data:<h264parse2:src> Got data flow before segment event (ges-launch-1.0:4387): GStreamer-WARNING **: gstpad.c:3829:gst_pad_chain_data_unchecked:<capsfilter8:sink> Got data flow before segment event (ges-launch-1.0:4387): GStreamer-WARNING **: gstpad.c:4063:gst_pad_push_data:<tsdemux1:audio_1100> Got data flow before segment event (ges-launch-1.0:4387): GStreamer-WARNING **: gstpad.c:3829:gst_pad_chain_data_unchecked:<multiqueue2:sink_1> Got data flow before segment event (ges-launch-1.0:4387): GStreamer-WARNING **: gstpad.c:4063:gst_pad_push_data:<capsfilter8:src> Got data flow before segment event (ges-launch-1.0:4387): GStreamer-WARNING **: gstpad.c:4063:gst_pad_push_data:<multiqueue2:src_1> Got data flow before segment event (ges-launch-1.0:4387): GStreamer-WARNING **: gstpad.c:3829:gst_pad_chain_data_unchecked:<ac3parse1:sink> Got data flow before segment event (ges-launch-1.0:4387): GStreamer-WARNING **: gstpad.c:4063:gst_pad_push_data:<ac3parse1:src> Got data flow before segment event (ges-launch-1.0:4387): GStreamer-WARNING **: gstpad.c:3829:gst_pad_chain_data_unchecked:<capsfilter9:sink> Got data flow before segment event (ges-launch-1.0:4387): GStreamer-WARNING **: gstpad.c:4063:gst_pad_push_data:<capsfilter9:src> Got data flow before segment event (ges-launch-1.0:4387): GStreamer-WARNING **: gstpad.c:3829:gst_pad_chain_data_unchecked:<a52dec1:sink> Got data flow before segment event (ges-launch-1.0:4387): GStreamer-WARNING **: gstpad.c:4063:gst_pad_push_data:<a52dec1:src> Got data flow before segment event (ges-launch-1.0:4387): GStreamer-WARNING **: gstpad.c:3829:gst_pad_chain_data_unchecked:<src_0:proxypad54> Got data flow before segment event (ges-launch-1.0:4387): GStreamer-WARNING **: gstpad.c:4063:gst_pad_push_data:<decodebin3:src_0> Got data flow before segment event (ges-launch-1.0:4387): GStreamer-WARNING **: gstpad.c:3829:gst_pad_chain_data_unchecked:<src_0:proxypad56> Got data flow before segment event (ges-launch-1.0:4387): GStreamer-WARNING **: gstpad.c:4063:gst_pad_push_data:<uridecodebin0:src_0> Got data flow before segment event (ges-launch-1.0:4387): GStreamer-WARNING **: gstpad.c:3829:gst_pad_chain_data_unchecked:<bin1:sink> Got data flow before segment event (ges-launch-1.0:4387): GStreamer-WARNING **: gstpad.c:4063:gst_pad_push_data:<sink:proxypad26> Got data flow before segment event (ges-launch-1.0:4387): GStreamer-WARNING **: gstpad.c:3829:gst_pad_chain_data_unchecked:<audioconvert0:sink> Got data flow before segment event ERROR from element tsdemux1: Internal data stream error. Debugging info: mpegtsbase.c(1366): mpegts_base_loop (): /GESPipeline:gespipeline0/GESTimeline:gestimeline0/GESAudioTrack:gesaudiotrack0/NleComposition:nlecomposition0/GstBin:current-bin/NleSource:nlesource2/GstBin:audiosrcbin/GstURIDecodeBin:uridecodebin0/GstDecodeBin:decodebin3/GstTSDemux:tsdemux1: stream stopped, reason not-negotiated In nle (gnonlin) after we set the sources to PAUSED/PLAYING, we have a pad block that fires a thread that will do a flushing seek on the source so that we can handle the notion of inpoint. I think that patche introduce a bug when we do that. That s 100% reproductible. That is a regression, reopening the bug as BLOCKER
Created attachment 296418 [details] [review] tsdemux: fix segment handling in seeks Could you check if this patch fixes the issue, please?
Created attachment 296433 [details] [review] tsdemux: Fix segment and segment event handling during seeking The same patch (just a test with new git-bz)
It fix the GES issue and according to the design docs, we have to send a segment after a seek. So the change looks fine to me.
(In reply to Thiago Sousa Santos from comment #16) > Created attachment 296418 [details] [review] [review] > tsdemux: fix segment handling in seeks > > Could you check if this patch fixes the issue, please? That patch removes keyframe/inaccurate seeking handling I think.
(In reply to Thibault Saunier from comment #19) > (In reply to Thiago Sousa Santos from comment #16) > > Created attachment 296418 [details] [review] [review] [review] > > tsdemux: fix segment handling in seeks > > > > Could you check if this patch fixes the issue, please? > > That patch removes keyframe/inaccurate seeking handling I think. If the seek was not performed on the segment, the base field doesn't get updated and the resulting segment disrupts playback. Both accurate and non-accurate should update the base. Accurate or not is related to making an extra effort to be precise when looking for the seeked position.
(In reply to Thiago Sousa Santos from comment #20) > (In reply to Thibault Saunier from comment #19) > > (In reply to Thiago Sousa Santos from comment #16) > > > Created attachment 296418 [details] [review] [review] [review] [review] > > > tsdemux: fix segment handling in seeks > > > > > > Could you check if this patch fixes the issue, please? > > > > That patch removes keyframe/inaccurate seeking handling I think. > If the seek was not performed on the segment, the base field doesn't get > updated and the resulting segment disrupts playback. Both accurate and > non-accurate should update the base. Accurate or not is related to making an > extra effort to be precise when looking for the seeked position. If you are seeking inaccurately the output segment will be updated so that the start field will match the time of the first outputed buffer and thus that buffer will not be ignore downstream.
Created attachment 296728 [details] [review] tsdemux: Fix segment and segment event handling during seeking Always update the segment and not only for accurate seeking and always send a new segment event after seeks. For non-accurate force a reset of our segment info to start from where our seek led us as we don't need to be accurate
commit b347ea98703e03b41f0f5fca003b15005e82c4aa Author: Thiago Santos <thiagoss@osg.samsung.com> Date: Mon Feb 9 11:21:35 2015 -0300 tsdemux: Fix segment and segment event handling during seeking Always update the segment and not only for accurate seeking and always send a new segment event after seeks. For non-accurate force a reset of our segment info to start from where our seek led us as we don't need to be accurate https://bugzilla.gnome.org/show_bug.cgi?id=743363 In 1.4: 613039a4ea75aeb5d05f352f6e48b266bc7a4dd5