Pipeline latency

[José Rafael]

Hi All

I need a way to estimate the latency inserted by the pipeline, from source to sink.

One source and one sink on each case.

One way I found was with tracers, but when using it with filesrc I get a segmentation fault (trace below).

Would you suggest another way to get this information?

Rebuilding the packages is also an option.

Thanks for any help or advice.

Best Regards

Rafael

---

GST_DEBUG="GST_TRACER:7" GST_TRACERS=latency ./encoder --dst-host=127.0.0.1 --dst-port=10200  --vid-filename=/root/Sample_1280x720.yuv  --vid-width=1280  --vid-height=720  --vid-frame-rate=25 --dst-plain

(...)

0:00:00.023130186 18340      0x1ebaa30 DEBUG             GST_TRACER gsttracer.c:163:gst_tracer_register:<registry0> update existing feature 0x1cf81b0 (latency)

0:00:00.023173239 18340      0x1ebaa30 DEBUG             GST_TRACER gsttracer.c:163:gst_tracer_register:<registry0> update existing feature 0x1cf8270 (log)

0:00:00.023186850 18340      0x1ebaa30 DEBUG             GST_TRACER gsttracer.c:163:gst_tracer_register:<registry0> update existing feature 0x1cf8330 (rusage)

0:00:00.023199345 18340      0x1ebaa30 DEBUG             GST_TRACER gsttracer.c:163:gst_tracer_register:<registry0> update existing feature 0x1cf83f0 (stats)

0:00:00.023234725 18340      0x1ebaa30 TRACE             GST_TRACER gsttracerrecord.c:110:gst_tracer_record_build_format: latency.class, src=(structure)"scope\,\ type\=\(GType\)NULL\,\ related-to\=\(GstTracerValueScope\)GST_TRACER_VALUE_SCOPE_PAD\;", sink=(structure)"scope\,\ type\=\(GType\)NULL\,\ related-to\=\(GstTracerValueScope\)GST_TRACER_VALUE_SCOPE_PAD\;", time=(structure)"value\,\ type\=\(GType\)NULL\,\ description\=\(string\)\"time\\\ it\\\ took\\\ for\\\ the\\\ buffer\\\ to\\\ go\\\ from\\\ src\\\ to\\\ sink\\\ ns\"\,\ flags\=\(GstTracerValueFlags\)GST_TRACER_VALUE_FLAGS_AGGREGATED\,\ min\=\(guint64\)0\,\ max\=\(guint64\)18446744073709551615\;";

0:00:00.023289384 18340      0x1ebaa30 DEBUG             GST_TRACER gsttracerrecord.c:124:gst_tracer_record_build_format: new format string: latency, src=(string)%s, sink=(string)%s, time=(guint64)%lu;

