intermediate30 minby DevFox

Profiling Before Optimising

Measuring where time actually goes: timeit for micro-questions, cProfile for real programs, reading the output, and the optimisation that made everything slower.

Python
Performance

The nightly job takes forty minutes. You are certain the bottleneck is the image resizing, because it is the heaviest thing in there, so you spend two days making it faster. The job now takes thirty-nine minutes. The actual cost was a database lookup inside a loop, running four hundred thousand times, which you never looked at because it was one line and looked cheap.

Everyone guesses wrong about performance, including people who have been doing it for twenty years. By the end of this lesson you will measure first, read a profile, know which numbers mean what, and — the part that matters more than any tool — know when not to optimise at all.

Measure, then change

The order is not a courtesy. Guessing wastes the effort, and it also frequently makes the code worse: the optimisation you were sure about adds complexity, and the complexity stays even when the speedup does not arrive.

Three questions, in order:

Is it too slow? Against a requirement, not a feeling. A job with an hour's window that takes forty minutes is fine, and making it faster is work with no value.

Where does the time actually go? Measured, not reasoned about.

Is the fix worth its cost? In complexity, in readability, in the bugs that come with both.

Skipping the first question is the most expensive mistake, and it is the most common.

Timing something small

For a single expression, timeit runs it many times and reports the best:

python

import timeit

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

Running once tells you almost nothing — a single measurement includes whatever else the machine was doing. timeit repeats and takes the minimum, which is the closest thing to "how fast can this go".

For a block in a real program, perf_counter is the tool, and it is a monotonic clock rather than the wall clock, per the dates lesson:

python

from contextlib import contextmanager
import time

@contextmanager
def timed(label):
    start = time.perf_counter()
    try:
        yield
    finally:
        log.info("%s took %.3fs", label, time.perf_counter() - start)

python

with timed("resizing"):
    resize_all(photos)

That is the context manager from earlier in this course, and it is often all the instrumentation a program needs.

Profiling a whole program

cProfile measures every function call:

bash

python -m cProfile -o profile.out -m photo_tools.main photos/

python

import pstats

stats = pstats.Stats("profile.out")
stats.sort_stats("cumulative").print_stats(20)

text

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.001    0.001   38.412   38.412 main.py:40(build_report)
   400000    0.812    0.000   36.223    0.000 loading.py:12(load_photo)
   400000    0.501    0.000   35.104    0.000 db.py:88(fetch_metadata)
   400000   34.603    0.000   34.603    0.000 {built-in method connect}
      400    1.204    0.003    1.204    0.003 resize.py:22(resize)

Two columns, and the difference between them is the whole skill.

cumtime

Tells you where the time goes.

Time in the function and everything it called. Sort by this to follow the path down from the top.

load_photo at 36 of 38 seconds — so the time is somewhere under there.

tottime

Tells you what is spending it.

Time in the function itself, excluding its calls. Sort by this to find the line actually doing the work.

connect at 34.6 seconds across four hundred thousand calls.

Both columns are in every profile, and reading the wrong one sends you to the wrong function

And there it is: the code opens a database connection per photo.

connect — one per photo0s

resize0s

everything else0s

Where those 38 seconds actually went — the resizing everyone suspected is the third bar

Two days of work on the resizing would have bought three percent.

python

stats.sort_stats("tottime").print_stats(20)
stats.print_callers("fetch_metadata")     # who calls this?

snakeviz renders the same data as an interactive chart, which is easier to read for anything large.

Fix the algorithm first

Bad — micro-optimising inside a bad shape.

python

known = load_all_names()                  # a list of 400,000

for photo in photos:                      # 400,000
    if photo.name in known:               # scans the list each time
        continue
    process(photo)

Good — changing the shape.

python

known = set(load_all_names())             # one word different

for photo in photos:
    if photo.name in known:               # constant time
        continue
    process(photo)

The first version performs up to 160 billion comparisons. Rewriting the loop body in a cleverer way, caching parts of it, or rewriting process in C changes a constant factor on a number that large and achieves nothing measurable. The second changes how the work grows — from proportional to the product of the two sizes to proportional to their sum — and takes seconds instead of hours.

The order to try things:

text

1. do it less often     caching, batching, not doing it at all
2. change the algorithm a set instead of a list; sort once
3. use a better library numpy, a real database index
4. micro-optimise       last, and rarely worth it

Most real speedups in Python come from levels one and two. Level four is where people start, which is why they are disappointed.

The database inside the loop

The single most common performance bug in application code, and worth naming because you will meet it repeatedly:

python

for photo in photos:                       # 400,000 queries
    meta = db.fetch_metadata(photo.id)

python

metadata = db.fetch_metadata_bulk([p.id for p in photos])   # one
for photo in photos:
    meta = metadata[photo.id]

Each individual query is fast, which is exactly why it hides — nothing in the code looks expensive. The cost is the round trip, multiplied. The same shape appears with HTTP calls, file opens and any other per-item I/O, and the fix is always the same: move the work out of the loop and do it in bulk.

Memory, and the other cost

Sometimes the problem is not time:

python

import tracemalloc

tracemalloc.start()
build_report(folder)
current, peak = tracemalloc.get_traced_memory()
print(f"peak: {peak / 1_000_000:.1f} MB")
tracemalloc.stop()

The usual fix is the generators lesson: stop building a list you walk once. Building the whole result before returning it is the memory equivalent of the connection-per-photo bug — invisible in the code, decisive at scale.

functools.lru_cache trades memory for time and is often the cheapest speedup available, provided it is bounded. An unbounded @cache on a function with varied arguments is a memory leak with a nice interface.

When not to

Optimisation has costs that do not show up in the benchmark. Faster code is usually less obvious code, and less obvious code is where bugs live and where the next person slows down.

It is already fast enough
Measured against the requirement, not against how it feels while you watch it.
You have not measured it
Every profile in this lesson exists because the obvious suspect was the wrong one.
It runs once a day for ten seconds
Whatever the graph says, nothing downstream is waiting.
It is not correct yet
You may be about to make the wrong answer arrive faster.

Four times the honest answer is to leave it alone

When you do, leave evidence:

python

# A dict keyed by name rather than a scan: this runs per photo
# and the linear version took 34s of a 38s job. See PERF-214.
by_name = {photo.name: photo for photo in photos}

The next reader will otherwise see an unnecessary-looking dictionary and tidy it away.

A cheat sheet to keep

text

THE ORDER
  1. is it too slow?      against a requirement, not a feeling
  2. where does time go?  measured, never guessed
  3. is the fix worth it? complexity is a real cost

MEASURING
  timeit.timeit(stmt, number=10_000)     one small expression
  time.perf_counter()                    a block, monotonic
  a `timed` context manager              often enough on its own

PROFILING
  python -m cProfile -o out.prof -m yourmodule
  pstats.Stats("out.prof").sort_stats("cumulative").print_stats(20)

  cumtime   includes callees   -> WHERE the time goes
  tottime   excludes callees   -> WHAT is spending it
  print_callers("f")           who calls this

  cProfile distorts; confirm with a plain timed run
  py-spy samples a RUNNING process, including in production

FIX IN THIS ORDER
  1. do it less often      cache, batch, or not at all
  2. change the algorithm  set not list; sort once; index
  3. a better library      numpy, a database index
  4. micro-optimise        last, rarely worth it

THE TWO CLASSIC BUGS
  `in` a list inside a loop      -> make it a set
  a query per item in a loop     -> fetch in bulk, once
  both look cheap on the line they are written

MEMORY
  tracemalloc for the peak
  generators instead of building a list you walk once
  lru_cache(maxsize=...) - bounded, or it is a leak

DO NOT
  optimise what is fast enough
  optimise without measuring
  optimise before it is correct
  leave a tuned path uncommented, or without a benchmark

Where to go next

You can now find where time actually goes rather than where it seems it should, read the two columns that distinguish "where" from "what", and reach for the algorithmic fix before the clever one. The habit worth keeping is the first question — most performance work should not happen, and asking whether it is too slow against a real requirement is what tells you.

That closes Python in Practice. You started this course able to write Python and now have the things a working codebase demands: isolated environments and reproducible installs, a package others can depend on, types a checker can verify, data that describes itself, exceptions callers can aim at, generators, context managers and decorators, tests that assert on behaviour, logs you can search, validated configuration, and the discipline to measure before changing.

Next is Advanced Python, which goes underneath all of it — the data model that makes your objects behave like built-in ones, descriptors and the import system, how memory and the GIL actually work, asyncio from the event loop up, and what it takes to write a library other people depend on.

Before you move on, profile something you wrote. Not something you suspect is slow — anything at all. The gap between where you expected the time to be and where it is, in your own code, is the most persuasive argument for measuring that exists.