Problem when using x264enc + mpegtsmux #96

mariannasb · 2021-08-05T11:29:59Z

Consider the following pipeline which encodes to H264, muxes to MPEG-TS and the streams over UDP

GST_DEBUG="*:3,GST_TRACER:7" GST_TRACERS="buffer(filter=bla)" gst-launch-1.0 v4l2src ! videoconvert ! x264enc key-int-max=30 speed-preset=1 tune=zerolatency ! video/x-h264,profile=high ! h264parse ! mpegtsmux name=mux ! rtpmp2tpay ! udpsink port=7000 host=127.0.0.1 sync=0

Receive with : vlc rtp://@:7000 or

gst-launch-1.0 udpsrc port=7000 caps="application/x-rtp,media=(string)video,clock-rate=(int)90000,encoding-name=(string)MP2T-ES" ! rtpbin ! rtpmp2tdepay ! decodebin name=dec ! videoconvert ! ximagesink

Works fine

Now if I add interpipesrc/sink in between:

GST_DEBUG="*:3,GST_TRACER:7" GST_TRACERS="buffer(filter=bla)" gst-launch-1.0 v4l2src ! videoconvert ! x264enc key-int-max=30 speed-preset=1 tune=zerolatency ! video/x-h264,profile=high ! h264parse ! interpipesink name=video_out sync=false async=false interpipesrc name=mux_V listen-to=video_out is-live=true stream-sync=passthrough-ts format=time ! h264parse ! mpegtsmux name=mux ! rtpmp2tpay ! udpsink port=7000 host=127.0.0.1 sync=0

Doesn't work and I get a lot of complains about backwards DTS:
0:00:00.729042661 192147 0x56175b8f50c0 WARN basetsmux gstbasetsmux.c:1608:gst_base_ts_mux_clip:<mux:sink_0> ignoring DTS going backward

I believe it is somehow related to problems with handling the SEGMENT, since x264enc adds an 1000 hours offset and sends a new SEGMENT event.

If I refuse events it then works:

GST_DEBUG="*:3,GST_TRACER:7" GST_TRACERS="buffer(filter=avenc)" gst-launch-1.0 v4l2src ! videoconvert ! x264enc key-int-max=30 speed-preset=1 tune=zerolatency ! video/x-h264,profile=high ! h264parse ! interpipesink name=video_out sync=false async=false interpipesrc name=mux_V listen-to=video_out is-live=true stream-sync=passthrough-ts format=time accept-events=false ! h264parse ! mpegtsmux name=mux ! rtpmp2tpay ! udpsink port=7000 host=127.0.0.1 sync=0

But if I try to add audio it doesn't anymore:

GST_DEBUG="*:3,GST_TRACER:7" GST_TRACERS="buffer(filter=bla)" gst-launch-1.0 v4l2src ! videoconvert ! x264enc key-int-max=30 speed-preset=1 tune=zerolatency ! video/x-h264,profile=high ! h264parse ! interpipesink name=video_out sync=false async=false interpipesrc name=mux_V listen-to=video_out is-live=true stream-sync=passthrough-ts format=time accept-events=false ! h264parse ! mpegtsmux name=mux ! rtpmp2tpay ! udpsink port=7000 host=127.0.0.1 sync=0 autoaudiosrc ! interpipesink name=audio_out sync=false async=false interpipesrc name=mux_A listen-to=audio_out is-live=true stream-sync=passthrough-ts format=time ! audioconvert ! avenc_aac ! mux.

gst-launch-1.0 udpsrc port=7000 caps="application/x-rtp,media=(string)video,clock-rate=(int)90000,encoding-name=(string)MP2T-ES" ! rtpbin ! rtpmp2tdepay ! decodebin name=dec ! videoconvert ! ximagesink dec. ! audioconvert ! autoaudiosink

Which I guess is because the timestamps of audio and video are 1000 hours apart...

And if I then change the video interpipesrc to restart-ts I can get it working again:

GST_DEBUG="*:3,GST_TRACER:7" GST_TRACERS="buffer(filter=bla)" gst-launch-1.0 v4l2src ! videoconvert ! x264enc key-int-max=30 speed-preset=1 tune=zerolatency ! video/x-h264,profile=high ! h264parse ! interpipesink name=video_out sync=false async=false interpipesrc name=mux_V listen-to=video_out is-live=true stream-sync=restart-ts format=time accept-events=false ! h264parse ! mpegtsmux name=mux ! rtpmp2tpay ! udpsink port=7000 host=127.0.0.1 sync=0 autoaudiosrc ! interpipesink name=audio_out sync=false async=false interpipesrc name=mux_A listen-to=audio_out is-live=true stream-sync=passthrough-ts format=time ! audioconvert ! avenc_aac ! mux.

Note that the same pipeline (with audio) works without the interpipesrc/sinks:

GST_DEBUG="*:3,GST_TRACER:7" GST_TRACERS="buffer(filter=bla)" gst-launch-1.0 v4l2src ! videoconvert ! x264enc key-int-max=30 speed-preset=1 tune=zerolatency ! video/x-h264,profile=high ! h264parse ! mpegtsmux name=mux ! rtpmp2tpay ! udpsink port=7000 host=127.0.0.1 sync=0 autoaudiosrc ! audioconvert ! avenc_aac ! mux.

So, here there is no problem, even though the timestamp difference also exists here.

The text was updated successfully, but these errors were encountered:

mariannasb · 2021-08-05T12:49:08Z

From what I can see the problem is that in the pipeline without the interpipe the mpegtsmux only receives 1 segment event, which comes from the encoder:

Inspect Event: <enum GST_EVENT_SEGMENT of type Gst.EventType> pad: enc_out::src
Segment: 
Base:0.0 Duration: 18446744073.709553 Format: <enum GST_FORMAT_TIME of type Gst.Format> Offset: 0.0 Position: 3599999.699365496
Start: 3599999.699365496 Stop: 18446744073.709553 Time: 0.0
to_running_time: 0

Inspect Event: <enum GST_EVENT_SEGMENT of type Gst.EventType> pad: mux_out::sink_0
Segment: 
Base:0.0 Duration: 18446744073.709553 Format: <enum GST_FORMAT_TIME of type Gst.Format> Offset: 0.0 Position: 3599999.699365496
Start: 3599999.699365496 Stop: 18446744073.709553 Time: 0.0
to_running_time: 0

But when I add the interpipe it gets 2 segment events, the 1st without the x264 offset and the 2nd with:

Inspect Event: <enum GST_EVENT_SEGMENT of type Gst.EventType> pad: enc_out::src
Segment: 
Base:0.0 Duration: 18446744073.709553 Format: <enum GST_FORMAT_TIME of type Gst.Format> Offset: 0.0 Position: 3599999.699365496
Start: 3599999.699365496 Stop: 18446744073.709553 Time: 0.0
to_running_time: 0

Inspect Event: <enum GST_EVENT_SEGMENT of type Gst.EventType> pad: mux_out::sink_0
Segment: 
Base:0.0 Duration: 18446744073.709553 Format: <enum GST_FORMAT_TIME of type Gst.Format> Offset: 0.0 Position: 0.0
Start: 0.0 Stop: 18446744073.709553 Time: 0.0
to_running_time: 0

Inspect Event: <enum GST_EVENT_SEGMENT of type Gst.EventType> pad: mux_out::sink_0
Segment: 
Base:0.0 Duration: 18446744073.709553 Format: <enum GST_FORMAT_TIME of type Gst.Format> Offset: 0.0 Position: 3599999.699365496
Start: 3599999.699365496 Stop: 18446744073.709553 Time: 0.0
to_running_time: 0

And then the mpegtsmux starts its execution using the 1st segment, which gives a DTS of +1000:00:00, and later when it starts calculating the DTS with the new segment it gets smaller than the initial one and therefore keeps getting ignored...

mariannasb · 2021-08-05T13:00:40Z

I don't know if the problem is in the interpipesrc or the mpegtsmux, so I have also created this: https://gitlab.freedesktop.org/gstreamer/gst-plugins-bad/-/issues/1637

mariannasb · 2021-08-06T07:37:43Z

Reply from gstreamer community:

Pretty clearly that's a bug in the interpipe source element, if it outputs data with a different segment than when it arrived at the interpipe sink element.

Send all queued events with "timestamp < buffer timestamp" instead of just the 1st one before sending the buffer. Only the 1st event of the event queue with "timestamp < buffer timestamp" was being send before the buffer. But there could be several events in the queue that should sent before the buffer. Fixes RidgeRun#96 The segment event was not being handled properly when using x264enc + mpegtsmux together with interpipesrc/sink. Which was causing 2 segment to be delivered to the mpegtsmux: 1st one generated by the interpipesrc (starting from zero) because no segment existed. 2nd coming from the x264 encoder (correcting the 1000 hours offset added by the encoder). The 1st segment resulted in all subsequent DTS being seen as invalid (backwards) by the muxer. This happened because the event queue contained the following: stream-start, segment, tag, tag, tag. All with timestamp 0. But only the stream-start was sent, then the 1st buffer, then the segment. Which caused the DTS issues.

michaelgruner · 2021-08-06T23:05:27Z

Hi @mariannasb thanks for your detailed report. Indeed it a problem with interpipes. The problem, as you described, is caused because, currently, the interpipesrc does not configure the segment from the interpipesink. This will cause problems when the timestamps come in a different time base, as with your x264enc.

The reason the x264enc uses timestamps starting on 1000 is to allow the encoder to add "negative" timestamps (B-frames may, for example, have such negative timestamps). To work this out, GStreamer configures configures the segment to start on that time, so everything works as it should. It only makes sense to continue using this same segment in the interpipesink.

Allow me coordinate this fix internally and assign someone to this.

michaelgruner · 2021-08-06T23:11:15Z

PR #97 is a potential fix for this report.

mariannasb · 2021-08-09T07:55:21Z

PR #97 is a potential fix for this report.

I have found out late Friday that event though PR #97 improves this problem it is unfortunately not a completely fix, it only shifts the problem.

With the fix I can see that mpegtsmux receives the segment from x264enc before receiving the 1st buffer, as it should.

However I can see that an extra segment (with a wrong position of 0) is still being generated, and coming afterwards.

I haven't succeeded in tracking where it is coming from, who is generating it and why (since there is already a proper segment).
Though it all points to the interpipesrc I can't find who is actually calling gst_event_new_segment(), if it is the interpipesrc itself, the underlying appsrc or another base class...

Inspect Event: <enum GST_EVENT_SEGMENT of type Gst.EventType> pad: enc_out::src
Segment: 
Base:0.0 Duration: 18446744073.709553 Format: <enum GST_FORMAT_TIME of type Gst.Format> Offset: 0.0 Position: 3599999.705140042
Start: 3599999.705140042 Stop: 18446744073.709553 Time: 0.0
to_running_time: 0

Inspect Event: <enum GST_EVENT_SEGMENT of type Gst.EventType> pad: mux_out::sink_0
Segment: 
Base:0.0 Duration: 18446744073.709553 Format: <enum GST_FORMAT_TIME of type Gst.Format> Offset: 0.0 Position: 3599999.705140042
Start: 3599999.705140042 Stop: 18446744073.709553 Time: 0.0
to_running_time: 0

Inspect Event: <enum GST_EVENT_SEGMENT of type Gst.EventType> pad: mux_out::sink_0
Segment: 
Base:0.0 Duration: 18446744073.709553 Format: <enum GST_FORMAT_TIME of type Gst.Format> Offset: 0.0 Position: 0.0
Start: 0.0 Stop: 18446744073.709553 Time: 0.0
to_running_time: 0

mariannasb · 2021-08-09T11:14:49Z

From what I could find it seems like the segment gets created by the basesrc because there seems to be a default seek in the initialization?

https://gitlab.freedesktop.org/gstreamer/gstreamer/-/blob/master/libs/gst/base/gstbasesrc.c#L1823

