Python profiling
Profiling Python scripts on OLPC machine with the profile module
Collecting data from the alt-0 xterm window (olpc user):
python -m profile -o /tmp/zzz /usr/bin/sugar-activity Web
When finish the profiler will write the data to /tmp/zzz. This file is not in human readable form. You will need to use a python shell to analyze the data. In the python shell import the pstat module and load the /tmp/zzz file with the following commands:
import pstats
p = pstats.Stats('/tmp/zzz')
You can examine the data in various ways. For a flat time based profile the following command will output the top ten functions that time was spent in, not including the time spent in children:
p.sort_stats('time').print_stats(10)
This results in the following output:
Mon Mar 26 20:41:14 2007 /tmp/zzz
9122 function calls (9045 primitive calls) in 12.080 CPU seconds
Ordered by: internal time
List reduced from 791 to 10 due to restriction <10>
ncalls tottime percall cumtime percall filename:lineno(function)
1 4.120 4.120 4.120 4.120 :0(browser_startup)
1 1.390 1.390 3.600 3.600 :0(main)
1 0.960 0.960 1.390 1.390 :0(present)
1 0.730 0.730 0.870 0.870 /usr/lib/python2.4/site-packages/gtk-2.0/gtk/__init__.py:23(?)
1 0.370 0.370 1.160 1.160 /usr/share/activities/Web.activity/webactivity.py:17(?)
13 0.200 0.015 0.350 0.027 /usr/lib/python2.4/ConfigParser.py:415(_read)
8 0.190 0.024 0.190 0.024 :0(lookup_icon)
7 0.170 0.024 0.170 0.024 :0(render_cairo)
1 0.160 0.160 0.210 0.210 /usr/lib/python2.4/socket.py:43(?)
14/8 0.140 0.010 0.280 0.035 /usr/lib/python2.4/sre_parse.py:374(_parse)
To get a list of top 15 cumulative times:
p.sort_stats('cumulative').print_stats(15)
The resulting output is:
Mon Mar 26 20:41:14 2007 /tmp/zzz
9122 function calls (9045 primitive calls) in 12.080 CPU seconds
Ordered by: cumulative time
List reduced from 791 to 15 due to restriction <15>
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 12.080 12.080 profile:0(execfile('/usr/bin/sugar-activity'))
1 0.010 0.010 12.080 12.080 :0(execfile)
15/1 0.000 0.000 12.080 12.080 <string>:1(?)
1 0.040 0.040 12.070 12.070 /usr/bin/sugar-activity:19(?)
1 0.010 0.010 5.400 5.400 /usr/lib/python2.4/site-packages/sugar/activity/activityfactoryservice.py:89(run)
1 0.000 0.000 5.340 5.340 /usr/lib/python2.4/site-packages/sugar/activity/activityfactoryservice.py:39(__init__)
1 0.000 0.000 4.130 4.130 /usr/share/activities/Web.activity/webactivity.py:106(start)
1 4.120 4.120 4.120 4.120 :0(browser_startup)
1 1.390 1.390 3.600 3.600 :0(main)
10 0.020 0.002 1.670 0.167 /usr/lib/python2.4/site-packages/dbus/service.py:424(_message_cb)
1 0.000 0.000 1.590 1.590 /usr/lib/python2.4/site-packages/sugar/activity/activityfactoryservice.py:60(create)
1 0.960 0.960 1.390 1.390 :0(present)
3 0.040 0.013 1.200 0.400 :0(__import__)
1 0.370 0.370 1.160 1.160 /usr/share/activities/Web.activity/webactivity.py:17(?)
1 0.730 0.730 0.870 0.870 /usr/lib/python2.4/site-packages/gtk-2.0/gtk/__init__.py:23(?)
Find the top 10 most frequently called functions:
p.sort_stats('calls').print_stats(10)
Results in the following output:
Mon Mar 26 20:41:14 2007 /tmp/zzz
9122 function calls (9045 primitive calls) in 12.080 CPU seconds
Ordered by: call count
List reduced from 791 to 10 due to restriction <10>
ncalls tottime percall cumtime percall filename:lineno(function)
625/612 0.050 0.000 0.050 0.000 :0(len)
532 0.060 0.000 0.060 0.000 :0(append)
318 0.040 0.000 0.040 0.000 :0(lower)
256 0.010 0.000 0.010 0.000 :0(chr)
214 0.020 0.000 0.040 0.000 /usr/lib/python2.4/ConfigParser.py:335(optionxform)
200 0.040 0.000 0.040 0.000 :0(b2a_hex)
184 0.030 0.000 0.030 0.000 :0(has_key)
182 0.030 0.000 0.030 0.000 :0(strip)
177 0.040 0.000 0.040 0.000 /usr/lib/python2.4/site-packages/dbus/_expat_introspect_parser.py:52(EndElementHandler)
177 0.050 0.000 0.130 0.001 /builddir/build/BUILD/Python-2.4.4/Modules/pyexpat.c:587(StartElement)
For more information about generating the profiling output see the "Instant User's Manual" at:
