Measuring Real Programs

Measure, don’t guess

Big-O tells you how an algorithm’s time grows. It doesn’t tell you how long a real program takes, or which part of it is slow: the constants it hides depend on the language, the machine, and the memory hierarchy, and a timing result holds only for the machine it was measured on ¹. Guessing which part of a program is slow is unreliable, so the method is:

1. Time the whole program, so you know where you’re starting.
2. Profile it to find where the time actually goes.
3. Fix the biggest part.
4. Measure again, to confirm the fix helped and nothing else broke.

Step 2 is what saves effort. If a function takes 5% of the running time, even making it infinitely fast saves only 5%.

Timing a whole program

Bash’s time (module 4) reports wall time, real, and CPU time, user and sys ². For memory, there’s also the separate GNU time program; since bash’s built-in time comes first, run it by its path, /usr/bin/time. With -v it reports, among much else, the program’s maximum resident set size: the most physical memory it used at once, in kilobytes ³.

time python3 dupes.py
/usr/bin/time -v python3 dupes.py

Timing small pieces

To compare two ways of writing a few lines, use Python’s timeit. It runs the code many times, repeats the whole measurement five times, and reports the best, which avoids several common mistakes, such as timing a single run or counting setup work ⁴. -s gives setup code that runs once and isn’t timed ⁴. On a desktop PC:

me@linuxbox:~$ python3 -m timeit -s "data = list(range(1000))" "total = 0" "for x in data: total += x"
20000 loops, best of 5: 12.9 usec per loop
me@linuxbox:~$ python3 -m timeit -s "data = list(range(1000))" "sum(data)"
100000 loops, best of 5: 3.37 usec per loop
me@linuxbox:~$ python3 -m timeit -s "data = list(range(1000))" "[x * 2 for x in data]"
20000 loops, best of 5: 14.9 usec per loop
me@linuxbox:~$ python3 -m timeit -s "data = list(range(1000))" "out = []" "for x in data: out.append(x * 2)"
20000 loops, best of 5: 17.4 usec per loop

Each extra argument is another line of the statement being timed. Read the output as: the statement ran 20,000 times per measurement, the measurement was repeated 5 times, and the best average was 12.9 microseconds per run ⁴. The built-in sum is almost four times faster than a loop doing the same O(n) work, and a list comprehension beats a loop calling append. Same big-O, different constants: built-ins run in C.

Profiling

A profiler records how many times each function was called and how long it took ⁵. Python’s is cProfile, which you can run on any script without changing it ⁵. Here’s a program that finds which visitor IDs appear more than once in a fake log of 40,000 lines. Save it as dupes.py:

# dupes.py: which visitor IDs appear more than once in a day's log?

def make_log(n):
    """Fake log lines; squares wrap around, so some IDs repeat."""
    return [f"visitor-{(i * i) % 19997}" for i in range(n)]

def find_repeats(lines):
    seen, repeats = [], []
    for line in lines:
        if line in seen:                # seen is a list: this checks every item so far
            if line not in repeats:
                repeats.append(line)
        else:
            seen.append(line)
    return repeats

def summarize(repeats):
    return sorted(repeats)[:3]

lines = make_log(40_000)
repeats = find_repeats(lines)
print(len(repeats), "repeated visitors, first few:", summarize(repeats))

Run it under the profiler, sorted by cumulative time:

me@linuxbox:~$ python3 -m cProfile -s cumulative dupes.py
9999 repeated visitors, first few: ['visitor-0', 'visitor-1', 'visitor-10']
         20007 function calls in 1.548 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    1.548    1.548 {built-in method builtins.exec}
        1    0.000    0.000    1.548    1.548 dupes.py:1(<module>)
        1    1.542    1.542    1.543    1.543 dupes.py:7(find_repeats)
        1    0.004    0.004    0.004    0.004 dupes.py:3(make_log)
    19998    0.001    0.000    0.001    0.000 {method 'append' of 'list' objects}
        1    0.000    0.000    0.001    0.001 dupes.py:17(summarize)
        1    0.001    0.001    0.001    0.001 {built-in method builtins.sorted}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
        1    0.000    0.000    0.000    0.000 {built-in method builtins.print}
        1    0.000    0.000    0.000    0.000 {built-in method builtins.len}

