Slow "import hippo" and other on web browser activity startup

William Cohen wcohen at redhat.com
Tue Apr 10 09:43:01 EDT 2007


Marco Pesenti Gritti wrote:
> On Mon, 2007-04-09 at 18:53 -0400, William Cohen wrote:
>> Hi all,
>>
>> I was taking a closer look at where the startup time was spent when starting the 
>> web browser activity.  The profile from python profiler looks like the following:
>>
>> import pstats
>> p = pstats.Stats('/tmp/pywebprof')
>> p.sort_stats('time').print_stats(10)
>>
>>
>> Mon Apr  9 18:19:30 2007    /tmp/pywebprof
>>
>>           11141 function calls (11070 primitive calls) in 20.860 CPU seconds
>>
>>     Ordered by: internal time
>>     List reduced from 802 to 10 due to restriction <10>
>>
>>     ncalls  tottime  percall  cumtime  percall filename:lineno(function)
>>          1    5.320    5.320    5.320    5.320 :0(browser_startup)
>>          1    4.360    4.360    7.650    7.650 :0(main)
>>          1    2.930    2.930    4.300    4.300 
>> /usr/share/activities/Web.activity/webactivity.py:17(?)
>>          1    1.390    1.390    2.320    2.320 :0(present)
>>          1    0.970    0.970    1.130    1.130 
>> /usr/lib/python2.4/site-packages/gtk-2.0/gtk/__init__.py:23(?)
>>          1    0.340    0.340    0.380    0.380 /usr/lib/python2.4/socket.py:43(?)
>>         29    0.200    0.007    0.200    0.007 :0(lookup_icon)
>>         12    0.150    0.012    0.310    0.026 
>> /usr/lib/python2.4/ConfigParser.py:415(_read)
>>         24    0.130    0.005    0.130    0.005 :0(type_register)
>>        327    0.130    0.000    0.130    0.000 :0(lower)
>>
>>
>> According to the profile the "import hippo" is taking a couple of seconds. I 
>> tried it from an interactive python command line and it does seems to take a 
>> while (2 or 3 seconds). Why does the import take so long?
> 
> I think "import hippo" will also cause the bindings for gtk to be
> loaded, which is known to take a while. It has been profiled in the past
> and it has been blamed on the big number of symbols that needs to be
> linked. See this blog entry:
> 
> http://blog.gustavobarbieri.com.br/2006/07/19/pygtk-is-getting-better-stay-tuned/
> 
> I think the work the blog entry talks about has not been completed
> because it would have required to change pygtk in incompatible ways.
> 
> There is also the fact that while importing gtk python tries to open a
> huge number of files (most of them doesn't exist) to find the modules in
> the python path. It's unclear how much this actually affect performance.
> (Python 2.5 is smarter about it and should try to open a lot less files)
> 
> Try:
> 
> strace python -c "import hippo"
> 
> to get an idea of what is going on.
> 
> This is not specific to the web activity and it's the reason because
> even an empty window activity takes several seconds to startup on the
> XO.
> 
>> Where is the code for browser_startup,
> 
> This will startup mozilla. The code is in
> sugar/browser/sugar-browser.cpp but it's not that interesting. It just
> call a function to initialize mozilla.
> 
>>  main
> 
> Just the gtk event loop, I think.
> 
>>  and present to be found?
> 
> It's just showing the gtk.Window. My guess is that this is slow because
> it cause the GtkMozEmbed widget to be realized and that triggers some
> more mozilla initilization code.
> 
> Hope it's useful, thanks for looking into this!
> 
> Marco
> 

Hi Marco,


Wow! "import hippo" pulls in a lot of other libraries. Did:

strace -c -o /tmp/trace_sum python

Then "import hippo" and then exit immediately. This yields the
following data:


% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  42.26    0.001187           2       665       544 open
  25.74    0.000723           2       468        27 read
  16.30    0.000458           3       152           mmap2
  15.70    0.000441           2       200       164 stat64
   0.00    0.000000           0        40           write
   0.00    0.000000           0       127           close

Below is the "strace -c" for just start up python then exit. The
"import hippo" triples the number of open and mmap2 operations, nearly
doubles numbers of reads, stat64s, and closes.


% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  46.05    0.000956           4       218       166 open
  32.90    0.000683           3       247           read
  12.62    0.000262           5        53           mmap2
   8.43    0.000175         175         1           uname
   0.00    0.000000           0         4           write
   0.00    0.000000           0        52           close
...
   0.00    0.000000           0        90        63 stat64

Used the "LD_DEBUG=all LD_DEBUG_OUTPUT=file" to take a closer look at
what is being loaded. After stripping off the first columns containing
the pid compared the remainder. Doing a diff and grepping for "needed by"
it looks like "import hippo" pulls in the following.



file=/usr/lib/python2.4/site-packages/hippo.so [0];  needed by 
/usr/lib/libpython2.4.so.1.0 [0]
file=libgtk-x11-2.0.so.0 [0];  needed by 
/usr/lib/python2.4/site-packages/hippo.so [0]
file=libgdk-x11-2.0.so.0 [0];  needed by 
/usr/lib/python2.4/site-packages/hippo.so [0]
file=libatk-1.0.so.0 [0];  needed by /usr/lib/python2.4/site-packages/hippo.so [0]
file=libgdk_pixbuf-2.0.so.0 [0];  needed by 
/usr/lib/python2.4/site-packages/hippo.so [0]
file=libpangocairo-1.0.so.0 [0];  needed by 
/usr/lib/python2.4/site-packages/hippo.so [0]
file=libcairo.so.2 [0];  needed by /usr/lib/python2.4/site-packages/hippo.so [0]
file=libpango-1.0.so.0 [0];  needed by /usr/lib/python2.4/site-packages/hippo.so [0]
file=libgobject-2.0.so.0 [0];  needed by 
/usr/lib/python2.4/site-packages/hippo.so [0]
file=libgmodule-2.0.so.0 [0];  needed by 
/usr/lib/python2.4/site-packages/hippo.so [0]
file=libglib-2.0.so.0 [0];  needed by /usr/lib/python2.4/site-packages/hippo.so [0]
file=libhippocanvas-1.so.0 [0];  needed by 
/usr/lib/python2.4/site-packages/hippo.so [0]
file=libX11.so.6 [0];  needed by /usr/lib/libgtk-x11-2.0.so.0 [0]
file=libXfixes.so.3 [0];  needed by /usr/lib/libgtk-x11-2.0.so.0 [0]
file=libpng12.so.0 [0];  needed by /usr/lib/libgtk-x11-2.0.so.0 [0]
file=libfontconfig.so.1 [0];  needed by /usr/lib/libgdk-x11-2.0.so.0 [0]
file=libXext.so.6 [0];  needed by /usr/lib/libgdk-x11-2.0.so.0 [0]
file=libXrender.so.1 [0];  needed by /usr/lib/libgdk-x11-2.0.so.0 [0]
file=libXinerama.so.1 [0];  needed by /usr/lib/libgdk-x11-2.0.so.0 [0]
file=libXi.so.6 [0];  needed by /usr/lib/libgdk-x11-2.0.so.0 [0]
file=libXrandr.so.2 [0];  needed by /usr/lib/libgdk-x11-2.0.so.0 [0]
file=libXcursor.so.1 [0];  needed by /usr/lib/libgdk-x11-2.0.so.0 [0]
file=libpangoft2-1.0.so.0 [0];  needed by /usr/lib/libpangocairo-1.0.so.0 [0]
file=libfreetype.so.6 [0];  needed by /usr/lib/libpangocairo-1.0.so.0 [0]
file=libz.so.1 [0];  needed by /usr/lib/libcairo.so.2 [0]
file=libXau.so.6 [0];  needed by /usr/lib/libX11.so.6 [0]
file=libXdmcp.so.6 [0];  needed by /usr/lib/libX11.so.6 [0]
file=libexpat.so.0 [0];  needed by /usr/lib/libfontconfig.so.1 [0]
file=/usr/lib/python2.4/site-packages/gtk-2.0/gobject/_gobject.so [0];  needed 
by /usr/lib/libpython2.4.so.1.0 [0]
file=libgthread-2.0.so.0 [0];  needed by 
/usr/lib/python2.4/site-packages/gtk-2.0/gobject/_gobject.so [0]
file=librt.so.1 [0];  needed by /lib/libgthread-2.0.so.0 [0]
file=/usr/lib/python2.4/site-packages/cairo/_cairo.so [0];  needed by 
/usr/lib/libpython2.4.so.1.0 [0]
file=/usr/lib/python2.4/site-packages/gtk-2.0/gtk/_gtk.so [0];  needed by 
/usr/lib/libpython2.4.so.1.0 [0]
file=/usr/lib/python2.4/site-packages/gtk-2.0/pango.so [0];  needed by 
/usr/lib/libpython2.4.so.1.0 [0]
file=/usr/lib/python2.4/site-packages/gtk-2.0/atk.so [0];  needed by 
/usr/lib/libpython2.4.so.1.0 [0]
file=/usr/lib/python2.4/site-packages/gtk-2.0/pangocairo.so [0];  needed by 
/usr/lib/libpython2.4.so.1.0 [0]
file=libnss_files.so.2 [0];  needed by python [0]
file=/usr/lib/gconv/ISO8859-1.so [0];  needed by python [0]

-Will



More information about the Devel mailing list