29Performance & profiling — measure before you cut

In Chapter 28 we made the program correct — the tests went green, the numbers came out right. This chapter makes it fast, and I want to go slow, because there's a trap here that swallows almost everyone. Your intuition about where a program spends its time is not a little off. It is reliably wrong, and it's wrong for a reason you can name. The source text tells you the truth about what your code does. It says nothing about what any of it costs. a + b can be one machine ADD or a heap allocation. x in seen can be one probe or a million compares, and the letters look identical. So here's the plan. First we prove your gut is a liar. Then we install real instruments between your mental model and the machine: timeit to time one snippet honestly, and cProfile to watch the whole program run and hand back a ranked list of suspects. And we learn to read what they say. The whole way through, we keep asking the one thing that actually matters — where is the time truly going, and how would you ever know without measuring? By the end you'll carry a discipline you can run on any slow program. Measure first. Fix only the one thing the measurement flagged. Then measure again. There's no magic in performance work — just the machine doing exactly what it does, once you stop guessing and actually look.

01Measure first — your intuition is wrong

Let's start with the mistake every one of us makes, because you have to feel it before the fix means anything. You closed Chapter 28 with a program that works. The numbers are right, the tests are green, and one problem remains: it is slow. So you do what everyone does. You read the code, your pulse rises at a particular line, and a voice says there — that triple-nested loop is the murderer. You spend an afternoon rewriting it into something clever. You run the program, and the stopwatch reads exactly what it read before. Not a little better. Identical. That loop was two percent of the runtime. The real cost was a config file being re-read and re-parsed on every iteration — a line so plain your eye slid right over it. You optimised the innocent and left the guilty untouched. And you paid for the privilege with new complexity and a fresh chance at a bug.

So what you actually need here is not a technique. It is a way to stop guessing. To earn that, you have to see why guessing fails so consistently, because it does not fail at random. It fails systematically, and a systematic error is one you can correct for. Here is the root cause, from the metal up. A CPU issues billions of instructions per second, and the cost of an operation is nowhere in its written form. Watch two lines that read as perfect equals:

# Two lines. They look equally cheap. They are not.
total = a + b                 # small ints: one C-level ADD, a few nanoseconds
found = key in seen        # seen is a list of 1,000,000: up to a million compares

Nothing in the second line looks expensive. There is no loop in the source. The loop is inside the in operator, hidden in C, invisible to your eye. This is the pattern behind every performance surprise: the real time-eaters are the operations with no syntactic weight. A helper called ten million times. An accidental O(n²) crouched behind x in some_list. A generator that quietly re-does its work each pass. An I/O wait where the core sits idle for milliseconds — an eternity — while a disk or a socket answers. None of these announce themselves in the text. And "thinking hard" about the text cannot find them, because thinking hard cannot see call counts or wait states.

There is a second reason reading fails, and it is subtler: cost is non-local. The line that looks expensive is usually not where the time is spent. The time is spent inside the functions that line calls, transitively, three and four levels down. total = summarize(data) is one short line. Say summarize calls normalize, which calls a square-root-heavy routine n² times. Then the cost lives at the bottom of a call chain you cannot see from the top. You could stare at summarize(data) for an hour and learn nothing.

So we stop reasoning about the schematic and start measuring the running circuit. A profiler is an instrument, exactly like a multimeter clipped onto a live board: it does not argue about what should happen, it reports what does. This reframes the whole activity. The profile is ground truth. Your opinion about the slow part is a hypothesis — legitimate, but worthless until a measurement confirms it. And the shape of all performance work is one loop: measure → find the hot path → fix only the hot path → measure again. Everything else in this chapter is filling in that loop with real tools.

One last piece of vocabulary, because it splits every performance problem cleanly in two. Latency is the time for one operation, and throughput is operations per second. They are not reciprocals once work runs in parallel, so name which one you care about. More important is the split between wall-clock time and CPU time. Wall-clock time is what the user actually feels — a real clock on the wall, which includes I/O and every other program on the machine. CPU time is the cycles your code truly burned. When those two numbers agree, your program is CPU-bound: it is computing, and to go faster it must compute less. When wall-clock time towers over CPU time, your program is waiting — for a disk, a network, a lock — and no amount of cleverer arithmetic will help. The fix for each is completely different. Telling them apart is the first diagnosis you will make on any slow program.

you type
# ---------- stopwatch.py ----------
"""stopwatch.py -- the two clocks, and what each one is honest about."""
import time

def work():
    return sum(i * i for i in range(20_000))     # ~1 ms of real arithmetic

print("clock resolution on this machine")
for name in ("time", "perf_counter", "process_time"):
    ci = time.get_clock_info(name)
    print(f"  time.{name:<13} {ci.resolution:>10} s   {ci.implementation}")

print("\nfive timings with time.time()")
for _ in range(5):
    t0 = time.time();          work(); print(f"  {time.time() - t0:.6f} s")

print("\nfive timings with time.perf_counter()")
for _ in range(5):
    t0 = time.perf_counter();  work(); print(f"  {time.perf_counter() - t0:.6f} s")

print("\nwall clock vs CPU clock, while we sleep")
w0, c0 = time.perf_counter(), time.process_time()
time.sleep(0.5)
print(f"  perf_counter  {time.perf_counter() - w0:.4f} s   <- what the user feels")
print(f"  process_time  {time.process_time() - c0:.4f} s   <- what the CPU burned")


# ---------- the terminal ----------
$ python stopwatch.py

you see
$ python stopwatch.py
clock resolution on this machine
  time.time            0.015625 s   GetSystemTimeAsFileTime()
  time.perf_counter       1e-07 s   QueryPerformanceCounter()
  time.process_time       1e-07 s   GetProcessTimes()

five timings with time.time()
  0.000000 s
  0.000000 s
  0.000000 s
  0.000000 s
  0.006701 s

five timings with time.perf_counter()
  0.000881 s
  0.000901 s
  0.000922 s
  0.000941 s
  0.000942 s

wall clock vs CPU clock, while we sleep
  perf_counter  0.5008 s   <- what the user feels
  process_time  0.0000 s   <- what the CPU burned

You know now to measure instead of guess. But your first attempt to measure — wrapping two snippets in a stopwatch — is about to betray you, because a single timing is almost pure noise. Next: how timeit subtracts the machine's chaos and hands you the one number that is really your code's. →

