High latency with my JPEG VAAPI pipeline

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

High latency with my JPEG VAAPI pipeline

Wolfgang Grandegger
Hello,

I'm trying to understand the latency figures measured with a smartphone
and camera for the following pipeline:

  # gst-launch-1.0 -v udpsrc port=5678 buffer-size=2000000 do-timestamp=1 \
     caps="application/x-rtp, media=(string)video, clock-rate=(int)90000, encoding-name=(string)JPEG, payload=(int)26, framerate=(fraction)30/1" \
     ! rtpjitterbuffer latency=5 \
     ! rtpjpegdepay \
     ! vaapijpegdec \
     ! vaapisink

I measure around 130 ms. The latency trace with "GST_TRACERS=latency
GST_DEBUG=GST_TRACER:7" is reporting src to sink latencies of just
around 40 ms:

  0:00:08.447955233   411       0x4d3c00 TRACE             GST_TRACER :0:: latency, src-element-id=(string)0x4f03a0, src-element=(string)udpsrc0, src=(string)src, sink-element-id=(string)0x51acc0, sink-element=
(string)vaapisink0, sink=(string)sink, time=(guint64)41801197, ts=(guint64)8447919094;
  0:00:08.481356539   411       0x4d3c00 TRACE             GST_TRACER :0:: latency, src-element-id=(string)0x4f03a0, src-element=(string)udpsrc0, src=(string)src, sink-element-id=(string)0x51acc0, sink-element=
(string)vaapisink0, sink=(string)sink, time=(guint64)41875079, ts=(guint64)8481323375;
  0:00:08.514592194   411       0x4d3c00 TRACE             GST_TRACER :0:: latency, src-element-id=(string)0x4f03a0, src-element=(string)udpsrc0, src=(string)src, sink-element-id=(string)0x51acc0, sink-element=
(string)vaapisink0, sink=(string)sink, time=(guint64)41766241, ts=(guint64)8514557403;

I wonder what is responsible for the 90 ms extra latency. Of course, the
camera and the network introduces some latency, but if I use MPV
instead,

  # mpv --profile=low-latency --untimed jpeg.sdp

I measure just 80 ms. Still a difference of 50 ms. Any idea where that
comes from?

TIA,

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

Re: High latency with my JPEG VAAPI pipeline

Nicolas Dufresne-5
On ven, 2020-02-07 at 12:26 +0100, Wolfgang Grandegger wrote:

> Hello,
>
> I'm trying to understand the latency figures measured with a smartphone
> and camera for the following pipeline:
>
>   # gst-launch-1.0 -v udpsrc port=5678 buffer-size=2000000 do-timestamp=1 \
>      caps="application/x-rtp, media=(string)video, clock-rate=(int)90000,
> encoding-name=(string)JPEG, payload=(int)26, framerate=(fraction)30/1" \
>      ! rtpjitterbuffer latency=5 \
>      ! rtpjpegdepay \
>      ! vaapijpegdec \
>      ! vaapisink
>
> I measure around 130 ms. The latency trace with "GST_TRACERS=latency

What method to you use to measure this ?

> GST_DEBUG=GST_TRACER:7" is reporting src to sink latencies of just
> around 40 ms:

You should look at the reported latency, maybe we are reporting too much. For
this do:

  GST_TRACERS="latency\(flags=pipeline,element,reported\)"

To view the results, I suggest using gst-stats-1.0 tool form the latency logs
saved to filed.

  pipeline ... 2> trace.log
  gst-stats-1.0 trace.log

