Checking Instantaneous Latencies - 2023.1 English

Measuring Instantaneous Latency for Serial Pipeline

To check the instantaneous latencies, run the following command:

GST_DEBUG="GST_TRACER:7" GST_TRACERS=latency GST_DEBUG_FILE="/run/instantaneous_latency_serial_4k_avc.txt" gst-launch-1.0 -v v4l2srcio-mode=dmabuf-import device=/dev/video0 num-buffers=1000 '!' video/x-raw, width=3840, height=2160, format=NV12, framerate=60/1 '!' omxh264enc control-rate=low-latency target-bitrate=20000 filler-data=0 prefetch-buffer=TRUE num-slices=16 '!' video/x-h264, alignment=nal '!' queue max-size-buffers=0 '!' omxh264dec low-latency=1 '!' queue max-size-bytes=0 '!' fpsdisplaysink name=fpssink text-overlay=false 'video-sink=kmssink bus-id=a0070000.v_mix plane-id=32 hold-extra-sample=1 show-preroll=false sync=true' sync=true -v
vi /run/instantaneous_latency_serial_4k_avc.txt
ement-reported-latency, element-id=(string)%s, element=(string)%s, live=(boolean)%i, min=(guint64)%lu, max=(guint64)%lu, ts=(guint64)%lu;

src0, src=(string)src, sink-element-id=(string)0x559373a200, sink-element=(string)fpssink, sink=(string)sink, time=(guint64)621055684, ts=(guint64)1162727046

src0, src=(string)src, sink-element-id=(string)0x559373a200, sink-element=(string)fpssink, sink=(string)sink, time=(guint64)477090690, ts=(guint64)1194432314

src0, src=(string)src, sink-element-id=(string)0x559373a200, sink-element=(string)fpssink, sink=(string)sink, time=(guint64)460875449, ts=(guint64)1194776858

src0, src=(string)src, sink-element-id=(string)0x559373a200, sink-element=(string)fpssink, sink=(string)sink, time=(guint64)30808839, ts=(guint64)1678839645;

src0, src=(string)src, sink-element-id=(string)0x559373a200, sink-element=(string)fpssink, sink=(string)sink, time=(guint64)25715240, ts=(guint64)1693021362;

src0, src=(string)src, sink-element-id=(string)0x559373a200, sink-element=(string)fpssink, sink=(string)sink, time=(guint64)11618481, ts=(guint64)1709828871;

src0, src=(string)src, sink-element-id=(string)0x559373a200, sink-element=(string)fpssink, sink=(string)sink, time=(guint64)9285958, ts=(guint64)1726560813;

src0, src=(string)src, sink-element-id=(string)0x559373a200, sink-element=(string)fpssink, sink=(string)sink, time=(guint64)9199919, ts=(guint64)1743164022;

src0, src=(string)src, sink-element-id=(string)0x559373a200, sink-element=(string)fpssink, sink=(string)sink, time=(guint64)9160456, ts=(guint64)1759786273;

src0, src=(string)src, sink-element-id=(string)0x559373a200, sink-element=(string)fpssink, sink=(string)sink, time=(guint64)9220741, ts=(guint64)1776525395;

src0, src=(string)src, sink-element-id=(string)0x559373a200, sink-element=(string)fpssink, sink=(string)sink, time=(guint64)9283527, ts=(guint64)1793272278;

src0, src=(string)src, sink-element-id=(string)0x559373a200, sink-element=(string)fpssink, sink=(string)sink, time=(guint64)9489308, ts=(guint64)1810173597;

src0, src=(string)src, sink-element-id=(string)0x559373a200, sink-element=(string)fpssink, sink=(string)sink, time=(guint64)9632312, ts=(guint64)1826959224;

src0, src=(string)src, sink-element-id=(string)0x559373a200, sink-element=(string)fpssink, sink=(string)sink, time=(guint64)9166446, ts=(guint64)1843155083;

