timeit and cProfile

15 min · Intermediate

Programs are slow in surprising places. Measuring finds the real place, and the tools for it are in the standard library.

Measure first, then change

A benchmark is a repeatable measurement of how long code takes, run on the same data and the same machine so that two versions can be compared fairly.

Guessing what is slow wastes time. Take a clock reading before and after the code you suspect. time.perf_counter() is the right clock for short intervals.

Python

1import time2
3start = time.perf_counter()4total = sum(range(1_000_000))5elapsed = time.perf_counter() - start6print(total)7print(elapsed > 0)

Example 1 · Timing one call

Python

1import time2
3def build_report(rows):4    return [row * 2 for row in rows]5
6start = time.perf_counter()7result = build_report(range(1_000_000))8elapsed = time.perf_counter() - start9print(len(result))10print(f"took {elapsed:.3f} seconds")

Sample output

1000000
took 0.064 seconds

What this code does

The length is always 1000000.
The time line is a sample: your result will be different.
Never put a printed time in a test; compare two versions instead.

The answer is always the same, but the time is not: it depends on your machine, its load and the Python version. That is why the examples in this module print comparisons such as True, not seconds.

timeit for small snippets

timeit is the standard-library module for timing small pieces of code. It repeats the code many times and reports the total time, which is far more reliable than one stopwatch reading.

One reading is noisy. The timeit module runs a snippet many times and repeat gives several such totals. Take the smallest, the run least disturbed by other programs.

Python

import timeit
runs = timeit.repeat("sum(range(1000))", number=200, repeat=3)print(len(runs))print(min(runs) > 0)

Example 2 · Comparing two versions with timeit

Python

1import timeit2
3orders = list(range(2000))4ids_list = [n * 3 for n in orders]5ids_set = set(ids_list)6
7def in_list():8    return 5997 in ids_list9
10def in_set():11    return 5997 in ids_set12
13t_list = min(timeit.repeat(in_list, number=500, repeat=3))14t_set = min(timeit.repeat(in_set, number=500, repeat=3))15print("set lookup is faster:", t_set < t_list)

Output

set lookup is faster: True

What this code does

Both functions answer the same question.
repeat runs three readings and min keeps the best one.
A list scans item by item; a set jumps straight to the item.

number is how many times the snippet runs inside one reading. You may also pass a function instead of text, which avoids quoting problems. timeit turns the garbage collector off while it times, so memory-heavy code looks cheaper than it is.

cProfile finds where the time goes

A profiler records which functions run, how often, and how long each takes. It points to the slow part of a program so you can fix that part instead of guessing.

timeit compares two versions. A profiler answers a different question: which function in a big program is the slow one? cProfile counts every call and the time spent in each function.

Python

1import cProfile2import pstats3
4def helper():5    return 16
7def main():8    for _ in range(100):9        helper()10
11profile = cProfile.Profile()12profile.runcall(main)13stats = pstats.Stats(profile)14calls = {key[2]: row[1] for key, row in stats.stats.items()}15print(calls["helper"])

Example 3 · Reading a profile table

Python

1import cProfile2import pstats3
4def parse(line):5    return line.split(",")6
7def load(lines):8    return [parse(line) for line in lines]9
10profile = cProfile.Profile()11profile.runcall(load, ["a,b,c"] * 1000)12stats = pstats.Stats(profile)13stats.sort_stats("tottime")14stats.print_stats(3)

Sample output

         2002 function calls in 0.001 seconds

   Ordered by: internal time
   List reduced from 4 to 3 due to restriction <3>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     1000    0.000    0.000    0.000    0.000 app.py:4(parse)
        1    0.000    0.000    0.001    0.001 app.py:7(load)
     1000    0.000    0.000    0.000    0.000 {method 'split' of 'str' objects}

What this code does

The table is a sample: file names and times differ on every machine.
ncalls of parse is 1000, once per line.
Read the columns tottime and cumtime first to see where to look.

Call counts are exact, so they are safe to print. The times vary. print_stats shows the table: ncalls, tottime (time inside the function itself) and cumtime (including everything it calls).

The measure, fix, measure loop

Profile to find the slowest function, change one thing, then measure again on the same data. If the number did not improve, undo the change. Clean code that is fast enough beats clever code.

Python

1import timeit2
3data = list(range(5000))4lookup = set(data)5slow = timeit.timeit(lambda: 4999 in data, number=300)6fast = timeit.timeit(lambda: 4999 in lookup, number=300)7print("set is faster:", fast < slow)