(encoder:18340): GLib-GObject-WARNING **: g_object_set_valist: passed '0' as denominator for `GstFraction'

Starting playback

Running...

MSG:1520958248814309:state-changed:enc_tx_sink:NULL->READY

MSG:1520958248814326:state-changed:enc_tx_rtppay:NULL->READY

MSG:1520958248814341:state-changed:enc_tx_enc:NULL->READY

MSG:1520958248814353:state-changed:enc_tx_videoparse:NULL->READY

MSG:1520958248814366:state-changed:enc_tx_src:NULL->READY

MSG:1520958248814380:state-changed:tx:NULL->READY

MSG:1520958248814397:state-changed:enc_tx_rtppay:READY->PAUSED

MSG:1520958248814413:state-changed:enc_tx_enc:READY->PAUSED

MSG:1520958248814434:state-changed:enc_tx_videoparse:READY->PAUSED

MSG:1520958248814449:state-changed:enc_tx_src:READY->PAUSED

MSG:1520958248834557:state-changed:enc_tx_sink:READY->PAUSED

MSG:1520958248834594:state-changed:tx:READY->PAUSED

0:00:00.050286313 18340      0x1eed5e0 TRACE             GST_TRACER :0:: latency, src=(string)enc_tx_src_src, sink=(string)enc_tx_sink_sink, time=(guint64)10552137;

MSG:1520958248835001:state-changed:enc_tx_sink:PAUSED->PLAYING

MSG:1520958248835044:state-changed:enc_tx_rtppay:PAUSED->PLAYING

MSG:1520958248835061:state-changed:enc_tx_enc:PAUSED->PLAYING

MSG:1520958248835074:state-changed:enc_tx_videoparse:PAUSED->PLAYING

MSG:1520958248835087:state-changed:enc_tx_src:PAUSED->PLAYING

MSG:1520958248835103:state-changed:tx:PAUSED->PLAYING

(encoder:18340): GStreamer-CRITICAL **: gst_event_get_structure: assertion 'GST_IS_EVENT (event)' failed

(encoder:18340): GStreamer-CRITICAL **: gst_structure_id_get: assertion 'GST_IS_STRUCTURE (structure)' failed

Segmentation fault

---

_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel

[Nicolas Dufresne-5]

Le mardi 13 mars 2018 à 17:30 +0100, José Rafael a écrit :

> Hi All
>
> I need a way to estimate the latency inserted by the pipeline, from
> source to sink.
> One source and one sink on each case.
> One way I found was with tracers, but when using it with filesrc I
> get a segmentation fault (trace below).
>
> Would you suggest another way to get this information?
>
> Rebuilding the packages is also an option.

It should not crash, but you'd need to give more information to allow
reproducing or debugging.

>
> Thanks for any help or advice.
>
> Best Regards
> Rafael
>
> ---
> GST_DEBUG="GST_TRACER:7" GST_TRACERS=latency ./encoder --dst-
> host=127.0.0.1 --dst-port=10200  --vid-
> filename=/root/Sample_1280x720.yuv  --vid-width=1280  --vid-
> height=720  --vid-frame-rate=25 --dst-plain
> (...)
> 0:00:00.023130186 18340      0x1ebaa30 DEBUG             GST_TRACER
> gsttracer.c:163:gst_tracer_register:<registry0> update existing
> feature 0x1cf81b0 (latency)
> 0:00:00.023173239 18340      0x1ebaa30 DEBUG             GST_TRACER
> gsttracer.c:163:gst_tracer_register:<registry0> update existing
> feature 0x1cf8270 (log)
> 0:00:00.023186850 18340      0x1ebaa30 DEBUG             GST_TRACER
> gsttracer.c:163:gst_tracer_register:<registry0> update existing
> feature 0x1cf8330 (rusage)
> 0:00:00.023199345 18340      0x1ebaa30 DEBUG             GST_TRACER
> gsttracer.c:163:gst_tracer_register:<registry0> update existing
> feature 0x1cf83f0 (stats)
> 0:00:00.023234725 18340      0x1ebaa30 TRACE             GST_TRACER
> gsttracerrecord.c:110:gst_tracer_record_build_format: latency.class,
> src=(structure)"scope\,\ type\=\(GType\)NULL\,\ related-
> to\=\(GstTracerValueScope\)GST_TRACER_VALUE_SCOPE_PAD\;",
> sink=(structure)"scope\,\ type\=\(GType\)NULL\,\ related-
> to\=\(GstTracerValueScope\)GST_TRACER_VALUE_SCOPE_PAD\;",
> time=(structure)"value\,\ type\=\(GType\)NULL\,\
> description\=\(string\)\"time\\\ it\\\ took\\\ for\\\ the\\\
> buffer\\\ to\\\ go\\\ from\\\ src\\\ to\\\ sink\\\ ns\"\,\
> flags\=\(GstTracerValueFlags\)GST_TRACER_VALUE_FLAGS_AGGREGATED\,\
> min\=\(guint64\)0\,\ max\=\(guint64\)18446744073709551615\;";
> 0:00:00.023289384 18340      0x1ebaa30 DEBUG             GST_TRACER
> gsttracerrecord.c:124:gst_tracer_record_build_format: new format
> string: latency, src=(string)%s, sink=(string)%s, time=(guint64)%lu;
>
> (encoder:18340): GLib-GObject-WARNING **: g_object_set_valist: passed
> '0' as denominator for `GstFraction'
> Starting playback
> Running...
> MSG:1520958248814309:state-changed:enc_tx_sink:NULL->READY
> MSG:1520958248814326:state-changed:enc_tx_rtppay:NULL->READY
> MSG:1520958248814341:state-changed:enc_tx_enc:NULL->READY
> MSG:1520958248814353:state-changed:enc_tx_videoparse:NULL->READY
> MSG:1520958248814366:state-changed:enc_tx_src:NULL->READY
> MSG:1520958248814380:state-changed:tx:NULL->READY
> MSG:1520958248814397:state-changed:enc_tx_rtppay:READY->PAUSED
> MSG:1520958248814413:state-changed:enc_tx_enc:READY->PAUSED
> MSG:1520958248814434:state-changed:enc_tx_videoparse:READY->PAUSED
> MSG:1520958248814449:state-changed:enc_tx_src:READY->PAUSED
> MSG:1520958248834557:state-changed:enc_tx_sink:READY->PAUSED
> MSG:1520958248834594:state-changed:tx:READY->PAUSED
> 0:00:00.050286313 18340      0x1eed5e0 TRACE             GST_TRACER
> :0:: latency, src=(string)enc_tx_src_src,
> sink=(string)enc_tx_sink_sink, time=(guint64)10552137;
> MSG:1520958248835001:state-changed:enc_tx_sink:PAUSED->PLAYING
> MSG:1520958248835044:state-changed:enc_tx_rtppay:PAUSED->PLAYING
> MSG:1520958248835061:state-changed:enc_tx_enc:PAUSED->PLAYING
> MSG:1520958248835074:state-changed:enc_tx_videoparse:PAUSED->PLAYING
> MSG:1520958248835087:state-changed:enc_tx_src:PAUSED->PLAYING
> MSG:1520958248835103:state-changed:tx:PAUSED->PLAYING
>
> (encoder:18340): GStreamer-CRITICAL **: gst_event_get_structure:
> assertion 'GST_IS_EVENT (event)' failed
>
> (encoder:18340): GStreamer-CRITICAL **: gst_structure_id_get:
> assertion 'GST_IS_STRUCTURE (structure)' failed
> Segmentation fault
> ---
>
> _______________________________________________
> gstreamer-devel mailing list
> [hidden email]
> https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel

_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel

[Baby Octopus]

To get latency, do a query through gst_query_parse_latency() and get the
min_latency. Max latency will
you the max amount of time the data can get buffered in the pipeline

~BO



--
Sent from: http://gstreamer-devel.966125.n4.nabble.com/
_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel

[José Rafael]

Hi!

Thank you. I tried with the code below:

static void check_latency (GstElement *element){

        GstQuery * query;

        gboolean live;

        GstClockTime min_latency, max_latency;

        g_print ( "DELAY: latency query\n" );

        query = gst_query_new_latency();

        if (!gst_element_query(GST_ELEMENT_CAST (element), query)){

                g_print ( "DELAY: error getting latency\n" );

        } else {

                gst_query_parse_latency (query, &live, &min_latency, &max_latency);

                gst_query_unref(query);

                g_print ( "DELAY: min_latency %lu %" GST_TIME_FORMAT "ms\n",min_latency, GST_TIME_ARGS(min_latency) );

        }

}

I am calling it from this tick_latency call using the sink element as parameter:

static gboolean tick_latency (gpointer data)

{

        check_latency(sink);

        return TRUE;

}

g_timeout_add (100, tick_latency, NULL);

However, the result is always zero. Do you see a problem? A reason to be zero?

In the log (below) this zero latency is returned through the pipeline.

Thanks for the help, don't know other way to collect this delay value.

[]s

Rafael

DELAY: latency query

0:00:23.013069583 25082      0x1710600 DEBUG                  query gstquery.c:674:gst_query_new_custom: creating new query 0x190acf0 latency

0:00:23.013155881 25082      0x1710600 DEBUG               basesink gstbasesink.c:1120:gst_base_sink_query_latency:<enc_tx_sink> we are ready for LATENCY query

