After an evaluation, GNOME has moved from Bugzilla to GitLab. Learn more about GitLab.
No new issues can be reported in GNOME Bugzilla anymore.
To report an issue in a GNOME project, go to GNOME GitLab.
Do not go to GNOME Gitlab for: Bluefish, Doxygen, GnuCash, GStreamer, java-gnome, LDTP, NetworkManager, Tomboy.
Bug 657835 - QOS messages are not reliable
QOS messages are not reliable
Status: RESOLVED OBSOLETE
Product: GStreamer
Classification: Platform
Component: gstreamer (core)
0.10.34
Other Linux
: Normal normal
: NONE
Assigned To: GStreamer Maintainers
GStreamer Maintainers
Depends on: 657941 657950 660562
Blocks:
 
 
Reported: 2011-08-31 14:45 UTC by Tvrtko Ursulin
Modified: 2012-01-12 17:41 UTC
See Also:
GNOME target: ---
GNOME version: ---



Description Tvrtko Ursulin 2011-08-31 14:45:40 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.
Comment 1 Wim Taymans 2011-08-31 18:37:47 UTC
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.
Comment 2 Tvrtko Ursulin 2011-09-01 07:16:12 UTC
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.
Comment 3 Wim Taymans 2011-09-01 07:24:22 UTC
(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?
Comment 4 Tvrtko Ursulin 2011-09-01 07:37:59 UTC
(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.
Comment 5 Wim Taymans 2011-09-01 07:46:11 UTC
> > 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.
Comment 6 Vincent Penquerc'h 2011-09-01 09:50:10 UTC
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.
Comment 7 Vincent Penquerc'h 2011-09-01 13:17:42 UTC
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.
Comment 8 Tvrtko Ursulin 2011-09-01 13:26:31 UTC
(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.
Comment 9 Vincent Penquerc'h 2011-09-01 13:31:43 UTC
Thanks, but I don't need a new sample at the moment, I can see the issue here.
Comment 10 Vincent Penquerc'h 2011-09-01 14:52:18 UTC
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.
Comment 11 Vincent Penquerc'h 2011-09-01 15:51:57 UTC
Done for ffmpegdec too.
Comment 12 Vincent Penquerc'h 2011-09-05 10:17:37 UTC
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.
Comment 13 Tim-Philipp Müller 2012-01-12 17:41:49 UTC
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!