pyinstrument is a call stack profiler, inspired by Apple’s Instruments.app.

Using example code from Cython about profiling, calculating Pi:

#!/usr/bin/env python
# encoding: utf-8
# filename: calc_pi.py

def recip_square(i):
    return 1./i**2

def approx_pi(n=100000):
    val = 0.
    for k in range(1,n+1):
        val += recip_square(k)
    return (6 * val)**.5

And the results of profiling by cprofile and pyinstrument:

Sat Mar 29 10:31:05 2014    Profile.prof

         100004 function calls in 0.273 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.137    0.137    0.273    0.273 calc_pi_py.py:4(approx_pi)
   100000    0.131    0.000    0.131    0.000 calc_pi_py.py:1(recip_square)
        1    0.004    0.004    0.004    0.004 {range}
        1    0.000    0.000    0.273    0.273 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

0.730 <module>  ./sample_standalone.py:14
| 0.730 approx_pi       /tmp/pyinstrument/calc_pi_py.py:4
| | 0.350 recip_square  /tmp/pyinstrument/calc_pi_py.py:1
| 0.000 start   /tmp/pyinstrument/pyinstrument/profiler.py:18
| 0.000 stop    /tmp/pyinstrument/pyinstrument/profiler.py:22

You can see there is a big issue with pyinstrument as already stated in its known issues, that’s high overhead with codes making lots of calls, and this example code certainly falls into that category. Anyway, it’s not an issue I care, and I just want to show you this alternative profiler. You will need to investigate on the issue further on your own.

Now, since we are using an example code from Cython, we might as well as profiling the .pyx:

# encoding: utf-8
# cython: profile=True
# filename: calc_pi.pyx

cimport cython

@cython.profile(False)
cdef inline double recip_square(int i):
    return 1./(i*i)

def approx_pi(int n=100000):
    cdef double val = 0.
    cdef int k
    for k in xrange(1,n+1):
        val += recip_square(k)
    return (6 * val)**.5

And the results are:

Exception ZeroDivisionError: 'float division' in 'calc_pi_pyx.recip_square' ignored
Sat Mar 29 10:31:07 2014    Profile.prof

         4 function calls in 0.003 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.003    0.003    0.003    0.003 calc_pi_pyx.pyx:11(approx_pi)
        1    0.000    0.000    0.003    0.003 {calc_pi_pyx.approx_pi}
        1    0.000    0.000    0.003    0.003 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

Exception ZeroDivisionError: 'float division' in 'calc_pi_pyx.recip_square' ignored
0.010 <module>  ./sample_standalone.py:35
| 0.010 approx_pi       calc_pi_pyx.pyx:11
| 0.000 start   /tmp/pyinstrument/pyinstrument/profiler.py:18
| 0.000 stop    /tmp/pyinstrument/pyinstrument/profiler.py:22