Nvv4l2decoder/nvv4l2h264enc with gst-rtsp-server latency increasement

[vexit123]

Hi, I build gst-rtsp-server and run the test-launch with 6 cameras in jetson Xavier(r35.2.1).

./test-launch "( rtspsrc buffer-mode=none location=rtsp://192.168.123.33:8554/test_x latency=0 ! rtph265depay ! nvv4l2decoder disable-dpb=true enable-max-performance=true ! nvv4l2h264enc bitrate=8000000 idrinterval=32 maxperf-enable=true control-rate=1 preset-level=1 profile=2 insert-sps-pps=true ! rtph264pay name=pay0 )"

test_x is test_0 to test_5 for each cameras.
And get the 6 streams with below

gst-launch rtspsrc location=rtsp://192.168.123.200:85xx/test latency=0 ! rtph264depay ! avdec_h264 ! videoconvert ! autovideosink sync=false

85xx is 8554~8559 for each streams.
At first, latency of each stream was almost same like ~300ms.
But as time goes by, like 4~6 hours, some of stream shows higher latency like 600~800ms and others shows stil ~300ms.

I have experience of below situation.

Gstreamer RSTP server with nvcompositor latency increases as time goes by

Hi, I build gst-rtsp-server and run the test-launch with below command ./test-launch "( rtspsrc buffer-mode=none location=rtsp://192.168.123.33:8554/media latency=0 ! rtph265depay ! nvv4l2decoder enable-max-performance=true ! comp.sink_0 nvcompositor name=comp sink_0::xpos=0 sink_0::ypos=0 sink_0::width=1280 sink_0::height=720 sink_1::xpos=1280 sink_1::ypos=0 sink_1::width=1280 sink_1::height=720 sink_2::xpos=2560 sink_2::ypos=0 sink_2::width=1280 sink_2::height=720 sink_3::xpos=0 sink_3::ypos=…

So I applied different IDR frame, but it seems like show same phenomenon.

Could it be nvv4l2decoder or nvv4l2h264enc that occur increament in latency?

Thank you for help in advance.

[DaneLLL]

Hi,
For comparison, you may try

1. execute sudo nvpmodel -m 0 and sudo jetson_clocks
2. UDP:
   Gstreamer TCPserversink 2-3 seconds latency - #5 by DaneLLL
3. try IDR interval = 15 or 30
4. use videotestsrc in the test-launch command

The latency may be from the rtspsrc, This should be identified by comparing with videotestsrc. Besides, RTSP may have higher latency than UDP.

[vexit123]

Hi, thank you for your help.

Actually I already tried 1, 3 and maximum VIC frequency but there was no difference.
About UDP protocol, currently I can’t apply this one because I need to use TCP based protocol.
Lastly, how can I check latency between streams with videotestsrc?
I think videotestsrc only shows video repeatly.

By any chance, any other options that I can test or pipeline option for rtspsrc?

[DaneLLL]

Hi,
It seems not possible to show video preview in test-launch. Would be great if you can try
Gstreamer TCPserversink 2-3 seconds latency - #5 by DaneLLL

We can check timestamp added by timeoverlay plugin.

[vexit123]

I just started the test like below.

1. Set UDP option in gst-rtsp-server and playing
2. Set videotestsrc and playing

I’ll let you know the result ASAP

Thank you for your help!

[vexit123]

Hi, I tested few hours.

1. Set UDP option in gst-rtsp-server and playing:
   used rtspsrc and send it via rtsp but with GST_RTSP_LOWER_TRANS_UDP option. I checked it with wireshark and it works via UDP.
   This shows latency increasement in some camera.

2. Set videotestsrc and playing:
   I want to check this one at simultaneously, because I can’t open the 6 stream at once, I used nvcompositor.
   Seems like works, but the time shown in display was slightly different about 2.5ms I think it’s acceptable.
   I’ll keep this test more longer

If using rtspsrc for the stream source is problem, what can I do? and If I send stream with gst-rtsp-server and client get the stream with rtspsrc, would it show same problem?

