Profiling with cProfile and py-spy: measure the production shape before touching code

cProfile: deterministic tracing, and what the overhead distorts

cProfile is a deterministic tracer: it registers a C-level profile hook (the lsprof machinery behind sys.setprofile) that fires on every function call and return, recording counts and timers per function. Nothing is missed — that is the appeal — but every call pays a fixed bookkeeping tax, so the whole program typically runs 1.3-2x slower under it. The distortion is not uniform. The fixed per-call cost is enormous relative to a 200 ns helper invoked ten million times and negligible relative to a 50 ms database query invoked twice. Tiny hot Python functions therefore look worse than they are, and the “top offenders” ranking bends toward call count rather than real cost.

Reading the output is its own skill: tottime is self time (excluding callees), cumtime is inclusive. Sort by cumtime to find the expensive subtree, then by tottime inside that subtree to find where the cycles actually burn. pstats slices programmatically; snakeviz renders the same data as a browsable sunburst.

import cProfile, pstats

cProfile.run("handle_request(req)", "out.prof")
p = pstats.Stats("out.prof")
p.sort_stats("cumulative").print_stats(12)  # find the expensive subtree
p.sort_stats("tottime").print_stats(12)     # find the self-cost inside it

Two blind spots are structural. First, C internals are invisible: json.dumps or a numpy op appears as a single opaque row — total time, zero breakdown of what happens inside. Second, threads: by default cProfile observes the thread it was started in; worker threads run unprofiled unless each installs its own profiler. Under asyncio, the event loop’s run method swallows everything into one cumtime and per-coroutine attribution gets murky.

py-spy: sampling from outside the process

py-spy inverts the deal. It runs as a separate process that reads the target’s memory — process_vm_readv/ptrace on Linux, mach APIs on macOS — locates the interpreter’s thread states, and walks the frame structs to reconstruct every Python stack, about 100 times per second. No code change, no import, no restart: attach by PID to a process started long before you knew it had a problem. The target is paused for microseconds per sample, so the overhead lands around 1% — safe against production.

Three subcommands cover the field workflow:

• py-spy top --pid 4137 — live htop-style view of which functions own the samples right now.
• py-spy record -o prof.svg --pid 4137 --duration 60 — a flamegraph; add --native to interleave C frames (this is how the Hook’s serializer became visible), --idle to include blocked threads.
• py-spy dump --pid 4137 — a one-shot stack of every thread: the stuck-process tool. A worker at 0% CPU that stopped consuming its queue is diagnosed in seconds — you see exactly which lock acquire or socket read every thread is parked on.

The honest caveat: sampling is statistical. A 5 ms spike that happens once a minute may never be sampled at 100 Hz; you need enough wall time on the behavior you are chasing, and rare-event latency needs tracing, not profiling.

timeit, and the lies of microbenchmarks

timeit disables GC and reports the best of N repeats — by design it measures the warm-cache, turbo-boosted ideal of an isolated snippet. A real service runs the same code with cold caches, interleaved work evicting branch predictors, frequency scaling, and a fragmented allocator. A 30% timeit win can be invisible at p99. Use it to compare two implementations of the same small operation under identical lies; never to predict service latency.

The discipline

When you reach for a profiler, ask first: does this environment match production? Real payload sizes, real concurrency, real data distributions, real cache hit rates. A synthetic loop on a dev box is a different program that happens to share source code. The working order: py-spy against production (or replayed prod traffic) to find where; cProfile and timeit locally to iterate on why; then re-measure p99 after the deploy — the profiler is evidence, the SLO metric is the verdict.