Debugging video jerking problem

[Wolfgang Grandegger]

Hello,

I did made some progress on that topic...

Am 08.12.2018 um 19:34 schrieb Wolfgang Grandegger:
> Am 07.12.2018 um 18:25 schrieb Wolfgang Grandegger:
>> Hello,
>>
>> Am 07.12.2018 um 14:43 schrieb Nicolas Dufresne:
>>>
>>>
>>> Le ven. 7 déc. 2018 05 h 11, Wolfgang Grandegger <wg at grandegger.com
>>> <mailto:wg at grandegger.com>> a écrit :
>>>
>>>     Hello,
>>>
>>>     hmm, the long story: My camera records AVCHD video with 1920x1080 pixel
>>>     and 50 frames/sec. Then I convert it to an 50 FPS AVI raw video using:
>>>
>>>       $ ffmpeg -i input.mts -vcodec rawvideo -y output-50fps.avi
>>>
>>>     To get the same video running at 60 FPS I do:
>>>
>>>       $ ffmpeg -i input.mts -filter:v "setpts=0.83333333*PTS" \
>>>              -r 60 -vcodec rawvideo -y output-60fps.avi
>>>
>>>     I assume that this video uses the same raw frames just with different
>>>     time stamps. What do I miss?
>>>
>>>
>>> Understand that this could also be the threshold your receiving socket
>>> can carry with its current setting. It cost nothing to try and increase
>>> it, see buffer-size on udp-sink and sysctl net.core.rmem_max setting of
>>> your Linux kernel (if Linux is your host OS).
>>
>> I already doubled both values. It does not help.
>>
>> I did debug the sink with with "GST_DEBUG=basesink:6". If I look to the
>> timestamps of the lines:
>>
>>   0:00:03.215045610 basesink gstbasesink.c:2921:gst_base_sink_is_too_late:<vaapisink0> object was scheduled in time
>>
>> And calculate the time difference to the previous line in ms I get:
>>
>>   16.631028
>>   33.438903
>>   233.507839
>>   16.668671
>>   ...
>>   16.941117
>>   33.009663
>>   183.428079
>>   16.470837
>>
>> This is the jerking I see, I guess. With 50 FPS, it's always 20ms.
>> What I do also realize at 60 FPS is that not all frames are recorded
>> but just 42.96 fps:
>>
>>   # ffprobe /tmp/rec0.mp4
>>   
>>       encoder         : VA-API H264 encoder
>>     Duration: 00:00:43.20, start: 0.000000, bitrate: 33813 kb/s
>>       Stream #0:0(und): Video: h264 (High) (avc1 / 0x31637661), yuv420p(tv, bt709), 1920x1080 [SAR 1:1 DAR 16:9], 33809 kb/s, 42.96 fps, 60 tbr, 10k tbn, 20k tbc (default)
>>       Metadata:
>>         creation_time   : 2018-12-07T17:18:53.000000Z
>>         handler_name    : VideoHandler
>>   [h264 @ 0x62dae0] time_scale/num_units_in_tick invalid or unsupported (0/1)
>>
>> It looks like there is a resource limit somewhere :(.
> 
> I now tried pipeline latency with "GST_DEBUG="GST_TRACER:7
> GST_TRACERS=latency". It shows me
> 
> 0:00:10.824079787 ... latency, src=(string)udpsrc0_src, sink=(string)display sink_sink, time=(guint64)78779611, ts=(guint64)10824035191;
> 0:00:10.837392036 ... latency, src=(string)udpsrc0_src, sink=(string)filesink0_sink, time=(guint64)52504281, ts=(guint64)10837353922;
> 0:00:10.843501996 ... latency, src=(string)udpsrc0_src, sink=(string)display sink_sink, time=(guint64)78006259, ts=(guint64)10843436324;
> 0:00:10.857081850 ... latency, src=(string)udpsrc0_src, sink=(string)filesink0_sink, time=(guint64)51733514, ts=(guint64)10857042971;
> 
> Here it takes approx. 80ms to display and 50 ms to record a frame. This
> is really cool stuff! I can now measure the effect of recording and text
> overlay but it does not tell me resource usage. 
> 
> For that I tried "GST_TRACERS=stats;rusage". I have attached the output
> of "gst-stats-1.0". Does it tell me the CPU usage? Are these numbers
> documented somewhere?

The tracing output of "rusage" analysed with "gst-plot-traces.sh" didn't
give meaningful results. It seems that it cannot deal properly with
multiple CPUs. Is this a known issue?

Anyway, "GST_TRACERS=latencies" and "GST_DEBUG=basesink:5" helped me to
understand a bit better what's going on. With 50 FPS, the latencies
reported by "GST_TRACERS=latencies" are rather constant around 80ms,
while with 60 FPS they are fluctuating much more. Also, if I look to
the "rendering" lines of the "GST_DEBUG=basesink:5" log:

00:03.665643643  ... basesink gstbasesink.c:3538:gst_base_sink_chain_unlocked:<display sink> rendering object 0x7f6c8c0752a0

I see that for 50 FPS, the difference between the timestamps is always
close to 20 ms:

  19.986890
  19.950369
  20.245006
  19.663664
  20.054239
  19.919339

while with 60 FPS, often the time difference is greater than 16.7 ms:

  16.663874
  16.182956
  17.571549
  27.771846
  16.442217
  28.842019

How does the default GStreamer pipeline compensate for the processing latency?

Does it adapt dynamically?

Wolfgang.