Profiling

Timing is a valuable tool to benchmark a program as a whole or small snippets. However it does not readily scale to check all parts of a program to locate the code that is taking most time. Instead one should turn to a profiler that gathers a set of statistics to describe how often and for how long the individual parts of the program are being executed.

cProfile

Python standard library provides two profilers, the first being cProfile with a C extension to reduce the profiling overhead to a minimum, the other being the slower pure Python implementation profile. We will again focus on the usage of its command-line interface. Consider fib.py with a naive computation of the Fibonacci sequence.

def fib(n):
    return n if n < 2 else fib(n - 2) + fib(n - 1)


fib(37)

$ python -m cProfile fib.py
         78176340 function calls (4 primitive calls) in 8.208 seconds

    Ordered by: cumulative time

    ncalls  tottime  percall  cumtime  percall filename:lineno(function)
         1    0.000    0.000    8.208    8.208 {built-in method builtins.exec}
         1    0.000    0.000    8.208    8.208 fib.py:1(<module>)
78176337/1    8.208    0.000    8.208    8.208 fib.py:2(fib)
         1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

Speed-up with Memoization

The profiler clearly shows that the program spends its time with repeated calls of the fib function. As is well-known, this code can easily be optimized with memoization to cache intermediate results instead of constantly re-computing them. This is of course not the best available optimization for computing Fibonacci numbers in general, but merely serves as illustration for our purposes. Consider fib_mem.py with a simple LRU cache decorator.

import functools


@functools.lru_cache()
def fib(n):
    return n if n < 2 else fib(n - 2) + fib(n - 1)


fib(37)

The profiler output confirms that the cache is working and the computation becomes instantaneous.

$ python -m cProfile fib_mem.py
         60 function calls (23 primitive calls) in 0.000 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 {built-in method builtins.exec}
        1    0.000    0.000    0.000    0.000 fib_mem.py:1(<module>)
     38/1    0.000    0.000    0.000    0.000 fib_mem.py:5(fib)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        1    0.000    0.000    0.000    0.000 functools.py:544(decorating_function)
        1    0.000    0.000    0.000    0.000 functools.py:36(update_wrapper)
        1    0.000    0.000    0.000    0.000 functools.py:504(lru_cache)
        8    0.000    0.000    0.000    0.000 {built-in method builtins.getattr}
        6    0.000    0.000    0.000    0.000 {built-in method builtins.setattr}
        1    0.000    0.000    0.000    0.000 {method 'update' of 'dict' objects}
        1    0.000    0.000    0.000    0.000 {built-in method builtins.isinstance}

pstats

When profiling larger code it may be preferable to save the data in a .prof file to be analyzed later on interactively with the profile statistics browser pstats.

$ python -m cProfile -o fib.prof fib.py
$ python -m pstats fib.prof
fib.prof% sort ncalls  # sort by number of function calls
fib.prof% stats 10     # show results for the top 10

See also

Tools like snakeviz or tuna allow to visualize the profiling data. Have a look at line-profiler providing kernprof to do line-by-line profiling, which may be shorter and easier to understand than function call profiling. There’s also memray in case you need to profile the memory allocations of your Python code to discover the cause of high memory usage or even memory leaks.