vault

Profiling with cProfile

14 min read

Profiling with cProfile

cProfile is CPython’s built-in deterministic profiler: it records every Python function call, return, and exception as it happens, and times the intervals between those events, producing an exact count of how many times each function ran and how much time was spent inside it. The official documentation defines deterministic profiling as the discipline where “all function call, function return, and exception events are monitored, and precise timings are made for the intervals between these events” — explicitly contrasting it with statistical profiling, “which is not done by this module” (per the profile module docs). Two implementations ship in the standard library with an identical interface: the pure-Python profile module (easy to extend, high overhead) and the C-accelerated cProfile (built on the _lsprof extension, low enough overhead for real programs and the one you should reach for). The price of exactness is the observer effect: instrumenting every call inflates the measured cost of cheap, hot functions, so the absolute numbers a deterministic profiler reports are systematically skewed — the ratios between functions are what you trust. Where you cannot tolerate that overhead, the sibling technique is statistical sampling — see Sampling Profilers and py-spy.

Mental Model

Think of cProfile as a stopwatch that the interpreter clicks on and off at the boundary of every function. When control enters a function, the profiler records the current clock; when control leaves (by return or by exception unwinding), it reads the clock again and attributes the elapsed interval to that function. Because it sees every boundary, it can compute exact call counts and split the total time into the time spent inside the function’s own body versus the time spent down in everything it called.

flowchart TD
    subgraph Interp["CPython interpreter (ceval.c)"]
        EV["bytecode dispatch<br/>fetch / decode / execute"]
    end
    EV -->|"per-call events"| LS["_lsprof.c (C accelerator)<br/>via sys.monitoring, PROFILER_ID = 2<br/>events: PY_START, PY_RETURN,<br/>CALL, C_RETURN, C_RAISE"]
    LS -->|"per function:<br/>callcount, tt, it"| TREE["rotating call tree<br/>(ProfilerEntry +<br/>ProfilerSubEntry)"]
    TREE -->|"snapshot_stats()"| STATS["pstats.Stats<br/>ncalls / tottime / cumtime"]
    STATS --> OUT["print_stats() table<br/>or .pstats file"]
    OUT -.->|"convert / visualize"| VIZ["snakeviz · gprof2dot"]

    PUREPY["pure-Python profile module"] -.->|"uses sys.setprofile<br/>(the classic hook)"| EV

Figure: the deterministic profiling pipeline in CPython 3.14. The interpreter emits an event at every function boundary; the C accelerator _lsprof catches each event and updates per-function counters in a rotating call tree; pstats turns that tree into the familiar ncalls/tottime/cumtime table. The insight: in 3.14 the C profiler is driven by sys.monitoring (PEP 669), not the older sys.setprofile hook — only the pure-Python profile module still rides sys.setprofile. Every arrow into the interpreter is a per-call interruption: that is exactly where the observer-effect overhead comes from.

Why Deterministic Profiling Is Cheap Enough in Python

A deterministic profiler in a compiled language like C normally requires instrumented binaries — the compiler injects prologue/epilogue calls into every function — which is invasive and slow. The Python docs make the key observation that this is unnecessary in CPython: “since there is an interpreter active during execution, the presence of instrumented code is not required in order to do deterministic profiling. Python automatically provides a hook (optional callback) for each event” (per the profile docs). The interpreter is already a dispatch loop (see The CPython Evaluation Loop); adding a per-event callback is a matter of checking a flag in that loop rather than rewriting the program.

The docs go further with a subtle, important point: “the interpreted nature of Python tends to add so much overhead to execution, that deterministic profiling tends to only add small processing overhead in typical applications.” In other words, Python code is already slow enough per operation that the relative cost of the profiler’s bookkeeping is smaller than it would be against tight native code. This is why deterministic profiling is practical for Python in a way it would not be for C — and it is also the reason the observer effect, discussed below, distorts fast functions most: those are the ones whose own runtime is closest to the fixed per-call profiler cost.

The C Accelerator and How It Hooks In

