PHASE 13Advanced ~30 min· topic 7 of 9

Topic 13.7

Measuring Speed: timeit and cProfile

In one line

Never guess where a program is slow. Time small snippets with timeit, find the slow function with cProfile, find the memory hog with tracemalloc, and always compare before and after.

Think of it like this

A long school-bus route that is always late. The driver thinks the slow part is the highway. He is wrong: a stopwatch at every stop shows that the bus waits eight minutes at one railway crossing. Fixing the highway would have changed nothing. In programs, profiling is the stopwatch at every stop. Programmers who guess where the time goes are wrong most of the time, so measure first.

Words you'll meet

New words in this topic, in plain English. Come back here whenever one feels fuzzy.

Profiling: Measuring where a program spends its time or memory.
Hot spot: The small part of a program that uses most of the time.
Benchmark: A repeatable measurement used to compare two versions of code.
`ncalls`: How many times a function was called, in a profile.
`tottime`: Time spent inside a function itself, not counting the functions it calls.
`cumtime`: Time spent in a function including everything it called.
Deterministic profiler: A profiler that hooks every call (cProfile). Exact counts, high overhead.
Sampling profiler: A profiler that peeks at the program every few milliseconds (py-spy). Low overhead.

Step by step

01Why we count work in this course

Timings change on every run and every machine, so the runnable examples here print counts of work instead: comparisons made, function calls made. A count is exactly repeatable, and it is the thing the big-O of an algorithm predicts. (Recall Topic 4.11: big-O describes how the amount of work grows with the input size.) A timing is what you measure on your own machine.

A list search compares item by item (1000 comparisons for 1000 items). A set jumps to the right slot by hashing (1 comparison; recall Topic 4.5). The Item class below counts every __eq__ call, which is Python's "are these two equal?" method (Topic 8.7).

main.pywhole filepython

class Item:
    comparisons = 0
    def __init__(self, n):
        self.n = n
    def __eq__(self, other):
        Item.comparisons += 1
        return self.n == other.n
    def __hash__(self):
        return hash(self.n)

02timeit on your machine

On a real computer, the same comparison in seconds looks like the output below. The numbers will differ on your machine, but the ratio (about 2000 times here) is the point. Use timeit to compare two small alternatives, and look at the ratio, not the absolute number.

bench.pywhole filepython

import timeit

data = list(range(10_000))
as_set = set(data)

print("list:", round(timeit.timeit("9999 in data", globals=globals(), number=2000), 4), "s for 2000 lookups")
print("set: ", round(timeit.timeit("9999 in as_set", globals=globals(), number=2000), 6), "s for 2000 lookups")

terminal

$ python bench.py # local Python 3.12, your numbers will differ

── expected output ──

list: 0.1396 s for 2000 lookups

set: 6e-05 s for 2000 lookups

03Reading a cProfile table

The profile below is from a local Python 3.12 run of a small recursive fib. Read it like this. 13510/18 in ncalls means 13,510 total calls but only 18 'primitive' (non-recursive) ones. tottime is the time inside fib itself, and cumtime includes children. The profiler is saying: almost everything happens inside fib, and it is called over thirteen thousand times. That points at the fix: cache the results (Topic 13.8).

terminal

$ python profile_demo.py # local Python 3.12, times are examples

── expected output ──

13534 function calls (42 primitive calls) in 0.003 seconds

Ordered by: cumulative time

List reduced from 7 to 6 due to restriction <6>

ncalls tottime percall cumtime percall filename:lineno(function)

1 0.000 0.000 0.003 0.003 {built-in method builtins.exec}

1 0.000 0.000 0.003 0.003 <string>:1(<module>)

1 0.000 0.000 0.003 0.003 profile_demo.py:16(main)

1 0.000 0.000 0.003 0.003 {built-in method builtins.sum}

19 0.000 0.000 0.003 0.000 profile_demo.py:17(<genexpr>)

13510/18 0.003 0.000 0.003 0.000 profile_demo.py:12(fib)

04Using pstats from code

pstats.Stats(profiler).stats is a dictionary from (file, line, function) to (primitive calls, total calls, tottime, cumtime, callers). The second runnable example reads it and prints only the call counts, which are repeatable: fib is called 3177 times to compute fifteen values.

You can also run a whole script under the profiler from the terminal and open the result later.

terminalwhole filebash

python -m cProfile -o out.prof myscript.py
python -m pstats out.prof          # interactive: sort cumulative, stats 10
python -m timeit -s "data=list(range(1000))" "sum(data)"

05Memory with tracemalloc

