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:

http://docs.python.org/lib/profile-instant.html