Example 4 · Finding the slowest function in code

Python

1import cProfile2import pstats3
4def heavy():5    return sum(i * i for i in range(300000))6
7def light():8    return 1 + 19
10def run():11    heavy()12    for _ in range(50):13        light()14
15with cProfile.Profile() as profile:16    run()17stats = pstats.Stats(profile)18rows = {key[2]: row[2] for key, row in stats.stats.items() if key[2] in ("heavy", "light", "<genexpr>")}19print(max(rows, key=rows.get) in ("heavy", "<genexpr>"))20print({key[2]: row[1] for key, row in stats.stats.items()}["light"])

Output

True
50

What this code does

Profile() works as a context manager from Python 3.8.
The time sits in heavy or its generator, never in light.
Call counts are exact: light ran 50 times.

The set wins by a wide margin, so the comparison is stable. Small differences of a few percent are noise: repeat the test before you believe them.

Next step

Check your understanding

12 quick questions

Measure first, then change

A benchmark is a repeatable measurement of how long code takes, run on the same data and the same machine so that two versions can be compared fairly.

Guessing what is slow wastes time. Take a clock reading before and after the code you suspect. time.perf_counter() is the right clock for short intervals.

1import time2 3def build_report(rows):4 return [row * 2 for row in rows]5 6start = time.perf_counter()7result = build_report(range(1_000_000))8elapsed = time.perf_counter() - start9print(len(result))10print(f"took {elapsed:.3f} seconds")

timeit for small snippets

timeit is the standard-library module for timing small pieces of code. It repeats the code many times and reports the total time, which is far more reliable than one stopwatch reading.

One reading is noisy. The timeit module runs a snippet many times and repeat gives several such totals. Take the smallest, the run least disturbed by other programs.

1import timeit2 3orders = list(range(2000))4ids_list = [n * 3 for n in orders]5ids_set = set(ids_list)6 7def in_list():8 return 5997 in ids_list9 10def in_set():11 return 5997 in ids_set12 13t_list = min(timeit.repeat(in_list, number=500, repeat=3))14t_set = min(timeit.repeat(in_set, number=500, repeat=3))15print("set lookup is faster:", t_set < t_list)

cProfile finds where the time goes

A profiler records which functions run, how often, and how long each takes. It points to the slow part of a program so you can fix that part instead of guessing.

timeit compares two versions. A profiler answers a different question: which function in a big program is the slow one? cProfile counts every call and the time spent in each function.

1import cProfile2import pstats3 4def helper():5 return 16 7def main():8 for _ in range(100):9 helper()10 11profile = cProfile.Profile()12profile.runcall(main)13stats = pstats.Stats(profile)14calls = {key[2]: row[1] for key, row in stats.stats.items()}15print(calls["helper"])

1import cProfile2import pstats3 4def parse(line):5 return line.split(",")6 7def load(lines):8 return [parse(line) for line in lines]9 10profile = cProfile.Profile()11profile.runcall(load, ["a,b,c"] * 1000)12stats = pstats.Stats(profile)13stats.sort_stats("tottime")14stats.print_stats(3)

2002 function calls in 0.001 seconds Ordered by: internal time List reduced from 4 to 3 due to restriction <3> ncalls tottime percall cumtime percall filename:lineno(function) 1000 0.000 0.000 0.000 0.000 app.py:4(parse) 1 0.000 0.000 0.001 0.001 app.py:7(load) 1000 0.000 0.000 0.000 0.000 {method 'split' of 'str' objects}

1import timeit2 3data = list(range(5000))4lookup = set(data)5slow = timeit.timeit(lambda: 4999 in data, number=300)6fast = timeit.timeit(lambda: 4999 in lookup, number=300)7print("set is faster:", fast < slow)

1import cProfile2import pstats3 4def heavy():5 return sum(i * i for i in range(300000))6 7def light():8 return 1 + 19 10def run():11 heavy()12 for _ in range(50):13 light()14 15with cProfile.Profile() as profile:16 run()17stats = pstats.Stats(profile)18rows = {key[2]: row[2] for key, row in stats.stats.items() if key[2] in ("heavy", "light", "<genexpr>")}19print(max(rows, key=rows.get) in ("heavy", "<genexpr>"))20print({key[2]: row[1] for key, row in stats.stats.items()}["light"])