Pyinstrument

pyinstrument is a statistical profiler for Python. While your code runs, it records which functions are on the call stack, then prints a tree of how long each function took, including the functions it called. People use it to find the slow part of a script before trying to speed it up. It measures wall-clock time, so waiting counts as well as computing. On this page it runs in your browser, so you can try it without installing anything. Run the example first, then paste any snippet below into a new cell to try it.

What the example does

Profiler() in a with block profiles the code inside the block. main_function() calls first_function() and second_function(), and both reach final_function() through helper_function(). final_function() calls time.sleep(0.1) to stand in for slow work. profiler.print() shows a header with the total duration, then the call tree: each branch takes 0.1 seconds, 0.2 in all.

The header reports only two or three samples. pyinstrument checks the clock when a function is called or returns, and records the stack if at least interval seconds (0.001 by default) have passed. Each sample carries the time since the previous one, so each sleep() call is one sample of 0.1 seconds.

Profile part of a script with start() and stop()

start() and stop() do the job of the with block when the code doesn't fit in one. Both functions count how many targets are in items:

from pyinstrument import Profiler

def count_in_list(items, targets):
    return sum(1 for t in targets if t in items)    # scans the list each time

def count_in_set(items, targets):
    lookup = set(items)
    return sum(1 for t in targets if t in lookup)   # one hash lookup each time

items = list(range(5_000))
targets = list(range(0, 10_000, 3))

profiler = Profiler()
profiler.start()
print(count_in_list(items, targets), count_in_set(items, targets))
profiler.stop()
profiler.print()

Both return 1667, but nearly all the time goes to count_in_list. count_in_set is missing from the tree: the report leaves out anything under 1% of the total.

Show time as percentages

ConsoleRenderer(time="percent_of_total") shows each line as a share of the run, which makes pipeline stages easier to compare. profiler.last_session holds the raw numbers:

import random
from pyinstrument import Profiler
from pyinstrument.renderers import ConsoleRenderer

def make_rows(n):
    random.seed(0)
    return [f"{random.randint(1, 999)},{random.choice('abc')}" for _ in range(n)]

def parse(rows):
    return [(int(a), b) for a, b in (row.split(",") for row in rows)]

def total_by_group(pairs):
    totals = {}
    for value, group in pairs:
        totals[group] = totals.get(group, 0) + value
    return totals

with Profiler() as profiler:
    print(total_by_group(parse(make_rows(100_000))))

session = profiler.last_session
print(session.sample_count, "samples in", round(session.duration, 2), "seconds")
print(profiler.output(ConsoleRenderer(unicode=True, time="percent_of_total")))

Making the test data takes about three quarters of the time, more than parsing and totalling together. A [self] line is time spent in a function's own code rather than in the functions it calls.

Look inside library calls

The report folds frames from the standard library and installed packages into one line ending in frames hidden. show_all=True shows them:

import random
import statistics
from pyinstrument import Profiler

random.seed(1)
values = [random.random() for _ in range(100_000)]

with Profiler() as profiler:
    spread = statistics.stdev(values)
    middle = statistics.median(values)

print(round(spread, 4), round(middle, 4))
profiler.print()               # library frames folded
profiler.print(show_all=True)  # every frame

The full tree shows that stdev() spends its time in the private helpers _ss() and _exact_ratio(), and median() in one call to sorted().

Good to know

• The header's CPU time always reads 0.000, because this build of Python cannot measure CPU time: time.process_time() stays at 0. Use the Duration instead.
• Profiler(interval=0.01) takes fewer samples on a long run. An interval below 0.001 adds no samples here, because the clock that decides when to sample counts whole milliseconds.
• This page runs pyinstrument 4.4.0, which lacks the pyinstrument.profile() decorator of newer releases. Use Profiler as shown above.