The columns ⁵:

• ncalls: how many times the function was called.
• tottime: time spent in the function’s own code, not counting functions it called.
• cumtime: time in the function and everything it called.
• percall: the time divided by the number of calls.

The top lines, exec and <module>, are just the whole script. The story is in find_repeats: 1.542 seconds of its own time out of 1.548, 99.6% of the program. Making the log or sorting the results doesn’t matter at all.

Why is it slow? line in seen on a list is O(n), done once per line, so the whole loop is O(n²): last module’s list-versus-set problem, hiding in a real program. The fix is to make both seen and repeats sets:

def find_repeats(lines):
    seen, repeats = set(), set()
    for line in lines:
        if line in seen:                # seen is a set: one hash lookup
            repeats.add(line)
        else:
            seen.add(line)
    return repeats

Then measure again:

me@linuxbox:~$ python3 -m cProfile -s cumulative dupes.py
9999 repeated visitors, first few: ['visitor-0', 'visitor-1', 'visitor-10']
         40009 function calls in 0.012 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.012    0.012 {built-in method builtins.exec}
        1    0.000    0.000    0.012    0.012 dupes.py:1(<module>)
        1    0.004    0.004    0.007    0.007 dupes.py:7(find_repeats)
        1    0.004    0.004    0.004    0.004 dupes.py:3(make_log)

Same answer, 1.548 seconds down to 0.012: over a hundred times faster, from changing the data structure, and with ten times more lines the gap would be over a thousand times. Note that a profiler slows down the code it watches; use it to find where time goes, and timeit or time for the real numbers ⁵.

When big-O isn’t the whole story

Big-O describes large n. For small inputs, the constant costs it ignores, such as function calls, building new lists, and Python’s own overhead, can decide the race. This program times last lesson’s two sorts on tiny lists. Save it as small.py, next to sorts.py:

# small.py: on tiny inputs, does O(n^2) insertion sort lose to O(n log n) merge sort?
import random
import timeit

from sorts import insertion_sort, merge_sort

random.seed(5)
print(f"{'n':>5}  {'insertion':>10}  {'merge':>10}   (microseconds per sort)")
for n in (8, 16, 32, 64, 128, 256):
    data = [random.random() for _ in range(n)]
    ins = min(timeit.repeat(lambda: insertion_sort(data), number=200, repeat=5)) / 200 * 1e6
    mrg = min(timeit.repeat(lambda: merge_sort(data), number=200, repeat=5)) / 200 * 1e6
    print(f"{n:>5}  {ins:>10.1f}  {mrg:>10.1f}")

me@linuxbox:~$ python3 small.py
    n   insertion       merge   (microseconds per sort)
    8         1.0         2.9
   16         3.0         6.9
   32         9.6        16.0
   64        37.0        36.0
  128       166.7        81.0
  256       626.1       177.9

Below about 64 items, the “worse” O(n²) sort wins: merge sort pays for its recursive calls and new lists on every split. Above that, n² takes over, and by 256 items insertion sort is three and a half times slower. Real sorts use both: Python’s sort extends short runs to a minimum length with insertion sort before merging them, and its authors found minimum lengths of 16 to 128 worked about equally well on random data ⁶.

Other constants that big-O ignores, from earlier modules:

• The memory hierarchy: summing the same ten million numbers took almost six times longer in a random order than in order (module 3). Same O(n), different use of the cache.
• The language: Python’s sorted() beat our merge sort by about twenty times, because it’s the same kind of algorithm written in C.
• System calls: a million one-byte writes took thirty times longer than buffered ones (module 4).

Big-O decides what happens at scale; measurement decides everything else.

Your turn

So

Measure, don’t guess: time the whole program, profile to find where the time goes, fix the biggest part, and measure again. time and /usr/bin/time -v measure whole programs, including memory; timeit compares small pieces of code; cProfile shows each function’s calls, own time (tottime), and total time (cumtime). In the example, one O(n²) list scan took 99.6% of the time, and sets made the program over a hundred times faster. Big-O wins at scale, but constants, from function calls to caches to C versus Python, decide small inputs, which is why real sorts combine insertion sort and merge sort.