Shortening live video streaming latency

[efecan_icoz]

Hi all,

I'm currently using i.MX8M Mini with yocto warrior (kernel is 4.19.35) with wayland. I have a camera on MIPI CSI2 (4lane 576mhz, 1 channel) bus and I'm streaming it with below command:

gst-launch-1.0 v4l2src device="/dev/video0" ! "video/x-raw, format=(string)UYVY, width=(int)1920, height=(int)1080, framerate=(fraction)25/1" ! imxvideoconvert_g2d !  waylandsink
‍‍‍

Currently I'm having 160-200ms of latency, which is quite high. What is my options to trace the bottleneck ? Is there any way to profile the gstreamer pipe, or at least see what is happening with timestamps (to see which part is creating this latency).

Here is log of gst-launch printing one frame  in debug level 5.

As i see from logs (please correct me if I'm wrong) v4l2 signals there is a new frame at the beginning (t=0) and imxvideoconvert_g2d is scheduled at 121738392 (+0.3ms) and wayland's hook is called at 130134037 (+8,6ms). I'm not sure where is the drawing the frame on screen is complete and what those QoS messages trying to tell me.

0:00:02.121438270  2402      0x1afdd40 INFO                 v4l2src gstv4l2src.c:961:gst_v4l2src_create:<v4l2src0> sync to 0:00:00.560000000 out ts 0:00:00.820877116
0:00:02.121468020  2402      0x1afdd40 DEBUG                basesrc gstbasesrc.c:2375:gst_base_src_do_sync:<v4l2src0> no sync needed
0:00:02.121493645  2402      0x1afdd40 DEBUG                basesrc gstbasesrc.c:2612:gst_base_src_get_range:<v4l2src0> buffer ok
0:00:02.121552769  2402      0x1afdd40 DEBUG         GST_SCHEDULING gstpad.c:4324:gst_pad_chain_data_unchecked:<capsfilter0:sink> calling chainfunction &gst_base_transform_chain with buffer buffer: 0x1be5a20, pts 0:00:00.820877116, dts 99:99:99.999999999, dur 0:00:00.040000000, size 4147200, offset 386, offset_end 387, flags 0x0
0:00:02.121603518  2402      0x1afdd40 DEBUG          basetransform gstbasetransform.c:1994:default_submit_input_buffer:<capsfilter0> handling buffer 0x1be5a20 of size 4147200, PTS 0:00:00.820877116 and offset 386
0:00:02.121633768  2402      0x1afdd40 DEBUG          basetransform gstbasetransform.c:2111:default_generate_output:<capsfilter0> calling prepare buffer
0:00:02.121664643  2402      0x1afdd40 DEBUG          basetransform gstbasetransform.c:2118:default_generate_output:<capsfilter0> using allocated buffer in 0x1be5a20, out 0x1be5a20
0:00:02.121690642  2402      0x1afdd40 DEBUG          basetransform gstbasetransform.c:2135:default_generate_output:<capsfilter0> doing inplace transform
0:00:02.121738392  2402      0x1afdd40 DEBUG         GST_SCHEDULING gstpad.c:4324:gst_pad_chain_data_unchecked:<imxvideoconvert_g2d0:sink> calling chainfunction &gst_base_transform_chain with buffer buffer: 0x1be5a20, pts 0:00:00.820877116, dts 99:99:99.999999999, dur 0:00:00.040000000, size 4147200, offset 386, offset_end 387, flags 0x0
0:00:02.121784641  2402      0x1afdd40 DEBUG          basetransform gstbasetransform.c:1994:default_submit_input_buffer:<imxvideoconvert_g2d0> handling buffer 0x1be5a20 of size 4147200, PTS 0:00:00.820877116 and offset 386
0:00:02.121812391  2402      0x1afdd40 DEBUG          basetransform gstbasetransform.c:2111:default_generate_output:<imxvideoconvert_g2d0> calling prepare buffer
0:00:02.121838015  2402      0x1afdd40 DEBUG          basetransform gstbasetransform.c:1614:default_prepare_output_buffer:<imxvideoconvert_g2d0> using pool alloc
0:00:02.121867515  2402      0x1afdd40 DEBUG          basetransform gstbasetransform.c:1754:default_copy_metadata:<imxvideoconvert_g2d0> copying metadata
0:00:02.121906640  2402      0x1afdd40 DEBUG          basetransform gstbasetransform.c:1721:foreach_metadata:<imxvideoconvert_g2d0> not copying memory specific metadata GstVideoMetaAPI
0:00:02.121937389  2402      0x1afdd40 DEBUG          basetransform gstbasetransform.c:2118:default_generate_output:<imxvideoconvert_g2d0> using allocated buffer in 0x1be5a20, out 0x1be56c0
0:00:02.121962889  2402      0x1afdd40 DEBUG          basetransform gstbasetransform.c:2138:default_generate_output:<imxvideoconvert_g2d0> doing non-inplace transform
0:00:02.122012513  2402      0x1afdd40 DEBUG             GST_BUFFER gstbuffer.c:1221:gst_buffer_get_memory_range: idx 0, length 1
0:00:02.122051388  2402      0x1afdd40 DEBUG             GST_BUFFER gstbuffer.c:1221:gst_buffer_get_memory_range: idx 0, length 1
0:00:02.122139887  2402      0x1afdd40 DEBUG               GST_CAPS gstpad.c:2733:gst_pad_get_current_caps:<imxvideoconvert_g2d0:sink> get current pad caps video/x-raw, format=(string)UYVY, width=(int)1920, height=(int)1080, framerate=(fraction)25/1, pixel-aspect-ratio=(fraction)1/1, colorimetry=(string)bt709, interlace-mode=(string)progressive
0:00:02.122200136  2402      0x1afdd40 DEBUG             video-info video-info.c:403:gst_video_info_from_caps: parsing caps video/x-raw, format=(string)UYVY, width=(int)1920, height=(int)1080, framerate=(fraction)25/1, pixel-aspect-ratio=(fraction)1/1, colorimetry=(string)bt709, interlace-mode=(string)progressive
0:00:02.122267885  2402      0x1afdd40 INFO         imxvideoconvert gstimxvideoconvert.c:1392:imx_video_convert_transform_frame:<imxvideoconvert_g2d0> buffer modifier type 0
0:00:02.122354759  2402      0x1afdd40 DEBUG            imx2ddevice imx_2d_device_g2d.c:408:imx_g2d_blit: src paddr fd vaddr: 0xb7800000 31 (nil) dst paddr fd vaddr: 0xb6400000 23 (nil)
0:00:02.122386009  2402      0x1afdd40 DEBUG            imx2ddevice imx_2d_device_g2d.c:436:imx_g2d_blit: src paddr: 0xb7800000 dst paddr: 0xb6400000
0:00:02.129807291  2402      0x1afdd40 DEBUG         v4l2bufferpool gstv4l2bufferpool.c:1508:gst_v4l2_buffer_pool_release_buffer:<v4l2src0:pool:src> release buffer 0x1be5a20
0:00:02.130134037  2402      0x1afdd40 DEBUG         GST_SCHEDULING gstpad.c:4324:gst_pad_chain_data_unchecked:<waylandsink0:sink> calling chainfunction &gst_base_sink_chain with buffer buffer: 0x1be56c0, pts 0:00:00.820877116, dts 99:99:99.999999999, dur 0:00:00.040000000, size 8355840, offset 386, offset_end 387, flags 0x0
0:00:02.130222786  2402      0x1afdd40 DEBUG               basesink gstbasesink.c:3524:gst_base_sink_chain_unlocked:<waylandsink0> got times start: 0:00:00.820877116, end: 0:00:00.860877116
0:00:02.130289285  2402      0x1afdd40 DEBUG               basesink gstbasesink.c:2112:gst_base_sink_get_sync_times:<waylandsink0> got times start: 0:00:00.820877116, stop: 0:00:00.860877116, do_sync 1
0:00:02.130353284  2402      0x1afdd40 DEBUG               basesink gstbasesink.c:2694:gst_base_sink_do_sync:<waylandsink0> reset rc_time to time 0:00:00.875877116
0:00:02.130399909  2402      0x1afdd40 DEBUG               basesink gstbasesink.c:2706:gst_base_sink_do_sync:<waylandsink0> possibly waiting for clock to reach 0:00:00.820877116, adjusted 0:00:00.875877116
0:00:02.130461783  2402      0x1afdd40 DEBUG              GST_CLOCK gstclock.c:557:gst_clock_id_wait:<GstSystemClock> waiting on clock entry 0xffff880431b0
0:00:02.130510282  2402      0x1afdd40 DEBUG              GST_CLOCK gstclock.c:1092:gst_clock_get_internal_time:<GstSystemClock> internal time 0:04:23.591640655
0:00:02.130553032  2402      0x1afdd40 DEBUG              GST_CLOCK gstclock.c:1137:gst_clock_get_time:<GstSystemClock> adjusted time 0:04:23.591640655
0:00:02.130607156  2402      0x1afdd40 DEBUG              GST_CLOCK gstsystemclock.c:714:gst_system_clock_id_wait_jitter_unlocked: entry 0xffff880431b0 time 0:04:23.619837001 now 0:04:23.591640655 diff (time-now) 28196346
0:00:02.130653031  2402      0x1afdd40 DEBUG               GST_POLL gstpoll.c:1414:gst_poll_wait: 0x1afde80: timeout :0:00:00.028196346
0:00:02.133554369  2402      0x1afdd90 DEBUG               GST_POLL gstpoll.c:1414:gst_poll_wait: 0x1afe0a0: timeout :99:99:99.999999999
0:00:02.159039051  2402      0x1afdd40 DEBUG              GST_CLOCK gstsystemclock.c:742:gst_system_clock_id_wait_jitter_unlocked: entry 0xffff880431b0 unlocked, status 3, ret 0
0:00:02.159128925  2402      0x1afdd40 DEBUG              GST_CLOCK gstsystemclock.c:766:gst_system_clock_id_wait_jitter_unlocked: entry 0xffff880431b0 unlocked after timeout
0:00:02.159181175  2402      0x1afdd40 DEBUG              GST_CLOCK gstclock.c:1092:gst_clock_get_internal_time:<GstSystemClock> internal time 0:04:23.620300798
0:00:02.159224424  2402      0x1afdd40 DEBUG              GST_CLOCK gstclock.c:1137:gst_clock_get_time:<GstSystemClock> adjusted time 0:04:23.620300798
0:00:02.159261049  2402      0x1afdd40 DEBUG              GST_CLOCK gstsystemclock.c:788:gst_system_clock_id_wait_jitter_unlocked: entry 0xffff880431b0 finished, diff -463797
0:00:02.159293548  2402      0x1afdd40 DEBUG              GST_CLOCK gstclock.c:567:gst_clock_id_wait:<GstSystemClock> done waiting entry 0xffff880431b0, res: 0 (ok)
0:00:02.159345798  2402      0x1afdd40 DEBUG               basesink gstbasesink.c:2713:gst_base_sink_do_sync:<waylandsink0> clock returned 0, jitter -0:00:00.028196346
0:00:02.159375922  2402      0x1afdd40 DEBUG               basesink gstbasesink.c:3024:gst_base_sink_is_too_late:<waylandsink0> object was scheduled in time
0:00:02.159401672  2402      0x1afdd40 DEBUG               basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<waylandsink0> rendering object 0x1be56c0
0:00:02.159427172  2402      0x1afdd40 DEBUG               basesink gstbasesink.c:1014:gst_base_sink_set_last_buffer_unlocked:<waylandsink0> setting last buffer to 0x1be56c0
0:00:02.159490546  2402      0x1afdd40 DEBUG            waylandsink wlwindow.c:571:gst_wl_window_render: use explicit sync create buffer release (GstBuffer: 0x1be56c0)
0:00:02.159617919  2402      0x1afdd40 DEBUG                GST_QOS gstbasesink.c:2854:gst_base_sink_perform_qos:<waylandsink0> start: 0:00:00.820877116, stop 0:00:00.860877116, entered 0:00:00.792680770, left 0:00:00.820877116, pt: 0:00:00.011813654, duration 0:00:00.045584054,jitter -28196346
0:00:02.159682043  2402      0x1afdd40 DEBUG                GST_QOS gstbasesink.c:2858:gst_base_sink_perform_qos:<waylandsink0> avg_pt: 0:00:00.014692969, avg_rate: 0.315799
0:00:02.159719168  2402      0x1afdd40 DEBUG                GST_QOS gstbasesink.c:2888:gst_base_sink_perform_qos:<waylandsink0> updated: avg_pt: 0:00:00.014333054, avg_rate: 0.315713
0:00:02.159756042  2402      0x1afdd40 DEBUG                GST_QOS gstbasesink.c:2782:gst_base_sink_send_qos:<waylandsink0> qos: type 0, proportion: 0.315713, diff -28196346, timestamp 0:00:00.820877116
0:00:02.159816667  2402      0x1afdd40 DEBUG              GST_EVENT gstevent.c:309:gst_event_new_custom: creating new event 0xffff88006260 qos 48641
0:00:02.159939165  2402      0x1afdd40 DEBUG              GST_EVENT gstpad.c:5697:gst_pad_send_event_unchecked:<imxvideoconvert_g2d0:src> have event type qos event: 0xffff88006260, time 99:99:99.999999999, seq-num 63, GstEventQOS, type=(GstQOSType)GST_QOS_TYPE_OVERFLOW, proportion=(double)0.31571310603274672, diff=(gint64)-28196346, timestamp=(guint64)820877116;
0:00:02.160025289  2402      0x1afdd40 DEBUG          basetransform gstbasetransform.c:1950:gst_base_transform_src_eventfunc:<imxvideoconvert_g2d0> handling event 0xffff88006260 qos event: 0xffff88006260, time 99:99:99.999999999, seq-num 63, GstEventQOS, type=(GstQOSType)GST_QOS_TYPE_OVERFLOW, proportion=(double)0.31571310603274672, diff=(gint64)-28196346, timestamp=(guint64)820877116;
0:00:02.160074288  2402      0x1afdd40 DEBUG                GST_QOS gstbasetransform.c:2654:gst_base_transform_update_qos:<imxvideoconvert_g2d0> qos: proportion: 0.315713, diff -28196346, timestamp 0:00:00.820877116
0:00:02.160140538  2402      0x1afdd40 DEBUG              GST_EVENT gstpad.c:5697:gst_pad_send_event_unchecked:<capsfilter0:src> have event type qos event: 0xffff88006260, time 99:99:99.999999999, seq-num 63, GstEventQOS, type=(GstQOSType)GST_QOS_TYPE_OVERFLOW, proportion=(double)0.31571310603274672, diff=(gint64)-28196346, timestamp=(guint64)820877116;
0:00:02.160212287  2402      0x1afdd40 DEBUG          basetransform gstbasetransform.c:1950:gst_base_transform_src_eventfunc:<capsfilter0> handling event 0xffff88006260 qos event: 0xffff88006260, time 99:99:99.999999999, seq-num 63, GstEventQOS, type=(GstQOSType)GST_QOS_TYPE_OVERFLOW, proportion=(double)0.31571310603274672, diff=(gint64)-28196346, timestamp=(guint64)820877116;
0:00:02.160258536  2402      0x1afdd40 DEBUG                GST_QOS gstbasetransform.c:2654:gst_base_transform_update_qos:<capsfilter0> qos: proportion: 0.315713, diff -28196346, timestamp 0:00:00.820877116
0:00:02.160319910  2402      0x1afdd40 DEBUG              GST_EVENT gstpad.c:5697:gst_pad_send_event_unchecked:<v4l2src0:src> have event type qos event: 0xffff88006260, time 99:99:99.999999999, seq-num 63, GstEventQOS, type=(GstQOSType)GST_QOS_TYPE_OVERFLOW, proportion=(double)0.31571310603274672, diff=(gint64)-28196346, timestamp=(guint64)820877116;
0:00:02.160387535  2402      0x1afdd40 DEBUG                basesrc gstbasesrc.c:2042:gst_base_src_default_event:<v4l2src0> handle event qos event: 0xffff88006260, time 99:99:99.999999999, seq-num 63, GstEventQOS, type=(GstQOSType)GST_QOS_TYPE_OVERFLOW, proportion=(double)0.31571310603274672, diff=(gint64)-28196346, timestamp=(guint64)820877116;
0:00:02.160434409  2402      0x1afdd40 DEBUG                GST_QOS gstbasesrc.c:2028:gst_base_src_update_qos:<v4l2src0> qos: proportion: 0.315713, diff -28196346, timestamp 0:00:00.820877116
0:00:02.160474533  2402      0x1afdd40 DEBUG               GST_PADS gstpad.c:5780:gst_pad_send_event_unchecked:<v4l2src0:src> sent event, ret ok
0:00:02.160506658  2402      0x1afdd40 DEBUG               GST_PADS gstpad.c:5780:gst_pad_send_event_unchecked:<capsfilter0:src> sent event, ret ok
0:00:02.160538158  2402      0x1afdd40 DEBUG               GST_PADS gstpad.c:5780:gst_pad_send_event_unchecked:<imxvideoconvert_g2d0:src> sent event, ret ok
0:00:02.160569532  2402      0x1afdd40 DEBUG               basesink gstbasesink.c:3680:gst_base_sink_chain_unlocked:<waylandsink0> object unref after render 0x1be56c0
0:00:02.160605907  2402      0x1afdd40 DEBUG         GST_SCHEDULING gstpad.c:4330:gst_pad_chain_data_unchecked:<waylandsink0:sink> called chainfunction &gst_base_sink_chain with buffer 0x1be56c0, returned ok
0:00:02.160647656  2402      0x1afdd40 DEBUG         GST_SCHEDULING gstpad.c:4330:gst_pad_chain_data_unchecked:<imxvideoconvert_g2d0:sink> called chainfunction &gst_base_transform_chain with buffer 0x1be5a20, returned ok
0:00:02.160684781  2402      0x1afdd40 DEBUG         GST_SCHEDULING gstpad.c:4330:gst_pad_chain_data_unchecked:<capsfilter0:sink> called chainfunction &gst_base_transform_chain with buffer 0x1be5a20, returned ok
0:00:02.160728155  2402      0x1afdd40 DEBUG                basesrc gstbasesrc.c:2521:gst_base_src_get_range:<v4l2src0> calling create offset 18446744073709551615 length 4096, time 0
0:00:02.160763530  2402      0x1afdd40 DEBUG         v4l2bufferpool gstv4l2bufferpool.c:1430:gst_v4l2_buffer_pool_acquire_buffer:<v4l2src0:pool:src> acquire
0:00:02.160803904  2402      0x1afdd40 DEBUG               GST_POLL gstpoll.c:1414:gst_poll_wait: 0xffff880041e0: timeout :99:99:99.999999999
0:00:02.160857529  2402      0x1afdd40 DEBUG               GST_POLL gstpoll.c:1241:gst_poll_fd_has_error: 0xffff880041e0: fd (fd:25, idx:1) 0
0:00:02.160918903  2402      0x1afdd40 DEBUG         v4l2bufferpool gstv4l2bufferpool.c:1839:gst_v4l2_buffer_pool_process:<v4l2src0:pool:src> process buffer 0xffff94c09748
0:00:02.160965402  2402      0x1afdd40 DEBUG              GST_CLOCK gstclock.c:1092:gst_clock_get_internal_time:<GstSystemClock> internal time 0:04:23.622096401
0:00:02.161004152  2402      0x1afdd40 DEBUG              GST_CLOCK gstclock.c:1137:gst_clock_get_time:<GstSystemClock> adjusted time 0:04:23.622096401
0:00:02.161061776  2402      0x1afdd40 DEBUG                v4l2src gstv4l2src.c:925:gst_v4l2src_create:<v4l2src0> ts: 0:04:23.604659000 now 0:04:23.622179275 delay 0:00:00.017520275‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

Have a nice day,

Efe

[sagarmane]

Hi @igorpadykov ,

Could you please me as well? I'm using i.MX8M Plus evk with basler camera. having a latency of 300=400ms.

Thanks for your help in advance.

[igorpadykov]

Hi Efe

I sent you some examples via mail, hope this helps.

Best regards
igor
-----------------------------------------------------------------------------------------------------------------------
Note: If this post answers your question, please click the Correct Answer button. Thank you!
-----------------------------------------------------------------------------------------------------------------------

[gebaba]

i am now meeting the same questions, would you please support some help to me?

my email: gzt08067101@126.com

thank you!

[EESTE]

Could you share those examples with us as well please.

We're running into same problem with 200-250ms latency.

[ottob]

Hi Igor ! 

Could you send those over to me as well please ? I'm seeing about 250ms using these pipelines on a imx8m plus

//UDP Video Server
gst-launch-1.0 v4l2src device=/dev/video1 ! video/x-raw,width=1920,height=1080 ! vpuenc_h264 ! rtph264pay pt=96 ! udpsink host=192.168.2.152 port=5000

//UDP Videp Client
export CAPS='"application/x-rtp, media=(string)video, clock-rate=(int)90000, encoding-name=(string)H264, packetization-mode=(string)1, payload=(int)96, seqnum-offset=(uint)30237, timestamp-offset=(uint)1709406490, ssrc=(uint)709870610, a-framerate=(string)30"'
gst-launch-1.0 udpsrc port=5000 caps = $CAPS ! rtpjitterbuffer latency=1 ! queue max-size-buffers=0 ! rtph264depay ! queue max-size-time=0 ! vpudec ! autovideosink sync=false

Thanks, 

/Otto