Profiling

From Gnash Project Wiki

Jump to: navigation, search

Contents

How to profile using gprof

  • configure with CXXFLAGS="-pg -g" and --disable-shared
  • play your movie, cleanly exit
  • run libtool --mode=execute gprof gui/gtk-gnash > profile

Here's the data from a recent gprof using the options 

gprof --flat-profile --exec-counts --graph

Each sample counts as 0.01 seconds.
 %   cumulative   self              self     total           
time   seconds   seconds    calls   s/call   s/call  name    
13.98      1.52     1.52     3236     0.00     0.00  gnash::fill_style::create_gradient_bitmap(gnash::Renderer&) const
 8.10      2.40     0.88 12487020     0.00     0.00  gnash::fill_style::sample_gradient(unsigned char) const
 5.66      3.02     0.61 33938759     0.00     0.00  gnash::frnd(float)
 4.78      3.54     0.52 12395080     0.00     0.00  std::sqrt(float)
 2.44      3.80     0.27 53901034     0.00     0.00  __gnu_cxx::__normal_iterator<gnash::gradient_record const*, std::vector<gnash::gradient_record, std::allocator<gnash::gradient_record> > >::__normal_iterator(gnash::gradient_record const* const&)
 2.25      4.04     0.24 11802009     0.00     0.00  gnash::ImageRGBA::setPixel(unsigned int, unsigned int, unsigned char, unsigned char, unsigned char, unsigned char)
 2.21      4.29     0.24                             malloc
 1.89      4.49     0.20  8750499     0.00     0.00  gnash::rgba::set_lerp(gnash::rgba const&, gnash::rgba const&, float)
 1.84      4.69     0.20 34431060     0.00     0.00  gnash::flerp(float, float, float)
 1.84      4.89     0.20                             free
 1.75      5.08     0.19 15538492     0.00     0.00  __gnu_cxx::__normal_iterator<gnash::gradient_record const*, std::vector<gnash::gradient_record, std::allocator<gnash::gradient_record> > >::operator-(int const&) const
 1.75      5.27     0.19 12311748     0.00     0.00  std::vector<gnash::gradient_record, std::allocator<gnash::gradient_record> >::begin() const
 1.66      5.45     0.18 27048503     0.00     0.00  std::vector<gnash::gradient_record, std::allocator<gnash::gradient_record> >::end() const
 1.61      5.62     0.17 15226630     0.00     0.00  std::vector<gnash::gradient_record, std::allocator<gnash::gradient_record> >::back() const
 1.56      5.79     0.17 37110625     0.00     0.00  std::auto_ptr<gnash::ImageRGBA>::operator->() const

How to profile using valgrind and kcachegrind

The advantage to profiling with valgrind is that there's no need to compile gnash with any special flags. The disadvantage is that it runs approximately 50x slower in valgrind.

Debug symbols should be included in the gnash build (CXXFLAGS="-g"), but this is the default.

  • Optional Install debug symbols for libc (e.g. libc6-dbg package)
  • Run valgrind --tool=callgrind /usr/local/bin/gtk-gnash file.swf
  • play your movie, cleanly exit
  • Run kcachegrind callgrind.out.XXXXX The XXXXX is a unique number.
  • Examine the results in the kcachegrind program. For more help read http://kcachegrind.sourceforge.net/html/Documentation.html


Oprofile

Oprofile is another good profiling tool. You initially start the oprofile daemon by using oprofd_start, the you can start and stop the daemon. Don't forget to flush the samples between runs unless you really want to confuse yourself. After collecting samples, you then run opreport or opannodate to produce a variety of output reports from the recorded samples. Some good examples on this are on the Oprofile web site.