cProfile is a thin Python wrapper (Lib/cProfile.py) around the C extension _lsprof (Modules/_lsprof.c). The wrapper’s Profile class subclasses _lsprof.Profiler; the heavy lifting — catching events and accumulating timings — happens in C, which is why cProfile is recommended over the pure-Python profile module for anything but trivial scripts.

The mechanism by which _lsprof receives events changed in a way the older literature gets wrong, so it is worth pinning precisely. Through Python 3.11, _lsprof registered its callback via the C function _PyEval_SetProfile — the C-level equivalent of [[sys.settrace and Tracing Hooks|sys.setprofile]]. As of Python 3.12, it no longer does. Issue gh-103533 moved cProfile/_lsprof onto the PEP 669 sys.monitoring API, and the v3.14.5 source confirms the new path: profiler_enable imports sys.monitoring, claims the predefined PROFILER_ID (tool id 2), and calls register_callback for the events PY_START, PY_RETURN, CALL, C_RETURN, and C_RAISE (per Modules/_lsprof.c at v3.14.5 and the sys.monitoring docs).

A concrete, verifiable consequence of this switch: while cProfile is running on 3.12+, sys.getprofile() returns None, because the profiler is no longer installed as the profile function. Issue gh-130377 reports exactly this — “Starting in 3.12 … _lsprof … no longer calls _PyEval_SetProfile,” so the old python -m cProfile -m whatever trick of reaching the profiler object through sys.getprofile() is broken. If you ever wonder why a tutorial’s sys.getprofile()-based introspection no longer works, this is why.

Why sys.monitoring instead of sys.setprofile

PEP 669’s whole point is low impact: instead of one callback that receives every event for every code object, each event type gets its own callback, events can be toggled per-event or even per-code-object, and a callback can return sys.monitoring.DISABLE to permanently switch off an event at a specific bytecode location (per PEP 669 and the docs). The PEP claims up to a 20× reduction in monitoring overhead versus the old API. For the full mechanism see sys.monitoring. The pure-Python profile module, by contrast, still installs a classic sys.setprofile callback — that is the right place to cross-reference sys.settrace and Tracing Hooks.

Internally, _lsprof stores one ProfilerEntry per profiled function with callcount (how many times it was called), recursivecallcount (recursive entries), tt (total time, including subcalls), it (inline/“own” time, excluding subcalls), and a recursionLevel. When subcall accounting is on, each entry hangs a rotating tree of ProfilerSubEntry objects keyed by caller, so the profiler can later answer “who called this function and how much time came in through each caller” (the data behind print_callers/print_callees).

The Statistics: ncalls, tottime, cumtime, percall

When you print a profile you get one row per function with these columns (definitions per the profile docs):

  • ncalls — the number of calls. When it shows as total/primitive (e.g. 214/207), the second number is the count of non-recursive (primitive) calls; the difference is recursion.
  • tottime — total time spent in this function alone, excluding time in functions it called. This is _lsprof’s “inline time” (it). This column finds the function that is itself slow.
  • percall (first) — tottime / ncalls: the average cost of one call’s own body.
  • cumtime — cumulative time spent in this function and all of its subfunctions, “accurate even for recursive functions.” This column finds the function under which most time accumulates (often high in the call tree).
  • percall (second) — cumtime / primitive calls.

The pair tottime vs cumtime is the single most useful distinction: a function with huge cumtime but tiny tottime is a router — it is slow only because of what it calls; a function with huge tottime is where the CPU actually burns. Optimize the latter; restructure around the former.

Configuration and Code

The simplest entry points

import cProfile
import re
 
# 1. Profile a statement given as a string, print to stdout:
cProfile.run('re.compile("foo|bar")')
 
# 2. Profile a statement and DUMP the raw stats to a file for later analysis:
cProfile.run('re.compile("foo|bar")', filename='restats')
 
# 3. Profile with explicit globals/locals (e.g. to reach names in your module):
cProfile.runctx('func(arg)', globals(), locals())