tracemalloc.get_traced_memory() returns (current, peak) in bytes. Byte counts vary between versions and platforms, so the example compares sizes with a very large gap (a million-item list added more than a megabyte) instead of printing them. In your own investigations, compare two snapshots to see which lines grew.

main.pywhole filepython

import tracemalloc

tracemalloc.start()
first = tracemalloc.take_snapshot()
data = [str(i) for i in range(100_000)]
second = tracemalloc.take_snapshot()

for stat in second.compare_to(first, "lineno")[:3]:
    print(stat)

06Sampling a live process

py-spy runs outside your program, so it needs no code change. py-spy top --pid 1234 shows a live view like the Unix top command, and py-spy record -o profile.svg --pid 1234 writes a flame graph, a picture where wide boxes are where the time goes. Use it on a slow service you cannot restart. Other options are scalene (CPU, memory and GPU) and austin.

07A profiling routine

First reproduce the slowness with a fixed input. Run cProfile and sort by cumulative time to find the slow top-level function. Zoom in with timeit or a line-level look at the loop. Make one change. Re-measure on the same input. Keep the change only if the numbers (and the tests) agree. Write down what you measured, so the next person does not repeat it.

A profiling routinediagram

Rendering diagram…

Try it yourself

1
Change the size
In the first example change range(1000) to range(5000). The list comparisons grow in step with the size, while the set stays at 1. That difference in growth is big-O made visible.
2
Profile your own function
In the second example replace fib with a function of your own (for example one that sorts a list inside a loop) and read which function has the most calls. Is the hot spot where you expected?
3
Time it for real
On your own computer run python -m timeit -s "data=list(range(10000))" "9999 in data" and then the same with a set. Write down the ratio.

Code & diagrams

Count the work instead of timing it New tab

The `timeit` part prints counts and types only, never the seconds, so this output is the same on every run.

Expected output

list  comparisons: 1000
set   comparisons: 1
calls made: 300
repeat returns 3 numbers (seconds, vary every run)
each is a float: True
trust the smallest of the repeats: True

cProfile call counts and tracemalloc New tab

Expected output

fib        called 3177 times
load       called 1 times
main       called 1 times
the big list added over 1 MB: True
peak is at least current: True

Break it on purpose

Errors are the best teachers. Make each change, read the error, guess what went wrong, then reveal the answer.

Break #1

timeit cannot see your function

Call timeit.timeit with a statement that uses a function defined in your script.

main.pywhole filepython

import timeit


def fib(n):
    return n if n < 2 else fib(n - 1) + fib(n - 2)


print(timeit.timeit("fib(10)", number=5))

terminal

$ python main.py

── what you'll see ──

Traceback (most recent call last):

File "main.py", line 8, in <module>

print(timeit.timeit("fib(10)", number=5))

...

File "<timeit-src>", line 6, in inner

NameError: name 'fib' is not defined

Myth vs fact

Myth

I can see which line is slow by reading the code.

Fact

Experienced programmers are wrong about hot spots often. Measure.

Myth

Run the benchmark once and use that number.

Fact

One run is noise. Repeat and take the minimum, and compare on the same machine under the same load.

Myth

A profiler's absolute times are what users will see.

Fact

cProfile adds overhead, so times are inflated. Trust the ranking and the call counts; confirm real speed with a timer without the profiler.

Myth

sys.getsizeof tells me how much memory a structure uses.

Fact

It measures the object itself, not the objects it points to. A list of a million strings reports only the list's pointer array.

Pro corner

Extra depth for experienced readers. New to this? Skip it for now and come back later.

▸
Reproduce production conditions: the same data size, a warm cache or a cold one as in reality, and the same Python version (specialisation and the GC differ between versions). A benchmark on 100 rows will not predict the behaviour with 100 million.
▸
Tool details that save time: with cProfile.Profile() as pr: (3.8+) profiles a block without a script wrapper; timeit.Timer(...).autorange() picks the loop count for you; time.perf_counter_ns() gives an integer in nanoseconds with no float rounding; tracemalloc.start(25) keeps 25 frames per allocation so the traceback is deep enough to be useful, at a real memory and speed cost (so use it in a staging copy, not for always-on monitoring); and python -X importtime -c "import mypkg" shows which import makes start-up slow.
▸
Know what you are measuring: tottime hides time spent in C functions called by the function unless they appear as their own rows ({built-in method ...}), and wall time includes waiting for I/O, locks and other threads while CPU time does not. For async code, a normal profile shows the event loop and not your coroutines' waits; use asyncio debug mode (slow-callback warnings) or per-call perf_counter logs instead.
▸
For benchmarks inside a codebase, use pytest-benchmark or pyperf, which handle warm-up, many processes and statistics. pyperf is what CPython's own benchmark suite is built on.
▸
Latency has a distribution. Report the median (the middle value) and the 95th or 99th percentile (the time that 95 or 99 percent of requests beat), not the mean; one slow request in a hundred is what users remember. This is the same reasoning as in the System Design course (/system-design).
▸
For AI services most time is spent waiting for the network or GPU. Profile at the level of 'time per model call, time to first token, time spent in retries' (logging with perf_counter) before reaching for a code profiler.

