[gst-devel] ffdec and QoS

[Arnout Vandecappelle]

 Hoi all,

 I've been struggling with QoS events for a while now, and I don't find a way out...

 I have a pipeline like this:
souphttpsrc location=... do-timestamp=true ! mpeg4videoparse ! ffdec_mpeg4 ! \
 videoscale ! fakesink sync=true qos=true

 The ffmpeg decoder element usually buffers one frame internally.  Unfortunately, this makes
the sink generate QoS events that causes basetransform to drop frames.

 Here is some pruned debug output to indicate the problem:

# A frame is pushed in the decoder, but it is buffered.
0:00:00.752352  ffmpeg gstffmpegdec.c:897:gst_ffmpegdec_get_buffer:<ffdec_mpeg40> getting buffer, apply pts 517907675
0:00:00.754003  ffmpeg gstffmpegdec.c:1600:gst_ffmpegdec_video_frame:<ffdec_mpeg40> after decode: len 10006, have_data 0
0:00:00.754047  ffmpeg gstffmpegdec.c:2099:gst_ffmpegdec_frame:<ffdec_mpeg40> We didn't get a decoded buffer

# 200ms later, the next frame arrives, the previous one is decoded
0:00:00.966332  ffmpeg gstffmpegdec.c:897:gst_ffmpegdec_get_buffer:<ffdec_mpeg40> getting buffer, apply pts 633476686
0:00:00.967236  ffmpeg gstffmpegdec.c:1600:gst_ffmpegdec_video_frame:<ffdec_mpeg40> after decode: len 1512, have_data 288
0:00:00.967269  ffmpeg gstffmpegdec.c:1614:gst_ffmpegdec_video_frame:<ffdec_mpeg40> ts-handler: pts 517907675
0:00:00.969201 GST_QOS gstbasesink.c:2542:gst_base_sink_do_render_stats:<fakesink0> avg_render: 0:00:00.000042465
0:00:00.969219 GST_QOS gstbasesink.c:2346:gst_base_sink_perform_qos:<fakesink0> start: 0:00:00.517907675, entered 0:00:00.850296431, left 0:00:00.850296431, pt: 
99:99:99.999999999, duration 0:00:00.000000000,jitter 332388756
0:00:00.969238 GST_QOS gstbasesink.c:2351:gst_base_sink_perform_qos:<fakesink0> avg_duration: 99:99:99.999999999, avg_pt: 99:99:99.999999999, avg_rate: -1
0:00:00.969255 GST_QOS gstbasesink.c:2386:gst_base_sink_perform_qos:<fakesink0> updated: avg_duration: 0:00:00.000000000, avg_pt: 99:99:99.999999999, avg_rate: -1
# no QoS event is sent yet...

# Again 200ms later, the next frame arrives, the previous one is decoded
0:00:01.188664  ffmpeg gstffmpegdec.c:897:gst_ffmpegdec_get_buffer:<ffdec_mpeg40> getting buffer, apply pts 848446910
0:00:01.189441  ffmpeg gstffmpegdec.c:1600:gst_ffmpegdec_video_frame:<ffdec_mpeg40> after decode: len 1339, have_data 288
0:00:01.189483  ffmpeg gstffmpegdec.c:1614:gst_ffmpegdec_video_frame:<ffdec_mpeg40> ts-handler: pts 633476686
0:00:01.189669 GST_QOS gstbasesink.c:2542:gst_base_sink_do_render_stats:<fakesink0> avg_render: 0:00:00.000043914
0:00:01.189684 GST_QOS gstbasesink.c:2346:gst_base_sink_perform_qos:<fakesink0> start: 0:00:00.633476686, entered 0:00:01.070752257, left 0:00:01.070752257, pt: 
0:00:00.220455826, duration 0:00:00.000000000,jitter 437275571
0:00:01.189700 GST_QOS gstbasesink.c:2351:gst_base_sink_perform_qos:<fakesink0> avg_duration: 0:00:00.000000000, avg_pt: 99:99:99.999999999, avg_rate: -1
0:00:01.189718 GST_QOS gstbasesink.c:2386:gst_base_sink_perform_qos:<fakesink0> updated: avg_duration: 0:00:00.000000000, avg_pt: 0:00:00.220455826, avg_rate: 0
# Now, a QoS event is sent.
0:00:01.189732 GST_QOS gstbasesink.c:2278:gst_base_sink_send_qos:<fakesink0> qos: proportion: 0.000000, diff 437275571, timestamp 0:00:00.633476686
0:00:01.189759 GST_QOS gstbasetransform.c:2331:gst_base_transform_update_qos:<videoscale0> qos: proportion: 0.000000, diff 437275571, timestamp 0:00:00.633476686

