lesson 182 Profiling & Optimization · advanced

cProfile: where does the time go?

Programs are rarely slow everywhere. A profiler records every function call, so you can see which functions are called most and which take the most time, and optimise the right one.

You'll be able to

Run a function under cProfile.Profile with runcall
Read pstats columns: ncalls, tottime and cumtime
Use call counts to find work that is repeated more than it should be

The idea

Guessing where a program is slow is usually wrong. cProfile (in the standard library) records every function call while it is enabled: how many times each function was called (ncalls), the time spent in its own code (tottime) and the time including everything it called (cumtime). pstats.Stats(profiler) turns the records into a table you can sort (sort_stats("cumulative")) and print (print_stats(10)).

Times vary between runs, but call counts don't, so counts are the most reliable first clue: a helper called 10,000 times for 100 records is doing something 100 times too often.

Run each example to see what it prints. Running examples doesn't count toward progress.

example-1.py · Profiling an order report

import cProfile
import pstats

def parse_price(text):
    return float(text.strip().replace("$", ""))

def order_total(lines):
    total = 0
    for line in lines:
        total += parse_price(line["price"]) * line["qty"]
    return total

def report(orders):
    totals = []
    for order in orders:
        totals.append(order_total(order))
    return max(totals)

orders = [[{"price": " $7.49", "qty": 2}, {"price": "$31.00 ", "qty": 1}]] * 500
profiler = cProfile.Profile()
best = profiler.runcall(report, orders)
stats = pstats.Stats(profiler)
counts = []
for (filename, line, name), (primitive, total, own, cumulative, callers) in stats.stats.items():
    if filename != "~":
        counts.append((total, name))
for total, name in sorted(counts, reverse=True):
    print(name, total)
print(round(best, 2))

In the printed table, ncalls can show two numbers, such as 177/1 for a recursive function: total calls / *primitive* calls (calls not made by the function itself). tottime is where to look for a function that is slow in its own right; cumtime shows which top-level step contains the slowness. The usual workflow: profile, sort by cumulative time, follow the biggest branch down to the function whose own time or call count is out of proportion, fix it, and profile again.

example-2.py · Recursive calls in the table

import cProfile
import io
import pstats

def ways(steps):
    if steps <= 1:
        return 1
    return ways(steps - 1) + ways(steps - 2)

profiler = cProfile.Profile()
profiler.runcall(ways, 10)
out = io.StringIO()
pstats.Stats(profiler, stream=out).sort_stats("ncalls").print_stats(1)
for line in out.getvalue().splitlines():
    if "ways" in line:
        print(line.split()[0], line.split()[-1])

When to use it: whenever a whole program or request is slow and you don't know why. Profile with realistic data. Mistakes to avoid: optimising before profiling; reading cumtime of a top-level function as its own cost; and profiling a toy input where start-up dominates. Profiling adds overhead to every call, so use the numbers to compare functions within one profile, not as exact timings.

Review

cProfile.Profile().runcall(func, *args) records every call; pstats.Stats reads them.
ncalls (total/primitive), tottime (own time) and cumtime (including callees).
Call counts are deterministic: a helper called far too often is a strong clue.
Next: when the same call repeats with the same arguments, remember the answer.

Practise this