The initial few readings might go high due to the initialization time, and after that the latency becomes stable, as shown in the previous snapshot where it stabilizes to ~9.4 ms.

The latencies should only be measured accurately when pipeline synchronization is set as enabled (sync=true). The instantaneous latencies might go high (up to one frame period) because GStreamer has an extra margin of buffer duration (except Xilinx low-latency mode). So, if the instantaneous latency is under the reported latency + buffer duration, it does not drop frames.

Total latency = MAX (pipeline reported latency (16 ms), AVG (instantaneous latency) (9.4 ms))

For the preceding use case, the total latency is 16 ms.

Measuring Latencies with Streaming Pipeline

Gstreamer Stream-out Pipeline

GST_DEBUG="GST_TRACER:7" GST_TRACERS="latency" GST_DEBUG_FILE=/run/server.txt gst-launch-1.0 v4l2src io-mode=4 device=/dev/video0 ! video/x-raw, width=3840, height=2160, format=NV12, framerate=60/1 ! omxh265enc qp-mode=auto gop-mode=low-delay-p gop-length=60 periodicity-idr=60 b-frames=0 target-bitrate=60000 num-slices=8 control-rate=low-latency prefetch-buffer=TRUE low-bandwidth=false filler-data=0 cpb-size=1000 initial-delay=500 ! video/x-h265, alignment=nal ! queue max-size-buffers=0 ! rtph265pay ! udpsink host=192.168.25.89 port=5004 buffer-size=60000000 max-bitrate=120000000 max-lateness=-1 qos-dscp=60 async=false

Check for the time (in nanosecond for latency) marked in bold in the following logs. The initial few readings may go high due to initialization time and after that it will become stable. For example, the following logs shows ~12 ms of latency for stream-out pipeline.

0:00:21.633532492 20066  0x558abfb8a0 TRACE      GST_TRACER :0:: latency, 
src-element-id=(string)0x558abea190, src-element=(string)v4l2src0, src=(string)src, 
sink-element-id=(string)0x558ac2b9e0, sink-element=(string)udpsink0, 
sink=(string)sink, time=(guint64)12399379, ts=(guint64)21633482297;

0:00:21.650023739 20066  0x558abfb8a0 TRACE      GST_TRACER :0:: latency, 
src-element-id=(string)0x558abea190, src-element=(string)v4l2src0, src=(string)src, 
sink-element-id=(string)0x558ac2b9e0, sink-element=(string)udpsink0, 
sink=(string)sink, time=(guint64)12221661, ts=(guint64)21649971634;
12017981, ts=(guint64)21666434929;

Gstreamer Stream-in Pipeline

GST_DEBUG="GST_TRACER:7" GST_TRACERS="latency" GST_DEBUG_FILE=/run/client.txt gst-launch-1.0 udpsrc port=5004 buffer-size=60000000 caps="application/x-rtp, media=video, clock-rate=90000, payload=96, encoding-name=H265" ! queue ! rtph265depay ! h265parse ! video/x-h265, alignment=nal ! omxh265dec low-latency=1 ! video/x-raw ! queue max-size-bytes=0 ! fpsdisplaysink name=fpssink text-overlay=false video-sink="kmssink bus-id=a0070000.v_mix plane-id=30" sync=true

Check for the time (in nanosecond for latency) marked in bold in the following logs. The initial few readings may go high due to initialization time and after that it will become stable. For example, the following logs shows ~17 ms of latency for stream-in pipeline.

0:00:11.979430881 6989  0x557ba91000 TRACE      GST_TRACER :0:: latency, 
src-element-id=(string)0x557bb83480, src-element=(string)udpsrc0, src=(string)src, 
sink-element-id=(string)0x557bbce130, sink-element=(string)fpssink, 
sink=(string)sink, time=(guint64)16888957, ts=(guint64)11979242832;
15518371, ts=(guint64)12011235439;
15872096, ts=(guint64)12028272281;