Profiling#

# if you're using colab, then install the required modules
import sys

IN_COLAB = "google.colab" in sys.modules
if IN_COLAB:
    %pip install --quiet line_profiler snakeviz pyinstrument eliot eliot-tree

Profiling analyses your code in terms of speed or memory.

This helps identify where the bottlenecks are (why and where is it slow?) and how much potential there is for improvement.

Note

IPython magic commands are useful, commonly used commands in Jupyter Notebooks.
They have one % at the start for use on a single line.
Or two %% at the start for use over a whole cell.

`timeit`#

A IPython magic command that measures the time execution of an expression.

It runs a few times, depending on how intensive the expression is, and returns the best result with the uncertainty.

It is useful for benchmarking a small code snippet.

Tip

timeit is different to time, which is a less optimised alternative.
Hence, use timeit.

%timeit range(100)

105 ns ± 0.0665 ns per loop (mean ± std. dev. of 7 runs, 10,000,000 loops each)

%%timeit
for x in range(100):
    pass

1.28 µs ± 0.468 ns per loop (mean ± std. dev. of 7 runs, 1,000,000 loops each)

Another option is:

`line_profiler`#

A module that measures the time spent in each line of a function.

We’ll load the extension first and then look at a simple example.

%load_ext line_profiler

import time


def relax():
    pass


def bottleneck():
    time.sleep(0.001)


def some_function():
    nums = [num for num in range(1_000)]
    bigger_nums = [num**2 for num in nums]
    bottleneck()
    bigger_nums.extend(bigger_nums)
    relax()

The Timer unit is the conversion to seconds.

The table shows the following columns for each line of the function (each row):

Line #: The line number.
Hits: The number of times that line was called.
Time: The total time spent calling that line (in the Timer units).
Per Hit: The time spent for one call of that line.
% Time: The percentage of total time spent on that line (this is the often the most useful column).
Line Contents: The source code for that line.

%lprun -f some_function some_function()

Note

In Colab, the results will pop up at the bottom under “Help”, rather than inline like we have for a local Jupyter Notebook.

We can see that most of the time was in the bottleneck() call, highlighting the potential here for possible improvements.

`SnakeViz`#

SnakeViz visualises the output from cProfile in nice interactive plots.

cProfile is part of the Python standard library.

It’s a deterministic profiler of wallclock time (producing the same output for the same input).

It is for serial code (not parallel, which we’ll cover later).

However, the output has lots of tabular information that isn’t ideal.

Every function call gets measured in seconds (each row).

For example:

import cProfile

cProfile.run("some_function()")

         10 function calls in 0.002 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.002    0.002 3630047074.py:12(some_function)
        1    0.000    0.000    0.000    0.000 3630047074.py:13(<listcomp>)
        1    0.000    0.000    0.000    0.000 3630047074.py:14(<listcomp>)
        1    0.000    0.000    0.000    0.000 3630047074.py:4(relax)
        1    0.000    0.000    0.002    0.002 3630047074.py:8(bottleneck)
        1    0.000    0.000    0.002    0.002 <string>:1(<module>)
        1    0.000    0.000    0.002    0.002 {built-in method builtins.exec}
        1    0.002    0.002    0.002    0.002 {built-in method time.sleep}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        1    0.000    0.000    0.000    0.000 {method 'extend' of 'list' objects}

Instead, visualising this output in SnakeViz is easier to interpret.

You can switch between the two styles using the “Style” dropdown.

Style: Icicle

Functions are represented by rectangles.
The root function is the top-most rectangle, with functions it calls below it, then the functions those call below them, and so on.
The amount of time spent inside a function is represented by the width of the rectangle.
- A big rectangle that stretches across most of the visualization represents a function that is taking up most of the time of its calling function, while a small rectangle represents a function that is using hardly any time at all.

Style: Sunburst

Functions are represented by arcs.
The root function is the centre circle, with functions it calls around it, then the functions those functions call around that, and so on.
The amount of time spent inside a function is represented by how far around the circle the arc goes.
- An big arc that wraps most of the way around the circle represents a function that is taking up most of the time of its calling function, while a small arc represents a function that is using hardly any time at all.

Warning

SnakeViz doesn’t currently work with Colab. Please, see the demonstrators results or use it in a local Jupyter Notebook.

%load_ext snakeviz

# %%snakeviz
# some_function()

`pyinstrument`#

A statistical profiler of wall-clock time (recording the call stack every 1ms), lowering the overhead compared to tracing profilers (like cProfile).

It hides library frames and fast functions, so you can focus on the slow parts of your code.

The output shows a tree of actions of how the function executes, using a traffic light colour legend (i.e., red = slow).

%load_ext pyinstrument

%%pyinstrument
some_function()

`Eliot`#

Logs the performance information.

It tracks each function called, its arguments, the return values, and any rasied exceptions.

Hence, it can be helpful for profiling in real use cases.

Note

Logging has a higher overhead than cProfile.

It works by using decorators.

Decorator are a nice way for functions to return other functions.

So:

@f1
def f2(): 
  pass

Is the same as:

def f2(): 
  pass 

f2 = f1(f2)

For example, here is a decorated function that logs calls to a function:

def log_calls(function):
    def wrapper():
        name = function.__name__

        print(f"Before {name} was called ...")
        function()
        print(f"After {name} was called ...")

    return wrapper

Calling this returns a function:

log_calls(some_function)

<function __main__.log_calls.<locals>.wrapper()>

So, to execute it we add ():

log_calls(some_function)()

Before some_function was called ...
After some_function was called ...

The @wrapper syntax is a nice way to return this same result, where the outer function is placed above the inner function with the @ symbol:

