Python profiling for beginners

def bar(i):
    return i*i

def foo():
    for i in range(0,1000000):
        bar(i)

Let's try to use these two silly functions to do a profiling exercise.

First of all, we need to import cProfile. And then call: cProfile.run('foo()')

Output (from my laptop):
         1000004 function calls in 3.564 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    1.926    1.926    3.564    3.564 <pyshell#11>:1(foo)
  1000000    1.638    0.000    1.638    0.000 <pyshell#9>:1(bar)
        1    0.000    0.000    3.564    3.564 <string>:1(<module>)
        1    0.000    0.000    3.564    3.564 {built-in method exec}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

At the first glance, it may look criptic, but: the total time is the time spent in a function excluding the time spent in callees. The cummulative time is the time spent in a function including the time spent in callees. Therefore, these two times are equal for bar function. ncalls and percall are self-explanatory.

But we can go further. I highly recommend trying out a GUI application that can read the cProfile output, such as RunSnakeRun from http://www.vrplumber.com/programming/runsnakerun For this simple case it'd be useless, but for much more complex call tree, it is of great help.

In order to use it, we need to run cProfile giving it the dump file name as the second argument:


cProfile.run('foo()', 'dump.txt')