02timeit controls the noise

You have two ways to write the same function, and you want to know which is faster. Reasonable. So you reach for the obvious tool: wrap each in a clock and diff:

import time
t0 = time.time(); build_a(); print(time.time() - t0)   # 0.0181
t0 = time.time(); build_b(); print(time.time() - t0)   # 0.0092  → B wins!

A wins. You run it again — B wins. Again — A by three times. The numbers are garbage, and you are one Enter away from making a permanent code decision on a coin flip. What you need is honest comparison: a way to tell which implementation is truly better that survives the fact that your machine is doing a thousand other things while it measures.

To fix this you have to see, from the metal up, why a single timing is meaningless. Your snippet does not run alone. The OS scheduler can preempt your process mid-measurement. Another program grabs the core, your clock keeps ticking, and you are charged for someone else's work. The CPU also changes its own clock frequency under you: turbo boost when it is cool, thermal throttling when it is hot. So the same instructions take different real time minute to minute. The first run has cold caches and untrained branch predictors. The second is warm and faster for reasons that have nothing to do with your code. And Python's own garbage collector can fire in the middle of your snippet and bill its pause to you. Layer on one more problem. A fast snippet may finish in nanoseconds, far below the resolution of a naive clock, so a single call measures the clock's own graininess, not your code.

Now look at exactly what timeit does about each of these, because every design choice answers one of the problems above. First, it runs the snippet a chosen number of times in a tight compiled loop and divides. So nanosecond operations are multiplied up into a span the clock can actually resolve, and the per-call overhead is amortised away. Second, it uses time.perf_counter, the highest-resolution monotonic clock available. It never runs backward, and it is immune to the wall clock being nudged by NTP mid-measurement. Third — and this is the part people miss — it disables the garbage collector for the duration, so a gc pause cannot pollute the number. Fourth, it repeats the whole trial several times (repeat) and hands you a list, and you report the minimum, never the mean.

you type
# ---------- the classic duel: building one 38,890-character string ----------
$ python -m timeit -s "parts=[str(i) for i in range(10000)]" "s=''" "for p in parts: s += p"
$ python -m timeit -s "parts=[str(i) for i in range(10000)]" "s=''.join(parts)"

# ---------- pin the counts instead of letting timeit choose ----------
$ python -m timeit -n 200 -r 7 -s "parts=[str(i) for i in range(10000)]" "s=''.join(parts)"

# ---------- the constant-folding trap ----------
$ python -m timeit "2 ** 20"
$ python -m timeit -s "x = 2" "x ** 20"

# ---------- is += really quadratic? ask the machine, three sizes ----------
$ python -m timeit -s "parts=[str(i) for i in range(10000)]" "s=''" "for p in parts: s += p"
$ python -m timeit -s "parts=[str(i) for i in range(10000)]" "s=''" "for p in parts: keep = s; s += p"

you see
$ python -m timeit -s "parts=[str(i) for i in range(10000)]" "s=''" "for p in parts: s += p"
500 loops, best of 5: 831 usec per loop

$ python -m timeit -s "parts=[str(i) for i in range(10000)]" "s=''.join(parts)"
10000 loops, best of 5: 24.2 usec per loop

$ python -m timeit -n 200 -r 7 -s "parts=[str(i) for i in range(10000)]" "s=''.join(parts)"
200 loops, best of 7: 21.7 usec per loop

$ python -m timeit "2 ** 20"
50000000 loops, best of 5: 7.5 nsec per loop

$ python -m timeit -s "x = 2" "x ** 20"
5000000 loops, best of 5: 54.2 nsec per loop

# the three sizes, plain += :
n=10000  500 loops, best of 5: 818 usec per loop
n=20000  200 loops, best of 5: 1.31 msec per loop
n=40000  100 loops, best of 5: 2.97 msec per loop

# the three sizes, with `keep = s` added to the loop body:
n=10000  50 loops, best of 5: 4.64 msec per loop
n=20000  20 loops, best of 5: 18.9 msec per loop
n=40000   5 loops, best of 5: 78.6 msec per loop

import timeit

# setup runs ONCE per trial and is NOT timed — build the input here
setup = "data = list(range(10_000))"

loop  = # the thing we actually want to measure
loop  = "total = []\nfor x in data: total.append(x*x)"
comp  = "total = [x*x for x in data]"

best_loop = min(timeit.repeat(loop, setup, number=1000, repeat=5))
best_comp = min(timeit.repeat(comp, setup, number=1000, repeat=5))
print(best_loop, best_comp)   # comprehension wins, and it wins every run

Two details in that code are the whole craft. The setup / stmt split is not decoration. setup runs once per trial and is not timed, so you build your input there and measure only the operation. Fold the input construction into the timed statement and you are secretly timing list(range(...)) too — the same operation gives a different and dishonest verdict. And beware the compiler. timeit('2 ** 20') reports a time near zero because 2 ** 20 is a constant expression folded at compile time into the literal 1048576. You measured nothing. To force real work, the operand must be unknown to the compiler: pull x from setup and time x ** 20.

"""timeit_duel.py -- four honest duels. Only ONE of them will ever matter."""
import timeit

REPEAT = 7


def duel(title, setup, a_stmt, b_stmt, number):
    """Interleave A and B trial by trial, then report each one's minimum."""
    ta = timeit.Timer(a_stmt, setup)
    tb = timeit.Timer(b_stmt, setup)
    best_a = best_b = float("inf")
    for _ in range(REPEAT):                       # A,B,A,B... so any drift
        best_a = min(best_a, ta.timeit(number))   # hits both candidates alike
        best_b = min(best_b, tb.timeit(number))
    a, b = best_a / number, best_b / number
    ratio = max(a, b) / min(a, b)
    print(title)
    print(f"   {a_stmt:<24} {a*1e6:10.3f} us")
    print(f"   {b_stmt:<24} {b*1e6:10.3f} us")
    if ratio < 1.05:                              # under 5% is not a result
        print(f"   -> dead heat ({ratio:.3f}x) -- same work, two spellings\n")
    else:
        print(f"   -> {a_stmt if a < b else b_stmt}  wins by {ratio:.2f}x\n")


duel("1. list-comp vs map        10,000 ints -> str",
     "d = list(range(10_000))",
     "[str(x) for x in d]", "list(map(str, d))", number=100)

