I've been doing a fair bit of optimisation lately, for a hobby project of mine written in Python. This means I've been using the Python profiler a lot. Remember: the word for "optimising without measuring" is "pessimisation".

Here's quick tutorial on the very basics of using the Python profiler.

1. Import the cProfile module
2. Invoke the main function of your program using cProfile.run().

As an example:

import cProfile

class SomeClass(object):

    def run(self):
        self.total = 0
        for i in xrange(10**6):
            self.add(1)
        return self.total

    def numbers(self):
        return xrange(10**6)

    def add(self, amount):
        self.total += amount

def main():
    obj = SomeClass()
    print obj.run()

if False:
    # Run normally.
    main()
else:
    # Run under profile, writing profile data to prof.prof.
    cProfile.run('main()', filename='prof.prof')

If you run the above, the profiler will write a file prof.prof with the profiling data. That data is in a binary form. The following code will display it in text form:

import pstats
import sys

p = pstats.Stats(sys.argv[1])
p.strip_dirs()
p.sort_stats('cumulative')
p.print_stats()
print '-' * 78
p.print_callees()

The profiler documentation has details to show what the different calls do. I'd like to concentrate on the output. The output from the above actually contains the profiling data in two forms:

• list of how much time is spent in each function or method
• a breakdown for each function/method of how much time is spent in each thing it calls

Both are useful. The latter is especially useful.

Example output:

Fri Oct 30 11:36:05 2015    prof.prof

         1000004 function calls in 0.302 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.302    0.302 <string>:1(<module>)
        1    0.000    0.000    0.302    0.302 prof.py:19(main)
        1    0.175    0.175    0.302    0.302 prof.py:6(run)
  1000000    0.127    0.000    0.127    0.000 prof.py:15(add)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}


------------------------------------------------------------------------------
   Ordered by: cumulative time

Function                                          called...
                                                      ncalls  tottime  cumtime
<string>:1(<module>)                              ->       1    0.000    0.302  prof.py:19(main)
prof.py:19(main)                                  ->       1    0.175    0.302  prof.py:6(run)
prof.py:6(run)                                    -> 1000000    0.127    0.127  prof.py:15(add)
prof.py:15(add)                                   ->
{method 'disable' of '_lsprof.Profiler' objects}  ->

From the first part, we see that the all cumulative time of the program is spent in the run method. From the second we see that its time is partially spent in the add method. The rest of the time is spent in run itself.

This is a trivial example, but it shows the principle. By starting from this, you can start drilling into where your program spends its time.