Wrong dts values for fdsrc before rtpbin

[Francesc Pinyol Margalef]

Hi,
On a CentOS 7 instance (3.10.0-1062.18.1.el7.x86_64), I'm using Snowmix video mixer (https://snowmix.sourceforge.io/)
version 0.5.1 with its output attached to the following pipeline (GStreamer 1.16.2, compiled from source):


outsocket=/tmp/53cc8523-dd33-47ac-8cd6-c69f42315578prog
width=320
height=180
VIDEOFORMAT="video/x-raw,framerate=25/1,width=$width,height=$height,format=BGRA,pixel-aspect-ratio=1/1"
AUDIOFORMAT="audio/x-raw,format=S16LE,layout=interleaved,rate=48000,channels=2"

( echo "audio sink ctr isaudio 1" ; sleep 1000000) | nc 127.0.0.1 $SNOWMIX_PORT | \
( head -1
   /usr/local/bin/gst-launch-1.0 -v rtpbin name=bin \
        shmsrc socket-path=$outsocket do-timestamp=true is-live=true ! \
          $VIDEOFORMAT                           ! \
          queue                                  ! \
          videoscale                             ! \
          videoconvert                           ! \
          x264enc bitrate=488 key-int-max=25 aud=false ! \
          video/x-h264,profile=baseline          ! \
          rtph264pay config-interval=0 pt=96     ! \
          bin.send_rtp_sink_0 bin.send_rtp_src_0 ! \
            udpsink host=224.0.0.0 port=7000 sync=true    \
           fdsrc fd=0 do-timestamp=true            ! \
           $AUDIOFORMAT                           ! \
           queue max-size-buffers=200 max-size-time=1000000000 max-size-bytes=192000 ! \
  identity silent=false ! \
           audiorate tolerance=40000000 skip-to-first=false ! \
           audioresample                          ! \
           audioconvert                           ! \
           queue                                  ! \
           opusenc bitrate=120000                 ! \
           rtpopuspay pt=97                       ! \
           bin.send_rtp_sink_1 bin.send_rtp_src_1 ! \
              udpsink host=224.0.0.0 port=7002 sync=true
) &

I start snowmix and then the gst-launch pipeline. Sometimes (about half of the times I start the pipeline)
snowmix gives the following error message:
Frame xxx - audio sink 1 would block"

This behaviour was reported to Snowmix (you can find more details and logs there):
https://sourceforge.net/p/snowmix/discussion/Snowmix_Support_Forum/thread/ccee999022/

Checking the logs from gst-launch, I've seen the following.

If at the beginning I get a line with a high dts (not always exactly the same high value),
after some seconds (usually less than a minute) I will get a would block error on Snowmix:


