NinjaProfile

From Gnash Project Wiki

Jump to: navigation, search

Test case: http://www.atomfilms.com/afassets/flash/nj_chapterninjai10_bb.swf

md5sum: a3d368108cadb2b6151d304b90911870
SWF: 5

This movie exposes a frustrating slowness in Gnash parser as of head 2007-08-24. In this page we'll try to find out why.

NEWS: running with -r1 (sound disabled) seems to speed up parsing a lot ! --Strk 12:08, 25 September 2007 (EDT);

Profile reports

Profile1

The following profile has been generated with gprof and loader thread disabled. As soon as parsing finishes the output window gets mapped and a screen prompting user for continuing playing gets rendered. At that point I quit (there should not be much rendering involved, due to invalidated ranges being NULL).

Flat profile:
Each sample counts as 0.01 seconds.
 %   cumulative   self              self     total           
time   seconds   seconds    calls  ms/call  ms/call  name    
34.81      0.28     0.28 18522890     0.00     0.00  gnash::stream::read_uint(unsigned short)
21.52      0.45     0.17     2689     0.06     0.24  gnash::shape_character_def::read(gnash::stream*, int, bool, gnash::movie_definition*)
 8.86      0.52     0.07  6521001     0.00     0.00  gnash::stream::read_sint(unsigned short)
 6.33      0.57     0.05   608793     0.00     0.00  gnash::rgba::set_lerp(gnash::rgba const&, gnash::rgba const&, float)
 3.80      0.60     0.03   652544     0.00     0.00  gnash::fill_style::sample_gradient(unsigned char) const


Excerpt from the graph:
               0.00    0.00       6/18522890     gnash::SWF::tag_loaders::sound_stream_head_loader(gnash::stream*, gnash::SWF::tag_type, gnash::movie_definition*) [169]
               0.00    0.00       8/18522890     gnash::font::readDefineFont2_or_3(gnash::stream*, gnash::movie_definition*) [69]
               0.00    0.00      16/18522890     gnash::edit_text_character_def::read(gnash::stream*, int, gnash::movie_definition*) [59]
               0.00    0.00     167/18522890     gnash::text_glyph_record::read(gnash::stream*, int, int, int) [117]
               0.00    0.00    2649/18522890     gnash::rect::read(gnash::stream*) [42]
               0.00    0.00    5685/18522890     gnash::cxform::read_rgba(gnash::stream*) [85]
               0.00    0.00  161381/18522890     gnash::matrix::read(gnash::stream*) [57]
               0.00    0.00  304424/18522890     gnash::SWF::PlaceObject2Tag::readPlaceObject2(gnash::stream*, int, bool) [41]
               0.10    0.01 6521001/18522890     gnash::stream::read_sint(unsigned short) [8]
               0.17    0.01 11527553/18522890     gnash::shape_character_def::read(gnash::stream*, int, bool, gnash::movie_definition*) [5]
[7]    37.2    0.28    0.02 18522890         gnash::stream::read_uint(unsigned short) [7]
               0.02    0.00 8045860/8464384     gnash::std_read_func(void*, int, void*) [32]


Profile2

Obtained in the same way as Profile1, but with optimized multi-byte read in stream::read_uint. This optimization basically reduces calls to the tu_file reader. You can see we now have 6588352 calls to std_read_func, versus the 6923837 calls previously made with this optimization disabled (there's a macro in stream.cpp to remove the multi-byte optimization)

Flat profile:
Each sample counts as 0.01 seconds.
 %   cumulative   self              self     total           
time   seconds   seconds    calls  ms/call  ms/call  name    
24.65      0.18     0.18  9876813     0.00     0.00  gnash::stream::read_uint(unsigned short)
14.08      0.28     0.10     2689     0.04     0.20  gnash::shape_character_def::read(gnash::stream*, int, bool, gnash::movie_definition*)
11.97      0.36     0.09  8646077     0.00     0.00  gnash::stream::read_bit()
 4.93      0.40     0.04  6521001     0.00     0.00  gnash::stream::read_sint(unsigned short)
 4.23      0.43     0.03  8128899     0.00     0.00  gnash::std_read_func(void*, int, void*)                                                     


Excerpt from the graph:
               0.00    0.00       4/9876813     gnash::SWF::tag_loaders::sound_stream_head_loader(gnash::stream*, gnash::SWF::tag_type, gnash::movie_definition*) [130]       
               0.00    0.00     167/9876813     gnash::text_glyph_record::read(gnash::stream*, int, int, int) [112]
               0.00    0.00    1895/9876813     gnash::cxform::read_rgba(gnash::stream*) [92]
               0.00    0.00    2649/9876813     gnash::rect::read(gnash::stream*) [90]
               0.00    0.00   89241/9876813     gnash::matrix::read(gnash::stream*) [66]
               0.06    0.01 3261856/9876813     gnash::shape_character_def::read(gnash::stream*, int, bool, gnash::movie_definition*) [5]
               0.12    0.02 6521001/9876813     gnash::stream::read_sint(unsigned short) [8]
[7]     28.1    0.18    0.02 9876813         gnash::stream::read_uint(unsigned short) [7]
               0.02    0.00 6588352/8128899     gnash::std_read_func(void*, int, void*) [15]