Profiling: timeit, cProfile and tracemalloc

Measuring a small snippet

import timeit

print(timeit.timeit("'-'.join(str(n) for n in range(100))", number=10_000))
print(timeit.timeit("'-'.join([str(n) for n in range(100)])", number=10_000))
print(timeit.timeit("'-'.join(map(str, range(100)))", number=10_000))

0.98      generator expression
0.86      list comprehension
0.63      map

import timeit

setup = "data = list(range(1000))"

print(min(timeit.repeat("sum(data)", setup=setup, number=10_000, repeat=5)))
print(min(timeit.repeat("sum(x for x in data)", setup=setup,
                        number=10_000, repeat=5)))

Use repeat and take the minimum, not the average. The minimum is the run least disturbed by other activity on the machine, so it is the most reproducible number.

python -m timeit "sum(range(100))"
python -m timeit -s "data = list(range(1000))" "sum(data)"
python -m timeit -n 1000 -r 5 "'-'.join(map(str, range(100)))"

Timing real code

import time
from contextlib import contextmanager


@contextmanager
def timed(label):
    start = time.perf_counter()
    try:
        yield
    finally:
        print(f"{label}: {time.perf_counter() - start:.4f}s")


with timed("building"):
    data = [i * i for i in range(1_000_000)]

with timed("summing"):
    total = sum(data)

import time
from functools import wraps


def timed(func):
    @wraps(func)
    def wrapper(*args, **kwargs):
        start = time.perf_counter()
        try:
            return func(*args, **kwargs)
        finally:
            wrapper.total += time.perf_counter() - start
            wrapper.calls += 1

    wrapper.total = 0.0
    wrapper.calls = 0
    wrapper.report = lambda: (
        f"{func.__name__}: {wrapper.calls} calls, {wrapper.total:.4f}s, "
        f"{wrapper.total / max(wrapper.calls, 1) * 1000:.3f}ms each"
    )
    return wrapper


@timed
def work(n):
    return sum(i * i for i in range(n))


for _ in range(5):
    work(100_000)

print(work.report())

Always use time.perf_counter() for durations. time.time() follows the system clock, which can be adjusted while your code runs, producing a wrong or even negative interval.

cProfile: where the time actually goes

import cProfile
import pstats
from io import StringIO


def slow_part(n):
    return [i ** 2 for i in range(n)]


def slower_part(n):
    total = 0
    for i in range(n):
        total += sum(range(100))
    return total


def main():
    slow_part(200_000)
    slower_part(2_000)
    return "done"


profiler = cProfile.Profile()
profiler.enable()
main()
profiler.disable()

stream = StringIO()
stats = pstats.Stats(profiler, stream=stream).sort_stats("cumulative")
stats.print_stats(8)
print(stream.getvalue())

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.001    0.001    1.240    1.240 app.py:14(main)
        1    0.005    0.005    1.150    1.150 app.py:8(slower_part)
     2000    1.140    0.001    1.145    0.001 {built-in method builtins.sum}
        1    0.085    0.085    0.089    0.089 app.py:4(slow_part)

Sort by cumtime to find which high level operation is slow. Sort by tottime to find the function doing the actual work.

python -m cProfile -s cumtime app.py
python -m cProfile -s tottime app.py
python -m cProfile -o profile.out app.py

import pstats

stats = pstats.Stats("profile.out")
stats.sort_stats("tottime").print_stats(10)
stats.print_callers("slow_function")       # who calls it
stats.print_callees("slow_function")       # what it calls

A profiling context manager

import cProfile
import pstats
from contextlib import contextmanager
from io import StringIO


@contextmanager
def profiled(rows=10, sort="cumulative"):
    profiler = cProfile.Profile()
    profiler.enable()
    try:
        yield profiler
    finally:
        profiler.disable()
        stream = StringIO()
        pstats.Stats(profiler, stream=stream).sort_stats(sort).print_stats(rows)
        print(stream.getvalue())


with profiled(rows=5):
    total = sum(sum(range(100)) for _ in range(5_000))

Profiling line by line, by hand

import time


def analyse(records):
    marks = {}

    start = time.perf_counter()
    cleaned = [r.strip().lower() for r in records]
    marks["clean"] = time.perf_counter() - start

    start = time.perf_counter()
    unique = list(dict.fromkeys(cleaned))
    marks["dedupe"] = time.perf_counter() - start

    start = time.perf_counter()
    ordered = sorted(unique)
    marks["sort"] = time.perf_counter() - start

    total = sum(marks.values())
    for label, seconds in marks.items():
        print(f"  {label:<8}{seconds:.4f}s  {seconds / total:6.1%}")
    return ordered


analyse([f"  Item{i % 5000}  " for i in range(200_000)])

Memory profiling

import tracemalloc

tracemalloc.start()

small = [i for i in range(1000)]
large = [[i] * 100 for i in range(5_000)]

snapshot = tracemalloc.take_snapshot()
for stat in snapshot.statistics("lineno")[:3]:
    print(stat)

