A route-optimisation job runs 40 minutes, yet its Python call profile accounts for two — where did the wall-clock time go?

This is the single most common profiling disappointment in Python: the report comes back, nothing is hot, and the job is still slow. The report is not wrong — it is answering a different question from the one you asked. ## Why a call profile can miss 95% of the time A deterministic profiler works by installing a per-thread hook that fires on every function call and return, and accumulating the interval between them. That design has four structural blind spots: 1. **Waiting is not a call.** If a function blocks for thirty seconds inside one socket read, the profiler records one call whose time is thirty seconds — and in a report sorted by *own* time the frame that actually waited is a single C call, easy to skim past, with no callees underneath to explain anything. 2. **Other threads are invisible.** The profiling hook is per-thread state. A profiler started around `main()` sees nothing that worker threads do. 3. **Subprocesses are invisible.** Work sent to a child process is charged to that child; the parent's report shows only the wait. 4. **Overhead distorts what it does see.** Instrumenting every call inflates functions that are called a great many times, so the shape of the report is biased toward small hot calls even when they are not the cost. ## Step one: classify the job in two lines Before anything else, take both clocks around the run: ```python import time wall, cpu = time.perf_counter(), time.process_time() run_job() print(time.perf_counter() - wall, time.process_time() - cpu) ``` Forty minutes of wall against two of CPU is decisive: the process was waiting. `time.process_time()` excludes sleeping and blocking by definition, so the gap *is* the waiting, and no optimisation of Python code can recover it. If instead CPU time were close to wall time, the call profile would be the right tool and the answer would be in it. ## Step two: attribute the wall time to phases A profile is not the only instrument. Wall-clock accounting — bracketing each phase with `time.perf_counter()` and accumulating the deltas into a dict — usually finds the sink in one run, is cheap enough to leave permanently enabled, and works in production where attaching a profiler does not: ```python from contextlib import contextmanager import time from collections import defaultdict wall = defaultdict(float) @contextmanager def phase(name): start = time.perf_counter() try: yield finally: wall[name] += time.perf_counter() - start ``` Count the phase entries as well as their seconds. On the route-optimisation job the four-person team owning it found the answer that way: the distance-matrix lookup was entered 900 times rather than the 30 they expected, because a broad `except Exception: pass` around it swallowed a configuration error and the surrounding loop quietly retried with a backoff sleep. Almost all forty minutes were sleeps and repeated waits. Nothing was hot because nothing was computing — and the swallowed exception meant nothing was logged either. ## Step three: sample on wall-clock, across threads Where phases are too coarse, switch measurement *style*. A sampling profiler periodically interrupts the program and records the current stack of every thread, then reports where samples landed. Its properties are the mirror image of the deterministic one: * Overhead is proportional to the sampling rate, not to the number of calls, so it stays low and does not distort call-heavy code. * Because a sample lands wherever the thread happens to be, a frame that is blocked on a wall-clock timer *accumulates samples*, which is precisely what makes waits visible. * Sampling every thread's stack — the mechanism is a periodic walk of `sys._current_frames()`, which returns a frame for each running thread — shows work the main-thread hook never saw. * The cost is statistical: rare calls may be missed, and exact call counts are unavailable. You get "where the time is", not "how many times this ran". Also decide *what* the sampler should sample on. A CPU-time profiler that only samples when the process is on-CPU will reproduce the original disappointment; for a waiting job you want wall-clock samples. ## Step four: check the remaining suspects * **Threads.** Profile them explicitly or use a sampler that covers all threads. * **Subprocesses.** Measure inside the child, or time the `wait()` in the parent to size the problem. * **C extensions.** A library call that releases the GIL for a long computation shows as one opaque frame; its cost appears in wall and CPU time but not in any Python-level breakdown. * **The machine.** Wall time includes CPU starvation from neighbours and from container quota throttling; a big wall-to-CPU gap can be scheduling, not I/O. ## The takeaway to say out loud Deterministic call profiling and wall-clock accounting answer different questions, and the first move on a slow job is deciding which question you have. Wall versus CPU time costs two lines and tells you which instrument to reach for; reaching for the call profiler first is how a team spends a week micro-optimising code that was never running.