duel("2. in-list vs in-set       100,000 items, needle absent",
     "big_list = list(range(100_000))\nbig_set = set(big_list)\nneedle = -1",
     "needle in big_list", "needle in big_set", number=100)

duel("3. f-string vs concat      two short strings",
     'a = "Blinding"; b = "Lights"',
     'f"{a} - {b}"', 'a + " - " + b', number=200_000)

duel("4. sorted(d) vs copy+sort  10,000 random floats",
     "import random; random.seed(29)\nd = [random.random() for _ in range(10_000)]",
     "sorted(d)", "t = d[:]; t.sort()", number=100)

$ python timeit_duel.py
1. list-comp vs map        10,000 ints -> str
   [str(x) for x in d]         484.143 us
   list(map(str, d))           595.555 us
   -> [str(x) for x in d]  wins by 1.23x

2. in-list vs in-set       100,000 items, needle absent
   needle in big_list          643.885 us
   needle in big_set             0.023 us
   -> needle in big_set  wins by 27995.14x

3. f-string vs concat      two short strings
   f"{a} - {b}"                  0.067 us
   a + " - " + b                 0.089 us
   -> f"{a} - {b}"  wins by 1.34x

4. sorted(d) vs copy+sort  10,000 random floats
   sorted(d)                  1077.487 us
   t = d[:]; t.sort()         1082.590 us
   -> dead heat (1.005x) -- same work, two spellings

timeit tells you which of two snippets is faster — but not which snippet to test. In a five-thousand-line program you have no idea where to point it. Next: an instrument that watches the whole program run and hands you a ranked list of suspects. →

03A profiler attributes time to functions

timeit is a scalpel, and a scalpel is useless until you know where to cut. In a real program of thousands of lines and hundreds of functions, the question is not "which of these two is faster." It is "which of these hundred is the problem." You need triage: something that watches the entire program run and returns a ranked list. Here are your functions, here is how many times each was called, here is how much time each ate. That instrument is a profiler, and CPython ships one built from a mechanism you already met in Chapter 25.

Recall the trace hook. CPython lets you register a callback that the interpreter invokes as your program runs. There are two flavours. The trace hook fires on every line. The profile hook, installed via sys.setprofile, fires only on function call and return events — far fewer events, far less overhead. cProfile installs such a hook written in C (the _lsprof module), so the per-event cost is small. The logic is simple and worth holding in your head. On a call event it pushes a frame record onto a stack and stamps a timer. On the matching return it stamps the timer again and folds the elapsed span into that function's running ledger. Do that for every call in the program, and per function you have three numbers that answer everything.

import cProfile, pstats

cProfile.run("main()", "out.prof")          # or: python -m cProfile -s cumtime prog.py
stats = pstats.Stats("out.prof")
stats.sort_stats("cumulative").print_stats(10)  # top 10 by inclusive time

The three numbers are these. ncalls is how many times the function was entered. tottime is time spent inside the function itself, excluding everything it called ("self time"). cumtime is total time from entry to return, including every callee ("inclusive time"). The distinction between the last two is not a detail. It is the entire skill of profile-reading, so hold it hard. A function with huge cumtime but tiny tottime is a conductor: it barely works itself, it just calls other expensive things, so chase its children. A function with tottime ≈ cumtime is a hot leaf: this is where cycles actually burn, and this is where you fix. Read the table sorted by cumtime to find the expensive subtree, then re-sort by tottime to find the leaf that is truly hot inside it.

you type
# ---------- shapes.py ----------
"""shapes.py -- half a second of computing, half a second of waiting."""
import time


def compute():
    return sum(i * i for i in range(2_000_000))


def fetch():
    time.sleep(0.5)              # stands in for a socket read
    return "payload"


def main():
    return compute(), fetch()


if __name__ == "__main__":
    main()


# ---------- the terminal ----------
$ python -m cProfile -s tottime shapes.py
$ python -c "import time, shapes; w=time.perf_counter(); c=time.process_time(); shapes.main(); print(f'wall {time.perf_counter()-w:.3f} s   cpu {time.process_time()-c:.3f} s')"

you see
$ python -m cProfile -s tottime shapes.py
         2000009 function calls in 0.771 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.501    0.501    0.501    0.501 {built-in method time.sleep}
        1    0.147    0.147    0.269    0.269 {built-in method builtins.sum}
  2000001    0.122    0.000    0.122    0.000 shapes.py:6(<genexpr>)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        1    0.000    0.000    0.501    0.501 shapes.py:9(fetch)
        1    0.000    0.000    0.771    0.771 {built-in method builtins.exec}
        1    0.000    0.000    0.771    0.771 shapes.py:14(main)
        1    0.000    0.000    0.771    0.771 shapes.py:1(<module>)
        1    0.000    0.000    0.269    0.269 shapes.py:5(compute)

$ python -c "... perf_counter and process_time around shapes.main() ..."
wall 0.630 s   cpu 0.141 s

you type
# ---------- read_the_profile.py ----------
"""read_the_profile.py -- run the profiler from code, then interrogate the .prof"""
import cProfile, pstats, find_the_hog

cProfile.run("find_the_hog.main()", "hog.prof")

st = pstats.Stats("hog.prof")
st.strip_dirs()                              # drop the long paths

print("\n=== sorted by TOTTIME, top 5 -- where cycles actually burn ===")
st.sort_stats("tottime").print_stats(5)

print("=== who does main() call, and what did each cost? ===")
st.print_callees("main")


# ---------- the terminal ----------
$ python read_the_profile.py
$ python -c "import pstats; pstats.Stats('hog.prof').strip_dirs().print_callers('genexpr')"

you see
$ python read_the_profile.py

=== sorted by TOTTIME, top 5 -- where cycles actually burn ===
Sun Aug 16 08:06:37 2026    hog.prof

         1148906 function calls in 2.218 seconds

   Ordered by: internal time
   List reduced from 13 to 5 due to restriction <5>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    2.033    2.033    2.033    2.033 find_the_hog.py:17(unique)
   444450    0.055    0.000    0.089    0.000 find_the_hog.py:14(<genexpr>)
    50000    0.038    0.000    0.127    0.000 {method 'join' of 'str' objects}
   444450    0.034    0.000    0.034    0.000 {method 'isalnum' of 'str' objects}
    50000    0.027    0.000    0.165    0.000 find_the_hog.py:12(normalise)


