Measuring speed with timeit and cProfile

A program that is slow is rarely slow everywhere. Usually one function takes most of the time, and guessing which one wastes an afternoon. The method is the same as for a bug: measure first, change one thing, measure again. The fundamentals lesson on Big O explains why some approaches scale badly. Python gives you two standard tools for finding out whether yours does: timeit for small snippets and a profiler for whole programs.

timeit: compare two small alternatives

timeit runs a snippet many times and reports the time. From the command line, -s gives set-up code that runs once, and the last argument is the statement to time:

$ python -m timeit -s "data = list(range(10_000))" "9_999 in data"
5000 loops, best of 5: 67.2 usec per loop
$ python -m timeit -s "data = set(range(10_000))" "9_999 in data"
10000000 loops, best of 5: 21.2 nsec per loop

timeit picked the number of loops itself, repeated the measurement five times, and reported the best, since the fastest run is the one least disturbed by other programs. Your numbers will differ. The ratio will not: a membership test in a list scans it item by item, taking 67 microseconds here, while a set answers in about 21 nanoseconds. That is more than three thousand times faster for this size.

In code, timeit.timeit and timeit.repeat do the same. A script that must print the same thing everywhere checks the ratio instead of the times:

import timeit

setup = "data = list(range(10_000)); as_set = set(data)"

in_list = timeit.timeit("9_999 in data", setup=setup, number=2_000)
in_set = timeit.timeit("9_999 in as_set", setup=setup, number=2_000)

# Exact times differ on every machine; the ratio is what matters.
print("list slower than set:", in_list > in_set)
print("at least 20 times slower:", in_list > 20 * in_set)

# Repeat the measurement and keep the best run, which has the least noise.
runs = timeit.repeat("sum(range(1_000))", number=1_000, repeat=5)
print("runs taken:", len(runs))
print("best is the smallest:", min(runs) == sorted(runs)[0])

list slower than set: True
at least 20 times slower: True
runs taken: 5
best is the smallest: True

timeit.timeit returns the total seconds for number runs. timeit.repeat returns a list of such totals, and you should take the min, not the average. To time your own function, pass globals=globals() so the snippet can see it, or give timeit a callable instead of a string.

Time what you actually do: a set is only faster if you can keep one around. Use realistic sizes, because many differences disappear at ten items and explode at ten million. And compare results first, so you are not timing something that is fast because it is wrong.

cProfile: find the slow part of a program

timeit needs you to know what to time. A profiler watches a whole program run and tells you where the time went. cProfile is the standard deterministic profiler: it records every function call. Here is a report that is slow for a reason a profiler finds in seconds.

"""A report that is slow for a reason a profiler finds in seconds."""


def load_ids(n):
    return list(range(n))


def is_known(user_id, known):
    return user_id in known  # linear search when known is a list


def count_known(candidates, known):
    return sum(1 for user_id in candidates if is_known(user_id, known))


def build_report():
    known = load_ids(3_000)
    candidates = range(0, 6_000, 2)
    return count_known(candidates, known)


if __name__ == "__main__":
    print(build_report())

$ python c40_slow.py
1500

Run it under the profiler, sorted by cumulative time (the time in a function including everything it calls):

$ python -m cProfile -s cumulative c40_slow.py
1500
         4509 function calls in 0.051 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.051    0.051 {built-in method builtins.exec}
        1    0.000    0.000    0.051    0.051 c40_slow.py:1(<module>)
        1    0.000    0.000    0.051    0.051 c40_slow.py:16(build_report)
        1    0.000    0.000    0.051    0.051 c40_slow.py:12(count_known)
        1    0.000    0.000    0.051    0.051 {built-in method builtins.sum}
     1501    0.001    0.000    0.051    0.000 c40_slow.py:13(<genexpr>)
     3000    0.050    0.000    0.050    0.000 c40_slow.py:8(is_known)
        1    0.000    0.000    0.000    0.000 c40_slow.py:4(load_ids)
        1    0.000    0.000    0.000    0.000 {built-in method builtins.print}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof...