[DaneLLL]

Hi,
Not sure if it helps but may try to set latency to 100 or 200ms, and drop-on-latency=true to rtspsrc. To have some room for buffering in the source.

[vexit123]

Hi,
If I apply drop-on-latency option, stream shows strange image.
I’ll test with 100ms latency and will let you know the result.

Thank you!

[vexit123]

Hi DaneLLL,

After quit a long time, videotestsrc works fine.
And about the applying 100ms latency shows increasement in latency.

Any other advice for this one?

[DaneLLL]

Hi,
It seems to be an issue in the camera source. We would suggest check if there is parameters you can configure the source and try.

For gstreamer command, one more thing to try is to add queue element between certain elements, such as

rtspsrc ! rtph265depay ! h265parse ! queue ! nvv4l2decoder ! ...

rtspsrc ! queue ! rtph265depay ! h265parse ! nvv4l2decoder ! queue ! nvv4l2h264enc ! ...

[vexit123]

Hi,

Thank you for your advice.

I’ll try the queue and will update the result!

[vexit123]

Hi,
I used rtspsrc ! rtph265depay ! h265parse ! queue ! nvv4l2decoder ! …
And if I run the pipeline sometimes pipeline get EOS but the test-launch is still alive.
What would be the reason?

Thank you.

[DaneLLL]

Hi,
Not sure but probably the network is not stable. But if you don’t see the issue while using videotestsrc, the network seems to be good.

Maybe you can try to configure the source to lower resolution such as 640x480, so that it may not be impacted by network bandwidth.

[vexit123]

Hi thank you for quick reply,

I just found that if I remove h265parse from the pipeline it works.

Still need to check the latency, I’ll update the result.

Thank you.

[DaneLLL]

Hi,
The h265parse plugin will filter out invalid data. If it is absent, invalid data will go to decoder and it may not work properly. We would suggest investigate why invalid data occurs. This may by why this issue occurs.

[vexit123]

Hi,

I just found that while rendering the stream if stream get IDR frame, stream occurs some stuck like below.

0:00:13.006349664 126999 0xaaaae3b02b60 DEBUG               basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<fakesink0> rendering object 0xffff48069120
0:00:13.040127072 126999 0xaaaae3b02b60 DEBUG               basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<fakesink0> rendering object 0xffff48069240
0:00:13.076663904 126999 0xaaaae3b02b60 DEBUG               basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<fakesink0> rendering object 0xffff48069360
0:00:13.116330560 126999 0xaaaae3b02b60 DEBUG               basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<fakesink0> rendering object 0xffff48069480
0:00:13.139838976 126999 0xaaaae3b02b60 DEBUG               basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<fakesink0> rendering object 0xffff480695a0
0:00:13.173847424 126999 0xaaaae3b02b60 DEBUG               basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<fakesink0> rendering object 0xffff480bf480
0:00:13.211266560 126999 0xaaaae3b02b60 DEBUG               basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<fakesink0> rendering object 0xffff480bf5a0
0:00:13.236013728 126999 0xaaaae3b02b60 DEBUG               basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<fakesink0> rendering object 0xffff480bf6c0
0:00:13.236739776 126999 0xaaaae3b02b60 DEBUG               basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<fakesink0> rendering object 0xffff480bf7e0
0:00:13.237306816 126999 0xaaaae3b02b60 DEBUG               basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<fakesink0> rendering object 0xffff48061d80
0:00:13.237718400 126999 0xaaaae3b02b60 DEBUG               basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<fakesink0> rendering object 0xffff48061ea0
0:00:13.238665120 126999 0xaaaae3b02b60 DEBUG               basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<fakesink0> rendering object 0xffff48069000
0:00:13.239143136 126999 0xaaaae3b02b60 DEBUG               basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<fakesink0> rendering object 0xffff48061360
0:00:13.239627232 126999 0xaaaae3b02b60 DEBUG               basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<fakesink0> rendering object 0xffff48061480
0:00:13.240064992 126999 0xaaaae3b02b60 DEBUG               basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<fakesink0> rendering object 0xffff48069120
0:00:13.501994208 126999 0xaaaae3b02b60 DEBUG               basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<fakesink0> rendering object 0xffff48069240
0:00:13.537057056 126999 0xaaaae3b02b60 DEBUG               basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<fakesink0> rendering object 0xffff48069360
0:00:13.579987936 126999 0xaaaae3b02b60 DEBUG               basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<fakesink0> rendering object 0xffff48069480
0:00:13.606857792 126999 0xaaaae3b02b60 DEBUG               basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<fakesink0> rendering object 0xffff480695a0