=== who does main() call, and what did each cost? ===
   Ordered by: internal time
   List reduced from 13 to 1 due to restriction <'main'>

Function                  called...
                              ncalls  tottime  cumtime
find_the_hog.py:26(main)  ->       1    0.009    0.012  find_the_hog.py:4(build_words)
                               50000    0.027    0.165  find_the_hog.py:12(normalise)
                                   1    2.033    2.033  find_the_hog.py:17(unique)

$ python -c "... print_callers('genexpr') ..."
Function                       was called by...
                                   ncalls  tottime  cumtime
find_the_hog.py:14(<genexpr>)  <-  444450    0.055    0.089  {method 'join' of 'str' objects}

Now the honest caveats, because an instrument that lies to you is worse than none. First, cProfile perturbs what it measures — the observer effect. Its hook samples a clock on every call. So a trivial function called ten million times has the hook's own overhead swamp its real cost, and the profiler over-blames tiny hot functions. This is why there are two families. Deterministic profilers like cProfile see every call exactly, but they slow the program roughly 2–5× and mis-charge micro-functions. Sampling profilers like py-spy take the opposite bet. They interrupt the program at a fixed frequency — say a thousand times a second — and record where it "usually is," attributing time statistically with near-zero overhead and no per-call distortion. For a tight CPU loop of tiny calls, reach for a sampler. For understanding call structure, cProfile.

The second caveat is the one that catches everyone, and it ties straight back to Section 1. cProfile measures the Python call structure — it fires on calls and returns. It does not fire while your program sits inside a socket read or a disk wait, because no Python function is being called during that wait. So an I/O-bound program produces a profile that blames almost nothing. Every function looks cheap, the totals are tiny, and yet the program took three real seconds. An empty profile is itself the diagnosis. It means your time went to waiting, not computing, and you should be reading wall-clock time, not a call profiler. The instrument that finds nothing has told you exactly where to look.

"""find_the_hog.py -- three functions. one of them is eating the program."""


def build_words(n):
    """Looks like the expensive one: it builds the whole dataset."""
    out = []
    for i in range(n):
        out.append(f"  Word{i % 10_000}!  ")
    return out


def normalise(word):
    """Called once per word -- 50,000 times. Surely this is the hog?"""
    return "".join(ch for ch in word.strip().lower() if ch.isalnum())


def unique(words):
    """Three lines. No nested loop. The innocent one."""
    seen = []
    for w in words:
        if w not in seen:
            seen.append(w)
    return seen


def main():
    raw = build_words(50_000)
    clean = [normalise(w) for w in raw]
    return unique(clean)


if __name__ == "__main__":
    print(len(main()), "unique words")


# ---------- the fix, once the profile has spoken ----------
def unique(words):                    # find_the_hog_fixed.py
    seen = set()                      # <-- hash-and-probe, not scan
    out = []
    for w in words:
        if w not in seen:
            seen.add(w)
            out.append(w)
    return out

$ python -m cProfile -s cumtime find_the_hog.py
10000 unique words
         1148916 function calls in 2.427 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    2.427    2.427 {built-in method builtins.exec}
        1    0.001    0.001    2.427    2.427 find_the_hog.py:1(<module>)
        1    0.007    0.007    2.426    2.426 find_the_hog.py:26(main)
        1    2.203    2.203    2.204    2.204 find_the_hog.py:17(unique)
    50000    0.032    0.000    0.199    0.000 find_the_hog.py:12(normalise)
    50000    0.046    0.000    0.153    0.000 {method 'join' of 'str' objects}
   444450    0.067    0.000    0.107    0.000 find_the_hog.py:14(<genexpr>)
   444450    0.040    0.000    0.040    0.000 {method 'isalnum' of 'str' objects}
        1    0.012    0.012    0.016    0.016 find_the_hog.py:4(build_words)
    50000    0.006    0.000    0.006    0.000 {method 'lower' of 'str' objects}
    50000    0.006    0.000    0.006    0.000 {method 'strip' of 'str' objects}
    60000    0.005    0.000    0.005    0.000 {method 'append' of 'list' objects}

$ python -m cProfile -s cumtime find_the_hog_fixed.py
10000 unique words
         1158916 function calls in 0.196 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.196    0.196 {built-in method builtins.exec}
        1    0.001    0.001    0.196    0.196 find_the_hog_fixed.py:1(<module>)
        1    0.007    0.007    0.195    0.195 find_the_hog_fixed.py:28(main)
    50000    0.027    0.000    0.170    0.000 find_the_hog_fixed.py:12(normalise)
    50000    0.040    0.000    0.132    0.000 {method 'join' of 'str' objects}
   444450    0.057    0.000    0.092    0.000 find_the_hog_fixed.py:14(<genexpr>)
   444450    0.035    0.000    0.035    0.000 {method 'isalnum' of 'str' objects}
        1    0.010    0.010    0.014    0.014 find_the_hog_fixed.py:4(build_words)
        1    0.003    0.003    0.005    0.005 find_the_hog_fixed.py:17(unique)
   10000    0.001    0.000    0.001    0.000 {method 'add' of 'set' objects}

$ python measure_hog.py            # perf_counter, no profiler attached
slow samples: [2.3876, 9.0066, 8.162, 8.1967, 8.1625]
fast samples: [0.1664, 0.1656, 0.1655, 0.1639, 0.1655]
slow best: 2.3876 s
fast best: 0.1639 s
speedup  : 14.6x

                  cumtime BEFORE   cumtime AFTER    change
  unique             2.204 s          0.005 s        441x
  normalise          0.199 s          0.170 s        1.2x
  build_words        0.016 s          0.014 s        1.1x
  ---------------------------------------------------------
  whole program      2.427 s          0.196 s       12.4x

The profiler has named your hot function. Now the amateur and the professional part ways. The amateur shaves the inner loop; the professional asks a deeper question — is this slow because each step is expensive, or because there are too many steps? The answer decides everything. →

04Algorithmic beats constant-factor

