How to Profile Python Code: timeit, cProfile and tracemalloc

How do you profile Python code?

To profile Python code, run it under cProfile, for example python -m cProfile -s cumulative app.py, which reports each function's call count, tottime (time in the function itself) and cumtime (including its callees). Sort by tottime to find the function doing the work and by cumtime for the path to it, then compare fixes with timeit; tracemalloc does the same job for memory.

Lesson

Performance work without measurement is guessing, and most guesses about where a program spends its time are wrong. Python ships the tools to find out: time.perf_counter for a stopwatch, timeit for micro-benchmarks that handle repetition and noise, cProfile with pstats to attribute time to functions, and tracemalloc to attribute memory to lines. This lesson covers each, how to read their output, the hygiene that makes a measurement mean something — warm-up, repetition, minimum rather than mean, isolating the thing measured — and the discipline of profiling before optimising and stopping when the numbers say so.

perf_counter: the stopwatch

from time import perf_counter

start = perf_counter()
result = work()
elapsed = perf_counter() - start        # seconds, as a float, monotonic, high resolution
print(f"work took {elapsed:.3f}s")

perf_counter is the clock for measuring durations (monotonic, fractional seconds, not affected by system clock changes); time.time() is wall-clock and can jump; process_time counts CPU time only. A small context manager wrapping this is the standard tool for timing phases of a real program:

from contextlib import contextmanager

@contextmanager
def timed(label, clock=perf_counter, report=print):
    start = clock()
    yield
    report(f"{label} {clock() - start:.3f}s")

Injecting the clock and the reporter is what makes it testable: a test passes a fake clock returning a scripted sequence and asserts on the labels and durations without any real time passing — the design from Module 18.

timeit: micro-benchmarks done right

python -m timeit -s "xs = list(range(1000))" "sum(xs)"
# 5000 loops, best of 5: 4.1 usec per loop
python -m timeit -s "xs = list(range(1000))" "total = 0" "for x in xs: total += x"
# 5000 loops, best of 5: 28 usec per loop

import timeit
timeit.timeit("sum(xs)", setup="xs = list(range(1000))", number=10_000)     # total seconds
min(timeit.repeat("sum(xs)", setup=..., number=10_000, repeat=5))           # the number to report

timeit disables garbage collection, runs the statement number times, repeats that repeat times and reports the best — the minimum is the right statistic for a benchmark, because noise only ever adds time. Setup code (building the data) is excluded. Compare alternatives on the same machine in the same session, at the same input size, and with a size large enough that the per-call overhead is not what you are measuring.

cProfile: where the time goes

python -m cProfile -s cumulative app.py | head -20

         2003 function calls in 1.204 seconds
   Ordered by: cumulative time
   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.001    0.001    1.204    1.204 app.py:30(main)
     1000    0.902    0.001    1.150    0.001 app.py:12(parse)
     1000    0.248    0.000    0.248    0.000 app.py:5(tokenize)

ncalls is how often the function ran; tottime is time inside it excluding callees; cumtime includes callees; percall divides each. Sort by tottime to find the function doing the work, by cumtime to find the path that leads there. In code: cProfile.Profile() as a context manager, then pstats.Stats(profile).sort_stats("tottime").print_stats(10). The profiler adds overhead (roughly 2×) that is uneven across call-heavy code, so use it to find the hot spot and timeit to compare fixes. Line-level profilers (line_profiler) and sampling profilers (py-spy, which attaches to a running process with no code changes) are the third-party next steps; python -X importtime profiles import time specifically.

tracemalloc: where the memory goes

import tracemalloc
tracemalloc.start()
before = tracemalloc.take_snapshot()
build()
after = tracemalloc.take_snapshot()
for stat in after.compare_to(before, "lineno")[:5]:
    print(stat)                      # file:line: size=…, count=…, average=…
current, peak = tracemalloc.get_traced_memory()

tracemalloc records every allocation with its call site; comparing two snapshots shows which lines allocated the growth. get_traced_memory gives the current and peak — the peak is what decides whether a program fits its limit. It slows the program and itself uses memory; run it once to find the culprit, then remove it.