Line by line: cProfile.run(command, filename=None, sort=-1) internally does exec(command, __main__.__dict__, __main__.__dict__) with a fresh Profile wrapped around it. Passing filename calls dump_stats (a marshal dump) instead of printing, so you can re-load it. runctx is the same but lets you supply the globals/locals dicts explicitly — necessary when the code references names that are not in __main__.

The Profile object as a context manager

cProfile gained context-manager support in Python 3.8, which is the cleanest way to profile a region of live code rather than a string:

import cProfile, pstats, io
from pstats import SortKey
 
with cProfile.Profile() as pr:          # __enter__ calls enable()
    do_some_work()                      # everything here is profiled
# __exit__ calls disable() automatically
 
s = io.StringIO()
ps = pstats.Stats(pr, stream=s).sort_stats(SortKey.CUMULATIVE)
ps.print_stats()
print(s.getvalue())

__enter__ calls enable() (which claims PROFILER_ID and registers the monitoring callbacks); __exit__ calls disable() (which unregisters them). The manual form pr.enable() / pr.disable() does the same without the with block. There is also runcall(func, *args, **kwargs) to profile exactly one call — but note the docs’ caveat: “profiling will only work if the called command/function actually returns”; a sys.exit() inside it prints nothing.

The Profile constructor is Profile(timer=None, timeunit=0.0, subcalls=True, builtins=True). The timer lets you substitute a custom clock (e.g. time.process_time to measure CPU rather than wall time); timeunit is the multiplier when that timer returns integer ticks (e.g. .001 for milliseconds). subcalls and builtins toggle whether per-caller subentries and C/built-in calls are tracked.

pstats.Stats: sorting, trimming, reading

import pstats
from pstats import SortKey
 
p = pstats.Stats('restats')             # load a dumped profile
p.strip_dirs()                          # drop leading path components from filenames
p.sort_stats(SortKey.CUMULATIVE)        # sort by cumulative time
p.print_stats(10)                       # print only the top 10 rows
 
# regex + fraction restrictions, and reverse the call direction:
p.print_stats(.25, 'json')              # first 25% of rows, then keep those matching 'json'
p.print_callers('parse')                # who called functions matching 'parse'
p.print_callees('parse')                # what those functions called

strip_dirs() removes leading path information so tottime-equal rows from the same file collapse and the table is readable; it is destructive (the stripped info is gone). sort_stats(*keys) accepts the SortKey enum (added 3.7) — CALLS, CUMULATIVE, FILENAME, NAME, TIME (== tottime), NFL, STDNAME — or the legacy numeric/string forms (-1=stdname, 0=calls, 1=time, 2=cumulative); multiple keys break ties left to right. print_stats(*restrictions) accepts an integer (top-N rows), a float in 0.0–1.0 (that fraction of rows), and/or a regex string (keep matching rows), applied in order. add(*files) merges several dumped profiles; get_stats_profile() (added 3.9) returns a structured StatsProfile object if you want to consume the numbers programmatically rather than print them.

Failure Modes and the Observer Effect

The dominant pitfall of deterministic profiling is the observer effect: the act of measuring perturbs what is measured. Two distinct sources, both documented under the profiler’s “Limitations”:

  1. Clock granularity. “The underlying ‘clock’ is only ticking at a rate (typically) of about .001 seconds. Hence no measurements will be more accurate than the underlying clock” (per the docs). Functions faster than a clock tick are timed as zero or one tick — noise.
  2. Dispatch lag. “It ‘takes a while’ from when an event is dispatched until the profiler’s call to get the time actually gets the state of the clock,” plus a symmetric lag on exit. This fixed per-event cost is small, “but it can accumulate and become very significant” for “functions that are called many times, or call many functions.” The pure-Python profile module offers calibrate() to estimate and subtract this bias; cProfile does not need it as much because its overhead is far smaller.

