Trying to understand the latency tracer

classic Classic list List threaded Threaded
6 messages Options
Reply | Threaded
Open this post in threaded view
|

Trying to understand the latency tracer

Damian Vicino
Hi, 
I found documentation on how to enable the GStreamer latency tracer exporting variables from the shell as follows:

export GST_TRACERS=latency
export GST_DEBUG="GST_TRACER:7"


I got log lines as the following one:
0:35:08.123456789     362   0x7f434c00fd40  TRACE           GST_TRACER :0:: latency, src=(string)nicesrc4_src, sink=(string)nicesink2_sink, time=(guint64)123456789, ts=(guint64)1234567890123

I couldn't find documentation of that are the meaning of the different parts of that log line.

Can someone point me to the right documentation or help me understand what I'm reading there?

Best regards, 
Damian



_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel
Reply | Threaded
Open this post in threaded view
|

Re: Trying to understand the latency tracer

Nicolas Dufresne-5
Le vendredi 24 mai 2019 à 11:31 -0400, Damian Vicino a écrit :

> Hi,
> I found documentation on how to enable the GStreamer latency tracer exporting variables from the shell as follows:
>
> export GST_TRACERS=latency
> export GST_DEBUG="GST_TRACER:7"
>
> As showed here https://gstreamer.freedesktop.org/documentation/design/tracing.html?gi-language=c#print-reported-latencies-for-each-element
>
> I got log lines as the following one:
> 0:35:08.123456789     362   0x7f434c00fd40  TRACE           GST_TRACER :0:: latency, src=(string)nicesrc4_src, sink=(string)nicesink2_sink, time=(guint64)123456789, ts=(guint64)1234567890123
>
> I couldn't find documentation of that are the meaning of the different parts of that log line.
>
> Can someone point me to the right documentation or help me understand what I'm reading there?
Per tracer documentation is a bit of a work in progress. Here's a quick
guide:
  src/sink: Name of the pad (this has been changed in newer GStreamer)
  time: That's the actual amount of time it too to process one buffer
  ts: That's when was this latency reported, should mostly match

>
> Best regards,
> Damian
>
>
> _______________________________________________
> 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

signature.asc (201 bytes) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Trying to understand the latency tracer

Damian Vicino
Thanks Nicolas, 
Those latencies are reported in nanoseconds, right?

On Sat, May 25, 2019 at 6:39 PM Nicolas Dufresne <[hidden email]> wrote:
Le vendredi 24 mai 2019 à 11:31 -0400, Damian Vicino a écrit :
> Hi,
> I found documentation on how to enable the GStreamer latency tracer exporting variables from the shell as follows:
>
> export GST_TRACERS=latency
> export GST_DEBUG="GST_TRACER:7"
>
> As showed here https://gstreamer.freedesktop.org/documentation/design/tracing.html?gi-language=c#print-reported-latencies-for-each-element
>
> I got log lines as the following one:
> 0:35:08.123456789     362   0x7f434c00fd40  TRACE           GST_TRACER :0:: latency, src=(string)nicesrc4_src, sink=(string)nicesink2_sink, time=(guint64)123456789, ts=(guint64)1234567890123
>
> I couldn't find documentation of that are the meaning of the different parts of that log line.
>
> Can someone point me to the right documentation or help me understand what I'm reading there?

Per tracer documentation is a bit of a work in progress. Here's a quick
guide:
  src/sink: Name of the pad (this has been changed in newer GStreamer)
  time: That's the actual amount of time it too to process one buffer
  ts: That's when was this latency reported, should mostly match

>
> Best regards,
> Damian
>
>
> _______________________________________________
> 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

_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel
Reply | Threaded
Open this post in threaded view
|

Re: Trying to understand the latency tracer

Guillaume Desmottes-2

Yes they are.

You can also use gst-stats-1.0 to parse the generated log file and get some stats/metrics about the latency.

On 26/05/2019 19:06, Damian Vicino wrote:
Thanks Nicolas, 
Those latencies are reported in nanoseconds, right?

On Sat, May 25, 2019 at 6:39 PM Nicolas Dufresne <[hidden email]> wrote:
Le vendredi 24 mai 2019 à 11:31 -0400, Damian Vicino a écrit :
> Hi,
> I found documentation on how to enable the GStreamer latency tracer exporting variables from the shell as follows:
>
> export GST_TRACERS=latency
> export GST_DEBUG="GST_TRACER:7"
>
> As showed here https://gstreamer.freedesktop.org/documentation/design/tracing.html?gi-language=c#print-reported-latencies-for-each-element
>
> I got log lines as the following one:
> 0:35:08.123456789     362   0x7f434c00fd40  TRACE           GST_TRACER :0:: latency, src=(string)nicesrc4_src, sink=(string)nicesink2_sink, time=(guint64)123456789, ts=(guint64)1234567890123
>
> I couldn't find documentation of that are the meaning of the different parts of that log line.
>
> Can someone point me to the right documentation or help me understand what I'm reading there?

Per tracer documentation is a bit of a work in progress. Here's a quick
guide:
  src/sink: Name of the pad (this has been changed in newer GStreamer)
  time: That's the actual amount of time it too to process one buffer
  ts: That's when was this latency reported, should mostly match

