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