# Profiling

## Detailed runtime measurements

The tools from the previous section can help us decide the question whether we need to optimize in the first place (is the total run time fast enough?) and it can guide when we want to replace code by a better-performing alternative (such as a more specialized numpy function instead of a general built-in function). They do not tell us *what* to optimize, though.

As a first example, let’s us have a look at the classical Fibonaci sequence , where each number is the sum of the two preceding numbers. This can be directly written down in a recursive function (note that for simplicity we leave away all error checking, e.g. for negative numbers):

```
def fibonacci(n):
if n < 2:
return n # fibonacci(0) == 0, fibonacci(1) == 1
else:
return fibonacci(n - 2) + fibonacci(n - 1)
```

This seems to work fine, but the runtime increases with `n`

in a dramatic fashion:

`%time factorial(10)`

```
CPU times: user 0 ns, sys: 0 ns, total: 0 ns
Wall time: 52.7 µs
89
```

`%time factorial(20)`

```
CPU times: user 12 ms, sys: 0 ns, total: 12 ms
Wall time: 9.63 ms
10946
```

`%time factorial(30)`

```
CPU times: user 696 ms, sys: 0 ns, total: 696 ms
Wall time: 695 ms
1346269
```

`%time factorial(35)`

```
CPU times: user 7.49 s, sys: 24 ms, total: 7.52 s
Wall time: 7.52 s
14930352
```

To get an idea what is going on, we can use `%prun`

, which runs a command with Python’s built-in profiler:

`% prun factorial(35)`

```
29860706 function calls (4 primitive calls) in 10.621 seconds
Ordered by: internal time
ncalls tottime percall cumtime percall filename:lineno(function)
29860703/1 10.621 0.000 10.621 10.621 <ipython-input-6-b471b8bf6ddb>:1(factorial)
1 0.000 0.000 10.621 10.621 {built-in method builtins.exec}
1 0.000 0.000 10.621 10.621 <string>:1(<module>)
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
```

The output gives us three pieces of information for every function called during the execution of the command: the number of times the function was called (`ncalls`

), the total time spend in that function itself (`tottime`

) and the time spend in that function, including all time spend in functions called by that function (`cumtime`

). It is not surprising that all of the time is spend in the `factorial`

function (after all, that’s the only function we have) but the function got called 29860703 times! There is no way we are going to get a decent performance from this function without changing the approach fundamentally.

## A better Fibonacci sequence

Do you know of a better way to write the Fibonacci function? Can you imagine specific ways of using that function where you would prefer yet another approach?

Optimizing a calculation by using a fundamentally different approach is called “algorithmic optimization” and it is the potentially most powerful way to increase the performance of a program. Whenever the runtime of a program appears to be slow, the first check should be whether there is a function that takes a lot of time and is called more often than expected (e.g. we calculate a measure on 1000 values and expect a function to be called about a 1000 times as well but it is called 1000*1000 times instead).

The output of a profiler run can easily become overwhelming in bigger projects. It can therefore be useful to use a graphical tool that represents this information in a more accessible and interactive way. One such tool is *snakeviz* that can also be used directly from ipython or a jupyter notebook.

Let’s have a another look at the `equalize`

function we used earlier:

```
def equalize(image, n_bins=256):
bins = numpy.linspace(0, 1, n_bins, endpoint=True)
hist, bins = numpy.histogram(image.flatten(), bins=bins, density=True)
cdf = hist.cumsum() / n_bins
# Invert the CDF by using numpy's interp function
equalized = numpy.interp(image.flatten(), bins[:-1], cdf)
# All this was performed on flattened versions of the image, reshape the
# equalized image back to the original shape
return equalized.reshape(image.shape)
```

We’ll again load our example image:

`image = plt.imread('Unequalized_Hawkes_Bay_NZ.png')[:, :, 0]`

With *snakeviz* installed, we can load the `snakeviz`

magic:

`%load_ext snakeviz`

We can then use `%snakeviz`

in the same way we previously used `%prun`

and it will show us a graphical representation of where the time was spent:

`%snakeviz equalize(image)`

This representation is useful for a global overview of the runtime of the various functions in a project. It might uncover functions that do not seem to be worth optimizing because of their short runtime but are in fact called from various places so that their total runtime is significant.

`%prun`

and `%snakeviz`

give information about which functions take up the most time, but they are less useful to see optimization potential in single functions. Another type of profiling is line-based profiling which measures the runtime of every line in one or more functions. This functionality is provided by the *line_profiler* package which also provides a magic extension for ipython and the jupyter notebook:

`%load_ext line_profiler`

The magic command is `%lprun`

and can be used in a similar way to `%prun`

and `%snakeviz`

, but in contrast to those other profiling functions it needs the specification of the functions of interest in addition:

`%lprun -f equalize equalize(image)`

```
Timer unit: 1e-06 s
Total time: 0.013282 s
File: <ipython-input-96-437a650e3f63>
Function: equalize at line 1
Line # Hits Time Per Hit % Time Line Contents
==============================================================
1 def equalize(image, n_bins=256):
2 1 79 79.0 0.6 bins = numpy.linspace(0, 1, n_bins, endpoint=True)
3 1 8160 8160.0 61.4 hist, bins = numpy.histogram(image.flatten(), bins=bins, density=True)
4 1 18 18.0 0.1 cdf = hist.cumsum() / n_bins
5 # Invert the CDF by using numpy's interp function
6 1 5006 5006.0 37.7 equalized = numpy.interp(image.flatten(), bins[:-1], cdf)
7
8 # All this was performed on flattened versions of the image, reshape the
9 # equalized image back to the original shape
10 1 19 19.0 0.1 return equalized.reshape(image.shape)
```

Note that you can specify several `-f function_name`

arguments to get the information for more than one function with a single `%lprun`

call. For each line, the output specifies how often the line was executed (“Hits”), how long the execution of that line took in total (“Time”) and for each time it was executed (“Per Hit”), and finally how much of the total time of the function was spent in the respective line.