After an evaluation, GNOME has moved from Bugzilla to GitLab. Learn more about GitLab.
No new issues can be reported in GNOME Bugzilla anymore.
To report an issue in a GNOME project, go to GNOME GitLab.
Do not go to GNOME Gitlab for: Bluefish, Doxygen, GnuCash, GStreamer, java-gnome, LDTP, NetworkManager, Tomboy.
Bug 743363 - tsdemux: push segment that cause sink to think it's late
tsdemux: push segment that cause sink to think it's late
Status: RESOLVED FIXED
Product: GStreamer
Classification: Platform
Component: gst-plugins-bad
git master
Other All
: Normal blocker
: 1.4.6
Assigned To: Thiago Sousa Santos
GStreamer Maintainers
: 743740 (view as bug list)
Depends on:
Blocks:
 
 
Reported: 2015-01-22 17:34 UTC by Aurélien Zanelli
Modified: 2015-02-13 19:26 UTC
See Also:
GNOME target: ---
GNOME version: ---


Attachments
tsdemux: don't mark streams as needing a new segment on flush (4.06 KB, patch)
2015-01-30 23:36 UTC, Aurélien Zanelli
none Details | Review
tsdemux: don't mark streams as needing a new segment on flush (3.52 KB, patch)
2015-02-03 14:01 UTC, Thiago Sousa Santos
none Details | Review
tsdemux: fix segment handling in seeks (1.75 KB, patch)
2015-02-09 23:36 UTC, Thiago Sousa Santos
none Details | Review
tsdemux: Fix segment and segment event handling during seeking (1.75 KB, patch)
2015-02-10 04:17 UTC, Thiago Sousa Santos
none Details | Review
tsdemux: Fix segment and segment event handling during seeking (2.89 KB, patch)
2015-02-13 00:06 UTC, Thiago Sousa Santos
committed Details | Review

Description Aurélien Zanelli 2015-01-22 17:34:14 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.
Comment 1 Thiago Sousa Santos 2015-01-26 23:29:28 UTC
(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?
Comment 2 Aurélien Zanelli 2015-01-30 14:32:48 UTC
(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.
Comment 3 Nicolas Dufresne (ndufresne) 2015-01-30 14:43:49 UTC
*** Bug 743740 has been marked as a duplicate of this bug. ***
Comment 4 Thiago Sousa Santos 2015-01-30 15:32:52 UTC
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?
Comment 5 Alexander Kanavin 2015-01-30 15:53:41 UTC
I think this is where it happens:

http://cgit.freedesktop.org/gstreamer/gst-plugins-bad/tree/gst/mpegtsdemux/mpegtsbase.c#n1129
Comment 6 Aurélien Zanelli 2015-01-30 15:57:08 UTC
(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
Comment 7 Aurélien Zanelli 2015-01-30 23:36:07 UTC
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.
Comment 8 Alexander Kanavin 2015-02-02 13:16:54 UTC
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.
Comment 9 Thiago Sousa Santos 2015-02-03 14:01:01 UTC
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
Comment 10 Aurélien Zanelli 2015-02-03 14:20:53 UTC
(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.
Comment 11 Alexander Kanavin 2015-02-03 15:00:50 UTC
The updated patch works for me too.
Comment 12 Thiago Sousa Santos 2015-02-03 16:54:29 UTC
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
Comment 13 Alexander Kanavin 2015-02-03 20:09:06 UTC
Will this be pushed to 1.4 branch as well?
Comment 14 Thiago Sousa Santos 2015-02-05 12:59:43 UTC
Pushed to 1.4: 1ce3260a638d97d8a2447140d88e1bce156aa40e
Comment 15 Thibault Saunier 2015-02-07 20:08:29 UTC
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
Comment 16 Thiago Sousa Santos 2015-02-09 23:36:51 UTC
Created attachment 296418 [details] [review]
tsdemux: fix segment handling in seeks

Could you check if this patch fixes the issue, please?
Comment 17 Thiago Sousa Santos 2015-02-10 04:17:59 UTC
Created attachment 296433 [details] [review]
tsdemux: Fix segment and segment event handling during seeking

The same patch (just a test with new git-bz)
Comment 18 Aurélien Zanelli 2015-02-10 08:34:36 UTC
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.
Comment 19 Thibault Saunier 2015-02-10 12:02:16 UTC
(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.
Comment 20 Thiago Sousa Santos 2015-02-10 17:21:28 UTC
(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.
Comment 21 Thibault Saunier 2015-02-10 19:43:22 UTC
(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.
Comment 22 Thiago Sousa Santos 2015-02-13 00:06:37 UTC
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
Comment 23 Thiago Sousa Santos 2015-02-13 19:26:18 UTC
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