Read the columns like this:

• ncalls: how many times the function was called.
• tottime: seconds spent in the function itself, excluding functions it called.
• cumtime: seconds including the functions it called.
• percall: each of the two times divided by the number of calls.

The top rows have a large cumtime because they contain everything below them. Look at tottime: is_known was called 3000 times and its own time is 0.050 of the 0.051 seconds. That is the hot spot. The function is one line, user_id in known, and known is a list. The cure is the one timeit pointed to. Profiling adds overhead, so the timings are a guide to proportions and change from run to run.

You can profile inside a program too, and read the numbers back with pstats rather than printing a table. Because the absolute times are different every run, the script below prints the call counts, which do not change:

import cProfile
import pstats

from c40_slow import build_report

profiler = cProfile.Profile()
profiler.enable()
result = build_report()
profiler.disable()
print("result:", result)

stats = pstats.Stats(profiler)
# stats.stats maps (file, line, name) to (cc, nc, tottime, cumtime, callers)
calls = {key[2]: value[1] for key, value in stats.stats.items()}
for name in ["build_report", "count_known", "is_known", "load_ids"]:
    print(f"{name:13} called {calls[name]} times")

result: 1500
build_report  called 1 times
count_known   called 1 times
is_known      called 3000 times
load_ids      called 1 times

cProfile.Profile() can also be used as a context manager (with cProfile.Profile() as profiler:). To print the table yourself, use stats.sort_stats("tottime").print_stats(10): it sorts by own time and shows ten rows. Redirect the profile to a file with -o out.prof and open it later with pstats or a viewer.

Change one thing, then measure again

The profile says the list search dominates. Change that one line’s data structure, a set instead of a list, and check three things: the answer is the same, the time dropped, and nothing else changed.

import timeit

import c40_slow


def build_report_fast():
    # one change: a set answers "in" in constant time
    known = set(c40_slow.load_ids(3_000))
    candidates = range(0, 6_000, 2)
    return c40_slow.count_known(candidates, known)


assert build_report_fast() == c40_slow.build_report()
slow = min(timeit.repeat(c40_slow.build_report, number=1, repeat=3))
fast = min(timeit.repeat(build_report_fast, number=1, repeat=3))
print("same answer:", build_report_fast() == c40_slow.build_report())
print("faster by at least 5x:", slow > 5 * fast)

same answer: True
faster by at least 5x: True

The assert at the top is the correctness check, which belongs to your tests. The two timeit runs are the speed check. Without both, “optimised” code may be wrong or no faster. Stop when the program is fast enough: the goal is the point where the next improvement is not worth its complexity. Code that is right first, and made fast only where a profile asked, beats both fast, wrong code and slow, clear code.

Profiling in Python 3.15

Python 3.15 added a profiling package 3.15+Requires version 3.15 or later (PEP 799) to gather the profilers under one roof. It has two parts, described in the documentation:

• profiling.tracing is the deterministic profiler, the former cProfile. The cProfile name remains as a backward-compatible alias, so existing code keeps working.
• profiling.sampling is a sampling profiler. Instead of recording every call, it looks at the running program’s stack many times a second. It adds very little overhead and can attach to a running process.

The old pure-Python profile module is deprecated in 3.15 and will be removed in 3.17. Use profiling.tracing or cProfile instead. The API of the new name matches the old one:

import pstats

import profiling.tracing  # Python 3.15 or newer

from c40_slow import build_report

profiler = profiling.tracing.Profile()
profiler.runcall(build_report)

stats = pstats.Stats(profiler)
calls = {key[2]: value[1] for key, value in stats.stats.items()}
print("is_known called", calls["is_known"], "times")

is_known called 3000 times

The sampling profiler runs from the command line, and its commands are run, attach, dump and replay. Running our slow script under it prints a table that points at the same function:

$ python -m profiling.sampling run c40_slow.py
1500
Captured 64 samples in 0.06 seconds
Sample rate: 1000.00 samples/sec
Profile Stats:
   nsamples   sample%  tottime (ms)  filename:lineno(function)
      50/50     100.0        50.000  c40_slow.py:9(is_known)
       0/50       0.0         0.000  c40_slow.py:13(count_known.<locals>.<genexpr>)
       0/50       0.0         0.000  c40_slow.py:13(count_known)

The real table has two more columns and more rows. Sample counts and times vary from run to run. Here 50 of 50 samples were inside is_known itself: the same conclusion as cProfile, reached by sampling. Sampling suits long-running programs where tracing every call would distort the result, and python -m profiling.sampling attach PID looks at a process that is already running, much like the pdb attach in the debugging lesson. For short scripts, cProfile is still the simplest tool, and it works on every version.

Common pitfalls

• Optimising without measuring. The part you believe is slow often is not. Profile first.
• Timing a single run. One run includes start-up noise and caching effects. Use timeit.repeat and take the min.
• Trusting the profiler’s seconds. Profiling slows the program. Treat it as showing proportions, not as the real speed.
• Reading cumtime as the culprit. A caller’s cumulative time includes everything below it. Sort by tottime to find where the time is actually spent.
• Forgetting to re-check correctness. A faster function that returns a different answer is a bug. Keep a test next to the benchmark.

import timeit


def build_with_plus(n):
    result = []
    for i in range(n):
        result = result + [i]  # copies the whole list every time
    return result


def build_with_append(n):
    result = []
    for i in range(n):
        result.append(i)
    return result


assert build_with_plus(100) == build_with_append(100)

def best(call):
    return min(timeit.repeat(call, globals=globals(), number=5, repeat=5))


plus = best("build_with_plus(4_000)")
append = best("build_with_append(4_000)")

print("same result:", build_with_plus(100) == build_with_append(100))
print("append is at least 3 times faster:", plus > 3 * append)

same result: True
append is at least 3 times faster: True

import cProfile
import pstats
import timeit


def duplicates_slow(items):
    return sorted({x for x in items if items.count(x) > 1})


data = [i % 1_000 for i in range(4_000)] + list(range(1_000, 3_000))

def duplicates_fast(items):
    seen = set()
    repeated = set()
    for x in items:
        if x in seen:
            repeated.add(x)
        seen.add(x)
    return sorted(repeated)

with cProfile.Profile() as profiler:
    answer = duplicates_slow(data)

stats = pstats.Stats(profiler)
calls = {key[2]: value[1] for key, value in stats.stats.items()}
count = "<method 'count' of 'list' objects>"
print("duplicates found:", len(answer))
print("list.count calls:", calls[count])

assert duplicates_fast(data) == answer
slow = min(timeit.repeat(lambda: duplicates_slow(data), number=1, repeat=3))
fast = min(timeit.repeat(lambda: duplicates_fast(data), number=1, repeat=3))
print("same answer:", duplicates_fast(data) == answer)
print("at least 20 times faster:", slow > 20 * fast)

duplicates found: 1000
list.count calls: 6000
same answer: True
at least 20 times faster: True

import cProfile
import pstats


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


with cProfile.Profile() as profiler:
    fib(10)

stats = pstats.Stats(profiler)
for key, value in stats.stats.items():
    if key[2] == "fib":
        print("primitive calls:", value[0])
        print("total calls:", value[1])

primitive calls: 1
total calls: 177

Summary

• Measure before changing anything. python -m timeit and timeit.repeat (take the min) compare small alternatives, and the ratio matters, not the absolute time.
• python -m cProfile -s cumulative script.py shows where a program spends its time. Look at ncalls and tottime to find the hot function, change one thing, and measure again, with a test for correctness.
• Python 3.15 adds the profiling package: profiling.tracing (the deterministic profiler, which cProfile now aliases) and the low-overhead profiling.sampling. The profile module is deprecated.
• This ends the module and the intermediate level. You can now test, debug, log and measure your code, and you have the vocabulary for the advanced level.
• Going further: the advanced lesson Concurrency models shows what to try when a profile says the program is waiting or CPU-bound.