0:00:00.146469458 29690 0x7fb678204930 DEBUG                 appsrc gstappsrc.c:924:gst_app_src_start:<mux_V> starting
0:00:00.146503993 29690 0x7fb678204930 DEBUG                basesrc gstbasesrc.c:3586:gst_base_src_start_complete:<mux_V> starting source
0:00:00.146526604 29690 0x7fb678204930 DEBUG                basesrc gstbasesrc.c:3607:gst_base_src_start_complete:<mux_V> format: time, have size: 0, size: 18446744073709551615, duration: -1
0:00:00.146529520 29690 0x7fb678204930 DEBUG                basesrc gstbasesrc.c:3613:gst_base_src_start_complete:<mux_V> is seekable: 0
0:00:00.146532516 29690 0x7fb678204930 DEBUG                basesrc gstbasesrc.c:3618:gst_base_src_start_complete:<mux_V> is random_access: 0
0:00:00.146536288 29690 0x7fb678204930 DEBUG                basesrc gstbasesrc.c:1690:gst_base_src_perform_seek:<mux_V> doing seek: (NULL)
0:00:00.146539012 29690 0x7fb678204930 DEBUG                basesrc gstbasesrc.c:1746:gst_base_src_perform_seek:<mux_V> seek with seqnum 62
0:00:00.146564698 29690 0x7fb678204930 DEBUG                basesrc gstbasesrc.c:1781:gst_base_src_perform_seek:<mux_V> segment configured from 0 to -1, position 0
0:00:00.146592988 29690 0x7fb678204930 INFO                 basesrc gstbasesrc.c:1430:gst_base_src_do_seek:<mux_V> seeking: 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
0:00:00.146906528 29690 0x7fb678204930 DEBUG                basesrc gstbasesrc.c:3723:gst_base_src_start_wait:<mux_V> got ok

Still no idea on how to "cancel" this segment since we got the proper one from x264enc

mariannasb · 2021-08-09T11:59:15Z

My best guess at the moment is that you are missing calling the appsrc->create() function (are only calling basesrc->create()), which seems to handle the segment:

https://github.com/RidgeRun/gst-interpipe/blob/master/gst/interpipe/gstinterpipesrc.c#L463

https://gitlab.freedesktop.org/gstreamer/gst-plugins-base/-/blob/master/gst-libs/gst/app/gstappsrc.c#L1676

https://gitlab.freedesktop.org/gstreamer/gstreamer/-/blob/master/libs/gst/base/gstbasesrc.c#L1570

So I have created #98 which does some of the segment handling from appsrc->create().
Seems to do the trick, though I don't know enough about the elements to see if I'm missing something.

It was missing something like what is done in appsrc->create(): https://gitlab.freedesktop.org/gstreamer/gst-plugins-base/-/blob/master/gst-libs/gst/app/gstappsrc.c#L1676 Related to RidgeRun#96

mariannasb · 2021-08-10T12:13:50Z

So #98 makes this work:

pipelines.append("v4l2src ! videoconvert ! "
                 "x264enc key-int-max=30 speed-preset=1 tune=zerolatency name=enc_out ! video/x-h264,profile=high ! h264parse ! "
                 "interpipesink name=video_out sync=false async=false "
                 "interpipesrc name=mux_V listen-to=video_out is-live=true stream-sync=passthrough-ts format=time ! "
                 "queue name=input_V ! mpegtsmux name=mux_out ! queue ! rtpmp2tpay ! udpsink port=7000 host=127.0.0.1 sync=0 "
                 "autoaudiosrc ! "
                 "interpipesink name=audio_out sync=false async=false "
                 "interpipesrc name=mux_A listen-to=audio_out is-live=true stream-sync=passthrough-ts format=time ! "
                 "queue ! audioconvert ! queue ! avenc_aac ! queue name=input_A ! mux_out. ")

However if I split it into 3 different pipelines it stops working again.
And I can see that is because there is something wrong with the timestamps on the events:

0:00:00.642750485 34587 0x7f647025dd20 DEBUG           interpipesrc gstinterpipesrc.c:748:gst_inter_pipe_src_push_event:<mux_V> Event segment with calculated timestamp 5124095:34:33.706131237 enqueued on serial pending events

So I have tracked the problem to here: https://github.com/RidgeRun/gst-interpipe/blob/master/gst/interpipe/gstinterpipesrc.c#L723
If srcbasetime > basetime and GST_EVENT_TIMESTAMP (event) == 0 you end up with a negative value for GST_EVENT_TIMESTAMP (event).

I have now added a fix for that as well in #98

Send all queued events with "timestamp < buffer timestamp" instead of just the 1st one before sending the buffer. Only the 1st event of the event queue with "timestamp < buffer timestamp" was being send before the buffer. But there could be several events in the queue that should sent before the buffer. Fixes RidgeRun#96 The segment event was not being handled properly when using x264enc + mpegtsmux together with interpipesrc/sink. Which was causing 2 segment to be delivered to the mpegtsmux: 1st one generated by the interpipesrc (starting from zero) because no segment existed. 2nd coming from the x264 encoder (correcting the 1000 hours offset added by the encoder). The 1st segment resulted in all subsequent DTS being seen as invalid (backwards) by the muxer. This happened because the event queue contained the following: stream-start, segment, tag, tag, tag. All with timestamp 0. But only the stream-start was sent, then the 1st buffer, then the segment. Which caused the DTS issues.

It was missing something like what is done in appsrc->create(): https://gitlab.freedesktop.org/gstreamer/gst-plugins-base/-/blob/master/gst-libs/gst/app/gstappsrc.c#L1676 Related to RidgeRun#96

Send all queued events with "timestamp < buffer timestamp" instead of just the 1st one before sending the buffer. Only the 1st event of the event queue with "timestamp < buffer timestamp" was being send before the buffer. But there could be several events in the queue that should sent before the buffer. Fixes RidgeRun#96 The segment event was not being handled properly when using x264enc + mpegtsmux together with interpipesrc/sink. Which was causing 2 segment to be delivered to the mpegtsmux: 1st one generated by the interpipesrc (starting from zero) because no segment existed. 2nd coming from the x264 encoder (correcting the 1000 hours offset added by the encoder). The 1st segment resulted in all subsequent DTS being seen as invalid (backwards) by the muxer. This happened because the event queue contained the following: stream-start, segment, tag, tag, tag. All with timestamp 0. But only the stream-start was sent, then the 1st buffer, then the segment. Which caused the DTS issues.

It was missing something like what is done in appsrc->create(): https://gitlab.freedesktop.org/gstreamer/gst-plugins-base/-/blob/master/gst-libs/gst/app/gstappsrc.c#L1676 Related to RidgeRun#96

mariannasb mentioned this issue Aug 6, 2021

Fix event queue handling mariannasb/gst-interpipe#2

Merged

mariannasb closed this as completed in mariannasb/gst-interpipe#2 Aug 6, 2021

mariannasb reopened this Aug 6, 2021

mariannasb mentioned this issue Aug 6, 2021

Event queue fix #97

Open

michaelgruner added the bug label Aug 6, 2021

This was referenced Aug 6, 2021

timestamp issues when using interpipe together with x264enc #89

Closed

Switch interpipesrc with MPEG-TS data between live and filesrc #88

Closed

This was referenced Aug 9, 2021

Fix segment handling in interpipesrc mariannasb/gst-interpipe#3

Merged

Fix segment handling in interpipesrc #98

Open

mariannasb mentioned this issue Sep 30, 2021

Fix segment handling in interpipesrc #102

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Problem when using x264enc + mpegtsmux #96

Problem when using x264enc + mpegtsmux #96

mariannasb commented Aug 5, 2021

mariannasb commented Aug 5, 2021

mariannasb commented Aug 5, 2021

mariannasb commented Aug 6, 2021

michaelgruner commented Aug 6, 2021

michaelgruner commented Aug 6, 2021

mariannasb commented Aug 9, 2021

mariannasb commented Aug 9, 2021

mariannasb commented Aug 9, 2021 •

edited

Loading

mariannasb commented Aug 10, 2021

Problem when using x264enc + mpegtsmux #96

Problem when using x264enc + mpegtsmux #96

Comments

mariannasb commented Aug 5, 2021

mariannasb commented Aug 5, 2021

mariannasb commented Aug 5, 2021

mariannasb commented Aug 6, 2021

michaelgruner commented Aug 6, 2021

michaelgruner commented Aug 6, 2021

mariannasb commented Aug 9, 2021

mariannasb commented Aug 9, 2021

mariannasb commented Aug 9, 2021 • edited Loading

mariannasb commented Aug 10, 2021

mariannasb commented Aug 9, 2021 •

edited

Loading