GNOME Bugzilla – Bug 345396
Performance degrades with gstreamer0.10
Last modified: 2006-07-28 09:18:11 UTC
Please describe the problem: The following sequence: takes a huge amount of CPU load. This happens with every version of gstreamer0.10.x (up to 0.10.5). Using gstreamer-0.8.12, gst-plugins-0.8.12, gst-ffmpeg-0.8.7 everything works quickly! Performance is more than FIVE times greater with gstreamer0.10.x.!! Steps to reproduce: 1. Install gstreamer0.10-0.10.4, gst-plugins-base0.10-0.10.x, gst-plugins-good0.10-0.10.x, gst-ffmpeg-0.10.1 2. command line: gst-launch filesrc location=mpeg4.avi ! ffdemux_avi ! ffdec_mpeg4 ! ffmpegcolorpace ! ximagesink 3. top (or similar to watch performance) 4. Install gstreamer-0.8.12, gst-plugins-0.8.12, gst-ffmpeg-0.8.7 5. command line: gst-launch filesrc location=mpeg4.avi ! ffdemux_avi ! ffdec_mpeg4 ! ffmpegcolorpace ! ximagesink 6. top (or similar) and watch performance be 5 times greater! Actual results: Performance may be observed very poor with gstreamer10. Expected results: Performance is poor. Does this happen every time? Yes Other information: Many combinations of ffmpeg and plugins have been tested to comfirm bug is in gstreamer core.
when reporting performance figures can you run this with again time, top can be very deceiving. like so: time filesrc location=blood.avi ! ffdemux_avi ! ffdec_mpeg4 ! ffmpegcolorpace ! videoscale ! fakesink silent=1 which typically gives in 0.10 (with blood.avi in bug #337866): real 0m4.364s user 0m3.205s sys 0m1.051s and in 0.8: real 0m3.163s user 0m2.468s sys 0m0.660s after that you need tools like cachgrind to figure out what's slowing stuff down. in 0.10 it could be bug #321662.
breakdown of callgrind for 0.10: 80% gstffmpeg.so, mostly in motion compensation, the real decoding etc. 7% libc, mostly memcpy (bug #321662) and strcmp when loading the registry. 4.7% gobject, type checking mostly. 2.18% gstreamer, caps stuff mostly. 1.9% pthread, mutex lock/unlock ... breakdown of callgrind for 0.8 (don't have symbols for ffmpeg): 90% gstffmpeg.so 2.24% gobject type checking 1.86% libc, strcpy/memcpy 1.71% gstreamer (debug) ...
(In reply to comment #2) > breakdown of callgrind for 0.10: > > 80% gstffmpeg.so, mostly in motion compensation, the real decoding etc. > 7% libc, mostly memcpy (bug #321662) and strcmp when loading the registry. > 4.7% gobject, type checking mostly. > 2.18% gstreamer, caps stuff mostly. > 1.9% pthread, mutex lock/unlock > ... > > breakdown of callgrind for 0.8 (don't have symbols for ffmpeg): > > 90% gstffmpeg.so > 2.24% gobject type checking > 1.86% libc, strcpy/memcpy > 1.71% gstreamer (debug) > ... > I applied the patch (bug #321662). No help on performance. I have used Linux Trace Toolkit to see that the performance indeed is very poor. ..well, so far I have to stick with gstreamer0.8.
> after that you need tools like cachgrind to figure out what's slowing stuff > down. in 0.10 it could be bug #321662. > We dont have cachgrind on ARM machine... I just verified the following chain (latest): gstreamer-0.10.8 gst-plugins-base-0.10.8 gst-plugins-good-0.10.3 gst-ffmpeg-0.10.1 also with the patch provided with bug #321662. In both cases, CPU performance is poor.
can you give some numbers with time?
(In reply to comment #5) > can you give some numbers with time? > Sure. Here we go: (see the huge difference in user) Gst0.10: real 2m 20.07s user 2m 5.35s sys 0m 2.15s gst0.8: real 2m 24.52s user 0m 38.67s sys 0m 2.28s
is ffmpeg compiled with any assembler optimisations? did you compile it yourself?
(In reply to comment #7) > is ffmpeg compiled with any assembler optimisations? did you compile it > yourself? No assembler optimizations. I compiled it myself using default options. This is, ./configure --prefix=/usr and make install. However, I'm using ARM processor. It's still the same for both 0.8 and 0.10.
(In reply to comment #5) > can you give some numbers with time? > I tried the following chain (hope this helps..) gstreamer-0.9.7, gst-plugings-base-0.9.7, gst-plugins-good-0.9.7, gst-ffmpeg-0.9.7 timed: real 2m 21.88s user 2m 1.69s sys 0m 4.48s
(In reply to comment #5) > can you give some numbers with time? > The following chain: gstreamer-0.9.3, gst-plugins-base-0.9.3, gst-plugins-good-0.9.3, gst-ffmpeg-0.9.3 provided good results. timed: real 2m 19.09s user 0m 37.37s sys 0m 7.57s ...now down to 0.9.3 <-> 0.9.7
In gstreamer-0.9.5, gst-plugins-base-0.9.5, gst-plugins-good-0.9.5, gst-ffmpeg-0.9.5, everything is ok. In gstreamer-0.9.6, gst-plugins-base-0.9.6, gst-plugins-good-0.9.6, gst-ffmpeg-0.9.6, performance is NOT ok. so we're down to 0.9.5<->0.9.6
I just ported gst-ffmpeg-0.9.5 version to work with gstreamer-0.9.6. I modified the gstffmpegdec.c with only the required lines in order it to work with gstreamer-0.9.6. with gst-ffmpeg-0.9.6 there's a funny line: (line 552) if ((width != context->width) || (height != context->height) || 1) { but it doesn't seem to cause the poor performance either. (what's the "|| 1" do there?) The required lines: (978, and 993) gst_event_parse_newsegment (event, NULL, &rate, &fmt, &start, &end, &base); ->gst_event_parse_new_segment (event, NULL, &rate, &fmt, &start, &end, &base); event = gst_event_new_newsegment (FALSE, rate, fmt, ->event = gst_event_new_new_segment (FALSE, rate, fmt, So I strongly suspect it has to do with the >= gstreamer-0.9.6 that the performance dives.
adding --gst-debug=2 to command line, I see the following, which I don't see with the "working" version: p.c(294):gst_ffmpeg_pixfmt_to_caps: No caps found for pix_fmt=25 WARN (0x117918 - 0:00:16.499634000) default( 2563) gstffmpegcodecm ap.c(294):gst_ffmpeg_pixfmt_to_caps: No caps found for pix_fmt=16 WARN (0x117918 - 0:00:16.499811000) default( 2563) gstffmpegcodecm ap.c(294):gst_ffmpeg_pixfmt_to_caps: No caps found for pix_fmt=17 WARN (0x117918 - 0:00:16.500173000) default( 2563) gstffmpegcodecm ap.c(294):gst_ffmpeg_pixfmt_to_caps: No caps found for pix_fmt=19 WARN (0x117918 - 0:00:16.500272000) default( 2563) gstffmpegcodecm ap.c(294):gst_ffmpeg_pixfmt_to_caps: No caps found for pix_fmt=20 WARN (0x117918 - 0:00:16.500367000) default( 2563) gstffmpegcodecm ap.c(294):gst_ffmpeg_pixfmt_to_caps: No caps found for pix_fmt=21 WARN (0x117918 - 0:00:16.500461000) default( 2563) gstffmpegcodecm ap.c(294):gst_ffmpeg_pixfmt_to_caps: No caps found for pix_fmt=22 WARN (0x117918 - 0:00:16.500556000) default( 2563) gstffmpegcodecm ap.c(294):gst_ffmpeg_pixfmt_to_caps: No caps found for pix_fmt=23 WARN (0x117918 - 0:00:16.500651000) default( 2563) gstffmpegcodecm ap.c(294):gst_ffmpeg_pixfmt_to_caps: No caps found for pix_fmt=24 WARN (0x117918 - 0:00:16.500745000) default( 2563) gstffmpegcodecm ap.c(294):gst_ffmpeg_pixfmt_to_caps: No caps found for pix_fmt=25 WARN (0x117918 - 0:00:16.517789000) default( 2563) gstffmpegcodecm ap.c(294):gst_ffmpeg_pixfmt_to_caps: No caps found for pix_fmt=16 WARN (0x117918 - 0:00:16.517967000) default( 2563) gstffmpegcodecm ap.c(294):gst_ffmpeg_pixfmt_to_caps: No caps found for pix_fmt=17 WARN (0x117918 - 0:00:16.518350000) default( 2563) gstffmpegcodecm ap.c(294):gst_ffmpeg_pixfmt_to_caps: No caps found for pix_fmt=19 WARN (0x117918 - 0:00:16.849174000) default( 2563) gstffmpegcodecm ap.c(294):gst_ffmpeg_pixfmt_to_caps: No caps found for pix_fmt=20 WARN (0x117918 - 0:00:16.849277000) default( 2563) gstffmpegcodecm ap.c(294):gst_ffmpeg_pixfmt_to_caps: No caps found for pix_fmt=21 WARN (0x117918 - 0:00:16.849373000) default( 2563) gstffmpegcodecm ap.c(294):gst_ffmpeg_pixfmt_to_caps: No caps found for pix_fmt=22 WARN (0x117918 - 0:00:16.849468000) default( 2563) gstffmpegcodecm ap.c(294):gst_ffmpeg_pixfmt_to_caps: No caps found for pix_fmt=23 WARN (0x117918 - 0:00:16.849563000) default( 2563) gstffmpegcodecm ap.c(294):gst_ffmpeg_pixfmt_to_caps: No caps found for pix_fmt=24 WARN (0x117918 - 0:00:16.849658000) default( 2563) gstffmpegcodecm ap.c(294):gst_ffmpeg_pixfmt_to_caps: No caps found for pix_fmt=25 WARN (0x117918 - 0:00:16.876543000) default( 2563) gstffmpegcodecm ap.c(294):gst_ffmpeg_pixfmt_to_caps: No caps found for pix_fmt=16 WARN (0x117918 - 0:00:16.876738000) default( 2563) gstffmpegcodecm ap.c(294):gst_ffmpeg_pixfmt_to_caps: No caps found for pix_fmt=17 WARN (0x117918 - 0:00:16.877201000) default( 2563) gstffmpegcodecm ap.c(294):gst_ffmpeg_pixfmt_to_caps: No caps found for pix_fmt=19
You can safely ignore those. (In reply to comment #13) > adding --gst-debug=2 to command line, I see the following, which I don't see > with the "working" version: > > p.c(294):gst_ffmpeg_pixfmt_to_caps: No caps found for pix_fmt=25 > > WARN (0x117918 - 0:00:16.499634000) default( 2563) > gstffmpegcodecm > ...
(In reply to comment #14) > You can safely ignore those. > I wouldn't agree... I'm glad to see that by adding videoscale before ximagesink seems to resolve the problem. Of course, it's not a solution, rather a way to get rid of the problem. The negotiation overhead seems to be huge. The command below: gst-launch filesrc location=mpeg4.avi ! ffdemux_avi ! ffdec_mpeg4 ! ffmpegcolorpace ! videoscale ! ximagesink gives much better performance. timed values here: gstreamer 0.8.12: real 2m 24.59s user 1m 9.69s sys 0m 3.08s gstreamer 0.9.6: real 2m 22.25s user 1m 8.55s sys 0m 9.17s --> no proble.
can you append a GST_DEBUG=*:5 debug log of the slow pipeline here, it's probably so slow due to some excessive caps negotiation thing.
Well, that's probably the overhead of ximagesink checking whether upstream can supply the caps it prefers on every buffer_alloc, since the ximagesink window size won't match the size of the decoded stream.
Ping? Eero, any chance you could create such a log?
Closing this bug report as no further information has been provided. Please feel free to reopen this bug if you can provide the information asked for. Thanks! If you have particular pipelines that you feel are too slow, please open a new bug for them and attach a GST_DEBUG=*:5 debug log so we can have a look what's happening.