An annotated listing as of March 2010 (revno #12118) is as follows, and was created with these options: opannodate-gnash.txt is here 

opannotate `which gtk-gnash` --source --threshold 2 --merge=tid

The report was created with these options opreport-gnash.txt is here 

opreport --symbols `which gtk-gnash` --merge tgid --callgraph --long-filenames --sort sample

Here's the list of the functions that get called the most when playing an animation: 

207171   99.9961  libgnashcore-trunk.so gnash::MovieClip::display(gnash::Renderer&)
207171   99.9464  libgnashcore-trunk.so gnash::DisplayList::display(gnash::Renderer&)
175403   99.2901  libgnashcore-trunk.so gnash::MovieClip::display(gnash::Renderer&)
175403   85.0348  libgnashcore-trunk.so gnash::movie_root::display()
174481   99.9994  libgnashrender.so.0.0.0 gnash::Renderer_agg<agg::pixfmt_alpha_blend_rgba<agg::blender_rgba_pre<agg::rgba8, agg::order_bgra>,  agg::row_accessor<unsigned char>, unsigned int> >::drawShape(gnash::SWF::ShapeRecord const&, gnash::cxform const&, gnash::SWFMatrix const&)
174481   99.7239  libgnashrender.so.0.0.0 gnash::Renderer_agg<agg::pixfmt_alpha_blend_rgba<agg::blender_rgba_pre<agg::rgba8, agg::order_bgra>, agg::row_accessor<unsigned char>, unsigned int> >::drawShape(std::vector<gnash::fill_style, std::allocator<gnash::fill_style> > const&, std::vector<gnash::LineStyle, std::allocator<gnash::LineStyle> > const&, std::vector<gnash::Path, std::allocator<gnash::Path> > const&, gnash::SWFMatrix const&, gnash::cxform const&)
174224   99.1678  libgnashcore-trunk.so gnash::movie_root::display()
174224   100.000  /usr/local/bin/gtk-gnash gnash::Gui::display(gnash::movie_root*)
169973   99.2642  /usr/local/bin/gtk-gnash gnash::Gui::advanceMovie()
169973   98.7371  /usr/local/bin/gtk-gnash gnash::Gui::display(gnash::movie_root*)
165401   99.9946  libgnashcore-trunk.so gnash::Shape::display(gnash::Renderer&)
165401   99.9722  libgnashcore-trunk.so gnash::SWF::DefineShapeTag::display(gnash::Renderer&, gnash::DisplayObject const&) const
165290   99.8773  libgnashrender.so.0.0.0 gnash::Renderer_agg<agg::pixfmt_alpha_blend_rgba<agg::blender_rgba_pre<agg::rgba8, agg::order_bgra>, agg::row_accessor<unsigned char>, unsigned int> >::drawShape(gnash::SWF::ShapeRecord const&, gnash::cxform const&, gnash::SWFMatrix const&)
165290   94.4844  libgnashcore-trunk.so gnash::SWF::DefineShapeTag::display(gnash::Renderer&, gnash::DisplayObject const&) const
164666   99.6044  libgnashcore-trunk.so gnash::DisplayList::display(gnash::Renderer&)
164666   79.2204  libgnashcore-trunk.so gnash::Shape::display(gnash::Renderer&)
164615   99.9982  /lib/libglib-2.0.so.0.2306.0 g_timeout_dispatch
164615   99.9775  /usr/local/bin/gtk-gnash gnash::Gui::advanceMovie()
151160   99.4179  /lib/libglib-2.0.so.0.2306.0 g_timeout_dispatch
151160   100.000  /lib/libglib-2.0.so.0.2306.0 g_main_context_dispatch
138952   99.9993  /lib/libglib-2.0.so.0.2306.0 g_main_context_iterate
138952   99.7487  /lib/libglib-2.0.so.0.2306.0 g_main_context_dispatch
119089   99.9992  /lib/libglib-2.0.so.0.2306.0 g_main_loop_run
119089   99.9866  /lib/libglib-2.0.so.0.2306.0 g_main_context_iterate
102775   99.9981  /lib/libglib-2.0.so.0.2306.0 g_main_loop_run
102775   100.000  /usr/lib/libgtk-x11-2.0.so.0.2000.0 gtk_main


These logs were produced by running the same swf file (gansta-rap.swf) the same amount of time (roughly), and the dumping the report after each run, so we can compare the performance of rendering and hardware acceleration options. I've extract the top handful of functions that get called the most times for comparison.

AGG

AGG Log 

105847   99.9500  8022     99.9751  libgnashcore-trunk.so gnash::DisplayList::display(gnash::Renderer&)
105847   100.000  8022     100.000  libgnashcore-trunk.so gnash::MovieClip::display(gnash::Renderer&)
99355    99.2092  7552     99.2770  libgnashcore-trunk.so gnash::MovieClip::display(gnash::Renderer&)
99355    94.1316  7552     94.3882  libgnashcore-trunk.so gnash::movie_root::display()
99110    99.9990  7531     100.000  /usr/local/bin/gtk-gnash gnash::Gui::display(gnash::movie_root*)
99110    99.0743  7531     99.4585  libgnashcore-trunk.so gnash::movie_root::display()
98833    99.9960  7537     100.000  libgnashrender.so.0.0.0 gnash::Renderer_agg<agg::pixfmt_alpha_blend_rgba<agg::blender_rgba_pre<agg::rgba8, agg::order_bgra>, agg::row_accessor<unsigned char>, unsigned int> >::drawShape(gnash::SWF::ShapeRecord const&, gnash::cxform const&, gnash::SWFMatrix const&)
98833    99.6813  7537     99.8543  libgnashrender.so.0.0.0 gnash::Renderer_agg<agg::pixfmt_alpha_blend_rgba<agg::blender_rgba_pre<agg::rgba8, agg::order_bgra>, agg::row_accessor<unsigned char>, unsigned int> >::drawShape(std::vector<gnash::fill_style, std::allocator<gnash::fill_style> > const&, std::vector<gnash::LineStyle, std::allocator<gnash::LineStyle> > const&, std::vector<gnash::Path, std::allocator<gnash::Path> > const&, gnash::SWFMatrix const&, gnash::cxform const&)
97900    99.6671  7403     99.6634  /usr/local/bin/gtk-gnash gnash::Gui::advanceMovie()
97900    98.6408  7403     99.0633  /usr/local/bin/gtk-gnash gnash::Gui::display(gnash::movie_root*)

AGG Video 

446802   99.9973  29919    100.000  libgnashcore-trunk.so gnash::MovieClip::display(gnash::Renderer&)
446802   88.3719  29919    88.4105  libgnashcore-trunk.so gnash::DisplayList::display(gnash::Renderer&)
400015   87.0868  26703    87.1280  libgnashcore-trunk.so gnash::MovieClip::display(gnash::Renderer&)
400015   85.5629  26703    85.2042  libgnashcore-trunk.so gnash::DisplayList::display(gnash::Renderer&)
108904   99.8570  4292     99.9767  libgnashcore-trunk.so gnash::SWF::SWFHandlers::execute(gnash::SWF::ActionType, gnash::ActionExec&) const
108904   99.0676  4292     99.2370  libgnashcore-trunk.so gnash::SWF::ActionHandler::execute(gnash::ActionExec&) const
102118   99.8182  7239     99.8070  libgnashcore-trunk.so gnash::as_object::markAsObjectReachable() const
102118   98.4782  7239     98.3827  libgnashcore-trunk.so gnash::PropertyList::setReachable() const
100936   99.9436  3944     99.9240  libgnashcore-trunk.so gnash::ActionExec::operator()()
100936   98.1247  3944     98.6740  libgnashcore-trunk.so gnash::SWF::SWFHandlers::execute(gnash::SWF::ActionType, gnash::ActionExec&) const

AGG and Xv

AGG & Xv log 

174218   100.000  10647    100.000  /lib/tls/i686/cmov/libpthread-2.11.1.so start_thread
174218   100.000  10647    100.000  /lib/tls/i686/cmov/libc-2.11.1.so clone
172358   99.9797  10639    99.9718  libgnashcore-trunk.so gnash::SWFMovieDefinition::read_all_swf()
172358   99.9530  10639    99.9812  libgnashcore-trunk.so gnash::SWFParser::read(int)
172215   100.000  10626    100.000  libgnashcore-trunk.so gnash::SWFMovieLoader::execute(gnash::SWFMovieLoader&, gnash::SWFMovieDefinition*)
172215   100.000  10626    100.000  libgnashcore-trunk.so gnash::SWFMovieDefinition::read_all_swf()
171995   100.000  10615    100.000  libgnashcore-trunk.so gnash::SWFMovieLoader::execute(gnash::SWFMovieLoader&, gnash::SWFMovieDefinition*)
171995   100.000  10615    100.000  libgnashcore-trunk.so boost::detail::thread_data<boost::_bi::bind_t<void, void (*)(gnash::SWFMovieLoader&, gnash::SWFMovieDefinition*), boost::_bi::list2<boost::reference_wrapper<gnash::SWFMovieLoader>, boost::_bi::value<gnash::SWFMovieDefinition*> > > >::run()
171450   99.9948  10596    99.9906  /lib/tls/i686/cmov/libpthread-2.11.1.so start_thread
171450   96.7622  10596    97.8845  /usr/lib/libboost_thread.so.1.40.0 /usr/lib/libboost_thread.so.1.40.0


Cairo

Cairo log 

91898    35.0983  6268     39.4760  /usr/lib/libpixman-1.so.0.16.4 /usr/lib/libpixman-1.so.0.16.4
91898    100.000  6268     100.000  /usr/lib/libpixman-1.so.0.16.4 /usr/lib/libpixman-1.so.0.16.4 [self]
64179    100.000  3890     100.000  /lib/tls/i686/cmov/libpthread-2.11.1.so start_thread
64179    100.000  3890     100.000  /lib/tls/i686/cmov/libc-2.11.1.so clone
62078    99.9581  3830     99.9217  libgnashcore-trunk.so gnash::SWFMovieDefinition::read_all_swf()
62078    99.9404  3830     99.9478  libgnashcore-trunk.so gnash::SWFParser::read(int)
62029    100.000  3828     100.000  libgnashcore-trunk.so gnash::SWFMovieLoader::execute(gnash::SWFMovieLoader&, gnash::SWFMovieDefinition*)
62029    100.000  3828     100.000  libgnashcore-trunk.so gnash::SWFMovieDefinition::read_all_swf()
61941    100.000  3821     100.000  libgnashcore-trunk.so gnash::SWFMovieLoader::execute(gnash::SWFMovieLoader&, gnash::SWFMovieDefinition*)
61941    100.000  3821     100.000  libgnashcore-trunk.so boost::detail::thread_data<boost::_bi::bind_t<void, void (*)(gnash::SWFMovieLoader&, gnash::SWFMovieDefinition*), boost::_bi::list2<boost::reference_wrapper<gnash::SWFMovieLoader>, boost::_bi::value<gnash::SWFMovieDefinition*> > > >::run()
Retrieved from "http://wiki.gnashdev.org/Profiling"