current, peak = tracemalloc.get_traced_memory()
print(f"current {current / 1024 / 1024:.1f} MB, peak {peak / 1024 / 1024:.1f} MB")
tracemalloc.stop()

import tracemalloc

tracemalloc.start()
before = tracemalloc.take_snapshot()

leaked = [str(i) * 100 for i in range(20_000)]

after = tracemalloc.take_snapshot()
for stat in after.compare_to(before, "lineno")[:3]:
    print(stat)

tracemalloc.stop()

compare_to shows what grew between two points, which is how you locate the code responsible for memory growth rather than guessing.

A method for optimising

1. Make it work. Correct first, always.
2. Decide whether it is too slow. If nobody is waiting, stop here.
3. Measure. Profile the real workload, not a guess about it.
4. Find the one hot spot. Almost always a small part of the code accounts for most of the time.
5. Improve the algorithm first. O(n²) to O(n) beats every constant factor.
6. Measure again. Confirm the change helped, and by how much.
7. Stop when it is fast enough. Readable code has value too.

import time


def benchmark(label, func, *args, repeats=3):
    """Run a function several times and report the best result."""
    best = float("inf")
    for _ in range(repeats):
        start = time.perf_counter()
        result = func(*args)
        best = min(best, time.perf_counter() - start)
    print(f"{label:<24}{best:.4f}s")
    return result


def version_one(data):
    result = []
    for item in data:
        if item not in result:
            result.append(item)
    return result


def version_two(data):
    seen = set()
    result = []
    for item in data:
        if item not in seen:
            seen.add(item)
            result.append(item)
    return result


def version_three(data):
    return list(dict.fromkeys(data))


data = [i % 3000 for i in range(30_000)]

a = benchmark("nested scan", version_one, data)
b = benchmark("set tracking", version_two, data)
c = benchmark("dict.fromkeys", version_three, data)

assert a == b == c          # the optimisation must not change the answer

Note the assertion. Every optimisation must be checked against the original for identical output. A faster wrong answer is not an improvement.

Comparing implementations properly

import timeit

setup = """
data = [
    {"name": f"user{i}", "score": (i * 37) % 100}
    for i in range(2000)
]
"""

approaches = {
    "loop": """
result = []
for r in data:
    if r["score"] > 50:
        result.append(r["name"])
""",
    "comprehension": 'result = [r["name"] for r in data if r["score"] > 50]',
    "filter and map": 'result = list(map(lambda r: r["name"], filter(lambda r: r["score"] > 50, data)))',
}

for label, code in approaches.items():
    best = min(timeit.repeat(code, setup=setup, number=500, repeat=3))
    print(f"{label:<16}{best:.4f}s")

Pitfalls when measuring

import timeit

# Wrong: the setup work is inside the timed code
print(timeit.timeit("sorted(list(range(1000)))", number=1000))

# Right: only the operation under test is timed
print(timeit.timeit("sorted(data)", setup="data = list(range(1000))", number=1000))

import timeit

# Wrong: the list is already sorted after the first run
print(timeit.timeit("data.sort()", setup="data = list(range(1000))", number=1000))

# Right: fresh data each time
print(timeit.timeit("sorted(data)",
                    setup="import random; data = [random.random() for _ in range(1000)]",
                    number=1000))

• Exclude setup from the timed section.
• Beware operations that mutate their input, so later runs are not comparable.
• Measure on realistic data sizes; conclusions from ten items do not transfer.
• Profiling adds overhead, so relative figures matter more than absolute ones.
• Run enough repetitions that the timing is stable.

Import time

python -X importtime -c "import json, csv, sqlite3"

import time (self) | cumulative | imported package
       412 |        412 |   json.decoder
      1830 |       3244 | json
       895 |        895 | csv

For a command line tool that runs in under a second, import time can dominate. Moving a heavy import inside the one function that needs it is a legitimate and measurable fix.

Common mistakes

• Optimising without measuring, and improving the wrong thing.
• Using time.time() to measure a duration.
• Timing setup code along with the operation.
• Drawing conclusions from a single run.
• Benchmarking on ten items and deploying on ten million.
• Rewriting readable code for a gain nobody will notice.
• Failing to check that the optimised version still produces the same result.

Best practices

• Profile the real workload before changing anything.
• Use timeit for snippets and cProfile for programs.
• Take the minimum of several runs.
• Fix the algorithm before the constants.
• Assert that the fast version matches the slow one.
• Keep a benchmark you can re-run, so a future change cannot quietly undo the gain.

Practice

1. Compare three ways of building a string from 10 000 numbers using timeit.
2. Profile a script of your own with cProfile and identify the top three functions.
3. Write a timing context manager and use it to break a function into stages.
4. Use tracemalloc to find the line allocating the most memory in a script.
5. Optimise a slow function, then prove with an assertion that the output is unchanged.

Conclusion

Measure, then change, then measure again. timeit compares snippets, cProfile finds the hot spot, tracemalloc finds the memory. Programmers guess the slow part wrongly often enough that the measurement is never wasted.