>
> Best regards,
> Damian
>
>
> _______________________________________________
> 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

_______________________________________________
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
Reply | Threaded
Open this post in threaded view
|

Re: Trying to understand the latency tracer

solo_juan
I have the same problem, I don't know how to interpret the data. For example:

The data:

- Rasberry Pi 3
- Raspbian Buster
- Raspberry Camera Module V2
- gstreamer, version 1.17.0.1
- Capture data: Motion-JPEG, 426x240, 15 fps and 429000 bps of bitrate

Pipeline:

/opt/vc/bin/raspivid -t 60000 -cd MJPEG -w 426 -h 240 -fps 15 -b 429000 -vf
-hf \
-o - | GST_DEBUG="GST_TRACER:7" GST_DEBUG_FILE=240.log
GST_TRACERS="latency(flags=pipeline+element+reported)" \
gst-launch-1.0 -v  fdsrc do-timestamp=true ! \
"image/jpeg,width=426,height=240,framerate=15/1,payload=(int)26" ! \
jpegparse ! rtpjpegpay ! \
udpsink port=13000 host=192.168.1.111 && gst-stats-1.0 240.log


The output:

Latency Statistics:
0x20340f0.fdsrc0.src|0x20ff150.udpsink0.sink: mean=0:00:00.001291400
min=0:00:00.000751041 max=0:00:00.007009887

Element Latency Statistics:
0x21040f0.capsfilter0.src: mean=0:00:00.000236961 min=0:00:00.000096875
max=0:00:00.000554530
0x20ec2d0.jpegparse0.src: mean=0:00:00.000558282 min=0:00:00.000346250
max=0:00:00.006139732
0x20f80b8.rtpjpegpay0.src: mean=0:00:00.000458047 min=0:00:00.000248542
max=0:00:00.004859044

Element Reported Latency:
0x20340f0.fdsrc0: min=0:00:00.000000000 max=0:00:00.000000000
ts=0:00:00.644349393
0x21040f0.capsfilter0: min=0:00:00.000000000 max=0:00:00.000000000
ts=0:00:00.644468508
0x20ec2d0.jpegparse0: min=0:00:00.000000000 max=0:00:00.000000000
ts=0:00:00.644528403
0x20f80b8.rtpjpegpay0: min=0:00:00.000000000 max=99:99:99.999999999
ts=0:00:00.644595383


My interpretation of the measure:

- it takes 644.3 ms to receive the data stream from the camera.
- it takes 0,06 ms to run jpegparse.


Is this interpretation of the data correct? If so, why does it take so long
to acquire the flow?






--
Sent from: http://gstreamer-devel.966125.n4.nabble.com/
_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel
Reply | Threaded
Open this post in threaded view
|

Re: Trying to understand the latency tracer

solo_juan
In reply to this post by Guillaume Desmottes-2
I have the same problem, I don't know how to interpret the data. For example:

The data:

- Rasberry Pi 3
- Raspbian Buster
- Raspberry Camera Module V2
- gstreamer, version 1.17.0.1
- Capture data: Motion-JPEG, 426x240, 15 fps and 429000 bps of bitrate

Pipeline:

/opt/vc/bin/raspivid -t 60000 -cd MJPEG -w 426 -h 240 -fps 15 -b 429000 -vf
-hf \
-o - | GST_DEBUG="GST_TRACER:7" GST_DEBUG_FILE=240.log
GST_TRACERS="latency(flags=pipeline+element+reported)" \
gst-launch-1.0 -v  fdsrc do-timestamp=true ! \
"image/jpeg,width=426,height=240,framerate=15/1,payload=(int)26" ! \
jpegparse ! rtpjpegpay ! \
udpsink port=13000 host=192.168.1.111 && gst-stats-1.0 240.log


The output:

Latency Statistics:
0x20340f0.fdsrc0.src|0x20ff150.udpsink0.sink: mean=0:00:00.001291400
min=0:00:00.000751041 max=0:00:00.007009887

Element Latency Statistics:
0x21040f0.capsfilter0.src: mean=0:00:00.000236961 min=0:00:00.000096875
max=0:00:00.000554530
0x20ec2d0.jpegparse0.src: mean=0:00:00.000558282 min=0:00:00.000346250
max=0:00:00.006139732
0x20f80b8.rtpjpegpay0.src: mean=0:00:00.000458047 min=0:00:00.000248542
max=0:00:00.004859044

Element Reported Latency:
0x20340f0.fdsrc0: min=0:00:00.000000000 max=0:00:00.000000000
ts=0:00:00.644349393
0x21040f0.capsfilter0: min=0:00:00.000000000 max=0:00:00.000000000
ts=0:00:00.644468508
0x20ec2d0.jpegparse0: min=0:00:00.000000000 max=0:00:00.000000000
ts=0:00:00.644528403
0x20f80b8.rtpjpegpay0: min=0:00:00.000000000 max=99:99:99.999999999
ts=0:00:00.644595383


My interpretation of the measure:

- it takes 644.3 ms to receive the data stream from the camera.
- it takes 0,06 ms to run jpegparse.


Is this interpretation of the data correct? If so, why does it take so long
to acquire the flow?



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