[gst-devel] ffdec and QoS

[Wim Taymans]

On Tue, 2009-06-09 at 19:18 +0200, Arnout Vandecappelle wrote:
> 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.
> 

QoS does take latency into account (or else RTSP or RTP streams would
never play). It's probably that ffmpeg totally does not specify its
latency and thus it seems that buffers are simply arriving too late.
Adding a meaningful reply to the LATENCY query in ffmpeg will likely
solve this.

Wim

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