The practical upshot: a tight function called ten million times will report a tottime dominated by profiler bookkeeping, not by its own work. Its absolute number is inflated and meaningless in isolation. What survives the distortion is the relative ranking — the function that is #1 by tottime is very likely your real hot spot even if its absolute time is off. Read ratios, not absolutes, and confirm any micro-optimization with timeit or a sampling profiler outside the observer’s frame.

Resolved (2026-06-01)

Resolved by reading Python/instrumentation.c at the v3.14.5 tag. Instrumenting an instruction does de-specialize that instruction: the per-instruction path takes int deopt = _PyOpcode_Deopt[opcode] (mapping a specialized opcode back to its base form), stores INSTRUMENTED_OPCODES[deopt] in its place, and resets the adaptive counter to adaptive_counter_warmup() (lines 773–781) — so the optimized form is replaced and must re-warm to re-specialize once de-instrumented. But the scope is event-specific, which is the key point for cProfile. The EVENT_FOR_OPCODE table (lines 77–84) maps the CALL event only to the call-family opcodes (CALL, CALL_KW, CALL_FUNCTION_EX, LOAD_SUPER_ATTR), and PY_START is delivered via RESUME. Arbitrary opcodes such as LOAD_ATTR_INSTANCE_VALUE are only touched by the LINE and per-INSTRUCTION events, which cProfile does not use. So enabling cProfile’s PY_START/CALL events de-specializes call sites and resumes, not attribute loads or other hot bytecodes — the example opcode named above (LOAD_ATTR_INSTANCE_VALUE) is in fact the case that stays specialized. The observer-effect conclusion (per-call bookkeeping inflates cheap/hot functions; trust ratios) is unaffected. Source: instrumentation.c@v3.14.5.

Visualizing the Output

The raw pstats table is hard to navigate for large programs; the ecosystem converts the dumped profile into call graphs and flame-graph-like views:

  • SnakeViz — a browser-based viewer for cProfile output; it renders an interactive icicle (default) or sunburst diagram where a function’s time is its element’s width/arc, plus a sortable pstats-style table beneath it (per the SnakeViz docs). Run snakeviz restats on a dumped profile.
  • gprof2dot — not a profiler but a converter: python -m gprof2dot -f pstats restats -o out.dot turns the profile into a Graphviz .dot call graph, which dot -Tpng renders to an image. It reads many profiler formats (cProfile, perf, callgrind, VTune), so the same graph style works across tools.

These are visualizations of deterministic data — they inherit the observer-effect distortion of the underlying cProfile run. For low-overhead, production-safe profiling of a running process, the answer is a sampling profiler, not a prettier view of cProfile.

Alternatives and When to Choose Them

  • Pure-Python profile — same API, much higher overhead, but written in Python and therefore easy to subclass and extend (custom timers, custom accounting). Use it only when you need to hack on the profiler itself, or on a platform where _lsprof is unavailable.
  • timeit — for micro-benchmarks of a single small snippet, timeit avoids the per-call profiler overhead entirely and is the right tool when you care about a 1–2% difference.
  • Sampling profilers — when overhead must be near-zero, when you must attach to an already-running (or production) process without restarting it, or when the program is long-lived. Sampling gives a statistical time distribution rather than exact counts, and crucially does not suffer the per-call observer effect on hot code. As of CPython 3.15 the standard library ships its own sampling profiler (profiling.sampling, “Tachyon”); in 3.14 the stdlib has only the deterministic profilers covered here, and sampling is the domain of external tools like py-spy (see the sibling note).

Production Notes

cProfile is built for offline and development profiling: run a representative workload under the profiler, dump the stats, analyze. It is not something you leave enabled in production — the per-call overhead, plus the fact that it claims PROFILER_ID and can interfere with other sys.monitoring-based tools (only one tool may own each id), make it unsuitable for always-on observability. For “what is this live service spending time on right now,” reach for sampling (see Sampling Profilers and py-spy and, on 3.15+, the stdlib profiling.sampling). A common, effective workflow is: sample in production to find which request path or subsystem is hot, then reproduce that path locally under cProfile to get exact per-function counts and the precise call tree.

See Also

Graph View

Backlinks