It seems like from 13.236013728~13.240064992 is stucking.

This could be the reason?

[DaneLLL]

Hi,
IDR frames have larger size than P frames, so it may be related to network bandwidth. Not sure if it helps but you may try:

Random blockiness in the picture RTSP server-client -Jetson TX2

Hi, Please refer to this post: H264 vs H265 - #4 by DaneLLL We suggest try vbv-size in bitrate/fps ~ 2*(bitrate/fps). In the example, the source is 50fps and bitrate is 14Mbps. May set in the range 280000 ~ 560000.

Furthermore, you can set this property to have stricter bitrate:

  EnableTwopassCBR    : Enable two pass CBR while encoding
                        flags: readable, writable, changeable only in NULL or READY state
                        Boolean. Default: false

[vexit123]

Hi, thank you for your quick reply.

I applied vbv-size=2*(bitrate/fps) and EnableTwopassCBR=true.

And it shows same results, also when get IDR frame streams seems to have degradation.

Could you give me another advice for this one?

[DaneLLL]

Hi,
Maybe you can add queue plugin in receiving the stream and make sure one complete IDR frame data is received. And then send to decoder.

[vexit123]

Hi, I got this one when I use h265parse.

0:28:47.286245846 59299 0x563dfaa98cc0 DEBUG               basesink gstbasesink.c:2712:gst_base_sink_do_sync:<fakesink0> clock returned 4, jitter  0:00:00.000000000
0:28:47.286248183 59299 0x563dfaa98cc0 DEBUG               basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<fakesink0> rendering object 0x7fdff800f120
0:28:47.286250687 59299 0x563dfaa98cc0 DEBUG               basesink gstbasesink.c:1014:gst_base_sink_set_last_buffer_unlocked:<fakesink0> setting last buffer to 0x7fdff800f120
0:28:47.286260143 59299 0x563dfaa98cc0 DEBUG               basesink gstbasesink.c:3680:gst_base_sink_chain_unlocked:<fakesink0> object unref after render 0x7fdff800f120
0:28:47.293521560 59299 0x7fe028019400 DEBUG               basesink gstbasesink.c:3354:gst_base_sink_event:<udpsink1> received event 0x7fe00801f110 eos event: 0x7fe00801f110, time 99:99:99.999999999, seq-num 174, (NULL)
0:28:47.293546075 59299 0x7fe028019400 DEBUG               basesink gstbasesink.c:2063:gst_base_sink_get_sync_times:<udpsink1> sync times for EOS 99:99:99.999999999
0:28:47.293549026 59299 0x7fe028019400 DEBUG               basesink gstbasesink.c:3223:gst_base_sink_default_event:<udpsink1> Now posting EOS
0:28:47.293551416 59299 0x7fe028019400 DEBUG               basesink gstbasesink.c:3226:gst_base_sink_default_event:<udpsink1> Got seqnum #174
0:28:47.308819326 59299 0x563dfaa98cc0 DEBUG               basesink gstbasesink.c:3523:gst_base_sink_chain_unlocked:<fakesink0> got times start: 0:28:46.282855833, end: 0:28:46.322855833
0:28:47.308833172 59299 0x563dfaa98cc0 DEBUG               basesink gstbasesink.c:2110:gst_base_sink_get_sync_times:<fakesink0> got times start: 0:28:46.282855833, stop: 0:28:46.322855833, do_sync 1
0:28:47.308838831 59299 0x563dfaa98cc0 DEBUG               basesink gstbasesink.c:2693:gst_base_sink_do_sync:<fakesink0> reset rc_time to time 0:28:46.282855833
0:28:47.308866459 59299 0x563dfaa98cc0 DEBUG               basesink gstbasesink.c:2704:gst_base_sink_do_sync:<fakesink0> possibly waiting for clock to reach 0:28:46.282855833, adjusted 0:28:46.282855833
0:28:47.308868495 59299 0x563dfaa98cc0 DEBUG               basesink gstbasesink.c:2326:gst_base_sink_wait_clock:<fakesink0> sync disabled
0:28:47.308871689 59299 0x563dfaa98cc0 DEBUG               basesink gstbasesink.c:2712:gst_base_sink_do_sync:<fakesink0> clock returned 4, jitter  0:00:00.000000000
0:28:47.308874207 59299 0x563dfaa98cc0 DEBUG               basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<fakesink0> rendering object 0x7fdff800f240
0:28:47.308876141 59299 0x563dfaa98cc0 DEBUG               basesink gstbasesink.c:1014:gst_base_sink_set_last_buffer_unlocked:<fakesink0> setting last buffer to 0x7fdff800f240
0:28:47.308886271 59299 0x563dfaa98cc0 DEBUG               basesink gstbasesink.c:3680:gst_base_sink_chain_unlocked:<fakesink0> object unref after render 0x7fdff800f240
0:28:47.309144392 59299 0x563dfaa98cc0 DEBUG               basesink gstbasesink.c:3354:gst_base_sink_event:<fakesink0> received event 0x7fe00c005480 eos event: 0x7fe00c005480, time 99:99:99.999999999, seq-num 110, (NULL)
0:28:47.309156123 59299 0x563dfaa98cc0 DEBUG               basesink gstbasesink.c:2063:gst_base_sink_get_sync_times:<fakesink0> sync times for EOS 0:28:46.322855833
0:28:47.309159148 59299 0x563dfaa98cc0 DEBUG               basesink gstbasesink.c:2693:gst_base_sink_do_sync:<fakesink0> reset rc_time to time 0:28:46.322855833
0:28:47.309162433 59299 0x563dfaa98cc0 DEBUG               basesink gstbasesink.c:2704:gst_base_sink_do_sync:<fakesink0> possibly waiting for clock to reach 0:28:46.322855833, adjusted 0:28:46.322855833
0:28:47.309164241 59299 0x563dfaa98cc0 DEBUG               basesink gstbasesink.c:2326:gst_base_sink_wait_clock:<fakesink0> sync disabled
0:28:47.309167217 59299 0x563dfaa98cc0 DEBUG               basesink gstbasesink.c:2712:gst_base_sink_do_sync:<fakesink0> clock returned 4, jitter  0:00:00.000000000
0:28:47.309168982 59299 0x563dfaa98cc0 DEBUG               basesink gstbasesink.c:3223:gst_base_sink_default_event:<fakesink0> Now posting EOS
0:28:47.309171011 59299 0x563dfaa98cc0 DEBUG               basesink gstbasesink.c:3226:gst_base_sink_default_event:<fakesink0> Got seqnum #110
Got EOS from element "pipeline0".
Execution ended after 0:28:46.302412038
0:28:47.309314750 59299 0x563dfaa7fac0 DEBUG               basesink gstbasesink.c:5256:gst_base_sink_change_state:<fakesink0> PLAYING to PAUSED
0:28:47.309324961 59299 0x563dfaa7fac0 DEBUG               basesink gstbasesink.c:5265:gst_base_sink_change_state:<fakesink0> got preroll lock
0:28:47.309330192 59299 0x563dfaa7fac0 DEBUG               basesink gstbasesink.c:3443:gst_base_sink_needs_preroll:<fakesink0> have_preroll: 0, EOS: 1 => needs preroll: 0
0:28:47.309333713 59299 0x563dfaa7fac0 DEBUG               basesink gstbasesink.c:5278:gst_base_sink_change_state:<fakesink0> PLAYING to PAUSED, we are prerolled
0:28:47.309337772 59299 0x563dfaa7fac0 DEBUG               basesink gstbasesink.c:5300:gst_base_sink_change_state:<fakesink0> rendered: 51795, dropped: 0
0:28:47.309671044 59299 0x563dfaa7fac0 DEBUG               basesink gstbasesink.c:4261:gst_base_sink_set_flushing:<fakesink0> flushing out data thread, need preroll to TRUE
0:28:47.309688148 59299 0x563dfaa7fac0 DEBUG               basesink gstbasesink.c:1014:gst_base_sink_set_last_buffer_unlocked:<fakesink0> setting last buffer to (nil)
0:28:47.309694602 59299 0x563dfaa7fac0 DEBUG               basesink gstbasesink.c:5341:gst_base_sink_change_state:<fakesink0> PAUSED to READY, don't need_preroll
0:28:47.316762836 59299 0x563dfaa98c00 DEBUG               basesink gstbasesink.c:5256:gst_base_sink_change_state:<udpsink0> PLAYING to PAUSED
0:28:47.316775601 59299 0x563dfaa98c00 DEBUG               basesink gstbasesink.c:5265:gst_base_sink_change_state:<udpsink0> got preroll lock
0:28:47.316786519 59299 0x563dfaa98c00 DEBUG               basesink gstbasesink.c:3443:gst_base_sink_needs_preroll:<udpsink0> have_preroll: 0, EOS: 1 => needs preroll: 0
0:28:47.316789658 59299 0x563dfaa98c00 DEBUG               basesink gstbasesink.c:5278:gst_base_sink_change_state:<udpsink0> PLAYING to PAUSED, we are prerolled
0:28:47.316793450 59299 0x563dfaa98c00 DEBUG               basesink gstbasesink.c:5300:gst_base_sink_change_state:<udpsink0> rendered: 5, dropped: 0
0:28:47.316801700 59299 0x563dfaa98c00 DEBUG               basesink gstbasesink.c:4261:gst_base_sink_set_flushing:<udpsink0> flushing out data thread, need preroll to TRUE
0:28:47.316807246 59299 0x563dfaa98c00 DEBUG               basesink gstbasesink.c:1014:gst_base_sink_set_last_buffer_unlocked:<udpsink0> setting last buffer to (nil)
0:28:47.316831747 59299 0x563dfaa98c00 DEBUG               basesink gstbasesink.c:5256:gst_base_sink_change_state:<udpsink1> PLAYING to PAUSED
0:28:47.316834030 59299 0x563dfaa98c00 DEBUG               basesink gstbasesink.c:5265:gst_base_sink_change_state:<udpsink1> got preroll lock
0:28:47.316837345 59299 0x563dfaa98c00 DEBUG               basesink gstbasesink.c:3443:gst_base_sink_needs_preroll:<udpsink1> have_preroll: 0, EOS: 1 => needs preroll: 0
0:28:47.316838972 59299 0x563dfaa98c00 DEBUG               basesink gstbasesink.c:5278:gst_base_sink_change_state:<udpsink1> PLAYING to PAUSED, we are prerolled
0:28:47.316840948 59299 0x563dfaa98c00 DEBUG               basesink gstbasesink.c:5300:gst_base_sink_change_state:<udpsink1> rendered: 360, dropped: 0
0:28:47.316844642 59299 0x563dfaa98c00 DEBUG               basesink gstbasesink.c:4261:gst_base_sink_set_flushing:<udpsink1> flushing out data thread, need preroll to TRUE
0:28:47.316849540 59299 0x563dfaa98c00 DEBUG               basesink gstbasesink.c:1014:gst_base_sink_set_last_buffer_unlocked:<udpsink1> setting last buffer to (nil)

Could you give an advice for this one?