Depending on the display rate, and considering you likely have a compositer,
you'll have about 1.5 vblank latency duration added to your glass to glass
latency. vaapisink maybe use more HW blocks, so there might be some latency
added there too (I'm not too wail informed on tha taspect).

There is an extra 15ms added in the vieo sink, see processing-deadline. In your
case, I assume it should have 33ms latency + processing time, so you have about
7ms of processing time.

>
>   0:00:08.447955233   411       0x4d3c00 TRACE             GST_TRACER :0::
> latency, src-element-id=(string)0x4f03a0, src-element=(string)udpsrc0,
> src=(string)src, sink-element-id=(string)0x51acc0, sink-element=
> (string)vaapisink0, sink=(string)sink, time=(guint64)41801197,
> ts=(guint64)8447919094;
>   0:00:08.481356539   411       0x4d3c00 TRACE             GST_TRACER :0::
> latency, src-element-id=(string)0x4f03a0, src-element=(string)udpsrc0,
> src=(string)src, sink-element-id=(string)0x51acc0, sink-element=
> (string)vaapisink0, sink=(string)sink, time=(guint64)41875079,
> ts=(guint64)8481323375;
>   0:00:08.514592194   411       0x4d3c00 TRACE             GST_TRACER :0::
> latency, src-element-id=(string)0x4f03a0, src-element=(string)udpsrc0,
> src=(string)src, sink-element-id=(string)0x51acc0, sink-element=
> (string)vaapisink0, sink=(string)sink, time=(guint64)41766241,
> ts=(guint64)8514557403;
>
> I wonder what is responsible for the 90 ms extra latency. Of course, the
> camera and the network introduces some latency, but if I use MPV
> instead,
>
>   # mpv --profile=low-latency --untimed jpeg.sdp
>
> I measure just 80 ms. Still a difference of 50 ms. Any idea where that
> comes from?
>
> TIA,
>
> Wolfgang
> _______________________________________________
> 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: High latency with my JPEG VAAPI pipeline

Wolfgang Grandegger
Hello,

thanks for your valuable input...

Am 07.02.20 um 14:01 schrieb Nicolas Dufresne:

> On ven, 2020-02-07 at 12:26 +0100, Wolfgang Grandegger wrote:
>> Hello,
>>
>> I'm trying to understand the latency figures measured with a smartphone
>> and camera for the following pipeline:
>>
>>   # gst-launch-1.0 -v udpsrc port=5678 buffer-size=2000000 do-timestamp=1 \
>>      caps="application/x-rtp, media=(string)video, clock-rate=(int)90000,
>> encoding-name=(string)JPEG, payload=(int)26, framerate=(fraction)30/1" \
>>      ! rtpjitterbuffer latency=5 \
>>      ! rtpjpegdepay \
>>      ! vaapijpegdec \
>>      ! vaapisink
>>
>> I measure around 130 ms. The latency trace with "GST_TRACERS=latency
>
> What method to you use to measure this ?

I put my Android smartphone close to the display. On the smartphone I
start the clock app and start the timer. Then I place the camera in
front, recording both, the smartphone screen and the display. Then I
take a picture with my compact camera and compare the times shown on
the picture. I think that's what you name "glass to glass" latency.

>> GST_DEBUG=GST_TRACER:7" is reporting src to sink latencies of just
>> around 40 ms:
>
> You should look at the reported latency, maybe we are reporting too much. For
> this do:
>
>   GST_TRACERS="latency\(flags=pipeline,element,reported\)"
Hm, what does "GST_TRACERS="latency" report? I think for the "flags=" I
need 1.6.x, IIRC.

> To view the results, I suggest using gst-stats-1.0 tool form the latency logs
> saved to filed.
>
>   pipeline ... 2> trace.log
>   gst-stats-1.0 trace.log

OK, here is what I get. I have added some comments/questions with (*):

  # gst-stats-1.0 /tmp/trace.log

  Overall Statistics:
  Number of Threads: 0
  Number of Elements: 0
  Number of Bins: 0
  Number of Pads: 0
  Number of GhostPads: 0
  Number of Buffers passed: 0
  Number of Events sent: 0
  Number of Message sent: 0
  Number of Queries sent: 0

(*) Shouldn't the numbers above show some real values?

  Time: 0:05:54.100866710

  Latency Statistics:
        0x4ef650.udpsrc0.src|0x5193a0.vaapisink0.sink: mean=43415981 min=38730503 max=108822660

(*) The 43 ms seem to be the src to sink latency similar to what
    "GST_TRACERS=latency" reports.

  Element Latency Statistics:
        0x4f5db0.rtpjitterbuffer0.src: mean=54507945 min=21104 max=107217916

(*) Why is the rtpjitterbuffer responsible for most of the latency?

        0x503fc0.rtpjpegdepay0.src: mean=340660 min=85865 max=655983
        0x51eba0.vaapidecode_jpeg0.src: mean=1123497 min=282112 max=108139722

  Element Reported Latency:
        0x4ef650.udpsrc0: min=0 max=0 ts=0:00:00.183949148
        0x4f5db0.rtpjitterbuffer0: min=5000000 max=18446744073709551615 ts=0:00:00.184021844

(*) Does this very high max value screw up the statistis?

        0x503fc0.rtpjpegdepay0: min=0 max=0 ts=0:00:00.184053451
        0x51eba0.vaapidecode_jpeg0: min=80000000 max=0 ts=0:00:00.184074524

Some of the figures above a really confusing.

> Depending on the display rate, and considering you likely have a compositer,
> you'll have about 1.5 vblank latency duration added to your glass to glass
> latency. vaapisink maybe use more HW blocks, so there might be some latency
> added there too (I'm not too wail informed on tha taspect).

The display runs at 60 Hz, hence 25 ms vblank latency. I'm using X11 and
the Matchbox Window manager. Can I avoid or improve the vblank latency
somehow? The latency is not really better if I use "kmssink" (without
X11).

> There is an extra 15ms added in the vieo sink, see processing-deadline. In your
> case, I assume it should have 33ms latency + processing time, so you have about
> 7ms of processing time.
>
>>
>>   0:00:08.447955233   411       0x4d3c00 TRACE             GST_TRACER :0::
>> latency, src-element-id=(string)0x4f03a0, src-element=(string)udpsrc0,
>> src=(string)src, sink-element-id=(string)0x51acc0, sink-element=
>> (string)vaapisink0, sink=(string)sink, time=(guint64)41801197,
>> ts=(guint64)8447919094;
>>   0:00:08.481356539   411       0x4d3c00 TRACE             GST_TRACER :0::
>> latency, src-element-id=(string)0x4f03a0, src-element=(string)udpsrc0,
>> src=(string)src, sink-element-id=(string)0x51acc0, sink-element=
>> (string)vaapisink0, sink=(string)sink, time=(guint64)41875079,
>> ts=(guint64)8481323375;
>>   0:00:08.514592194   411       0x4d3c00 TRACE             GST_TRACER :0::
>> latency, src-element-id=(string)0x4f03a0, src-element=(string)udpsrc0,
>> src=(string)src, sink-element-id=(string)0x51acc0, sink-element=
>> (string)vaapisink0, sink=(string)sink, time=(guint64)41766241,
>> ts=(guint64)8514557403;
>>
>> I wonder what is responsible for the 90 ms extra latency. Of course, the
>> camera and the network introduces some latency, but if I use MPV
>> instead,
>>
>>   # mpv --profile=low-latency --untimed jpeg.sdp
>>
>> I measure just 80 ms. Still a difference of 50 ms. Any idea where that
>> comes from?

Still puzzled why "mpv" does a much better job here (50 ms less latency!).

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

Re: High latency with my JPEG VAAPI pipeline

Wolfgang Grandegger
Hello,

still hunting latency! When I use "vaapisink sync=false" the latency
drops from 130 ms to 60 ms. There seem to be a kind of backlog
somewhere. Any idea how that could happen or be avoided. Is there a
tracer showing buffer/queue usage?

Thanks,

Wolfgang

Am 09.02.20 um 19:07 schrieb Wolfgang Grandegger:

> Hello,
>
> thanks for your valuable input...
>
> Am 07.02.20 um 14:01 schrieb Nicolas Dufresne:
>> On ven, 2020-02-07 at 12:26 +0100, Wolfgang Grandegger wrote:
>>> Hello,
>>>
>>> I'm trying to understand the latency figures measured with a smartphone
>>> and camera for the following pipeline:
>>>
>>>   # gst-launch-1.0 -v udpsrc port=5678 buffer-size=2000000 do-timestamp=1 \
>>>      caps="application/x-rtp, media=(string)video, clock-rate=(int)90000,
>>> encoding-name=(string)JPEG, payload=(int)26, framerate=(fraction)30/1" \
>>>      ! rtpjitterbuffer latency=5 \
>>>      ! rtpjpegdepay \
>>>      ! vaapijpegdec \
>>>      ! vaapisink
>>>
>>> I measure around 130 ms. The latency trace with "GST_TRACERS=latency
>>
>> What method to you use to measure this ?
>
> I put my Android smartphone close to the display. On the smartphone I
> start the clock app and start the timer. Then I place the camera in
> front, recording both, the smartphone screen and the display. Then I
> take a picture with my compact camera and compare the times shown on
> the picture. I think that's what you name "glass to glass" latency.
>
>>> GST_DEBUG=GST_TRACER:7" is reporting src to sink latencies of just
>>> around 40 ms:
>>
>> You should look at the reported latency, maybe we are reporting too much. For
>> this do:
>>
>>   GST_TRACERS="latency\(flags=pipeline,element,reported\)"
> Hm, what does "GST_TRACERS="latency" report? I think for the "flags=" I
> need 1.6.x, IIRC.
>
>> To view the results, I suggest using gst-stats-1.0 tool form the latency logs
>> saved to filed.
>>
>>   pipeline ... 2> trace.log
>>   gst-stats-1.0 trace.log
>
> OK, here is what I get. I have added some comments/questions with (*):
>
>   # gst-stats-1.0 /tmp/trace.log
>
>   Overall Statistics:
>   Number of Threads: 0
>   Number of Elements: 0
>   Number of Bins: 0
>   Number of Pads: 0
>   Number of GhostPads: 0
>   Number of Buffers passed: 0
>   Number of Events sent: 0
>   Number of Message sent: 0
>   Number of Queries sent: 0
>
> (*) Shouldn't the numbers above show some real values?
>
>   Time: 0:05:54.100866710
>
>   Latency Statistics:
> 0x4ef650.udpsrc0.src|0x5193a0.vaapisink0.sink: mean=43415981 min=38730503 max=108822660
>
> (*) The 43 ms seem to be the src to sink latency similar to what
>     "GST_TRACERS=latency" reports.
>
>   Element Latency Statistics:
> 0x4f5db0.rtpjitterbuffer0.src: mean=54507945 min=21104 max=107217916
>
> (*) Why is the rtpjitterbuffer responsible for most of the latency?
>
> 0x503fc0.rtpjpegdepay0.src: mean=340660 min=85865 max=655983
> 0x51eba0.vaapidecode_jpeg0.src: mean=1123497 min=282112 max=108139722
>
>   Element Reported Latency:
> 0x4ef650.udpsrc0: min=0 max=0 ts=0:00:00.183949148
> 0x4f5db0.rtpjitterbuffer0: min=5000000 max=18446744073709551615 ts=0:00:00.184021844
>
> (*) Does this very high max value screw up the statistis?
>
> 0x503fc0.rtpjpegdepay0: min=0 max=0 ts=0:00:00.184053451
> 0x51eba0.vaapidecode_jpeg0: min=80000000 max=0 ts=0:00:00.184074524
>
> Some of the figures above a really confusing.
>
>> Depending on the display rate, and considering you likely have a compositer,
>> you'll have about 1.5 vblank latency duration added to your glass to glass
>> latency. vaapisink maybe use more HW blocks, so there might be some latency
>> added there too (I'm not too wail informed on tha taspect).
>
> The display runs at 60 Hz, hence 25 ms vblank latency. I'm using X11 and
> the Matchbox Window manager. Can I avoid or improve the vblank latency
> somehow? The latency is not really better if I use "kmssink" (without
> X11).
>
>> There is an extra 15ms added in the vieo sink, see processing-deadline. In your
>> case, I assume it should have 33ms latency + processing time, so you have about
>> 7ms of processing time.
>>
>>>
>>>   0:00:08.447955233   411       0x4d3c00 TRACE             GST_TRACER :0::
>>> latency, src-element-id=(string)0x4f03a0, src-element=(string)udpsrc0,
>>> src=(string)src, sink-element-id=(string)0x51acc0, sink-element=
>>> (string)vaapisink0, sink=(string)sink, time=(guint64)41801197,
>>> ts=(guint64)8447919094;
>>>   0:00:08.481356539   411       0x4d3c00 TRACE             GST_TRACER :0::
>>> latency, src-element-id=(string)0x4f03a0, src-element=(string)udpsrc0,
>>> src=(string)src, sink-element-id=(string)0x51acc0, sink-element=
>>> (string)vaapisink0, sink=(string)sink, time=(guint64)41875079,
>>> ts=(guint64)8481323375;
>>>   0:00:08.514592194   411       0x4d3c00 TRACE             GST_TRACER :0::
>>> latency, src-element-id=(string)0x4f03a0, src-element=(string)udpsrc0,
>>> src=(string)src, sink-element-id=(string)0x51acc0, sink-element=
>>> (string)vaapisink0, sink=(string)sink, time=(guint64)41766241,
>>> ts=(guint64)8514557403;
>>>
>>> I wonder what is responsible for the 90 ms extra latency. Of course, the
>>> camera and the network introduces some latency, but if I use MPV
>>> instead,
>>>
>>>   # mpv --profile=low-latency --untimed jpeg.sdp
>>>
>>> I measure just 80 ms. Still a difference of 50 ms. Any idea where that
>>> comes from?
>
> Still puzzled why "mpv" does a much better job here (50 ms less latency!).
>
> Wolfgang
> _______________________________________________
> 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: High latency with my JPEG VAAPI pipeline

Nicolas Dufresne-5


Le mar. 18 févr. 2020 10 h 45, Wolfgang Grandegger <[hidden email]> a écrit :
Hello,

still hunting latency! When I use "vaapisink sync=false" the latency
drops from 130 ms to 60 ms. There seem to be a kind of backlog
somewhere. Any idea how that could happen or be avoided. Is there a
tracer showing buffer/queue usage?

I would investigated why the depaylaoder reports that 80ms. For this use case, you should use the fast start on the JB too, it should remove the 100ms start-up latency, and most likely drops at start.


Thanks,

Wolfgang

Am 09.02.20 um 19:07 schrieb Wolfgang Grandegger:
> Hello,
>
> thanks for your valuable input...
>
> Am 07.02.20 um 14:01 schrieb Nicolas Dufresne:
>> On ven, 2020-02-07 at 12:26 +0100, Wolfgang Grandegger wrote:
>>> Hello,
>>>
>>> I'm trying to understand the latency figures measured with a smartphone
>>> and camera for the following pipeline:
>>>
>>>   # gst-launch-1.0 -v udpsrc port=5678 buffer-size=2000000 do-timestamp=1 \
>>>      caps="application/x-rtp, media=(string)video, clock-rate=(int)90000,
>>> encoding-name=(string)JPEG, payload=(int)26, framerate=(fraction)30/1" \
>>>      ! rtpjitterbuffer latency=5 \
>>>      ! rtpjpegdepay \
>>>      ! vaapijpegdec \
>>>      ! vaapisink
>>>
>>> I measure around 130 ms. The latency trace with "GST_TRACERS=latency
>>
>> What method to you use to measure this ?
>
> I put my Android smartphone close to the display. On the smartphone I
> start the clock app and start the timer. Then I place the camera in
> front, recording both, the smartphone screen and the display. Then I
> take a picture with my compact camera and compare the times shown on
> the picture. I think that's what you name "glass to glass" latency.
>
>>> GST_DEBUG=GST_TRACER:7" is reporting src to sink latencies of just
>>> around 40 ms:
>>
>> You should look at the reported latency, maybe we are reporting too much. For
>> this do:
>>
>>   GST_TRACERS="latency\(flags=pipeline,element,reported\)"
> Hm, what does "GST_TRACERS="latency" report? I think for the "flags=" I
> need 1.6.x, IIRC.
>
>> To view the results, I suggest using gst-stats-1.0 tool form the latency logs
>> saved to filed.
>>
>>   pipeline ... 2> trace.log
>>   gst-stats-1.0 trace.log
>
> OK, here is what I get. I have added some comments/questions with (*):
>
>   # gst-stats-1.0 /tmp/trace.log
>
>   Overall Statistics:
>   Number of Threads: 0
>   Number of Elements: 0
>   Number of Bins: 0
>   Number of Pads: 0
>   Number of GhostPads: 0
>   Number of Buffers passed: 0
>   Number of Events sent: 0
>   Number of Message sent: 0
>   Number of Queries sent: 0
>
> (*) Shouldn't the numbers above show some real values?
>
>   Time: 0:05:54.100866710
>
>   Latency Statistics:
>       0x4ef650.udpsrc0.src|0x5193a0.vaapisink0.sink: mean=43415981 min=38730503 max=108822660
>
> (*) The 43 ms seem to be the src to sink latency similar to what
>     "GST_TRACERS=latency" reports.
>
>   Element Latency Statistics:
>       0x4f5db0.rtpjitterbuffer0.src: mean=54507945 min=21104 max=107217916
>
> (*) Why is the rtpjitterbuffer responsible for most of the latency?
>
>       0x503fc0.rtpjpegdepay0.src: mean=340660 min=85865 max=655983
>       0x51eba0.vaapidecode_jpeg0.src: mean=1123497 min=282112 max=108139722
>
>   Element Reported Latency:
>       0x4ef650.udpsrc0: min=0 max=0 ts=0:00:00.183949148
>       0x4f5db0.rtpjitterbuffer0: min=5000000 max=18446744073709551615 ts=0:00:00.184021844
>
> (*) Does this very high max value screw up the statistis?
>
>       0x503fc0.rtpjpegdepay0: min=0 max=0 ts=0:00:00.184053451
>       0x51eba0.vaapidecode_jpeg0: min=80000000 max=0 ts=0:00:00.184074524
>
> Some of the figures above a really confusing.
>
>> Depending on the display rate, and considering you likely have a compositer,
>> you'll have about 1.5 vblank latency duration added to your glass to glass
>> latency. vaapisink maybe use more HW blocks, so there might be some latency
>> added there too (I'm not too wail informed on tha taspect).
>
> The display runs at 60 Hz, hence 25 ms vblank latency. I'm using X11 and
> the Matchbox Window manager. Can I avoid or improve the vblank latency
> somehow? The latency is not really better if I use "kmssink" (without
> X11).
>
>> There is an extra 15ms added in the vieo sink, see processing-deadline. In your
>> case, I assume it should have 33ms latency + processing time, so you have about
>> 7ms of processing time.
>>
>>>
>>>   0:00:08.447955233   411       0x4d3c00 TRACE             GST_TRACER :0::
>>> latency, src-element-id=(string)0x4f03a0, src-element=(string)udpsrc0,
>>> src=(string)src, sink-element-id=(string)0x51acc0, sink-element=
>>> (string)vaapisink0, sink=(string)sink, time=(guint64)41801197,
>>> ts=(guint64)8447919094;
>>>   0:00:08.481356539   411       0x4d3c00 TRACE             GST_TRACER :0::
>>> latency, src-element-id=(string)0x4f03a0, src-element=(string)udpsrc0,
>>> src=(string)src, sink-element-id=(string)0x51acc0, sink-element=
>>> (string)vaapisink0, sink=(string)sink, time=(guint64)41875079,
>>> ts=(guint64)8481323375;
>>>   0:00:08.514592194   411       0x4d3c00 TRACE             GST_TRACER :0::
>>> latency, src-element-id=(string)0x4f03a0, src-element=(string)udpsrc0,
>>> src=(string)src, sink-element-id=(string)0x51acc0, sink-element=
>>> (string)vaapisink0, sink=(string)sink, time=(guint64)41766241,
>>> ts=(guint64)8514557403;
>>>
>>> I wonder what is responsible for the 90 ms extra latency. Of course, the
>>> camera and the network introduces some latency, but if I use MPV
>>> instead,
>>>
>>>   # mpv --profile=low-latency --untimed jpeg.sdp
>>>
>>> I measure just 80 ms. Still a difference of 50 ms. Any idea where that
>>> comes from?
>
> Still puzzled why "mpv" does a much better job here (50 ms less latency!).
>
> Wolfgang
> _______________________________________________
> 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: High latency with my JPEG VAAPI pipeline

Wolfgang Grandegger
Hello,

Am 18.02.20 um 23:23 schrieb Nicolas Dufresne:

>
>
> Le mar. 18 févr. 2020 10 h 45, Wolfgang Grandegger <[hidden email]
> <mailto:[hidden email]>> a écrit :
>
>     Hello,
>
>     still hunting latency! When I use "vaapisink sync=false" the latency
>     drops from 130 ms to 60 ms. There seem to be a kind of backlog
>     somewhere. Any idea how that could happen or be avoided. Is there a
>     tracer showing buffer/queue usage?
>
>
> I would investigated why the depaylaoder reports that 80ms. For this use
> case, you should use the fast start on the JB too, it should remove the
> 100ms start-up latency, and most likely drops at start.

"faststart-min-packets=0" is the default, but when I look to the
following debug lines:

  # egrep "rendering|setting last buffer" /tmp/gst5.log
  0:00:00.030705838   407       0x419400 DEBUG              vaapisink gstvaapisink.c:1241:gst_vaapisink_display_changed: use texture rendering mode
  0:00:00.086864483   407       0x4d1000 DEBUG               basesink gstbasesink.c:1014:gst_base_sink_set_last_buffer_unlocked:<vaapisink0> setting last buffer to 0x7fa0d4057240
  0:00:00.171122862   407       0x4d1000 DEBUG               basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<vaapisink0> rendering object 0x7fa0d4057240

I see, that the first frame is rendered with a delay of approx.
80..90 ms.

  0:00:00.204135691   407       0x4d1000 DEBUG               basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<vaapisink0> rendering object 0x7fa0d40575a0
  0:00:00.204142943   407       0x4d1000 DEBUG               basesink gstbasesink.c:1014:gst_base_sink_set_last_buffer_unlocked:<vaapisink0> setting last buffer to 0x7fa0d40575a0
  0:00:00.237458751   407       0x4d1000 DEBUG               basesink gstbasesink.c:3641:gst_base_sink_chain_unlocked:<vaapisink0> rendering object 0x7fa0d4057240

I think the problem is that the calculated latency is simply too long.
I see events like:

  0:00:00.088237076   407 0x7fa0d000a8a0 DEBUG               basesink gstbasesink.c:4612:gst_base_sink_send_event:<vaapisink0> sending event 0x7fa0d0010520 latency event: 0x7fa0d0010520,
                                                             time 99:99:99.999999999, seq-num 66, GstEventLatency, latency=(guint64)100000000;

How can I find out how much time each element is contributing to the latency?

And I can lower the latency using:

  gst_pipeline_set_latency (GST_PIPELINE (pipeline), latency:ms * 1000000);

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

Re: High latency with my JPEG VAAPI pipeline

Nicolas Dufresne-5
On mer, 2020-02-19 at 15:53 +0100, Wolfgang Grandegger wrote:

> Hello,
>
> Am 18.02.20 um 23:23 schrieb Nicolas Dufresne:
> >
> > Le mar. 18 févr. 2020 10 h 45, Wolfgang Grandegger <[hidden email]
> > <mailto:[hidden email]>> a écrit :
> >
> >     Hello,
> >
> >     still hunting latency! When I use "vaapisink sync=false" the latency
> >     drops from 130 ms to 60 ms. There seem to be a kind of backlog
> >     somewhere. Any idea how that could happen or be avoided. Is there a
> >     tracer showing buffer/queue usage?
> >
> >
> > I would investigated why the depaylaoder reports that 80ms. For this use
> > case, you should use the fast start on the JB too, it should remove the
> > 100ms start-up latency, and most likely drops at start.
>
> "faststart-min-packets=0" is the default, but when I look to the
> following debug lines:

0 means it will wait for "latency" before emitting anything. Use 3 here for a
good and safe fast start. Mean if you have 3 packets following each other, it
starts.

>
>   # egrep "rendering|setting last buffer" /tmp/gst5.log
>   0:00:00.030705838   407       0x419400 DEBUG              vaapisink
> gstvaapisink.c:1241:gst_vaapisink_display_changed: use texture rendering mode
>   0:00:00.086864483   407       0x4d1000 DEBUG               basesink
> gstbasesink.c:1014:gst_base_sink_set_last_buffer_unlocked:<vaapisink0> setting
> last buffer to 0x7fa0d4057240
>   0:00:00.171122862   407       0x4d1000 DEBUG               basesink
> gstbasesink.c:3641:gst_base_sink_chain_unlocked:<vaapisink0> rendering object
> 0x7fa0d4057240
>
> I see, that the first frame is rendered with a delay of approx.
> 80..90 ms.
>
>   0:00:00.204135691   407       0x4d1000 DEBUG               basesink
> gstbasesink.c:3641:gst_base_sink_chain_unlocked:<vaapisink0> rendering object
> 0x7fa0d40575a0
>   0:00:00.204142943   407       0x4d1000 DEBUG               basesink
> gstbasesink.c:1014:gst_base_sink_set_last_buffer_unlocked:<vaapisink0> setting
> last buffer to 0x7fa0d40575a0
>   0:00:00.237458751   407       0x4d1000 DEBUG               basesink
> gstbasesink.c:3641:gst_base_sink_chain_unlocked:<vaapisink0> rendering object
> 0x7fa0d4057240
>
> I think the problem is that the calculated latency is simply too long.
> I see events like:

Yes.

>
>   0:00:00.088237076   407 0x7fa0d000a8a0 DEBUG               basesink
> gstbasesink.c:4612:gst_base_sink_send_event:<vaapisink0> sending event
> 0x7fa0d0010520 latency event: 0x7fa0d0010520,
>                                                              time
> 99:99:99.999999999, seq-num 66, GstEventLatency, latency=(guint64)100000000;
>
> How can I find out how much time each element is contributing to the latency?

GST_TRACERS=latency\(flags=reported\) GST_DEBUG=GST_TRACER:7 ./pipeline-app-...

>
> And I can lower the latency using:
>
>   gst_pipeline_set_latency (GST_PIPELINE (pipeline), latency:ms * 1000000);
>
> Wolfgang
> _______________________________________________
> 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