Python Observability

Using cProfile and pstats in Production

Deterministic profiling has one capability nothing else offers — exact call counts — and one property that disqualifies it from live production: its cost scales with the number of calls, and Python services make a great many. This page covers getting the counts without taking a service down, reading the output correctly, and the specific situations where this tool is the right one. It is a task article under CPU profiling Python services, part of the Python profiling and performance observability section.

Why one scales with the workload and the other does not Two overhead curves are plotted against the number of function calls per second a program makes. The sampling profiler's overhead is a flat line at roughly one to two percent, because its cost is a fixed number of stack reads per second regardless of what happens between them. The deterministic profiler's overhead rises steeply and without bound, because it executes a hook on every call and every return; at a hundred thousand calls per second the runtime is roughly doubled, and at a million it is several times worse. A marker shows where a typical Python web request sits, which is well into the steep region, making the point that a framework-heavy service is precisely the workload this profiler handles worst. profiler overhead against call volume function calls per second cost sampling — flat, 1–2%, whatever the program does deterministic — a hook on every call and return a typical framework request sits here — tens of thousands the workload it handles worst is exactly the one people want to profile
The overhead is not a fixed percentage to budget for. It is a multiplier that grows with the thing you are trying to measure.

Prerequisites

cProfile and pstats are in the standard library. The only dependency worth adding is a viewer that renders the output as a graph rather than a table.

pip install "snakeviz>=2.2.0,<3.0.0" \
            "gprof2dot>=2024.6.6,<2025.0.0"

Implementation

Step 1 — Reproduce rather than observe. The correct venue for this tool is a test, a benchmark or an instance taken out of rotation. A code path that can be exercised by a script is one that can be profiled deterministically with no production risk at all, and most performance questions of the "how many times is this called" kind can be reproduced in a few lines.

# reproduce.py — the narrow path, exercised deliberately
import cProfile
import pstats

from app.serializers import OrderSerializer
from app.testdata import build_orders

orders = build_orders(500)

profiler = cProfile.Profile()
profiler.enable()
for order in orders:
    OrderSerializer(order).data
profiler.disable()

stats = pstats.Stats(profiler)
stats.dump_stats("/tmp/serializer.prof")       # keep it for comparison
stats.sort_stats("cumulative").print_stats(12)

Expected Output: the call counts that identify the problem, which no sampling profile would have shown.

         3184920 function calls (2991204 primitive calls) in 4.118 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      500    0.004    0.000    4.118    0.008 serializers.py:88(data)
   500/500  0.031    0.000    4.101    0.008 serializers.py:104(to_representation)
   184000    0.212    0.000    3.402    0.000 fields.py:212(get_attribute)
   184000    0.664    0.000    3.190    0.000 dateutil/parser.py:640(parse)
   184000    1.918    0.000    1.918    0.000 dateutil/parser.py:401(_parse)

One hundred and eighty-four thousand date parses for five hundred orders is three hundred and sixty-eight per order, which is the finding. No sampling profile would have expressed it that way.

Step 2 — Profile the narrowest scope that contains the problem. Enabling the profiler around a whole process produces output dominated by startup and framework machinery. A context manager around one request handler, or one function, keeps the output readable and the overhead bounded.

import contextlib, cProfile, pstats

@contextlib.contextmanager
def profiled(path: str, top: int = 15):
    pr = cProfile.Profile()
    pr.enable()
    try:
        yield pr
    finally:
        pr.disable()
        st = pstats.Stats(pr)
        st.dump_stats(path)
        st.sort_stats("tottime").print_stats(top)

Step 3 — Sort by cumulative first, then by total. Cumulative time includes everything a function called, so sorting by it finds the expensive path — which handler, which serialiser, which query builder. Total time excludes callees, so sorting by it finds the function actually burning the cycles. Reading both, in that order, goes from "this request is slow" to "this specific function is doing the work" in two commands.

Step 4 — Read the call count before the duration. This is the habit that makes the tool worth using. A function taking two hundred milliseconds across four thousand calls is fine; the same two hundred milliseconds across four calls is a function to look at. More often, the count itself is absurd — the three hundred and sixty-eight parses per order above — and no amount of making the function faster would have been the right fix.

Step 5 — Keep the stats file. A binary profile on disk can be loaded later, merged with others, and compared against a run from before a change. Printing to a terminal and closing it loses the only artefact that would have made the next investigation a comparison.

import pstats
before = pstats.Stats("/tmp/serializer-before.prof")
after = pstats.Stats("/tmp/serializer-after.prof")
for label, st in (("before", before), ("after", after)):
    st.sort_stats("tottime")
    print(f"--- {label} ---")
    st.print_stats(5)

Step 6 — Render it as a graph when the table stops helping. A call graph shows where the volume comes from, which a flat table does not. This matters when the expensive function has many callers and the question is which one is responsible.

python -m gprof2dot -f pstats /tmp/serializer.prof | dot -Tsvg -o /tmp/calls.svg
The count belongs to the caller A call graph shows a date parsing function at the bottom, reached from three call sites above it. The first caller invokes it twice per request and accounts for a negligible share. The second invokes it four times. The third, a field serialiser inside a loop over line items, invokes it three hundred and sixty-two times per request and accounts for almost all of the total. The expensive function itself is unremarkable and cannot be improved much; the fix is in the third caller, which parses the same value repeatedly inside a loop where it could be parsed once. The diagram makes the point that a flat profile table names the function, while the call graph names the caller responsible, and only the second is actionable. one expensive function, three callers header fields 2 calls audit stamps 4 calls line item serialiser, inside a loop 362 calls per request dateutil.parse unremarkable, and not the problem the table names the function · the graph names the caller · only one of those is a change you can make
Optimising the function at the bottom would have been a day's work for nothing. The fix is one line in the caller with the absurd count.

Where this tool genuinely belongs

Deterministic profiling has a reputation as the amateur option, which is unfair. There are four situations where it is straightforwardly the right tool and a sampling profiler is not.

Counting calls. The defining capability. Any question of the form "how many times does this actually happen" — database round trips, serialiser invocations, cache lookups, template renders — is answered exactly here and approximately nowhere else.

Short-lived work. A function that runs for eighty milliseconds cannot be sampled usefully at a hundred hertz: eight samples is not a distribution. A deterministic profile of the same eighty milliseconds is complete.

Benchmarks and tests. In a test suite the overhead does not matter, and the exactness means a regression check can assert on call counts. A test that fails when a code path starts issuing twice as many queries is a genuinely useful test, and it is built on the same mechanism.

Local development. Profiling a request on a developer machine with no traffic and no risk is the cheapest performance work available, and the deterministic profile is more informative there than a sampled one.

What it is not for is a live service under load. The overhead is not a percentage to accept but a multiplier that grows with call volume, and applying it to a busy process can itself cause the incident. The rule that keeps this straight: sampling answers where the time goes in production, deterministic answers why, somewhere it is safe to ask.

Reading the numbers without being misled

Three properties of the output regularly mislead people who are reading it for the first time, and all three are worth knowing before drawing a conclusion.

The profiler's own overhead is inside the numbers. Every call is charged the cost of the hook, so a function called two hundred thousand times carries two hundred thousand hook executions in its measured time. This inflates cheap, frequently called functions relative to expensive, rarely called ones. The ranking by call count is unaffected and reliable; the ranking by time is distorted in a direction that exaggerates exactly the functions the tool is best at finding. Treat the durations as comparative within one profile, not as absolute measurements of the unprofiled program.

Recursive calls are reported as a pair. A count displayed as five hundred over five hundred means total calls over primitive calls, the second excluding recursion. A large gap between the two indicates a recursive structure, which changes how the cumulative time should be read, because a recursive function's cumulative time includes itself.

