cProfile Tutorial: Deterministic Function Profiling
cProfile is Python's deterministic profiler built into the standard library. It counts every function call, measures cumulative time (including callees), measures time in only that function, and produces a detailed report showing exactly where your program spends CPU cycles. Unlike timeit which times isolated snippets, cProfile profiles entire programs and shows the call graph: which functions called which, how many times, and who consumed the most time. This is your primary tool for finding bottlenecks in real code.
I learned cProfile while debugging a web scraper that should finish in 5 minutes but took 45. Without profiling, I would have guessed: "Maybe the regex is slow" or "The HTTP library is blocking." With cProfile, the report immediately showed 99% of time was in a single function—a JSON parser called 100,000 times due to a missing cache. One line of caching code solved it.
cProfile vs. Sampling Profilers vs. timeit
Understanding the differences helps you choose the right tool:
- cProfile (deterministic): Counts every function call and measures cumulative time. High overhead (10–50%), large output, but complete. Use for development to identify bottlenecks.
- Sampling profilers (e.g.,
py-spy): Interrupt the code at fixed intervals and record the call stack. Low overhead (<5%), suitable for production, but statistical (may miss short functions). Covered in Chapter 6. - timeit: Measures a single code snippet in isolation, not a whole program. Use for micro-benchmarking. Covered in Chapter 2.
Start with cProfile on your entire program, identify the hot function, then drill down with timeit or line_profiler to optimize that function.
Running cProfile: Three Methods
Method 1: Command-line profiling (quickest, no code changes):
python -m cProfile -o program.prof your_script.py
Then analyze the output with pstats:
python -m pstats program.prof
# Then type "sort cumtime" and "stats 10" in the pstats shell
Method 2: Inline with pstats (control output):
import cProfile
import pstats
from io import StringIO
def your_program():
# Your code here
for i in range(1000):
x = sum(range(1000))
# Profile the function
prof = cProfile.Profile()
prof.enable()
your_program()
prof.disable()
# Print a report
s = StringIO()
ps = pstats.Stats(prof, stream=s).sort_stats("cumtime")
ps.print_stats(10)
print(s.getvalue())
Method 3: Decorate a function (reusable profiler wrapper):
import cProfile
import functools
import pstats
from io import StringIO
def profile_this(func):
"""Decorator that profiles a function."""
@functools.wraps(func)
def wrapper(*args, **kwargs):
prof = cProfile.Profile()
prof.enable()
result = func(*args, **kwargs)
prof.disable()
s = StringIO()
ps = pstats.Stats(prof, stream=s).sort_stats("cumtime")
ps.print_stats(15)
print(s.getvalue())
return result
return wrapper
@profile_this
def compute_something():
for i in range(10000):
x = sum(range(100))
compute_something()
This decorator automatically profiles any function you decorate with @profile_this.
Understanding the cProfile Report
Here's a sample report from profiling a function that processes data:
ncalls tottime percall cumtime percall filename:lineno(function)
1000 0.050 0.000 2.345 0.002 process.py:10(parse_json)
1000000 0.120 0.000 0.120 0.000 process.py:20(validate)
5000 0.001 0.000 0.500 0.000 process.py:15(transform)
10 0.000 0.000 2.350 0.235 process.py:1(main)
Each column explains:
| Column | Meaning | Use Case |
|---|---|---|
| ncalls | Total function calls | Spot functions called unexpectedly often (a sign of a loop issue) |
| tottime | Seconds in this function only (not children) | Identify functions with heavy computation |
| percall (tottime) | Average tottime per call | Find functions that are slow per call (algorithmic issue) |
| cumtime | Seconds in this function and all callees | Find the true bottleneck—highest cumtime = biggest impact |
| percall (cumtime) | Average cumtime per call | Compare the cost of calling this function once |
Key insight: Sort by cumtime to find your bottleneck. The function with highest cumtime is the one consuming the most CPU overall (either because it's slow or because it's called many times).
In the example above, parse_json is the bottleneck: 2.345 seconds cumulative time, called 1000 times. It spends 2.245 seconds waiting for validate to complete (which is called by parse_json). If you optimize validate, you improve parse_json and thus the whole program.
Finding Unexpected Calls: The ncalls Anomaly
High ncalls numbers often reveal bugs. Here's an example:
import cProfile
import pstats
from io import StringIO
def fetch_user(user_id):
"""Simulates fetching user data (intentionally called in a loop)."""
return {"id": user_id, "name": f"User {user_id}"}
def process_users():
"""Process users—but has a hidden inefficiency."""
users = []
for i in range(100):
# BUG: fetch_user() called 100 times, but maybe should cache?
user = fetch_user(i)
users.append(user)
return users
prof = cProfile.Profile()
prof.enable()
process_users()
prof.disable()
s = StringIO()
ps = pstats.Stats(prof, stream=s).sort_stats("cumtime")
ps.print_stats()
print(s.getvalue())
Output:
ncalls tottime percall cumtime percall filename:lineno(function)
100 0.050 0.000 0.050 0.000 script.py:2(fetch_user)
1 0.000 0.000 0.051 0.051 script.py:7(process_users)
If fetch_user is a database query, being called 100 times is expensive. The ncalls = 100 is a red flag: you'd want to batch-fetch all users in one query, not 100 separate queries.
Filtering and Sorting cProfile Output
By default, cProfile reports all functions, including the Python interpreter. Filter to focus on your code:
import cProfile
import pstats
prof = cProfile.Profile()
prof.enable()
# ... your code ...
prof.disable()
# Sort by cumulative time, show only your module
ps = pstats.Stats(prof)
ps.sort_stats("cumtime")
ps.print_stats("mymodule.py") # Only functions in mymodule.py
Common sorting options:
| Sort Key | Meaning |
|---|---|
cumtime | Cumulative time (most useful for bottleneck hunting) |
tottime | Time in function only |
ncalls | Number of calls |
percall | Per-call time |
Common Pitfalls and How to Avoid Them
Pitfall 1: Garbage collection skewing results. Like timeit, cProfile is affected by garbage collection. Disable it during profiling for cleaner results:
import cProfile
import gc
prof = cProfile.Profile()
gc.disable()
prof.enable()
your_program()
prof.disable()
gc.enable()
# Analyze...
Pitfall 2: Reading cumtime wrong. Remember: cumtime includes all children. If process_data() cumtime is 5 seconds but its tottime is 0.1 seconds, the other 4.9 seconds are inside functions it called. Look at the call tree to see who's responsible.
Pitfall 3: Profiling too short a run. If your program runs in 10 milliseconds, cProfile overhead might double the runtime. Profile a longer run (at least a few seconds) to see the true proportions.
Example: Profiling a Data Pipeline
Here's a realistic example: a pipeline that reads, parses, and aggregates data.
import cProfile
import pstats
from io import StringIO
import json
def read_file(filename):
"""Read raw data from file."""
with open(filename) as f:
return f.read()
def parse_json(raw_data):
"""Parse JSON lines."""
lines = raw_data.split('\n')
return [json.loads(line) for line in lines if line]
def aggregate(records):
"""Aggregate records by key."""
result = {}
for record in records:
key = record.get("category", "unknown")
if key not in result:
result[key] = []
result[key].append(record)
return result
def pipeline():
"""Full pipeline."""
# Simulate data
data = "\n".join(
json.dumps({"id": i, "category": chr(65 + i % 5), "value": i * 2})
for i in range(10000)
)
records = parse_json(data)
aggregated = aggregate(records)
return aggregated
prof = cProfile.Profile()
prof.enable()
result = pipeline()
prof.disable()
s = StringIO()
ps = pstats.Stats(prof, stream=s).sort_stats("cumtime")
ps.print_stats(10)
print(s.getvalue())
This shows cumulative time per function, revealing that parse_json (which calls json.loads) dominates the pipeline. If you wanted to optimize, you'd focus on parsing: maybe use a faster JSON library like ujson, or batch-load data differently.
Key Takeaways
cProfilecounts every function call and measures cumulative time, revealing true bottlenecks in complex programs.- Always sort by
cumtimeto find the function consuming the most CPU overall. - High
ncallsis a red flag: a function called 1 million times might be a loop that should be vectorized or cached. - Disable garbage collection during profiling for cleaner results that reflect actual code cost.
- Use the profiler early and often during development; it turns guessing into precision.
Frequently Asked Questions
Why is cumtime higher than the total program time?
It shouldn't be. The root function (usually <module>) should have cumtime equal to total runtime. If you see discrepancies, you're likely looking at a subset of the report. Use print_stats() without filtering to see the full picture.
How do I profile a Flask/Django web app?
Wrap a request handler with cProfile or use Flask/Django middleware that profiles requests automatically. Tools like Flask-Profiler automate this. Alternatively, use sampling profilers (py-spy) which are less intrusive for long-running servers.
What if the slowest function is in a compiled library like NumPy?
cProfile can't profile C code in detail. Use py-spy (sampling profiler) or the library's profiling tools. For NumPy, you're often better off reducing the number of calls (better algorithm) rather than optimizing NumPy internals.
How do I save the profiler output for later analysis?
Use prof.dump_stats('output.prof') then pstats.Stats('output.prof').print_stats() to load it later. This is useful for comparing before/after optimization runs.