# cProfile Slowed It 2.9x and Moved the Ranking by One Point > cProfile adds a flat 25 to 30 ns to every call it observes. That inflates a 47 ns function's reported time by 1.57x and a one-microsecond function's by nothing at all. - Published: 2026-10-25 - Category: tooling - Tags: profiling, benchmarking - Sources: https://github.com/CognatePress/erperiments.pydepth.com/blob/main/evalloop/profileoverhead.py - Source: https://pydepth.com/blog/cprofile-error/ - Language: en-US - Author: Elliot Sayer --- The warning attached to `cProfile` is that its overhead distorts what it reports, and the documentation says so in the profiler's own words: "functions that are called many times, or call many functions, will typically accumulate this error … it _can_ accumulate and become very significant". What neither the warning nor the documentation gives is the size of it, so the practical question — is this profile pointing at a real hotspot or at its own overhead — has no answer. It has a small one. The profiler adds 25 to 30 nanoseconds to the time it reports for a call, the constant does not change with the size of the function, and above about a microsecond a call there is nothing left to correct. That is the same shape as the per-call arithmetic in [what an await actually costs](/blog/the-real-cost-of-an-async-call/): a fixed overhead only matters against the size of the thing it is added to. ## What the profiler adds A leaf function whose body grows from nothing to about nine microseconds, called 500,000 times, timed with no profiler attached and then under one: ``` $ python3 experiments/evalloop/profileoverhead.py ~/.pyenv/versions/3.15.0rc1/bin/python3 python 3.15.0rc1 on darwin 500,000 calls a row, best of 5 what the profiler adds to a call, by how much the callee does body loops true reported added inflation 0 52.3 ns 84.7 ns 32.4 ns 1.62x 1 58.0 ns 87.1 ns 29.1 ns 1.50x 3 77.7 ns 111.0 ns 33.2 ns 1.43x 10 148.2 ns 172.3 ns 24.1 ns 1.16x 30 330.4 ns 343.8 ns 13.5 ns 1.04x 100 979.5 ns 992.2 ns 12.7 ns 1.01x 300 2736.5 ns 2715.0 ns -21.4 ns 0.99x 1000 8851.0 ns 8977.6 ns 126.6 ns 1.01x what it costs to run, by how dense the calls are workload unprofiled profiled factor 500,000 calls of an empty body 25.5 ms 74.2 ms 2.9x 400,100 calls, real work in each 290.1 ms 333.5 ms 1.1x the ranking: same total work, two call granularities function calls wall clock share reported share unit 400,000 115.2 ms 39% 124.1 ms 41% chunk 100 177.4 ms 61% 180.6 ms 59% ``` The `added` column is the finding. It sits between 13 and 33 nanoseconds across a range of callee sizes spanning a factor of 170, and it does not trend with the body. On 3.13.2 the same column runs 20 to 27 ns. That is a fixed cost per event, which is exactly what the documentation describes: the lag between the event and the clock read, twice per call. Because the cost is fixed and the body is not, the `inflation` column is just the ratio between them. At a 52 ns callee the profiler's 32 ns is 62% on top. At a 980 ns callee the same 13 ns is 1%. Nothing about the profiler changed between those two rows. ## The ranking that did not invert The other half of the folklore is that this distortion reorders the profile — that a small function called a great many times climbs above a large one that is genuinely hotter. That is a testable claim and it did not reproduce. The bottom block splits identical total work two ways: 400,000 calls of a 25-iteration loop, and 100 calls of a 100,000-iteration loop. The clock says 39% and 61%. The profile says 41% and 59%. On 3.13.2 both readings are 40% and 60%. The reason is arithmetic rather than luck. 400,000 calls at 27 ns is 10.8 ms of added attribution, against a true 115 ms, which is 9%. To move a ranking, the added time has to be comparable to the true time, and that requires a function whose body is in the tens of nanoseconds *and* which accounts for a large share of the program. A function like that exists — the top row of the table is one — but it is not the ordinary case the warning is usually applied to. ## The slowdown is a different number The middle block is the one that deserves the alarm. The same profiler, on the same machine, made one workload 2.9x slower and another 1.1x slower. The difference between them is call density, not work. That is why a quoted overhead figure for `cProfile` is meaningless without the workload. It also means the wall-clock duration of anything measured under a profiler is not a duration: profile a request handler that makes half a million small calls and it will take three times as long, and none of that is the handler's fault. The two numbers pull in opposite directions, which is what makes the tool confusing. The clock under a profiler is badly wrong. The shares in the report are close to right. ## Reading a profile with this in hand Take `tottime`, take `ncalls`, and subtract `ncalls × 27 ns`. If what is left is most of what was there, the function is genuinely hot. If the subtraction removes most of it, the profiler was measuring itself. For a function at a microsecond a call or more, skip the arithmetic — the correction is under 1% and the reported number is the number. Where the correction does bite, the fix is usually not a faster function but fewer calls: at 27 ns of pure measurement cost per call, a profile that spends its time in a leaf called millions of times is telling you about call count, and call count is the thing to change. ## Where to stop One machine, macOS on Apple silicon, CPython 3.13.2 and 3.15.0rc1. Ground truth is wall time with no profiler attached, taken in the same process immediately before each profiled run. The sampling profiler that 3.15 ships would be the better ground truth and it is not used here. On macOS `profiling.sampling` refuses to start, with a permission error: it reads the target process's memory even in the mode where it launches that process itself, and that needs root. The `added` column is noisy at the large end — 127 ns on the nine-microsecond row is 1.4% of the measurement, not a real trend — so the constant is established by the rows below 350 ns, where it is large enough to see. Nothing here says how the same profiler behaves on a workload that is mostly C extension calls, which are dispatched differently and were not measured. And a corrected profile is still a profile of one shape. The reads a hot loop performs get specialised to whatever the loop keeps seeing, and [that specialisation is a property of the build as much as of the code](/blog/slots-did-not-get-slower/).