0:00:23.013261063 25082      0x1710600 DEBUG                  query gstquery.c:674:gst_query_new_custom: creating new query 0x190aa30 latency

0:00:23.013284896 25082      0x1710600 DEBUG               GST_PADS gstpad.c:4042:gst_pad_peer_query:<enc_tx_sink:sink> peer query 0x190aa30 (latency)

0:00:23.013402964 25082      0x1710600 DEBUG               GST_PADS gstpad.c:3915:gst_pad_query:<enc_tx_rtppay:src> doing query 0x190aa30 (latency)

0:00:23.013573045 25082      0x1710600 DEBUG                  query gstquery.c:674:gst_query_new_custom: creating new query 0x190aca0 latency

0:00:23.013616803 25082      0x1710600 DEBUG               GST_PADS gstpad.c:4042:gst_pad_peer_query:<enc_tx_rtppay:sink> peer query 0x190aca0 (latency)

0:00:23.013671896 25082      0x1710600 DEBUG               GST_PADS gstpad.c:3915:gst_pad_query:<enc_tx_enc:src> doing query 0x190aca0 (latency)

0:00:23.013740225 25082      0x1710600 DEBUG           videoencoder gstvideoencoder.c:1298:gst_video_encoder_src_query:<enc_tx_enc> received query 7683, latency

0:00:23.013768880 25082      0x1710600 LOG             videoencoder gstvideoencoder.c:1233:gst_video_encoder_src_query_default:<enc_tx_enc> handling query: latency query: 0x190aca0, GstQueryLatency, live=(boolean)false, min-latency=(guint64)0, max-latency=(guint64)18446744073709551615;

0:00:23.013812794 25082      0x1710600 DEBUG               GST_PADS gstpad.c:4042:gst_pad_peer_query:<enc_tx_enc:sink> peer query 0x190aca0 (latency)

0:00:23.013868931 25082      0x1710600 DEBUG               GST_PADS gstpad.c:3915:gst_pad_query:<enc_tx_videoparse:src> doing query 0x190aca0 (latency)

0:00:23.013923871 25082      0x1710600 DEBUG               rawparse gstrawparse.c:957:gst_raw_parse_src_query: src_query latency

0:00:23.014137909 25082      0x1710600 DEBUG                  query gstquery.c:674:gst_query_new_custom: creating new query 0x190a850 latency

0:00:23.014193904 25082      0x1710600 DEBUG               GST_PADS gstpad.c:4042:gst_pad_peer_query:<enc_tx_videoparse:sink> peer query 0x190a850 (latency)

0:00:23.014248918 25082      0x1710600 DEBUG               GST_PADS gstpad.c:3915:gst_pad_query:<enc_tx_src:src> doing query 0x190a850 (latency)

0:00:23.014306937 25082      0x1710600 LOG                  basesrc gstbasesrc.c:733:gst_base_src_query_latency:<enc_tx_src> latency: live 0, min 0:00:00.000000000, max 0:00:00.000000000

0:00:23.014329539 25082      0x1710600 LOG                  basesrc gstbasesrc.c:1188:gst_base_src_default_query:<enc_tx_src> report latency: live 0, min 0:00:00.000000000, max 0:00:00.000000000

0:00:23.014358112 25082      0x1710600 DEBUG                basesrc gstbasesrc.c:1296:gst_base_src_default_query:<enc_tx_src> query latency returns 1

0:00:23.014426751 25082      0x1710600 DEBUG               GST_PADS gstpad.c:3938:gst_pad_query:<enc_tx_src:src> sent query 0x190a850 (latency), result 1

0:00:23.014483790 25082      0x1710600 LOG                 GST_PADS gstpad.c:3216:query_latency_default_fold:<enc_tx_videoparse:sink> got latency live:false min:0 max:0

0:00:23.014596087 25082      0x1710600 LOG                 GST_PADS gstpad.c:3287:gst_pad_query_latency_default:<enc_tx_videoparse:src> got latency live:false min:0 max:-1

