GNOME Bugzilla – Bug 657835
QOS messages are not reliable
Last modified: 2012-01-12 17:41:49 UTC
This was observed with different media, so far with mp4 video over RTSP, or mpeg transport streams from a file or UDP streamed. Two issues here: 1. QOS messages are sometimes not sent when frames are dropped 2. Rendered/dropped frame counts are sometimes incorrect Examples (custom logging format from a proprietary application using PyGst): 1. MP4 over RTSP rtsp://184.72.239.149/vod/mp4:BigBuckBunny_175k.mov 2011-08-31 15:25:09.317 DEBUG Player now playing 2011-08-31 15:25:09.317 INFO Video format 240x160 24.000000fps aspect=1.500000 interlaced=False 2011-08-31 15:25:10.750 DEBUG QOS[xvimagesink0] @ 1.395367s rendered/dropped=27/1 (dpr=0.033534 compensation=5.488799); jitter=146ms 2011-08-31 15:25:10.750 DEBUG QOS[xvimagesink0] @ 1.437367s rendered/dropped=27/2 (dpr=0.038695 compensation=0.000000); jitter=104ms 2011-08-31 15:25:10.751 DEBUG QOS[xvimagesink0] @ 1.478367s rendered/dropped=27/3 (dpr=0.043790 compensation=0.000000); jitter=63ms 2011-08-31 15:25:47.068 DEBUG QOS[xvimagesink0] @ 37.661284s rendered/dropped=859/4 (dpr=0.041169 compensation=8.390006); jitter=198ms Notice how in all messages rendered + dropped frame count is in shortfall compared to expected numbers which are stream time * frame rate. 2. Channel 4 (UK) DVB-T MPEG TS 25fps interlaced (stream available on request) QOS[xvimagesink0] @ 11.478789s rendered/dropped=917/1; jitter=109ms QOS[xvimagesink0] @ 11.488789s rendered/dropped=917/2; jitter=99ms QOS[xvimagesink0] @ 11.498789s rendered/dropped=917/3; jitter=89ms QOS[xvimagesink0] @ 13.278789s rendered/dropped=1082/4; jitter=229ms QOS[xvimagesink0] @ 13.288789s rendered/dropped=1082/5; jitter=219ms QOS[xvimagesink0] @ 13.298789s rendered/dropped=1082/6; jitter=210ms Frame counts totally to high. Now same media via gst-launch: Got message #579 from element "vconv" (qos): GstMessageQOS, live=(boolean)false, running-time=(guint64)11468788889, stream-time=(guint64)11468788889, timestamp=(guint64)70776028066666, duration=(guint64)40000000, jitter=(gint64)42211111, proportion=(double)0.029221459808303867, quality=(int)1000000, format=(GstFormat)GST_FORMAT_BUFFERS, processed=(guint64)229, dropped=(guint64)1; Got message #621 from element "vconv" (qos): GstMessageQOS, live=(boolean)false, running-time=(guint64)13268788889, stream-time=(guint64)13268788889, timestamp=(guint64)70777828066666, duration=(guint64)40000000, jitter=(gint64)161377777, proportion=(double)0.029551520163774225, quality=(int)1000000, format=(GstFormat)GST_FORMAT_BUFFERS, processed=(guint64)270, dropped=(guint64)2; Got message #752 from element "videosink-actual-sink-xvimage" (warning): GstMessageWarning, gerror=(GError)NULL, debug=(string)"gstbasesink.c\(2866\):\ gst_base_sink_is_too_late\ \(\):\ /GstPlayBin2:playbin20/GstPlaySink:playsink0/GstBin:vbin/GstAutoVideoSink:videosink/GstXvImageSink:videosink-actual-sink-xvimage:\012There\ may\ be\ a\ timestamping\ problem\,\ or\ this\ computer\ is\ too\ slow."; WARNING: from element /GstPlayBin2:playbin20/GstPlaySink:playsink0/GstBin:vbin/GstAutoVideoSink:videosink/GstXvImageSink:videosink-actual-sink-xvimage: A lot of buffers are being dropped. Additional debug info: gstbasesink.c(2866): gst_base_sink_is_too_late (): /GstPlayBin2:playbin20/GstPlaySink:playsink0/GstBin:vbin/GstAutoVideoSink:videosink/GstXvImageSink:videosink-actual-sink-xvimage: There may be a timestamping problem, or this computer is too slow. Got message #802 from element "vconv" (qos): GstMessageQOS, live=(boolean)false, running-time=(guint64)20828788889, stream-time=(guint64)20828788889, timestamp=(guint64)70785388066666, duration=(guint64)40000000, jitter=(gint64)41044444, proportion=(double)0.030325550728272158, quality=(int)1000000, format=(GstFormat)GST_FORMAT_BUFFERS, processed=(guint64)449, dropped=(guint64)3; Frame counts to low.
Not all frames make it to the sink, some frames are dropped by the decoders or by the conversion elements. Maybe that explains your observation. Maybe also the decoder that drops a frame does not correctly post a QOS message. What decoder is in use here? The code to calculate total frames and number of dropped frames in the sink is very simple, I would be surprised if there was a bug there.
Why are elements which drop frames not reporting that? Also, what about the inflated numbers in my second example? According to those messages it should be a ~80fps video while it is in fact 25fps.
(In reply to comment #2) > Why are elements which drop frames not reporting that? Because they have a bug. > > Also, what about the inflated numbers in my second example? According to those > messages it should be a ~80fps video while it is in fact 25fps. Where do you see that?
(In reply to comment #3) > (In reply to comment #2) > > Why are elements which drop frames not reporting that? > > Because they have a bug. I guess it is tricky to know which ones if they are not reporting it. Since I have two different media types where I saw this, does it mean buggy elements are likely to be common elements, or that different media demuxers/decoders could be buggy just as well? > > > > Also, what about the inflated numbers in my second example? According to those > > messages it should be a ~80fps video while it is in fact 25fps. > > Where do you see that? In my second example above, which is output from a PyGst test program. I can attach that program here, but test stream is to big at 35Mb.
> > Because they have a bug. > > I guess it is tricky to know which ones if they are not reporting it. Since I > have two different media types where I saw this, does it mean buggy elements > are likely to be common elements, or that different media demuxers/decoders > could be buggy just as well? All sinks and basetransform derived elements should work correctly. I know theoradec does it correctly too. I know ffmpeg does not do it correctly and I assume most other video decoders are wrong as well.
Additionally, dropped seems to refer to frames dropped specifically because of being too late. This counter will not account for frames dropped for other reasons, such as waiting for a keyframe, decoding error, etc. I'm going to look at that issue now.
More findings: The deinterlacer outputs (on some videos) twice as many frames as it gets in input. The sink (and any element downstream of the deinterlacer, when actually deinterlacing) will see the larger amount. This is seen on the c4-sync.ts sample, where deinterlacing causes twice as many frames to reach the sink. Additionally, the deinterlacer can switch on and off based on whether input interlacing changes, which can, on some inputs, cary actual frame rate seen by the sink in a non linear way. Last, on the c4-sync.ts sample, ffmpeg reports the file to be 27.02 fps, but when looking at the timestamps and the duration, the real fps is about 23, making a direct comparison of number of frames against framerate*duration error prone.
(In reply to comment #7) > More findings: > > The deinterlacer outputs (on some videos) twice as many frames as it gets in > input. The sink (and any element downstream of the deinterlacer, when actually > deinterlacing) will see the larger amount. This is seen on the c4-sync.ts > sample, where deinterlacing causes twice as many frames to reach the sink. > > Additionally, the deinterlacer can switch on and off based on whether input > interlacing changes, which can, on some inputs, cary actual frame rate seen by > the sink in a non linear way. > > Last, on the c4-sync.ts sample, ffmpeg reports the file to be 27.02 fps, but > when looking at the timestamps and the duration, the real fps is about 23, > making a direct comparison of number of frames against framerate*duration error > prone. Noted - so that approach goes out the window. I guess that makes it more important to make everyone who drops frames actually report it via a QOS message. I'll try to capture a stream which demonstrates this.
Thanks, but I don't need a new sample at the moment, I can see the issue here.
The deinterlacer was not sending QoS messages when dropping late frames. https://bugzilla.gnome.org/show_bug.cgi?id=657941 I'm going through others elements used by playbin2 to check if others don't.
Done for ffmpegdec too.
Done for mpeg2dec too, that's the last element that was missing it in those used in a playbin2 pipeline playing a MPEG TS file.
Looks like we can close this. If any others are missing, please file bugs against the decoder elements that don't implement this properly, thanks!