The profiler flagged your hot function and you did the obvious thing. You rewrote its inner loop to be cleverer, hoisted a method into a local variable, unrolled it a little. You got fifteen percent. You felt good. Then the input doubled — a normal Tuesday for real data — and the function was slower than when you started. Something you did not touch scaled against you and ate your fifteen percent alive. The need now is to understand why some optimisations evaporate the instant the data grows while others compound. And you want to tell which kind of situation you are in before you spend a day fixing the wrong thing.

Here is the idea the entire chapter has been walking toward. A running time is, roughly, c × f(n). The constant factor c is how expensive each unit of work is — the thing micro-optimisation shrinks. The growth function f(n) is how the number of units scales with the input size, and that is set entirely by your algorithm. Micro-optimising changes c: it slides the whole curve down, uniformly, but it never changes the curve's shape. Choosing a better algorithm changes f(n) itself: it bends the curve. Slide versus bend. That is the difference between a junior's afternoon and a senior's five-minute rewrite, and at scale it is not close.

# O(n²): 'in' on a list scans element by element, every time
def has_dup_list(items):
    seen = []
    for x in items:
        if x in seen: return True   # up to n compares, done n times → n²
        seen.append(x)
    return False

# O(n): a set membership test is one hash-and-probe (from the hash-table mechanism)
def has_dup_set(items):
    seen = set()
    for x in items:
        if x in seen: return True   # one probe, done n times → n
        seen.add(x)
    return False

The two functions differ by one word — [] became set() — and that word changes f(n) from n² to n, because a list must scan while a set does a single hash-and-probe. At n = 100 nobody notices. At n = 1,000,000 it is the difference between instant and never, and the arithmetic makes it visceral. O(n²) at a million is 10¹² operations. Even at a billion operations per second, that is about a thousand seconds — seventeen minutes. O(n) is a million operations, about a millisecond. No constant factor in the universe closes that gap. Make the quadratic inner loop a hundred times faster and you move a thousand seconds to ten seconds, while the linear version still sits at a millisecond. You cannot micro-optimise your way across a change in curve. That is the punchline of the whole chapter.

you type
# ---------- step 1: measure. slow_report.py builds a 30,000-line report ----------
$ python -m cProfile -s cumtime slow_report.py

# ---------- step 3: one index built once, and lookup() becomes a dict get ----------
BY_ID = {row[0]: row for row in CUSTOMERS}

def lookup(cid):
    return BY_ID.get(cid)

# ---------- step 6: measure again ----------
$ python -c "import time, slow_report, slow_report_fixed
for m in (slow_report, slow_report_fixed):
    ts = [ ... three perf_counter brackets around m.main() ... ]
    print(m.__name__, min(ts))"

# ---------- now try step 5 ON TOP: hoist BY_ID.get and out.append into locals,
#            and inline fmt() as an f-string. four edits. how much is it worth? ----------
$ python micro.py

you see
$ python -m cProfile -s cumtime slow_report.py
30000 lines rendered
         120019 function calls in 1.220 seconds
        1    0.012    0.012    1.205    1.205 slow_report.py:17(enrich)
    30000    1.180    0.000    1.180    0.000 slow_report.py:6(lookup)
    30000    0.011    0.000    0.011    0.000 slow_report.py:13(fmt)

$ python -c "... perf_counter, three samples each, minimum ..."
slow_report        best 1.1103 s   samples [1.111, 1.11, 3.225]
slow_report_fixed  best 0.0729 s   samples [0.075, 0.073, 0.075]

$ python micro.py
enrich       (dict index)        11.57 ms
enrich_micro (hoisted+inlined)   10.59 ms
the micro-edit bought          1.09x

So stock your head with the curves you will actually meet, in order of how they scale. O(1) is a hash lookup or dict access, the dream. O(log n) is binary search or a balanced tree, where doubling n adds one step. O(n) is a single scan. O(n log n) is a good sort, the ceiling for comparison sorting. O(n²) is the nested scan, the all-pairs comparison, the accidental disaster. And O(2ⁿ) is naive recursion over subsets, the fib-without-memoisation explosion that dies at n = 40. Almost every real optimisation is one of a small handful of moves that step you down this ladder. Replace a scan with a hash lookup. Replace all-pairs with sort-then-scan. Replace recomputation with memoisation of overlapping subproblems. And above all, pick the data structure whose cheap operation is the one you do most — a set for membership, a dict for lookup, a heap for "smallest so far," a deque for both ends. The right structure is not a tidiness choice. It is the choice of which curve you live on.

# ---------- the ranking, with the arithmetic that produced it ----------
#
#  p = each function's share of the 41-minute run, read straight off the profile:
#      find_account  38.2 / 41.0 = 0.932      parse_row   1.9 / 41.0 = 0.046
#      format_line    0.5 / 41.0 = 0.012      read file   0.4 / 41.0 = 0.010
#
#  B  find_account -> dict lookup
#       p = 0.932. ceiling = 1/(1-0.932) = 14.7x.
#       A dict get is O(1) instead of a 60,000-element scan, so realistically
#       38.2 min collapses to a few seconds: about 14x, near the ceiling.
#       41 min -> roughly 2.8 min.
#
#  C  multiprocessing on 8 cores
#       p = ~0.99 (nearly all of it is CPU work), s = 8 at the very best.
#       1/((1-0.99) + 0.99/8) = 7.5x, and that is the fantasy number:
#       no pickling cost, no start-up, perfect balance. Ch 28 measured 2.35x
#       where the theory said 4x. Call it 4-5x, for a large permanent
#       increase in complexity -- and it makes the quadratic scan run on
#       eight cores instead of removing it.
#
#  D  hoist locals inside find_account
#       p = 0.932, s = 1.1. 1/((1-0.932) + 0.932/1.1) = 1.09x.
#       41 min -> 37.6 min. It touches the right function and still
#       does almost nothing, because it shaves c and leaves f(n) alone.
#
#  A  faster format_line
#       p = 0.012, s = 1.3. ceiling even at s = infinity is 1/(1-0.012) = 1.012x.
#       41 min -> 40.9 min. A perfect rewrite here cannot buy 1%.
#
#  RANK:  B  >>  C  >  D  >  A
#
#
# ---------- which lever does each one pull? ----------
#
#   changes f(n):   B only.   n*m scan  ->  n hash lookups.
#   changes c:      A, D.     same number of operations, each slightly cheaper.
#   changes neither: C.       it buys more workers to do the SAME operations.
#
# That is why the ranking is not the same as the ranking of measured speedups.
# D's benchmark (1.1x) and A's benchmark (1.3x) are both honest -- A's is even
# the larger of the two -- and both are nearly worthless here, because a
# constant-factor win is capped by its slice and B is capped by nothing.
#
#
# ---------- the new cost of proposal B ----------
#
#   The dict holds all 60,000 account rows in memory at once, keyed by id.
#   Check it: 60,000 entries is trivial (tens of MB at worst) -- confirm with
#   tracemalloc, not with a guess. Two real risks to check, not assume:
#     1. duplicate ids. A list scan returns the FIRST match; a dict keeps the
#        LAST insert. If ids repeat, B silently changes the answer.
#     2. build cost. Building the index is one O(n) pass over 60,000 rows,
#        paid once. Against 38 minutes it is free, but measure it anyway.
#   Correctness first: run the existing tests, then diff old and new output.
#
#
# ---------- what is left after B ----------
#
#   New total: about 2.8 min. The old 93% is now a few seconds, so the
#   profile has completely reshaped. parse_row was 1.9 min and did NOT get
#   faster -- it is now roughly 1.9 / 2.8 = 68% of the run and the new
#   tallest bar. Its ceiling: 1/(1-0.68) = 3.1x.
#
#   So the honest answer to "what can anything else still buy": about 3x
#   more, all of it now living in parse_row -- and only if you re-profile,
#   because that ranking did not exist an hour ago.
#
#   Proposal C is worth revisiting AFTER B, not instead of it. Parallelising
#   a linear job is a reasonable second move; parallelising a quadratic one
#   is buying eight cores to hide a bug in your data structure.

