Profile the application¶

A benchmark says whether performance changed; it does not say where time went. We will now profile the complete word-count call, rank functions by their contribution, and resist optimizing the most visually complicated code unless the data points there.

Objectives

Capture deterministic function-level data with cProfile.
Interpret call count, internal time, and cumulative time in pstats.
Select a call path for deeper investigation.

Instructor note

15 min teaching
15 min type-along
10 min exercise and discussion

Deterministic profiling¶

cProfile records function calls and elapsed time. Run the prepared driver from the code directory:

$ cd content/episodes/code
$ python profile_wordcount.py --implementation slow

It writes wordcount-slow.prof and prints a table sorted by cumulative time. Generated profile files are evidence, not source, and are ignored by Git.

Important columns are:

ncalls: calls made, sometimes shown as primitive/total for recursion;
tottime: time in the function body, excluding subcalls;
percall: time divided by calls;
cumtime: time in the function and everything it called;
filename:lineno(function): the measured callable.

A coordinator often has high cumulative time and low internal time. A leaf function with high internal time can be a better optimization candidate.

Create a smaller profile in the notebook. The profile is written under the ignored build directory so it cannot be mistaken for course source:

from pathlib import Path
import sys

code_dir = next(
    path.resolve()
    for path in (Path("content/episodes/code"), Path("../content/episodes/code"))
    if path.is_dir()
)
if str(code_dir) not in sys.path:
    sys.path.insert(0, str(code_dir))

from profile_wordcount import create_profile

runtime_dir = Path("_build/notebook-runtime")
runtime_dir.mkdir(parents=True, exist_ok=True)
profile_path = create_profile(
    runtime_dir / "wordcount-notebook.prof", workload_repeats=2_000
)
profile_path.name

Before printing a table, predict which functions should have many calls and which should have large cumulative time. Predictions turn the report into a test of a model rather than a wall of numbers.

Type-along: ask focused questions¶

Start an interactive session in content/episodes/code:

import pstats

stats = pstats.Stats(str(profile_path))
stats.strip_dirs().sort_stats("cumulative").print_stats(12)
stats.sort_stats("tottime").print_stats(12)
stats.print_callers("normalize_slow")

Sorting is a question, not cosmetic formatting. Cumulative order finds expensive call paths; internal-time order highlights work performed in function bodies; callers and callees explain relationships.

Read one row aloud as a sentence: “under this workload, this function was called this many times and accounted for this much measured internal or cumulative time.” Adding the boundary and workload prevents a local profile from becoming an unsupported claim about every run of the application.

Other useful entry points are:

$ python -m cProfile -o wordcount-slow.prof wordcount.py

and, in IPython:

from wordcount import count_words, make_workload
text = make_workload(2_000)
%prun -s cumulative count_words(text)

Profiling adds overhead, especially around frequently called tiny functions. Use it to rank costs, then return to the benchmark for the final comparison.

Follow a call path, not just a name¶

A function can appear expensive because it performs work itself or because it coordinates expensive callees. Start with cumulative time to locate a costly path, compare internal time, and then inspect callers or callees. This avoids rewriting a coordinator whose own work is negligible. It also explains why a profile is not a substitute for understanding the code path and its data.

Exercise

Compare the tables sorted by cumulative and internal time. Which function would you investigate next, and what evidence—not intuition—supports that choice?

Solution

On the supplied workload, normalize_slow and its repeated string replacement work should appear prominently. Exact times and ranks can vary, but a defensible answer names the table, sort order, workload, and observed contribution. If another function dominates on your system, investigate that evidence instead.

Keypoints

Benchmark to compare; profile to locate.
Internal and cumulative time answer different questions.
Profiler output is an investigation map, not proof of a final speedup.