Hygiene

• Warm up. The first run pays for imports, .pyc compilation, cache filling and the 3.11 specialiser; measure the second run onward.
• Repeat and take the minimum for micro-benchmarks; for whole programs, several runs and the median.
• Isolate. Time the computation, not the print, not the input parsing, not the file open — unless those are the question.
• Same conditions. Same machine, same Python, same data, nothing else running; a laptop on battery throttles.
• Realistic size. Constant factors dominate small inputs; asymptotics dominate large ones; measure at the size that matters.
• Hypothesis first. "parse is 75 % of the time" is a claim the profile confirms or refutes before any code changes.
• Stop. When the target is met or the remaining hot spot is essential work, stop; every optimisation costs clarity.

Amdahl's rule

If a phase is 75 % of the run time, making it infinitely fast gains at most 4×; making a 5 % phase infinitely fast gains 5 %. Optimise the largest slice first, re-profile, repeat — the largest slice changes after each fix. This single division is the difference between a productive afternoon and a wasted one.

Pitfalls

• time.time() for durations.
• Reporting the mean of a noisy benchmark instead of the minimum.
• Timing code that includes I/O or the profiler's own overhead.
• Optimising the function that looks slow without profiling.
• Measuring at n = 10 and extrapolating to n = 10⁷.
• Printing measured times from a program whose output must be reproducible — report computed quantities instead.

Key takeaways

• perf_counter for durations, wrapped in a context manager with an injectable clock; timeit for micro-benchmarks with repeat and the minimum.
• cProfile attributes time to functions: tottime finds the worker, cumtime the path; pstats sorts and prints.
• tracemalloc snapshots attribute memory growth to lines and report the peak.
• Warm up, repeat, isolate, fix conditions and sizes, form a hypothesis, stop when done.
• Amdahl: optimise the largest slice; re-profile after each change.

Common questions

What is the difference between tottime and cumtime in cProfile?

tottime is the time spent inside a function excluding the functions it calls; cumtime includes them. A high tottime marks the function doing the work, while a high cumtime with a low tottime marks a path that leads to it.

Why does timeit report the minimum time?

Noise from other processes, caches and the scheduler only ever adds time, so the fastest of several repeats is closest to the code's true cost. timeit also disables garbage collection while timing and excludes the setup code; report min(timeit.repeat(...)).

Should I use time.time() or time.perf_counter() to time code?

time.perf_counter(). It is monotonic and high-resolution, made for measuring durations, whereas time.time() is wall-clock time and can jump when the system clock changes. time.process_time() counts CPU time only.

How do you find what is using memory in Python?

Call tracemalloc.start(), take a snapshot before and after the suspect code, and print after.compare_to(before, 'lineno') to see which lines allocated the growth. tracemalloc.get_traced_memory() returns the current and peak sizes; the peak decides whether a program fits its limit.

What does Amdahl's law mean for optimisation?

Speeding up one part is capped by that part's share of the run time: making a phase that takes 75 percent of it infinitely fast gains at most 4×, and a 5 percent phase gains at most 5 percent. Optimise the largest slice first and re-profile after each change.

Exercises

1 0.001 1.204 main
1000 0.902 1.150 parse
1000 0.248 0.248 tokenize

parse tottime=0.902 percall=0.000902 share=78.4%
tokenize tottime=0.248 percall=0.000248 share=21.5%
main tottime=0.001 percall=0.001000 share=0.1%
total 1.151s

0.0 0.25 0.3 1.1
parse render

parse 0.250s
render 0.800s
total 1.050s
slowest render

In this module: Memory, performance and the interpreter

• The object model — objects, references, reference counting and the cycle collector
• The cost model — what the built-in operations really cost
• Bytecode and the interpreter — code objects, dis, name lookup and the 3.11 specialiser
• Measuring — timeit, perf_counter, cProfile, tracemalloc and benchmarking hygiene (this lesson)
• Numeric performance — boxed numbers, array, bytes and NumPy vectorisation
• Writing fast Python — the checklist, from algorithm to micro-optimisation
• Checkpoint — Memory, performance and the interpreter