🔬 Profiling & Benchmarking Under Load

The Only Method That Works

Wall Time vs CPU Time — and Why Load Needs Both

For a single CPU-bound function, wall ≈ CPU and a microbenchmark tells the whole story. For anything that waits (I/O, DB, locks, the GIL), wall time is dominated by waiting — and under concurrency the metric that matters isn't one function's time at all, it's throughput and tail latency of the whole system.

import time

t0_wall = time.perf_counter()    # real elapsed time (includes waiting)
t0_cpu  = time.process_time()    # CPU time actually burned (excludes waiting)
result = do_work()
wall = time.perf_counter() - t0_wall
cpu  = time.process_time()  - t0_cpu
print(f"wall={wall:.3f}s  cpu={cpu:.3f}s")
# wall >> cpu  => I/O-bound (waiting): fix with async/threads/pooling/batching
# wall ~= cpu  => CPU-bound (computing): fix with multiprocessing/C ext/algorithm

Microbenchmarks with timeit

timeit runs a snippet many times, disables the cyclic GC for the run, and reports the best loops — good for comparing two implementations of a tiny hot function.

import timeit

setup = "data = list(range(1000))"

loops = timeit.timeit("[x*x for x in data]", setup=setup, number=100_000)
gener = timeit.timeit("list(x*x for x in data)", setup=setup, number=100_000)
print(f"listcomp {loops:.3f}s   genexpr {gener:.3f}s")

# Prefer .repeat() and take the MIN — it filters out scheduler/GC noise spikes
best = min(timeit.repeat("[x*x for x in data]", setup=setup, repeat=5, number=100_000))

# CLI form — quick A/B without writing a file:
python -m timeit -s "data=list(range(1000))" "[x*x for x in data]"

Deterministic Profiling with cProfile

cProfile instruments every call and counts exactly where time goes. Sort by cumulative time (cumtime) to find the expensive call tree, or tottime for time in a function excluding its callees.

import cProfile, pstats, io

profiler = cProfile.Profile()
profiler.enable()
run_request_handler()          # the code you want to dissect
profiler.disable()

s = io.StringIO()
stats = pstats.Stats(profiler, stream=s).sort_stats("cumulative")
stats.print_stats(15)          # top 15 by cumulative time
print(s.getvalue())

# CLI: profile a whole script and dump a binary stats file
python -m cProfile -o out.prof myscript.py
python -c "import pstats; pstats.Stats('out.prof').sort_stats('cumtime').print_stats(20)"

# Reading the output — the columns that matter:
#   ncalls  tottime  percall  cumtime  percall  filename:lineno(function)
#     300    0.012    0.000    4.812    0.016   db.py:44(get_user)   <- 300 calls = N+1!
# High CUMTIME + high NCALLS on a DB/HTTP call => you found your bottleneck.

Sampling Profiling in Production with py-spy

py-spy reads another process's stacks from the outside at a fixed sample rate. Zero code changes, near-zero overhead, no restart — the right tool for a live high-load process that's slow right now.

# Live top-like view of where CPU is going, by function (great first look):
py-spy top --pid 12345

# Record a flamegraph over 60s of real traffic → open the SVG in a browser:
py-spy record --pid 12345 --duration 60 --output flame.svg

# Process is HUNG / stuck? Dump every thread's current stack instantly:
py-spy dump --pid 12345
# → shows exactly which line each thread is parked on (a lock? a socket recv?)

Line-Level Profiling with line_profiler

Once cProfile points at a function, line_profiler tells you which line inside it costs the time.

# Decorate the target function with @profile (injected by kernprof, no import needed)
@profile
def score_batch(rows):
    features = [extract(r) for r in rows]     # suspect line
    matrix   = np.array(features)             # suspect line
    return model.predict(matrix)

# Run under kernprof, then read the per-line report:
kernprof -l -v score.py
# Output columns: Line #  Hits  Time  Per Hit  % Time  Line Contents
# The "% Time" column points straight at the one line eating the function.

Memory Profiling — tracemalloc & memory_profiler

tracemalloc ships with CPython and attributes allocations to source lines. Snapshot, run, diff — the top deltas are your leak or your buffer bloat (ties straight to memory optimization).

import tracemalloc

tracemalloc.start()
snap1 = tracemalloc.take_snapshot()

handle_1000_requests()                 # the workload you suspect grows RSS

snap2 = tracemalloc.take_snapshot()
top = snap2.compare_to(snap1, "lineno")    # biggest allocation growth first
for stat in top[:10]:
    print(stat)     # e.g. cache.py:88: size=412 MiB (+412 MiB), count=1.2M (+1.2M)

# memory_profiler: per-line RSS, like line_profiler but for memory
from memory_profiler import profile

@profile
def build_report(rows):
    data = [transform(r) for r in rows]    # watch the "Increment" column jump here
    return summarize(data)
# run:  python -m memory_profiler report.py   → Mem usage / Increment per line

Profiling Async Code

In asyncio, "slow" usually means something blocked the event loop — a sync call (CPU work, requests.get, a blocking DB driver) stalls every coroutine. Turn on debug mode; it logs any callback that hogs the loop.

import asyncio

# Debug mode: warns on slow callbacks, un-awaited coroutines, loop-blocking calls
asyncio.run(main(), debug=True)
# or:  PYTHONASYNCIODEBUG=1 python app.py
# Also set the threshold explicitly:
loop = asyncio.get_running_loop()
loop.slow_callback_duration = 0.1     # warn if any callback blocks the loop > 100ms

Load-Testing the Whole System

Everything above measures one process. Under load you need the system's behavior: throughput and the latency distribution, generated by concurrent clients. locust gives you a Python-defined workload; wrk/ab are quick one-liners.

# locustfile.py — a runnable load scenario
from locust import HttpUser, task, between

class ApiUser(HttpUser):
    wait_time = between(0.1, 0.5)        # think-time between requests per user

    @task(3)                              # weight 3: hit this 3× as often
    def read(self):
        self.client.get("/api/items?page=1")

    @task(1)
    def write(self):
        self.client.post("/api/items", json={"name": "x"})

# Ramp to 500 concurrent users, spawning 50/s, headless, for 2 minutes:
locust -f locustfile.py --host http://localhost:8000 \
       --users 500 --spawn-rate 50 --run-time 2m --headless

# Quick alternatives (no scenario file):
wrk -t8 -c200 -d30s --latency http://localhost:8000/api/items   # 200 conns, 30s
ab  -n 10000 -c 200 http://localhost:8000/api/items             # 10k reqs, 200 conc

Tool Reference