Profiling: finding where the time actually goes before you optimise anything

Guessing is wrong more often than not

Every programmer has a story of optimising the wrong thing. The loop that looked slow was 0.3 per cent of the run; the innocent-looking line that formatted a date was called two million times. Intuition about performance is poor even in experienced people, because the cost of an operation is invisible in the source. The remedy is to measure, and Python ships the instruments.

The stopwatch

import time

t = time.perf_counter()
vectors = embed(chunks)
print(f"embed: {time.perf_counter() - t:.2f}s")

perf_counter is a high-resolution clock for measuring intervals. time.time() is wall-clock time and can jump when the system clock adjusts; do not use it for durations. The timed context manager from earlier in this module is this pattern packaged.

Put stopwatches around the three or four things you suspect, run once, and read the numbers. This alone settles most performance questions in an AI program, and the answer is usually that the network call is 95 per cent of the time and everything you were about to rewrite is noise.

timeit for small things

For a single expression, the stopwatch is too coarse — one run is dominated by noise. timeit runs it many times and reports the best:

python -m timeit -s "s = 'a' * 1000" "s.split()"

import timeit
timeit.timeit("''.join(parts)", setup="parts = ['x'] * 1000", number=10_000)

In a notebook, %timeit expr does the same with a friendlier report. Use it to settle "is a comprehension faster than a loop here" questions honestly: usually a little, occasionally not, and rarely enough to matter.

cProfile for the whole program

python -m cProfile -o run.prof -m tagger.cli input.csv
python -c "import pstats; pstats.Stats('run.prof').sort_stats('cumulative').print_stats(20)"

The output is a table of every function called: how many times, how long inside it (tottime), and how long including everything it called (cumtime). Sort by cumulative and read from the top: the first lines are your program's entry points, and a few lines down is the first function that is not merely a wrapper — that is where the time lives. Sort by tottime to find the function that is itself expensive rather than expensive because of what it calls.

Two things to know about reading it. The profiler adds overhead, so absolute numbers are inflated; the proportions are what you trust. And {built-in method ...} or {method 'read' of '_ssl._SSLSocket'} near the top means the time is being spent waiting on the network, which no Python change will fix — only fewer calls, concurrent calls, or caching.

snakeviz run.prof (pip-installable, free) draws the same data as a clickable sunburst, and is worth the install the first time a profile is more than a screen long.

The string trap, measured

One pure-Python cost that does matter and does show up:

text = ""
for part in parts:          # 100,000 parts
    text += part            # copies the growing string each time

Each += builds a new string containing everything so far, so the total work is proportional to the square of the length. "".join(parts) is one pass. At 100,000 parts the loop can take seconds and the join milliseconds — which is why module 6's streaming lesson collected fragments in a list. timeit both and you will remember it.

Import time

A command that takes two seconds to print --help is usually paying for imports. pandas alone is around half a second; torch several.

python -X importtime -c "import tagger.cli" 2> imports.log
sort -t'|' -k2 -n imports.log | tail -20

lists the slowest imports. The fix is to import heavy libraries inside the function that needs them, so --help and the fast paths do not pay for them.

Memory

import tracemalloc

tracemalloc.start()
data = load_everything(path)
current, peak = tracemalloc.get_traced_memory()
print(f"peak {peak / 1e6:.1f} MB")
tracemalloc.stop()

peak is the number that matters: it is what the machine had to have. For a closer look, tracemalloc.take_snapshot().statistics("lineno")[:10] shows the ten lines that allocated the most. When a process is killed on a small server with no traceback, this is how you find out which structure grew.

sys.getsizeof(obj) reports one object's own size and not what it references; a list of a million strings reports the list, not the strings. It is fine for "how big is this array" and misleading for containers.

The order of operations

1. Measure with a stopwatch. Find the 80 per cent.
2. If it is the network: fewer calls (cache, batch), overlapped calls (module 6), or a smaller model. Nothing else helps.
3. If it is your Python: profile, find the top function, and look for a better algorithm or a NumPy replacement before micro-optimising syntax.
4. Measure again. Keep the change only if the number moved.

Step four is the one people skip. A change that made the code harder to read and the run two seconds faster out of fourteen minutes should be reverted, and only the number tells you that.

Try this now

Profile your tagging script with cProfile, sort by cumulative, and write down what fraction of the total is inside the HTTP library. Then timeit string concatenation against join at 10,000 parts, and -X importtime your CLI to see what --help is paying for.