Time spent waiting appears as time spent in the call. The profiler measures wall-clock duration between a call and its return, so a database call that waited two hundred milliseconds is recorded as two hundred milliseconds inside that function. That is correct and it is not CPU time, so a profile of a code path that does input and output will be dominated by frames that consume no processor at all. Knowing which frames are waiting requires knowing what the code does, which is one more reason this tool suits a narrow reproduction rather than an unfamiliar service.

Sorting pstats output A table of pstats sort keys and what each reveals. Sorting by tottime lists functions by time spent in their own code, excluding callees, which finds hot inner loops. Sorting by cumtime lists functions by time including everything they called, which finds the expensive entry points. Sorting by ncalls lists the most frequently called functions, which finds unexpected call volume such as a function called once per row. Sorting by percall on tottime finds functions that are slow each time they run. The note says tottime and cumtime together separate where the time is spent from who caused it. sort by lists by finds tottime own time, excluding callees hot inner loops cumtime time including callees expensive entry points ncalls number of calls unexpected call volume percall (tottime) own time per call slow-every-time functions tottime says where the time is spent; cumtime says who caused it
The same profile answers different questions depending on the sort. Reading only cumtime hides the hot loop.

Configuration options

Setting Value Why
Venue test, benchmark, or drained instance overhead is a multiplier, not a percentage
Scope one function or one request keeps output readable and cost bounded
First sort cumulative finds the expensive path
Second sort tottime finds the function doing the work
Output dump_stats to a file enables comparison later
Visualisation call graph attributes the count to a caller
Async services prefer a task-aware profiler attribution through the loop is poor

Verification

Check that the profile describes what you think it does, by confirming the call count against an independent counter.

# does the profile's count agree with a direct measurement?
import pstats
stats = pstats.Stats("/tmp/serializer.prof")
for (file, line, func), (ncalls, *_rest) in stats.stats.items():
    if func == "parse":
        print(f"{file}:{line} {func} called {ncalls} times")

Expected Output: a count that matches what an instrumented counter reports for the same workload.

/usr/lib/python3.12/site-packages/dateutil/parser.py:640 parse called 184000 times

A mismatch usually means the profiler was enabled for a different scope than the counter, which is worth resolving before drawing conclusions from either.

Common mistakes

Running it against live traffic. Error signature: latency multiplying while the profiler is enabled, and an incident caused by the diagnosis. Root cause: overhead proportional to call volume. Remediation: reproduce the path elsewhere, or drain the instance first.

Sorting only by total time. Error signature: an investigation that stops at a standard library function with no context. Root cause: total time hides which path reached it. Remediation: sort by cumulative first to find the path, then by total.

Ignoring the call count. Error signature: an optimisation of a function that was never the problem. Root cause: reading durations and skipping the leftmost column. Remediation: check whether the count is plausible before looking at anything else.

Profiling the whole process. Error signature: output dominated by imports, framework setup and machinery. Root cause: the profiler enabled at startup rather than around the path of interest. Remediation: use a context manager with the narrowest scope that reproduces the problem.

Discarding the stats file. Error signature: no way to confirm whether a change helped. Root cause: output printed and lost. Remediation: dump to disk and compare the two runs directly.

Frequently Asked Questions

Can cProfile be used on a live service?

Only on an instance removed from the load balancer, and even then briefly. It hooks every call and return, so its cost is proportional to call volume — in a framework-heavy Python service that is a multiple of runtime, not a percentage.

What does cProfile give that a sampling profiler cannot?

Exact call counts. A sampling profiler observes what is executing at instants and can never say how many times something was called. A function invoked four thousand times when it should have been invoked four is invisible to sampling unless the aggregate time is large, and obvious in a deterministic profile.

What is the difference between tottime and cumtime?

Total time is the time spent inside the function itself, excluding calls it made. Cumulative time includes everything it called. Sorting by cumulative finds the expensive path; sorting by total finds the function actually doing the work.

Does cProfile work with asyncio?

It records the calls, but its output attributes everything through the event loop's frames, so per-coroutine attribution is poor. For async services a profiler that understands tasks, or a sampling profiler with idle threads included, gives a more useful picture.

Related Guides