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: