gst-interpipe icon indicating copy to clipboard operation
gst-interpipe copied to clipboard

Published 20 hours ago • verified publisher icon RidgeRun

Problem when using x264enc + mpegtsmux

Open mariannasb opened this issue 3 years ago • 9 comments

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.

mariannasb avatar Aug 05 '21 11:08 mariannasb

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 avatar Aug 05 '21 12:08 mariannasb

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 avatar Aug 05 '21 13:08 mariannasb

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.

mariannasb avatar Aug 06 '21 07:08 mariannasb

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 avatar Aug 06 '21 23:08 michaelgruner

PR #97 is a potential fix for this report.

michaelgruner avatar Aug 06 '21 23:08 michaelgruner

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 avatar Aug 09 '21 07:08 mariannasb

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 avatar Aug 09 '21 11:08 mariannasb

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 https://github.com/RidgeRun/gst-interpipe/pull/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.

mariannasb avatar Aug 09 '21 11:08 mariannasb

So https://github.com/RidgeRun/gst-interpipe/pull/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 https://github.com/RidgeRun/gst-interpipe/pull/98

mariannasb avatar Aug 10 '21 12:08 mariannasb