0:00:23.014624050 25082      0x1710600 DEBUG               GST_PADS gstpad.c:3372:gst_pad_query_default:<enc_tx_videoparse:src> not forwarding 0x190aca0 (latency) query

0:00:23.014672412 25082      0x1710600 DEBUG               GST_PADS gstpad.c:3938:gst_pad_query:<enc_tx_videoparse:src> sent query 0x190aca0 (latency), result 1

0:00:23.014745701 25082      0x1710600 DEBUG           videoencoder gstvideoencoder.c:1262:gst_video_encoder_src_query_default:<enc_tx_enc> Peer latency: live 0, min 0:00:00.000000000 max 99:99:99.999999999

0:00:23.014782668 25082      0x1710600 DEBUG               GST_PADS gstpad.c:3938:gst_pad_query:<enc_tx_enc:src> sent query 0x190aca0 (latency), result 1

0:00:23.014823211 25082      0x1710600 LOG                 GST_PADS gstpad.c:3216:query_latency_default_fold:<enc_tx_rtppay:sink> got latency live:false min:0 max:-1

0:00:23.014909482 25082      0x1710600 LOG                 GST_PADS gstpad.c:3287:gst_pad_query_latency_default:<enc_tx_rtppay:src> got latency live:false min:0 max:-1

0:00:23.014937584 25082      0x1710600 DEBUG               GST_PADS gstpad.c:3372:gst_pad_query_default:<enc_tx_rtppay:src> not forwarding 0x190aa30 (latency) query

0:00:23.014991787 25082      0x1710600 DEBUG               GST_PADS gstpad.c:3938:gst_pad_query:<enc_tx_rtppay:src> sent query 0x190aa30 (latency), result 1

0:00:23.015118808 25082      0x1710600 DEBUG               basesink gstbasesink.c:1162:gst_base_sink_query_latency:<enc_tx_sink> latency query: live: 1, have_latency 1, upstream: 0, min 0:00:00.000000000, max 99:99:99.999999999

0:00:23.015140338 25082      0x1710600 DEBUG               basesink gstbasesink.c:4915:default_element_query:<enc_tx_sink> query latency returns 1

DELAY: min_latency 0 0:00:00.000000000ms

On 14 March 2018 at 13:29, Baby Octopus <[hidden email]> wrote:

To get latency, do a query through gst_query_parse_latency() and get the
min_latency. Max latency will
you the max amount of time the data can get buffered in the pipeline

~BO



--
Sent from: http://gstreamer-devel.966125.n4.nabble.com/

_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel

_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel

[Baby Octopus]

Do you have sync=1 set for the sink element? Latency isn't applicable if the
pipeline is not synced

Easiest way to check latency is the do --gst-debug=basesink:5, and look for
message something like "Possibly waiting for the clock". It should two
timings, current and adjusted. Difference should give you the latency(min
latency)

~BO



--
Sent from: http://gstreamer-devel.966125.n4.nabble.com/
_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel

[José Rafael]

Hi BO

I included the sync for udpsink and do-timestamp for filesrc.

Always with the same values, difference zero, as below (for a 3840x2160 raw file). What makes sense with the zero given by the query.

basesink gstbasesink.c:2547:gst_base_sink_do_sync:<enc_tx_sink> possibly waiting for clock to reach 0:00:00.240000000, adjusted 0:00:00.240000000

My pipeline is filesrc/videoparse/x264enc/rtph264pay/udpsink.

Another way may solve my problem, if I can print the timestamps for the first buffer processed by the source and the sink. Maybe not the ideal measure point, but probably suits my need.

Still trying to figure it out here ;-)

Thanks!

[]s

Rafael

On 15 March 2018 at 19:17, Baby Octopus <[hidden email]> wrote:

Do you have sync=1 set for the sink element? Latency isn't applicable if the
pipeline is not synced

Easiest way to check latency is the do --gst-debug=basesink:5, and look for
message something like "Possibly waiting for the clock". It should two
timings, current and adjusted. Difference should give you the latency(min
latency)

~BO



--
Sent from: http://gstreamer-devel.966125.n4.nabble.com/
_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel

_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel