Profiling Python Code: Measure Before You Optimize

Don't guess where your code is slow. Measure. Most of the time the slow part is not where you expected, and optimizing the part you suspected only makes that code harder to read while the program stays just as slow.

First: is it actually too slow?

"Slow" needs a number and a reason. A nightly job that takes 40 seconds is fine. A web page that takes 4 seconds is not. Write down how long it takes now and how long it needs to take. If you can't say why the second number matters, stop here. Faster code that nobody needed is time you could have spent on something else.

The example

A report script that loads 20,000 orders, counts unique SKUs and totals the amounts. The data is generated with a fixed seed so the result is the same every run:

# report.py
import random


def load_orders(n):
    rng = random.Random(42)
    return [{"id": i, "sku": f"SKU-{rng.randint(1, 5000)}", "amount": rng.randint(100, 5000)}
            for i in range(n)]


def unique_skus(orders):
    seen = []
    for order in orders:
        if order["sku"] not in seen:
            seen.append(order["sku"])
    return seen


def total_amount(orders):
    return sum(order["amount"] for order in orders)


def main():
    orders = load_orders(20_000)
    print(len(unique_skus(orders)), "unique SKUs")
    print(total_amount(orders), "total")


if __name__ == "__main__":
    main()

If you had to guess, you might pick the random data generation, since it makes 40,000 random numbers. Let's see.

Step 1: profile the whole program with cProfile

cProfile is in the standard library. It records every function call and how long it took:

import cProfile
import pstats

import report

cProfile.run("report.main()", "report.prof")
stats = pstats.Stats("report.prof")
stats.sort_stats("cumulative").print_stats("report.py")

4915 unique SKUs
51060787 total
...
   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    ...report.py:23(main)
        1    ...report.py:11(unique_skus)
        1    ...report.py:5(load_orders)
        1    ...report.py:19(total_amount)
...

The numbers are replaced with "..." above because they differ on every computer. On the machine this course was tested on, the run took about half a second, and unique_skus was about 0.37 seconds of it, roughly three quarters of the total. load_orders, the one you might have guessed, took about 0.1 seconds. Run it and look at your own numbers; the ranking should be the same.

How to read the columns:

• ncalls: how many times the function was called.
• tottime: time spent inside the function itself, not counting functions it called.
• cumtime: time including everything it called. Sorting by this shows which top-level step is expensive. Sorting by tottime shows where the actual work happens.

You can also profile a script without changing it: python -m cProfile -s cumulative report.py. The output includes every function from every library, so it is longer; the print_stats("report.py") filter above keeps only your own code.

Step 2: understand why it is slow

order["sku"] not in seen checks a list. A list has no index, so in compares against every item, one by one. With about 5,000 unique SKUs, each of the 20,000 orders compares against up to 5,000 items. That is tens of millions of comparisons for a job that needs 20,000 lookups. A set finds an item directly, in about the same time no matter how big it is.

Step 3: compare the fix with timeit

timeit runs a small piece of code many times and reports the total, which smooths out random noise:

import timeit

from report import load_orders, unique_skus


def unique_skus_fast(orders):
    seen = set()
    result = []
    for order in orders:
        if order["sku"] not in seen:
            seen.add(order["sku"])
            result.append(order["sku"])
    return result


orders = load_orders(20_000)
assert unique_skus_fast(orders) == unique_skus(orders)   # same result, same order

slow = timeit.timeit(lambda: unique_skus(orders), number=5)
fast = timeit.timeit(lambda: unique_skus_fast(orders), number=5)
print(f"set version is {slow / fast:.0f}x faster")

set version is ...x faster

On the test machine, the set version was more than a hundred times faster. Your exact number will be different; the gap will still be huge. Notice the assert before the timing. A faster function that returns a different result isn't an optimization, it is a new bug. The fast version keeps a list too, so the SKUs stay in the order they were first seen, exactly like the original.

Step 4: profile again

After the fix, the profile looks different: load_orders is now the biggest part. Is it worth optimizing? It runs once and takes a fraction of a second. Probably not. This is where you stop. Optimizing has diminishing returns, and each step makes the code a little less obvious.

What usually matters

In everyday business code, the big wins are rarely clever micro-tricks. They are usually:

• The wrong data structure. Like the list lookup above. in on a list inside a loop is the classic.
• Doing the same work again and again. Reading a file or calling an API inside a loop when once would do. functools.cache helps when the same inputs repeat.
• One database query per row. 10,000 small queries instead of one query that fetches 10,000 rows.
• Waiting. If the profile shows most time in network or disk calls, the fix is concurrency (previous section), not faster Python.

Common mistakes

• Optimizing without profiling. The point of this whole lesson.
• Measuring once. One run can be slowed by anything else on the computer. timeit repeats for that reason.
• Profiling with tiny test data. With 50 orders, the list version is fast too. Profile with data the size of production, or the bottleneck doesn't show.
• Reading profiler times as exact. Profiling adds overhead to every call, so absolute times are inflated. Use them to compare functions, not as the real runtime.

What happens if you skip this step

You spend a day rewriting the part you thought was slow, the code gets harder to read, and the program is exactly as slow as before, because the real problem was a list lookup in a function you never looked at. Ten minutes of profiling would have pointed straight at it.

What is the slowest thing your code does today, and are you guessing, or did you measure it?