Remember this

1
The rule has three steps. Measure the real program with realistic input. Find the hot spot, the small part that takes most of the time (often one function or one loop). Change one thing and measure again. Donald Knuth's often-quoted warning applies: we should forget about small efficiencies, say about 97 percent of the time, because premature optimisation is the root of all evil; yet we should not pass up the opportunities in the critical 3 percent. Use the tools below to find that 3 percent.
2
timeit measures a small snippet many times and is the right tool to compare two ways of writing one thing. timeit.timeit(stmt, number=...) returns total seconds; timeit.repeat runs it several times and you take the minimum, because other programs on the machine can only make a run slower, never faster. From a terminal, python -m timeit -s "setup" "statement" picks a good number of loops for you. It temporarily switches off the garbage collector so that a collection does not land in one run.
3
time.perf_counter() is the clock to use for timing a block of code by hand: it is monotonic (never goes backwards) and has the highest resolution available. time.time() is the wall-clock date (the time on the wall clock, which people can change) and can jump when the system clock is adjusted. time.process_time() counts only CPU time of your process. Timings of code that waits on a network or a disk include the waiting, so use them to answer 'how long did the user wait?'.
4
cProfile is a deterministic profiler that watches every function call. It reports for each function how many times it was called (ncalls), the time spent inside it excluding sub-calls (tottime), and the time including sub-calls (cumtime). Sort by cumulative to find the slow path from the top, or by tottime to find the function that burns time itself. It slows the program down, most of all for code made of many tiny calls (a program that spends its time in a few long C calls is barely affected), so absolute times are inflated and tiny functions look more expensive than they are. The call counts are exact and the ranking is usually reliable, but confirm with a plain timer. It profiles one thread, so use it inside the thread you care about.
5
tracemalloc tells you where memory was allocated. Start it with tracemalloc.start(), take a snapshot, run your code, take another and compare: snapshot2.compare_to(snapshot1, "lineno") lists the lines that allocated the most new memory. It answers 'which line makes my process grow?' where sys.getsizeof (which measures one object, shallowly) cannot.
6
A sampling profiler such as py-spy looks at a running process from outside every few milliseconds and records what it is doing. It adds almost no overhead, needs no code change and can attach to a live production process, which makes it the tool for 'the service is slow right now'. Inside a notebook, %timeit and %prun are the same ideas. Remember that benchmarks are noisy: close other programs, use the minimum of several runs, and be suspicious of a difference of a few percent.

Explain it without notes

Why measure before optimising, and what is a good workflow?

What do ncalls, tottime and cumtime mean in a cProfile table?

Why take the minimum of several timeit repeats?

When would you choose py-spy over cProfile?

Practice

Read time.perf_counter() before and after sum(range(100_000)), subtract to get the elapsed time, and print elapsed is not negative: True by checking elapsed >= 0. Do not print the elapsed time itself.

Profile a function work() that calls helper(i) fifty times, and print the call counts of both from pstats.

Use tracemalloc to check that building list(range(500_000)) grows traced memory by more than a megabyte.

Trade-offs

↔
Accuracy versus overhead. cProfile is exact but slows the program, py-spy is light but statistical. Pick by whether you can start the program under the tool.
↔
Micro-benchmarks versus real workloads. A tiny timeit shows which of two snippets is faster in isolation, but the whole program may spend its time elsewhere. Confirm with an end-to-end measurement.

Done when you can

Done when you can write a three-step measuring routine and follow it.
Done when you can use timeit correctly (globals, repeat, minimum) and explain why.
Done when you can read a cProfile table and name the columns.
Done when you can find which lines allocate memory with tracemalloc.
Done when you can say when a sampling profiler is the better tool.

Command Palette

Words you'll meet

Step by step

01Why we count work in this course

02timeit on your machine

03Reading a cProfile table

04Using pstats from code

05Memory with tracemalloc

06Sampling a live process

07A profiling routine

Try it yourself

Change the size

Profile your own function

Time it for real

Code & diagrams

Break it on purpose

timeit cannot see your function

Myth vs fact

Pro corner

Remember this

Explain it without notes

Practice

Trade-offs

Done when you can