@log_calls
def some_function_with_logging():
    some_function()

some_function_with_logging()

Before some_function_with_logging was called ...
After some_function_with_logging was called ...

Okay, so now we can use the @eliot.log_call decorator to profile a function:

import eliot

def bottleneck():
    time.sleep(0.5)

@eliot.log_call
def multiply(x, y):
    bottleneck()
    return x * y

@eliot.log_call
def add(x, y):
    return x + y

This next cell is just to remove the log file, if you’re trying different things:

# remove file if exists
import os

try:
    os.remove("profiling_some_function.log")
except OSError:
    pass

Now, tell eliot where to log the output messages and run the function call:

eliot.to_file(open("profiling_some_function.log", "w+"))
result = multiply(add(3, 4), add(5, 6))

You can now view this log file by calling eliot-tree from a terminal.

This shows that add() was called twice as inputs to multiply().

The input and output arguments are shown too.

The time of the call is shown to the right, where multiply() took 0.5 seconds (due to the time.sleep(0.5) call).

Note

You can call terminal commands from within a Jupyter Notebook cell by adding the prefix !.

!eliot-tree profiling_some_function.log

db52c423-6ced-46a0-ba9d-64c5d998f78a
└── __main__.add/1 ⇒ started 2022-11-01 17:15:03Z ⧖ 0.000s
    ├── x: 3
    ├── y: 4
    └── __main__.add/2 ⇒ succeeded 2022-11-01 17:15:03Z
        └── result: 7

e20fb119-b325-405a-85fb-93abb0ed4d9d
└── __main__.add/1 ⇒ started 2022-11-01 17:15:03Z ⧖ 0.000s
    ├── x: 5
    ├── y: 6
    └── __main__.add/2 ⇒ succeeded 2022-11-01 17:15:03Z
        └── result: 11

5e5693dd-8ec4-41a9-8ee3-491d3f4d0925
└── __main__.multiply/1 ⇒ started 2022-11-01 17:15:03Z ⧖ 0.501s
    ├── x: 7
    ├── y: 11
    └── __main__.multiply/2 ⇒ succeeded 2022-11-01 17:15:04Z
        └── result: 77

Visualising how Python handles functions can be helpful in understanding then.

Click here to see an example.

Exercises#

Exercise 1

What is profiling and why is it useful?

Exercise 2

What profiling tool times the execution of a cell in a Jupyter Notebook?

Exercise 3

Below are two approaches for filling up an empty NumPy array.

Which approach is faster and why?

def fill_array_approach_1(n):
    array = np.empty(1)

    for index in range(n):
        new_point = np.random.rand()
        array = np.append(array, new_point)

    return array

def fill_array_approach_2(n):
    array = np.empty(n)

    for index in range(len(array)):
        new_point = np.random.rand()
        array[index] = new_point

    return array

Exercise 4

Below are two methods that find two numbers from an array of unique integers that add up to a target sum.

If the target can’t be made, then an empty list is returned.

Each element in the array can only be used once.

Which method is faster and why?

def two_sum_brute_force(array, target):
    """
    A brute force approach to find two numbers from an array that add up to a target.

    Steps
    1. Loop through the array twice, adding up pairs of array elements.
    2. Compare each of these sums to the target.
    3. Return the pair that sums to the target, if one exists.
    """
    for index_one in range(len(array)):
        for index_two in range(index_one + 1, len(array)):
            if (
                array[index_one] + array[index_two] == target  # check sum of pair
                and index_one != index_two  # can't use the same element twice
            ):
                return [index_one, index_two]  # return the target pair

    return []  # return an empty list if the target pair isn't found

def two_sum_cache(array, target):
    """
    Use caching to find two numbers from an array that add up to a target.

    Steps
    1. Create a dictionary of cached differences relative to the target sum.
    2. Loop through the array once, adding each index and difference to the cache.
    3. If the required difference of a new array element is already in the cache,
       then you've found a matching pair, which you can return.
    """
    cache_differences = {}
    for index, element in enumerate(array):
        difference = (
            target - element
        )  # calculate the target difference for this element
        if difference in cache_differences:  # if we have the matching pair
            return [index, cache_differences[difference]]  # return the target pair
        cache_differences[element] = index  # if we don't have a match, add to the cache

    return []  # return an empty list if the target pair isn't found

You can test them out using the following array and target:

import numpy as np

array = np.random.choice(1_000, 500, replace=False)
target = 250

Solutions #

Key Points#

Important

Measure the time of cells, functions, and programs to find bottlenecks e.g., using timeit and line_profiler.
Visualise the profiled code e.g., using SnakeViz and pyinstrument.
Log profiling information e.g., using Eliot.
Consider how fast the code could go e.g., Big O notation.

Further information#

Other options#

pyheat
- Combines pprofile and matplotlib to show a heatmap of the profiled code.
VizTracer
- A low-overhead logging/debugging/profiling tool that can trace and visualize your python code execution.

Memory profiling#

memory_profiler
- Measures the memory used by a function, at its peak and the overall increment.
memray
- Memray is a memory profiler for Python, generating several different types of reports to help you analyze the captured memory usage data.

Resources#

Beyond cProfile: Choosing the right tool for performance optimization

SWD6: High Performance Python

Profiling

Contents

Profiling#

timeit#

line_profiler#

SnakeViz#

pyinstrument#

Eliot#

Exercises#

Solutions#

Key Points#

Further information#

Other options#

Memory profiling#

Resources#

`timeit`#

`line_profiler`#

`SnakeViz`#

`pyinstrument`#

`Eliot`#

Solutions #