You picked the optimal algorithm and the Big-O is as good as it gets — and two programs with the same O(n) still differ by tenfold. The algorithm cannot explain that gap. The layer below it can: where your data lives in memory, and how the CPU waits for it. →

05Memory, allocation, and the cache

You did everything right. The algorithm is optimal, the Big-O is O(n), there is no wasted work in the operation count — and one program is ten times faster than the other. The one that flies stores its numbers in a packed array of raw floats. The slow one stores them in an ordinary Python list. Same n, same arithmetic, same complexity class. The algorithm cannot explain a tenfold gap, because the gap does not live in the algorithm. It lives one layer down, in the physics the algorithm sits on. The CPU spends most of its life not computing but waiting for memory, and where your data lives decides how long it waits.

Start with the hardware truth, because it is stark. Reading a value already in a CPU register costs about one cycle. From L1 cache, ~4 cycles. L2, ~12. L3, ~40. From main RAM — ~200+ cycles. A cache miss can cost fifty to a hundred times a hit. The CPU fights this with two tricks you must design around. It never fetches one byte; it fetches a cache line of 64 bytes at once — so if the next value you need is right beside the last, it is already there, free. And it prefetches: when it sees you walking memory sequentially, it fetches ahead of you. The consequence is enormous: contiguous, sequential access is vastly faster than chasing pointers to scattered addresses, even for the identical number of elements.

Now the Python-specific reality, and this is where the volume's thread comes home. A Python list of integers is not a block of integers. It is a contiguous array of pointers, and each pointer aims at a separate, heap-allocated PyObject — a little box holding a refcount, a type pointer, and the actual value — that can live anywhere in memory. Iterating the list means pointer-chasing: read a pointer, jump to a random address, almost certainly miss the cache, unbox the object, repeat. Contrast an array.array('d', ...) or a NumPy array, which stores raw C doubles packed end to end. One 64-byte cache line delivers eight of them at once. The prefetcher sees the straight-line pattern and runs ahead, and every value is already unboxed. Same eight numbers: eight misses versus one fetch.

import array, timeit

py_list = list(range(1_000_000))          # array of pointers → scattered PyObjects
packed  = array.array('q', range(1_000_000)) # contiguous raw 64-bit ints

# identical operation, identical O(n) — only the memory layout differs
print(min(timeit.repeat(lambda: sum(py_list), number=100)))
print(min(timeit.repeat(lambda: sum(packed),  number=100)))  # faster — the prefetcher can see it coming

There is a second cost centre hiding in Python's object model: allocation and refcount churn. Every time Python creates an object it calls the allocator — pymalloc hands out small blocks from pre-carved pools and arenas. And every assignment or function argument bumps a refcount up, then later down. Py_INCREF and Py_DECREF are not free bookkeeping. They are real memory writes, and writing to a shared object's refcount even invalidates that cache line across every core that holds it. A loop that creates a million short-lived temporary objects pays allocation, then refcount traffic, then deallocation for each one — that is churn — even though it computes nothing extra. This is why s += piece in a loop is a quiet O(n²) allocation disaster, a new string object every pass. Collecting pieces into a list and calling ''.join(pieces) once allocates the result a single time.

Hence the concrete levers, each one a move against a real cost you can now name. Prefer contiguous homogeneous storage for large numeric data. Reuse buffers instead of reallocating. Use generators to stream instead of materialising a huge intermediate list all at once. And add __slots__ to a class you make millions of, which drops the per-instance __dict__ — smaller objects, tighter packing, less allocation. Then tie it back to measurement, because this is the sting. These effects are invisible in the source, and largely invisible to cProfile's function-level view. The profiler points at a loop that is "slow for no reason," and the reason is the memory beneath it. The tools that confirm it are timeit comparisons and memory instruments — tracemalloc and sys.getsizeof — not the call profiler.

you type
# ---------- what is actually installed in this environment? ----------
$ python -c "import line_profiler"
$ python -c "import snakeviz"

# ---------- mem_check.py ----------
"""mem_check.py -- where the bytes go. Run: python -m memory_profiler mem_check.py"""

@profile
def build_list(n):
    rows = [f"row-{i}" for i in range(n)]      # materialise everything
    total = sum(len(r) for r in rows)
    return total


@profile
def stream(n):
    total = sum(len(f"row-{i}") for i in range(n))   # one row alive at a time
    return total


if __name__ == "__main__":
    print(build_list(50_000), stream(50_000))


$ python -m memory_profiler mem_check.py

# ---------- the same question with the stdlib, at 500,000 rows ----------
$ python -c "... tracemalloc.start(); fn(500_000); get_traced_memory() ..."

