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
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!
-----------------------------------------------------------------------------------------------------------------------
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