A cProfile run on an invoice-PDF renderer blames a tiny helper called millions of times; how far do you trust that number?

### What "deterministic" costs `cProfile` is a deterministic profiler: it is notified on **every** call and **every** return, plus every call into a built-in, and it does bookkeeping at each of those events — reading a clock, finding or creating the entry for that code object, updating counters, and maintaining its own view of the stack. The C implementation makes that bookkeeping small, but it is not free, and crucially it is a **fixed cost per event**, not a percentage of the work. That is the whole distortion in one sentence: the profiler's error is proportional to your **call count**, while the thing you are trying to measure is proportional to your **work**. A function that runs for 50 milliseconds per call absorbs the overhead invisibly. A function that runs for a microsecond per call and is called two million times can easily spend more time being profiled than being executed — and, because the overhead is charged at the call boundary, it lands on exactly that function's row and on its callers' `cumtime`. ### The invoice-PDF scenario Take a renderer with a 45-second cold start. A profile blames a one-line helper that encodes a single character, called several million times because the text layer falls back to a per-character encoding path whenever a glyph is missing from the chosen font — an encoding mismatch between the document's text and the font's coverage. The report says that helper owns most of the `tottime`. Three readings are possible, and only measurement separates them: 1. **The helper really is the cost.** Millions of Python-level calls are genuinely expensive, and the fix is structural: encode whole strings instead of characters, or resolve the font fallback once. 2. **The helper is cheap and the profiler is loud.** The real cost is elsewhere, and the helper only floated to the top because the per-event overhead multiplied by its call count outweighs everyone else's honest time. 3. **Both.** The commonest outcome. The discriminator is simple: run the same work **without** the profiler and compare totals. If an unprofiled run takes 45 seconds and the profiled run takes 45 seconds, the profile is close to truthful. If the profiled run takes three or four times as long, a large slice of what you are reading is instrumentation, and the per-call seconds are fiction — though the **ranking** usually survives, because the overhead scales with call count and call count is itself a real property of the program. ```python import cProfile, time def encode_glyph(ch): return ch.encode("latin-1", "replace") def render(n): return sum(len(encode_glyph(c)) for c in "invoice" * n) t0 = time.perf_counter() render(200000) plain = time.perf_counter() - t0 prof = cProfile.Profile() t0 = time.perf_counter() prof.runcall(render, 200000) profiled = time.perf_counter() - t0 print(f"plain {plain:.3f}s profiled {profiled:.3f}s ratio {profiled / plain:.1f}x") ``` ### What to do about it **Profile a coarser unit.** If the inner loop is call-heavy, move the profiled boundary outward — profile a whole page render rather than a glyph — so the number of instrumented events drops by orders of magnitude and the fixed cost stops dominating. You lose fine attribution and gain trustworthy stage-level totals, which is usually the decision you actually need first. **Read `ncalls` alongside the times.** A row with an enormous call count and a tiny per-call cost is the profiler's blind spot *and* frequently a real design problem: a Python-level call is expensive regardless of who is measuring, so "called two million times" is a finding in its own right, even when the seconds beside it are inflated. **Prefer ratios to seconds.** Compare a before-and-after profile captured the same way, under the same instrumentation. The overhead is roughly constant per event, so it largely cancels and the delta means something even when the absolute numbers do not. **Confirm the win outside the profiler.** Any change justified by a profile must be re-measured without one. It is entirely possible to "optimise" away calls that only mattered because they were instrumented, and to ship a change that is neutral or worse in production. **Know when to switch tools.** A deterministic profiler pays per event; a sampling profiler pays per sample interval, so its cost is bounded by frequency rather than by your program's shape. That makes sampling the right instrument when per-call overhead is the thing corrupting the measurement, or when the process must keep serving while you look at it. The failure to avoid is treating the report as a stopwatch. `cProfile` is an attribution tool. It is excellent at telling you which region of a program is responsible for the time and roughly how the cost is distributed, and it is unreliable as a source of absolute per-call latencies in exactly the regime — many tiny calls — where people most want to believe it.