you see
$ python -c "import line_profiler"
Traceback (most recent call last):
  File "<string>", line 1, in <module>
ModuleNotFoundError: No module named 'line_profiler'

$ python -c "import snakeviz"
Traceback (most recent call last):
  File "<string>", line 1, in <module>
ModuleNotFoundError: No module named 'snakeviz'

$ python -m memory_profiler mem_check.py
438890 438890
Filename: mem_check.py

Line #    Mem usage    Increment  Occurrences   Line Contents
=============================================================
     3   58.996 MiB   58.996 MiB           1   @profile
     4                                         def build_list(n):
     5   62.805 MiB    3.809 MiB       50001       rows = [f"row-{i}" for i in range(n)]      # materialise everything
     6   62.805 MiB    0.000 MiB      100003       total = sum(len(r) for r in rows)
     7   62.805 MiB    0.000 MiB           1       return total


Filename: mem_check.py

Line #    Mem usage    Increment  Occurrences   Line Contents
=============================================================
    10   60.809 MiB   60.809 MiB           1   @profile
    11                                         def stream(n):
    12   60.809 MiB    0.000 MiB      100003       total = sum(len(f"row-{i}") for i in range(n))   # one row alive at a time
    13   60.809 MiB    0.000 MiB           1       return total

$ python -c "... tracemalloc, 500,000 rows ..."
  build_list  peak   28.19 MiB
  stream      peak    0.00 MiB

You can now find the hot path, choose the right curve, and lay the data out for the cache. One question remains — the one that decides whether any of it is worth doing. You made a function 4× faster and the program barely moved. Amdahl's Law explains exactly why, and turns your profile into a budget. →

06Optimize the hot path, then remeasure

You found the hot function, you fixed it, it is now four times faster — and the whole program got six percent faster. It feels like a swindle. Meanwhile a colleague spent the same afternoon and got 3× on the total. Same effort, wildly different payoff, and the difference was not skill. It was which part they chose to fix. The need now is to know, before you spend the day, whether an optimisation is worth doing at all. And you have to accept that performance work is never one-and-done, because the moment you fix the top of the list a different function becomes the new bottleneck.

The law that governs all of this is Amdahl's Law, and it is simple enough to keep in your head. Say a portion p of the total runtime is the part you speed up, and you make that part s times faster. Then the overall speedup is:

def speedup(p, s):
    # p = fraction of runtime you optimized; s = how many times faster you made it
    return 1 / ((1 - p) + p / s)

print(speedup(0.08, 4))    # 1.06  → your 4x fix on an 8% slice: +6% total
print(speedup(0.70, 2))    # 1.54  → a mere 2x on the 70% slice beats it easily
print(speedup(0.05, 10_000)) # 1.052 → infinite speed on a 5% slice caps at ~5%

Three consequences fall straight out, and together they are the lesson. First, the ceiling. Let s → ∞ — make the optimised part infinitely fast — and the best you can ever reach is 1 / (1 − p). A function that is 5% of runtime caps your total improvement at about 5.3%, no matter how brilliant the rewrite. Optimising cold code is money left on the table. Optimising the 5% part is nearly pointless even done perfectly. Second, it explains your swindle exactly: with p = 0.08 and s = 4, the total speedup is 1 / (0.92 + 0.02) ≈ 1.06. The fix worked. The part was just too small to matter. Third — and this is what turns theory into a tool — it tells you where to spend effort before you spend it. A modest 2× on the function that is 70% of runtime crushes a heroic 100× on the 3% function. Read this way, the profile is not just a list of suspects. It is a budget: each row's cumtime is the maximum payoff any fix to it can ever return.

30000 lines rendered
         120019 function calls in 1.220 seconds

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.001    0.001    1.216    1.216 slow_report.py:29(main)
        1    0.012    0.012    1.205    1.205 slow_report.py:17(enrich)
    30000    1.180    0.000    1.180    0.000 slow_report.py:6(lookup)
    30000    0.011    0.000    0.011    0.000 slow_report.py:13(fmt)
        1    0.000    0.000    0.010    0.010 slow_report.py:25(render)
    30001    0.008    0.000    0.008    0.000 slow_report.py:26(<genexpr>)

# ---------- the answers ----------
#
# 1. THE HOG IS lookup.  The column that convicted it is TOTTIME: 1.180 s of
#    1.220 s, 97% of the run, spent inside lookup's own body. main and enrich
#    have huge cumtime and near-zero tottime -- they are conductors.
#
# 2. enrich's 1.205 s is INHERITED. Its own tottime is 0.012 s, so a perfect
#    rewrite of enrich saves at most 0.012 s: 1% of the run. cumtime tells you
#    which way to walk; tottime tells you where to stop.
#
# 3. Not the call count -- it is identical. The signal is COST PER CALL, and
#    the profile prints it: percall for lookup is 1.180/30000 = 39 us, for fmt
#    it is 0.011/30000 = 0.37 us. Same number of calls, 107x the cost each.
#
# 4. tottime == cumtime means lookup calls NOTHING that the profiler can see.
#    It is a hot leaf. 39 us of pure self-time per call, on a 4,000-row table,
#    is the fingerprint of a linear SCAN written in Python.
#
#
# ---------- the source, once you look ----------
CUSTOMERS = [(i, f"customer-{i}", i * 3) for i in range(4_000)]

def lookup(cid):
    for row in CUSTOMERS:          # 4,000 rows, walked from the top
        if row[0] == cid:          # ...for every one of 30,000 orders
            return row
    return None                    # 30,000 x ~2,000 average = ~60M compares


# ---------- the fix: index once, look up in O(1) ----------
BY_ID = {row[0]: row for row in CUSTOMERS}    # built ONE time, at import

def lookup(cid):
    return BY_ID.get(cid)


# ---------- the proof ----------
$ python -m cProfile -s cumtime slow_report_fixed.py
30000 lines rendered
         150019 function calls in 0.045 seconds

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.001    0.001    0.040    0.040 slow_report_fixed.py:29(main)
        1    0.011    0.011    0.029    0.029 slow_report_fixed.py:17(enrich)
        1    0.000    0.000    0.010    0.010 slow_report_fixed.py:25(render)
    30000    0.009    0.000    0.009    0.000 slow_report_fixed.py:13(fmt)
    30001    0.008    0.000    0.008    0.000 slow_report_fixed.py:26(<genexpr>)
    30000    0.004    0.000    0.006    0.000 slow_report_fixed.py:9(lookup)
    30000    0.003    0.000    0.003    0.000 {method 'get' of 'dict' objects}

