High latency with my JPEG VAAPI pipeline

Tue Feb 18 14:32:15 UTC 2020

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
> gstreamer-devel at lists.freedesktop.org
> https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel
> 
> 