Python Basics: Find Repeated Work with cProfile and pstats

A slow program may spend time in a helper that is called more often than expected. cProfile records function activity during a run, and pstats turns that recording into a report. Start with a representative workload and a specific question, such as whether normalization happens once per item or once per batch.

These small examples teach how to collect and read the data. Their call counts are useful checks; their tiny timings are not evidence for an optimization.

Prepare a scratch directory

These examples were tested on Linux with Python 3.12.14. Use Python 3.9 or newer for get_stats_profile. Use Bash, a text editor, and the standard mktemp, rm, and rmdir utilities. No third-party packages are required. Run without -O so the assertions remain enabled.

Create a fresh directory and keep using the same terminal:

start_dir="$PWD"
work_dir="$(mktemp -d)" || exit 1
cd -- "$work_dir" || exit 1

If either setup command fails, stop before saving any files. Save each source below as UTF-8. Avoid names such as cProfile.py or pstats.py that shadow standard-library modules.

1. Profile one call and retain its result

Save as count_profiled_helpers.py:

import cProfile
import pstats


def normalize_label(label):
    return label.strip().casefold()


def build_labels(labels):
    return [normalize_label(label) for label in labels]


profiler = cProfile.Profile()
result = profiler.runcall(build_labels, [" Alpha ", "BETA", " Gamma "])
assert result == ["alpha", "beta", "gamma"]
profiles = pstats.Stats(profiler).get_stats_profile().func_profiles
assert profiles["build_labels"].ncalls == "1"
assert profiles["normalize_label"].ncalls == "3"
print("Result:", result)
for name in ("build_labels", "normalize_label"):
    print(f"{name}: {profiles[name].ncalls} calls")

Run it:

python3 -B count_profiled_helpers.py

Output:

Result: ['alpha', 'beta', 'gamma']
build_labels: 1 calls
normalize_label: 3 calls

runcall returns the callable’s result while collecting statistics. The normalized labels still need a correctness check. get_stats_profile exposes a function-name mapping; this example deliberately uses unique names. See the profiler interfaces and structured profile data.

2. Recognize recursive call counts

Save as read_recursive_profile.py:

import cProfile
import pstats


def count_down(remaining):
    if remaining == 0:
        return 0
    return 1 + count_down(remaining - 1)


profiler = cProfile.Profile()
assert profiler.runcall(count_down, 5) == 5
profile = pstats.Stats(profiler).get_stats_profile().func_profiles["count_down"]
assert profile.ncalls == "6/1"
total_calls, primitive_calls = map(int, profile.ncalls.split("/"))
print("Displayed calls:", profile.ncalls)
print("Total entries:", total_calls)
print("Non-recursive entries:", primitive_calls)

Run it:

python3 -B read_recursive_profile.py

Output:

Displayed calls: 6/1
Total entries: 6
Non-recursive entries: 1

The initial call and five recursive calls make six entries. Only the initial call is primitive, meaning it was not entered recursively. Do not read 6/1 as a fraction. The report-column explanation also distinguishes internal time from cumulative time, which includes subcalls.

The input is deliberately bounded. This recursive function only illustrates the report and is not a general implementation for large or negative counts.

3. Write a focused report for inspection

Save as write_focused_profile.py:

import cProfile
import io
from pathlib import Path
import pstats


def square_sample(value):
    return value * value


def calculate_total(values):
    return sum(square_sample(value) for value in values)


with cProfile.Profile() as profiler:
    result = calculate_total(range(100))
assert result == 328350

output = io.StringIO()
statistics = pstats.Stats(profiler, stream=output)
statistics.strip_dirs().sort_stats(pstats.SortKey.CUMULATIVE)
statistics.print_stats(r"\((calculate_total|square_sample)\)$")
report = output.getvalue()
assert "calculate_total" in report and "square_sample" in report
assert "tottime" in report and "cumtime" in report
with Path("profile-summary.txt").open("x", encoding="utf-8") as target:
    target.write(report)
print("Result:", result)
print("Report written: profile-summary.txt")
print("Inspect columns: ncalls, tottime, cumtime")

Run it once in the fresh directory:

python3 -B write_focused_profile.py

Output:

Result: 328350
Report written: profile-summary.txt
Inspect columns: ncalls, tottime, cumtime

Open profile-summary.txt in your editor to see the actual timings. They vary between runs. The report sorts by cumulative time, then limits displayed functions with a regular expression. Filtering display rows does not remove their work from the recorded totals. The exclusive x mode avoids overwriting an existing report.

Use sort_stats and print_stats to answer a narrow question rather than dumping every row. Profiling adds overhead, and the recorded run still executes the application’s side effects. Use local fixtures for experiments; measure a proposed improvement separately under realistic conditions. A zero-looking rounded time does not mean no work occurred.

Clean up

In the same terminal, remove only the named sources and report, then the empty scratch directory:

rm -- count_profiled_helpers.py read_recursive_profile.py write_focused_profile.py profile-summary.txt
cd -- "$start_dir" || exit 1
rmdir -- "$work_dir"
unset start_dir work_dir

If rmdir reports remaining files, inspect them instead of deleting unknown contents.

References

• Python 3.12 profiling and report columns
• Structured profile data
• Sorting and filtering reports

Acknowledgements

This post was created with assistance from AI.