$ python -c "... perf_counter, best of three, no profiler ..."
slow_report        best 1.1103 s
slow_report_fixed  best 0.0729 s        # 15.2x


# ---------- the three numbers, and the ceiling ----------
#
#   whole program : 1.220 s -> 0.045 s profiled, 1.110 s -> 0.073 s real (15.2x)
#   lookup cumtime: 1.180 s -> 0.006 s  (about 200x)
#   tallest bar now: enrich, tottime 0.011 s of a 0.045 s run
#
#   The bottleneck MOVED. enrich did not get slower -- it is now 24% of a much
#   smaller total, and its own loop is the largest single piece left.
#   Ceiling for enrich: p = 0.011/0.045 = 0.24, so 1/(1-0.24) = 1.32x.
#
#   Verdict: no. A perfect rewrite of enrich buys at most 32%, on a job that
#   now takes 73 milliseconds. Stop. The next afternoon is worth more somewhere
#   else -- and that judgement is only defensible because it is measured.
#
#
# ---------- the trap to notice ----------
#
#   The dict keeps the LAST row for a duplicate id; the scan returned the FIRST.
#   If CUSTOMERS can hold duplicate ids, this fix is not equivalent, it is a
#   behaviour change wearing an optimisation's clothes. Check before shipping.

Now the part people skip, and it is why performance work is a loop and not a task: the bottleneck moves. Say function A was 70% and you cut it in half. It is now a much smaller slice, and function B, which was a quiet 15%, is suddenly the tallest bar in a completely reshaped profile. Your first-round intuition is now worthless, because it was built against a distribution that no longer exists. This is why re-measure is mandatory, not optional. After every fix you must re-profile against the new reality, because the target physically relocated. Measure → find the hot path → fix only the hot path → measure again → repeat until the remaining wins cannot beat their cost.

"""bench_bad.py -- a benchmark with three sins. It reports a lie."""
import time, random

random.seed(29)
data = [random.random() for _ in range(200_000)]

t0 = time.time()
out = sorted([random.random() for _ in range(200_000)])
print(f"sorted()  {time.time() - t0:.6f} s")

t0 = time.time()
for _ in range(5):
    data.sort()
print(f".sort()   {(time.time() - t0) / 5:.6f} s")

# ---------- why the verdict is impossible ----------
#
#   CPython's sorted(x) does exactly two things:
#       1. build a new list from the iterable        (a copy)
#       2. call list.sort on that new list           (the same C sort)
#   So sorted(d) IS "copy, then sort". It cannot be 7x slower than itself.
#   When the arithmetic is impossible, stop editing code and audit the harness.
#
#
# ---------- the three sins ----------
#
#   SIN 1  -- THE CLOCK.  time.time() on Windows resolves to 15.625 ms, and
#             each candidate is timed exactly ONCE. A single sample from a
#             coarse, adjustable clock is a coin flip, not a measurement.
#             Fix: timeit (which uses perf_counter), repeated, minimum taken.
#
#   SIN 2  -- WHAT IS IN THE BRACKET.  The sorted() timing includes building
#             200,000 fresh random floats INSIDE the timed region. That is
#             ~15 ms of list-building charged to sorted(). The .sort() timing
#             includes no construction at all. The two brackets do not hold
#             the same work, so the comparison is meaningless.
#             Fix: construction goes in setup, which timeit does not time.
#
#   SIN 3  -- THE DATA MUTATES.  data.sort() sorts IN PLACE. The first of the
#             five iterations sorts a random list; the other four sort an
#             ALREADY SORTED list. Timsort detects existing runs and finishes
#             a sorted list in O(n). So four of the five reps do almost no
#             work, and the average is divided by five anyway.
#             Fix: hand every trial the same fresh input -- t = d[:]; t.sort().
#
#             Measured, so it is not a story:
#                 t = d[:];  t.sort()   on random input     20.38 ms
#                 t = s[:];  t.sort()   on sorted input      1.39 ms   (14.7x)
#
#             This is the sin that inverts a verdict. Sins 1 and 2 add noise
#             and bias; sin 3 hands the winner's medal to the wrong candidate.
#
#
# ---------- bench_good.py ----------
"""bench_good.py -- the same question, asked honestly."""
import timeit

SETUP = "import random; random.seed(29)\nd = [random.random() for _ in range(200_000)]"
NUMBER, REPEAT = 5, 7

a = timeit.Timer("sorted(d)", SETUP)
b = timeit.Timer("t = d[:]; t.sort()", SETUP)

best_a = best_b = float("inf")
for _ in range(REPEAT):                                # interleave A and B so
    best_a = min(best_a, a.timeit(NUMBER) / NUMBER)    # any drift is shared
    best_b = min(best_b, b.timeit(NUMBER) / NUMBER)

print(f"sorted(d)           {best_a*1000:7.2f} ms")
print(f"t = d[:]; t.sort()  {best_b*1000:7.2f} ms")
print(f"ratio               {max(best_a,best_b)/min(best_a,best_b):.3f}x  -- a dead heat")


$ python bench_good.py
sorted(d)             21.02 ms
t = d[:]; t.sort()    21.07 ms
ratio               1.002x  -- a dead heat

$ python bench_good.py
sorted(d)             20.81 ms
t = d[:]; t.sort()    20.63 ms
ratio               1.009x  -- a dead heat


# ---------- the real verdict ----------
#
#   1.002x and 1.009x, and the winner swaps between runs. That is a tie, and a
#   tie is a RESULT: these two spellings do identical work, so choose between
#   them on meaning, not speed. Use .sort() when you want the original list
#   reordered; use sorted() when you want a new list and the original kept.
#
#   The 7x from bench_bad.py measured three bugs. Notice that fixing sin 3
#   alone would still have left a wrong number, and fixing sin 1 alone would
#   have made a wrong number more precise. A benchmark is only as honest as
#   its weakest line.

And that closes both the chapter and the volume. Correctness first — the whole of Volumes 1 and 2. Then measure. Then fix the one thing the measurement flagged. Then measure again. Not the guesser's leap — the engineer's loop. →