import cProfile, pstats
profiler = cProfile.Profile()
profiler.enable()
do_the_work()
profiler.disable()
pstats.Stats(profiler).sort_stats("tottime").print_stats(15)Six lines, and they are the difference between optimising the thing that is slow and optimising the thing you assumed was slow. Everybody’s intuition about where their program spends time is wrong; it is wrong in a specific way, which is that people guess the function that is conceptually complicated rather than the function that is called a million times.
The two columns
| column | meaning |
|---|---|
ncalls |
how many times it was called |
tottime |
time in this function’s own body, excluding sub-calls |
cumtime |
time in this function including everything it called |
percall |
the previous column divided by ncalls |
Sort by tottime to find a function that is itself slow — the one whose body you would rewrite. Sort by cumulative to find the costliest subtree — the call whose whole branch you might delete or cache.
The docs note that cumtime is “accurate even for recursive functions”, which is not obvious: a naive “sum the time between entry and exit” would count a recursive function’s time once per level. pstats handles it.
The mistake
Sorting by cumulative and reading the top row.
The top of a cumulative sort is always main, or your entry point, or a thin dispatcher — anything near the root of the call tree has a cumulative time approaching the whole program’s. Below that sit the wrappers, decorators, context managers and framework layers, each with a cumulative time close to the total and a tottime of essentially zero. None of them is where the time goes. All of them look like it.
A do-nothing wrapper that calls one expensive function has the expensive function’s cumtime and a tottime of about a microsecond. Sort by cumulative and it ranks alongside the thing it wraps. Sort by tottime and it correctly disappears.
💡A profile shows parse_row with ncalls 2,000,000, tottime 4.1 s, and percall 0.000002. Nothing in its four-line body looks expensive. What are you actually looking at, and what are the two available fixes?
click to reveal
You are looking at a function whose per-call cost is genuinely tiny and whose call count is the problem. Two microseconds is roughly the floor for a Python function call plus a few operations; there is no inefficiency inside it to remove. Rewriting the body might get you to 3.5 s.
Fix one: call it fewer times. Move the loop out — process a batch per call instead of a row per call, or push the whole loop into a vectorised operation. This is the same principle as article 11.24’s “move the loop, not the loop body”, and it is usually where the order of magnitude lives.
Fix two: make the call itself cheaper by not making it — inline the body into the caller, or make it a comprehension. Ugly, and worth it only when the call count is irreducible.
And a caution specific to this shape: tottime for a function called two million times includes two million units of profiler overhead. cProfile instruments every call, so high-ncalls functions are systematically over-represented in a profile relative to their real cost. Confirm the improvement with timeit on the unprofiled code before believing the size of the win.
The caveat that invalidates a genre of blog post
Straight from the documentation: “The profiler modules are designed to provide an execution profile for a given program, not for benchmarking purposes (for that, there is timeit for reasonably accurate results)… the profilers introduce overhead for Python code, but not for C-level functions, and so the C code would seem faster than any Python one.”
Two consequences.
Never quote profiler numbers as benchmark results. A profile tells you the shape of where time goes. Absolute numbers under instrumentation are not the numbers you deploy.
A profile systematically overstates the case for rewriting Python in C. Your Python function is instrumented; the C function it competes with is not. So a profile-driven “we should port this to Cython” argument is starting from a biased comparison — which is exactly the trap article 11.24 opens with.
The 3.15 rename, and how to import version-tolerantly
PEP 799 restructures the profiling surface. The deterministic profiler moves to profiling.tracing; cProfile remains as a permanent alias, so existing code keeps working indefinitely. The old pure-Python profile module is deprecated for removal in 3.17.
For code that must run on 3.12 through 3.15:
import sys
if sys.version_info >= (3, 15):
from profiling.tracing import Profile
else:
from cProfile import Profile
A version-gated import rather than try/except ImportError is deliberate: mypy understands sys.version_info comparisons and prunes the unreachable branch under your configured python_version, so you get a clean check on the branch that will actually run. A try/except around an import is opaque to the checker and it will complain about the module it cannot find.
💡pstats.Stats.stats is not in typeshed, so mypy --strict rejects reading it. Profile.getstats() is typed. What does that tell you about which API to build on?
click to reveal
That the typed one is the supported one, and that this is useful information rather than an inconvenience.
Stats.stats is a raw dict of tuples whose layout is a documented-by-convention implementation detail — index 2 is tottime, index 3 is cumtime, and nothing tells you that except folklore. getstats() returns profiler_entry objects with named fields: callcount, inlinetime (which is tottime), totaltime (which is cumtime), code. The names are self-documenting and typeshed models them.
The general habit worth forming: when --strict rejects an attribute on a stdlib object, the first question is not “how do I silence this” but “is there a supported spelling I am reaching past?”. Reasonably often there is, and typeshed’s coverage is a decent proxy for which parts of an API the ecosystem considers stable. When there genuinely is no alternative, a narrow # type: ignore[attr-defined] with a comment explaining why is the honest answer — but reaching for it first is how you end up depending on a tuple index that changes.
Where this sits in a workflow
Profile to find where. Then timeit (article 11.17) on the candidate, unprofiled, to find out whether your change helped. Then profile again to confirm the shape moved. Skipping the middle step is how people ship changes that were faster under the profiler and slower in production.