/GstPipeline:pipeline0/GstIdentity:identity0: last-message = chain   ******* (identity0:sink) (3496 bytes, dts: none, pts: none, duration: none, offset: 387980, offset_end: -1, flags: 00000000 , meta: none) 0x7fd69c02bb40
/GstPipeline:pipeline0/GstIdentity:identity0: last-message = chain   ******* (identity0:sink) (4096 bytes, dts: none, pts: none, duration: none, offset: 391476, offset_end: -1, flags: 00000000 , meta: none) 0x7fd69c02bc60
/GstPipeline:pipeline0/GstIdentity:identity0: last-message = chain   ******* (identity0:sink) (3616 bytes, dts: none, pts: none, duration: none, offset: 395572, offset_end: -1, flags: 00000000 , meta: none) 0x7fd69c02bd80
/GstPipeline:pipeline0/GstIdentity:identity0: last-message = chain   ******* (identity0:sink) (4096 bytes, dts: 9:30:20.594089255, pts: 9:30:20.594089255, duration: none, offset: 399188, offset_end: -1, flags: 00000000 , meta: none) 0x7fd69c02bea0
0:00:03.744090862 [332m13087 [00m      0x16f71e0 [36mINFO   [00m [00;01;34m           GST_EVENT gstevent.c:820:gst_event_new_caps: [00m creating caps event video/x-h264, codec_data=(buffer)0142c00dffe1001d6742c00dd901419f9f016a0c020b4a000003000200000300651e28549001000468cb8cb2, stream-format=(string)avc, alignment=(string)au, level=(string)1.3, profile=(string)baseline, width=(int)320, height=(int)180, pixel-aspect-ratio=(fraction)1/1, framerate=(fraction)25/1, interlace-mode=(string)progressive, colorimetry=(string)bt601, chroma-site=(string)jpeg


However, if dts values start at zero, I will not get a would block error on Snowmix:

/GstPipeline:pipeline0/GstIdentity:identity0: last-message = chain   ******* (identity0:sink) (3552 bytes, dts: none, pts: none, duration: none, offset: 372480, offset_end: -1, flags: 00000000 , meta: none) 0x7f990c01f6c0
/GstPipeline:pipeline0/GstIdentity:identity0: last-message = chain   ******* (identity0:sink) (4096 bytes, dts: none, pts: none, duration: none, offset: 376032, offset_end: -1, flags: 00000000 , meta: none) 0x7f990c01f7e0
/GstPipeline:pipeline0/GstIdentity:identity0: last-message = chain   ******* (identity0:sink) (3764 bytes, dts: none, pts: none, duration: none, offset: 380128, offset_end: -1, flags: 00000000 , meta: none) 0x7f990c01f900
/GstPipeline:pipeline0/GstIdentity:identity0: last-message = chain   ******* (identity0:sink) (4096 bytes, dts: 0:00:00.023109823, pts: 0:00:00.023109823, duration: none, offset: 383892, offset_end: -1, flags: 00000000 , meta: none) 0x7f990c01fa20
/GstPipeline:pipeline0/GstIdentity:identity0: last-message = chain   ******* (identity0:sink) (3416 bytes, dts: 0:00:00.023165513, pts: 0:00:00.023165513, duration: none, offset: 387988, offset_end: -1, flags: 00000000 , meta: none) 0x7f990c01fb40
/GstPipeline:pipeline0/GstIdentity:identity0: last-message = chain   ******* (identity0:sink) (4096 bytes, dts: 0:00:00.063396237, pts: 0:00:00.063396237, duration: none, offset: 391404, offset_end: -1, flags: 00000000 , meta: none) 0x7f990c01fc60
/GstPipeline:pipeline0/GstIdentity:identity0: last-message = chain   ******* (identity0:sink) (3596 bytes, dts: 0:00:00.063551013, pts: 0:00:00.063551013, duration: none, offset: 395500, offset_end: -1, flags: 00000000 , meta: none) 0x7f990c01fd80
/GstPipeline:pipeline0/GstIdentity:identity0: last-message = chain   ******* (identity0:sink) (4096 bytes, dts: 0:00:00.105300171, pts: 0:00:00.105300171, duration: none, offset: 399096, offset_end: -1, flags: 00000000 , meta: none) 0x7f990c03f480
/GstPipeline:pipeline0/GstIdentity:identity0: last-message = chain   ******* (identity0:sink) (3764 bytes, dts: 0:00:00.105402911, pts: 0:00:00.105402911, duration: none, offset: 403192, offset_end: -1, flags: 00000000 , meta: none) 0x7f990c03f360


What could be causing these wrong (9:30:20.594089255) dts values?

Francesc


--

_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel

[Francesc Pinyol Margalef]

Hi,

I've found a more compact way to reproduce the problem:

export GST_DEBUG=WARN
AUDIOCAPS="audio/x-raw,format=S16LE,layout=interleaved,rate=44100,channels=2"

gst-launch-1.0 -v audiotestsrc wave=5 ! volume volume=0.1 ! ${AUDIOCAPS} ! fdsink fd=3 3>&1 1>&2 | gst-launch-1.0 -v rtpbin name=bin fdsrc fd=0 do-timestamp=true ! "audio/x-raw,format=S16LE,layout=interleaved,rate=48000,channels=2" ! queue max-size-buffers=200 max-size-time=1000000000 max-size-bytes=192000 ! identity silent=false ! audiorate tolerance=40000000 skip-to-first=false ! audioresample ! audioconvert ! queue ! opusenc bitrate=120000 ! rtpopuspay pt=97 ! bin.send_rtp_sink_1 bin.send_rtp_src_1 ! udpsink host=224.0.0.0 port=7002 sync=true

Sometimes, dts values do not start from 0, but from another value, that turns out to be the uptime:
/GstPipeline:pipeline0/GstIdentity:identity0: last-message = chain   ******* (identity0:sink) (4096 bytes, dts: none, pts: none, duration: none, offset: 208896, offset_end: -1, flags: 00000000 , meta: none) 0x7f0454044120
/GstPipeline:pipeline0/GstIdentity:identity0: last-message = chain   ******* (identity0:sink) (4096 bytes, dts: none, pts: none, duration: none, offset: 212992, offset_end: -1, flags: 00000000 , meta: none) 0x7f0454044240
/GstPipeline:pipeline0/GstIdentity:identity0: last-message = chain   ******* (identity0:sink) (4096 bytes, dts: none, pts: none, duration: none, offset: 217088, offset_end: -1, flags: 00000000 , meta: none) 0x7f0454044360
/GstPipeline:pipeline0/GstIdentity:identity0: last-message = chain   ******* (identity0:sink) (4096 bytes, dts: 8:58:02.591006549, pts: 8:58:02.591006549, duration: none, offset: 221184, offset_end: -1, flags: 00000000 , meta: none) 0x7f

$ uptime
 18:22:19 up  8:58, 34 users,  load average: 3,81, 2,71, 2,51


--

_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel

[Francesc Pinyol Margalef]

Hi,

Sorry, the right pipeline is (use the same audio rate in both):

export GST_DEBUG=WARN
AUDIOCAPS="audio/x-raw,format=S16LE,layout=interleaved,rate=44100,channels=2"

gst-launch-1.0 -v audiotestsrc wave=5 ! volume volume=0.1 ! ${AUDIOCAPS} ! fdsink fd=3 3>&1 1>&2 | gst-launch-1.0 -v rtpbin name=bin fdsrc fd=0 do-timestamp=true ! ${AUDIOCAPS} ! queue max-size-buffers=200 max-size-time=1000000000 max-size-bytes=192000 ! identity silent=false ! audiorate tolerance=40000000 skip-to-first=false ! audioresample ! audioconvert ! queue ! opusenc bitrate=120000 ! rtpopuspay pt=97 ! bin.send_rtp_sink_1 bin.send_rtp_src_1 ! udpsink host=224.0.0.0 port=7002 sync=true

But the problem is still there.

Francesc

--

_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel

[Francesc Pinyol Margalef]

Hi,

If I remove the audiorate element, it works every time:

AUDIOCAPS="audio/x-raw,format=S16LE,layout=interleaved,rate=44100,channels=2"

gst-launch-1.0 -v audiotestsrc wave=5 ! volume volume=0.1 ! ${AUDIOCAPS} ! fdsink fd=3 3>&1 1>&2 | gst-launch-1.0 -v rtpbin name=bin fdsrc fd=0 do-timestamp=true ! ${AUDIOCAPS} ! queue ! identity silent=false ! audioresample ! audioconvert ! queue ! opusenc bitrate=120000 ! rtpopuspay pt=97 ! bin.send_rtp_sink_1 bin.send_rtp_src_1 ! udpsink host=224.0.0.0 port=7002 sync=true

Francesc

--

_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel

[Peter Maersk-Moller-2]

Hi Francesc.

Yes, the audiorate is the causing the pipeline to lock up when seeing an unexpected jump in DTS. That is too be expected. However the interesting question is, why do we see this jump in DTS (Jumping from None to 8:58:02.591006549)

Since timestamps are generated by the fdsrc, and fdsrc is receiving a bytestream pretty regularly, it make little sense to suddenly see DTS jump to almost 9 hours ....

Anyway, what causes this jump? Anybody ?

Best regards

Peter MM

On Tue, May 12, 2020 at 7:02 PM Francesc Pinyol Margalef <[hidden email]> wrote:

Hi,

If I remove the audiorate element, it works every time:

AUDIOCAPS="audio/x-raw,format=S16LE,layout=interleaved,rate=44100,channels=2"

gst-launch-1.0 -v audiotestsrc wave=5 ! volume volume=0.1 ! ${AUDIOCAPS} ! fdsink fd=3 3>&1 1>&2 | gst-launch-1.0 -v rtpbin name=bin fdsrc fd=0 do-timestamp=true ! ${AUDIOCAPS} ! queue ! identity silent=false ! audioresample ! audioconvert ! queue ! opusenc bitrate=120000 ! rtpopuspay pt=97 ! bin.send_rtp_sink_1 bin.send_rtp_src_1 ! udpsink host=224.0.0.0 port=7002 sync=true

Francesc

--

Francesc Pinyol Margalef
http://www.francescpinyol.cat/

_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel

_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel

[AniketH]

Hi Francesc and Peter,

I wonder if you found any reason for the DTS jump shown in the logs?
I'm seeing a similar issue with my program stream where I get a sudden jump of 8 hours at the start itself. My source is interleaved but I'm only concerned with the video.


Logs:
--------------
/GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = event   ******* (fakesink0:sink) E (type: stream-start (10254), GstEventStreamStart, stream-id=(string)e6b45e53ebc85973c7058ec02d96c2fa08ed800e6a49bbc619c8e8561543f10a/e0, flags=(GstStreamFlags)GST_STREAM_FLAG_NONE, group-id=(uint)1;) 0x7f91f0008720
/GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = event   ******* (fakesink0:sink) E (type: caps (12814), GstEventCaps, caps=(GstCaps)"video/mpeg\,\ mpegversion\=\(int\)2\,\ systemstream\=\(boolean\)false\,\ parsed\=\(boolean\)false";) 0x7f91f0008c20
/GstPipeline:pipeline0/GstFakeSink:fakesink0.GstPad:sink: caps = video/mpeg, mpegversion=(int)2, systemstream=(boolean)false, parsed=(boolean)false
/GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = event   ******* (fakesink0:sink) E (type: segment (17934), GstEventSegment, segment=(GstSegment)"GstSegment, flags=(GstSegmentFlags)GST_SEGMENT_FLAG_NONE, rate=(double)1, applied-rate=(double)1, format=(GstFormat)GST_FORMAT_TIME, base=(guint64)0, offset=(guint64)0, start=(guint64)0, stop=(guint64)18446744073709551615, time=(guint64)0, position=(guint64)879182, duration=(guint64)18446744073709551615;";) 0x7f91f0008d00
/GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = event   ******* (fakesink0:sink) E (type: tag (20510), GstTagList-stream, taglist=(taglist)"taglist\,\ video-codec\=\(string\)\"MPEG-2\\\ Video\"\;";) 0x7f91f0008d70
/GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = preroll   *******
/GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = chain   ******* (fakesink0:sink) (2025 bytes, dts: none, pts: none, duration: none, offset: -1, offset_end: -1, flags: 00004040 discont tag-memory , meta: none) 0x7f9204048360
/GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = chain   ******* (fakesink0:sink) (2025 bytes, dts: none, pts: none, duration: none, offset: -1, offset_end: -1, flags: 00004040 discont tag-memory , meta: none) 0x55ead85226c0
/GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = chain   ******* (fakesink0:sink) (2025 bytes, dts: none, pts: none, duration: none, offset: -1, offset_end: -1, flags: 00004000 tag-memory , meta: none) 0x55ead8522a20
/GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = chain   ******* (fakesink0:sink) (2025 bytes, dts: none, pts: none, duration: none, offset: -1, offset_end: -1, flags: 00004000 tag-memory , meta: none) 0x7f9204048360
/GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = chain   ******* (fakesink0:sink) (2025 bytes, dts: none, pts: none, duration: none, offset: -1, offset_end: -1, flags: 00004000 tag-memory , meta: none) 0x7f9204048120
/GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = chain   ******* (fakesink0:sink) (2025 bytes, dts: none, pts: none, duration: none, offset: -1, offset_end: -1, flags: 00004040 discont tag-memory , meta: none) 0x7f9204048480
/GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = chain   ******* (fakesink0:sink) (1817 bytes, dts: none, pts: none, duration: none, offset: -1, offset_end: -1, flags: 00004000 tag-memory , meta: none) 0x7f9204048120
/GstPipeline:pipeline0/GstFakeSink:fakesink0: last-message = chain   ******* (fakesink0:sink) (2020 bytes, dts: 8:45:15.005400000, pts: 8:45:15.005400000, duration: none, offset: -1, offset_end: -1, flags: 00004000 tag-memory , meta: none) 0x55ead8522b40


--
Aniket