# Again 200ms later, the next frame arrives, the previous one is decoded.
0:00:01.352582  ffmpeg gstffmpegdec.c:1274:gst_ffmpegdec_do_qos:<ffdec_mpeg40> QOS: qostime 0:00:01.070718163, earliest 0:00:01.070752257
0:00:01.352631  ffmpeg gstffmpegdec.c:1331:gst_ffmpegdec_do_qos:<ffdec_mpeg40> QOS: hurry up, diff 34094 >= 0
0:00:01.352676  ffmpeg gstffmpegdec.c:897:gst_ffmpegdec_get_buffer:<ffdec_mpeg40> getting buffer, apply pts 1070718163
0:00:01.353261  ffmpeg gstffmpegdec.c:1600:gst_ffmpegdec_video_frame:<ffdec_mpeg40> after decode: len 1395, have_data 288
0:00:01.353282  ffmpeg gstffmpegdec.c:1614:gst_ffmpegdec_video_frame:<ffdec_mpeg40> ts-handler: pts 848446910

# The timestamp of this frame is earlier than the time that the previous 
# one was rendered, so basetransform drops it.
0:00:01.353402 GST_QOS gstbasetransform.c:1862:gst_base_transform_handle_buffer:<videoscale0> skipping transform: qostime 0:00:00.848446910 <= 0:00:01.070752257

# And this story repeats itself.
0:00:01.608276  ffmpeg gstffmpegdec.c:1274:gst_ffmpegdec_do_qos:<ffdec_mpeg40> QOS: qostime 0:00:01.234701170, earliest 0:00:01.070752257
0:00:01.608329  ffmpeg gstffmpegdec.c:1311:gst_ffmpegdec_do_qos:<ffdec_mpeg40> QOS: normal mode 0 < 0.4
0:00:01.608371  ffmpeg gstffmpegdec.c:897:gst_ffmpegdec_get_buffer:<ffdec_mpeg40> getting buffer, apply pts 1234701170
0:00:01.608943  ffmpeg gstffmpegdec.c:1600:gst_ffmpegdec_video_frame:<ffdec_mpeg40> after decode: len 1352, have_data 288
0:00:01.608963  ffmpeg gstffmpegdec.c:1614:gst_ffmpegdec_video_frame:<ffdec_mpeg40> ts-handler: pts 1070718163
0:00:01.609079 GST_QOS gstbasetransform.c:1862:gst_base_transform_handle_buffer:<videoscale0> skipping transform: qostime 0:00:01.070718163 <= 0:00:01.070752257

# The next frame will pass basetransform because we have caught up with the
# previous rendering time


 One problem is that the framerate is unknown; with a correct framerate, the 
buffers have a duration and this gives a more accurate estimate of the expected
rendering time of the next buffer.  However, even so, small differences in
decoding time may still make a buffer seem late (e.g. add 200ms to the first
dropped buffer, above).

 The core of the problem, I think, is that the QoS handling doesn't take 
into account pipeline latency.  It just assumes that throughput = 1/latency
and doesn't seem to take into account that data can be buffered in the
pipeline.

 Does anyone have any idea how to solve this?  (Except for disabling qos, of
course...)

 Regards,
 Arnout
-- 
Arnout Vandecappelle                               arnout at mind be
Senior Embedded Software Architect                 +32-16-286540
Essensium/Mind                                     http://www.mind.be
G.Geenslaan 9, 3001 Leuven, Belgium                BE 872 984 063 RPR Leuven
LinkedIn profile: http://www.linkedin.com/in/arnoutvandecappelle
GPG fingerprint:  D206 D44B 5155 DF98 550D  3F2A 2213 88AA A1C7 C933