cProfile and pstats

### The two clocks in every profiling row `cProfile` is CPython's **deterministic** profiler: it registers a callback on the interpreter's profiling hook — the same hook `sys.setprofile` exposes — and records an event on **every** function call and every return, including calls into built-in and C functions. Because it sees each event, it can attribute time exactly, and that attribution is reported through two different clocks. * **`tottime`** — the time spent executing the bytecode of *this* function's own body, with the time of everything it called subtracted out. It is sometimes called *self time* or *internal time*. * **`cumtime`** — the *cumulative* time from entering the function to leaving it, including every descendant call. It is sometimes called *inclusive time*. For a leaf function that calls nothing, the two are equal. For a thin wrapper that immediately delegates, `tottime` is near zero while `cumtime` is the whole subtree. Summing `tottime` over every row approximates the program's total run time, because each unit of time is charged to exactly one frame; summing `cumtime` does not, because nested time is counted again at every level of the stack. ### Reading a report ```python import cProfile, pstats, io def encode_glyph(ch): return ch.encode("latin-1", "replace") def encode_line(line): return b"".join(encode_glyph(c) for c in line) def render(pages): return sum(len(encode_line(f"invoice page {p}")) for p in range(pages)) prof = cProfile.Profile() prof.enable() render(3000) prof.disable() buf = io.StringIO() pstats.Stats(prof, stream=buf).strip_dirs().sort_stats("tottime").print_stats(5) print(buf.getvalue()) ``` The header line names the ordering ("Ordered by: internal time"), and each row carries six fields: `ncalls`, `tottime`, a `percall` that is `tottime / ncalls`, `cumtime`, a second `percall` that is `cumtime` divided by the number of **primitive** (non-recursive) calls, and `filename:lineno(function)`. `ncalls` is printed as a single number when no recursion is involved and as `total/primitive` when it is — `120/20` means the function was entered 120 times, 20 of which were top-level entries rather than re-entries from itself. That distinction is exactly why `cumtime` stays honest for recursive functions: the cumulative clock runs for the **outermost** active frame only, so a recursive descent does not add its own time again at every level, and `cumtime` can never exceed the wall time of the run. ### Which one you sort by is a question about what you are looking for `Stats.sort_stats("tottime")` answers *"where is the CPU actually burning?"* — the row at the top is the code whose own bytecode costs the most, and it is the code worth rewriting, caching or vectorising. This is the view you want once you have narrowed the problem to a stage. `Stats.sort_stats("cumtime")` answers *"which call path costs the most?"* — the top rows are usually your entry point and the frames just beneath it, and reading down that list tells you which branch of the program owns the time. This is the view you want first, when you have no idea where the time goes: it walks you from `main` down toward the hot region. The classic diagnostic mistake is to look only at `tottime` and conclude "there is no hot spot" when the top row is 4% of the run. That reading is often correct in the narrow sense and useless in practice: the cost is spread across many small functions, and only `cumtime` — plus `ncalls` — shows that one stage is calling something two million times. The inverse mistake is optimising the top `cumtime` row, which is frequently `main` or a loop driver whose own body does nothing. ### From a hot row to a cause Once a row is suspicious, `pstats.Stats` will attribute it. `print_callers("encode_glyph")` lists the functions that called it and how much of its time came from each; `print_callees` goes the other way. Both accept a restricting regex or a row count, exactly as `print_stats` does. A shared helper that looks expensive in aggregate usually turns out to be driven by one caller, and `print_callers` is how you find that caller instead of guessing. ### What the numbers do not tell you Time is charged to the frame that is running, so time blocked on I/O inside a call still shows up as that call's `cumtime` — a profile does not distinguish "computing" from "waiting" on its own. Time inside a single C call is opaque: the call appears as one `{built-in method ...}` row with a real cost and no internal breakdown. And every number carries the profiler's own per-event overhead, which falls hardest on functions with enormous `ncalls`. The practical rule is to trust the **ranking** much more than the absolute seconds.