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