Profiling Python code

Measure first, then optimise

A backtest that takes four hours or a pricing function called a million times a second makes everyone want to speed things up, and almost everyone guesses wrong about where the time goes. The loop that looks heavy may be nothing; a line that looks innocent may be the whole run. Profiling is measuring where a program spends its time, before changing anything. The rule is simple: do not optimise a line you have not measured, and after a change measure again to see whether it helped.

# The simplest measurement: read a clock before and after
import time

def slow_sum(n):
    total = 0
    for i in range(n):
        total += i * i
    return total

start = time.perf_counter()
result = slow_sum(200_000)
elapsed = time.perf_counter() - start
print(result)                                        # 2666646666700000
print(elapsed > 0)                                   # True  a real duration; the exact value changes every run

Noise, repeats and the minimum

A single timing is unreliable: the operating system, other programs, the CPU cache and Python's own start-up all add noise, and they only ever add time. So time a function several times and take the minimum, the run that was disturbed least; timeit does exactly this. Use time.perf_counter() (a high-resolution monotonic clock), not time.time(). Time with realistic input sizes, because a function that is fast on ten rows can be slow on ten million, and warm up first so one-off costs (imports, caches) are not charged to the code you are measuring.

# Repeat and take the minimum: the least disturbed run
import time

def work():
    return sum(i * i for i in range(50_000))

def best_of(func, repeats):
    best = None
    for _ in range(repeats):
        start = time.perf_counter()
        func()
        elapsed = time.perf_counter() - start
        if best is None or elapsed < best:
            best = elapsed
    return best

runs = [best_of(work, 1) for _ in range(5)]
print(best_of(work, 5) <= max(runs))                 # True  the minimum is never above the worst single run
print(min(runs) > 0)                                 # True

Where the time goes: profilers and Amdahl's law

A timer tells you how long, a profiler tells you where. The standard library's cProfile records every function call and reports, for each function, how many calls it received, the time spent in the function itself and the cumulative time including what it called; python -m cProfile -s cumtime script.py prints the worst first. The share of each function is then simply its time over the total. The payoff of fixing one is limited by Amdahl's law: speeding up a fraction f of the run by a factor s gives an overall 1 / ((1 - f) + f / s). Making 60 % of a run ten times faster gives only 2.2 times overall, and even an infinitely fast half of the run caps the gain at 2. Go after the biggest hotspot first.

# Shares of the total and the payoff of fixing the biggest one (the timings are made-up numbers)
timings = {"load_prices": 6.0, "price_options": 3.0, "write_report": 1.0}
total = sum(timings.values())
for name, seconds in sorted(timings.items(), key=lambda item: -item[1]):
    print(f"{name:14s} {seconds / total:5.1%}")      # load_prices 60.0%, price_options 30.0%, write_report 10.0%

def amdahl_gain(fraction, speedup):
    return 1 / ((1 - fraction) + fraction / speedup)

print(round(amdahl_gain(0.6, 10), 2))                # 2.17  ten times faster on 60% of the run
print(round(amdahl_gain(0.1, 1000), 2))              # 1.11  a huge win on the smallest part barely helps

# cProfile records every call; the function that sleeps shows up as the hotspot
import cProfile
import time

def slow_part():
    time.sleep(0.02)

def fast_part():
    return sum(range(10))

def run_all():
    slow_part()
    for _ in range(100):
        fast_part()

profiler = cProfile.Profile()
profiler.runcall(run_all)
entries = {str(entry.code): entry for entry in profiler.getstats()}
slow = next(entry for name, entry in entries.items() if "slow_part" in name)
fast = next(entry for name, entry in entries.items() if "fast_part" in name)
print(fast.callcount, slow.callcount)                # 100 1   calls are counted exactly
print(slow.totaltime > fast.totaltime)               # True    one slow call outweighs 100 fast ones

• Measure before changing anything; time with perf_counter, repeat and keep the minimum, with realistic input sizes.
• A profiler (cProfile) shows where the time goes: calls, own time and cumulative time per function; each share is its time over the total.
• Amdahl's law: speeding a fraction f by s gives 1 / ((1 - f) + f / s); fix the biggest hotspot first and re-measure after each change.

Next up: optimising hot loops, the changes that make the code the profiler pointed at faster.

Lab · what's graded

• Time one call with time_call25 pts
• Take the best of several runs with best_of25 pts
• Find where the time goes with hotspots25 pts
• Predict the payoff with amdahl_gain25 pts