AnsweredAssumed Answered

Shortening live video streaming latency

Question asked by Efe Can İçöz on Apr 27, 2020
Latest reply on May 3, 2020 by igorpadykov

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

Outcomes