A slow endpoint is not evidence that its longest function is the problem. It might call a small function ten million times, wait on a database, serialize an unexpectedly large response, or spend nearly everything below a library boundary. Until you observe the whole workload, rewriting the most suspicious loop is guesswork.

Profiling and benchmarking answer different questions. A profiler asks where did this run spend instrumented time? A benchmark asks how long does a defined operation take under controlled conditions? Profile to find candidates. Benchmark without the profiler to decide whether a change helped.

This tutorial uses only the standard library. Put each complete listing in the named file and run it from the repository root.

Test environment. Results were recorded with .venv/bin/python, CPython 3.14.7, arm64, macOS 26.5.2, traditional GIL enabled, optimization level 0, and a non-debug build. Ordinary background applications were running. Profiler timings are especially environment-dependent; reproduce the commands and expect different numbers.

Experiment 1: profile a representative command

Create profile_words.py:

def normalize(text):
    return "".join(
        ch.lower() if ch.isalnum() else " " for ch in text
    ).split()


def score_document(text, stop_words):
    counts = {}
    for word in normalize(text):
        if word not in stop_words:
            counts[word] = counts.get(word, 0) + 1
    return sorted(
        counts.items(), key=lambda item: (-item[1], item[0])
    )[:10]


def main():
    document = (
        "Python profiling finds repeated work and slow algorithms. "
        * 2_000
    )
    stop_words = {"and", "work"}
    results = [score_document(document, stop_words) for _ in range(20)]
    assert all(result == results[0] for result in results)


if __name__ == "__main__":
    main()

Capture binary statistics rather than relying only on terminal output:

.venv/bin/python -m cProfile -o words.prof profile_words.py
.venv/bin/python -m pstats words.prof

At the pstats prompt, enter:

strip
sort cumulative
stats 10
quit

Our run recorded about 6.84 million calls in 1.19 seconds. score_document was called only 20 times, but its path generated millions of character operations. That is already more actionable than "the request feels slow."

Use production-shaped input: comparable record counts, text lengths, hit rates, enabled features, and cache state. Preserve output assertions so a "faster" trial cannot silently do less work. Remove credentials and personal data, but do not replace a million-row skewed workload with ten tidy records and call it representative.

Experiment 2: read the columns correctly

A deterministic profiler records events such as function calls and returns. cProfile aggregates those events into a table. The important columns are related but not interchangeable:

| Column | Meaning | |---|---| | ncalls | Calls observed; recursion may display primitive/total calls | | tottime | Time in the function's own body, excluding subcalls | | percall after tottime | tottime / total calls | | cumtime | Time in the function and all descendants | | percall after cumtime | cumtime / primitive calls |

Inspect the same data two ways:

.venv/bin/python - <<'PY'
import pstats

stats = pstats.Stats("words.prof").strip_dirs()
print("CUMULATIVE")
stats.sort_stats("cumulative").print_stats(6)
print("INTERNAL")
stats.sort_stats("time").print_stats(6)
PY

In our cumulative view, score_document owned almost the whole 1.19-second call path while normalize accounted for about 1.13 cumulative seconds. In the internal-time view, the generator expression led because it executed once per character. A high cumtime wrapper can merely delegate expensive work. A high tottime function performs work directly.

Neither ranking says what to change. Millions of calls may be legitimate. A built-in may show substantial time because it efficiently performs the real job in C. Start with large totals, surprising call counts, and code you can safely alter, then inspect callers and callees.

Experiment 3: follow a call path, not just a leaderboard

Flat tables lose context. Ask who called normalize, then what score_document called:

.venv/bin/python - <<'PY'
import pstats

stats = pstats.Stats("words.prof").strip_dirs().sort_stats("cumulative")
stats.print_callers("normalize")
stats.print_callees("score_document")
PY

The first report links normalize to 20 calls from score_document; the second divides the score path among normalization, dictionary updates, sorting, and other children. This distinction matters in real applications. A generic JSON helper may be hot only because one endpoint passes it huge objects. Optimizing every caller would solve the wrong problem; changing that endpoint's boundary may remove the work.

print_stats() and the caller/callee methods accept restrictions. They are applied in order, so this prints the first 20% of cumulative rows and then matches profile_words.py:

stats.print_stats(0.20, r"profile_words\.py")

Restrictions improve navigation, not evidence. Keep the complete .prof artifact until the investigation is finished.

Experiment 4: understand recursive call counts

Recursion gives ncalls its two-number form:

.venv/bin/python - <<'PY'
import cProfile
import pstats

def factorial(n):
    return 1 if n < 2 else n * factorial(n - 1)

profiler = cProfile.Profile()
assert profiler.runcall(factorial, 10) == 3_628_800
pstats.Stats(profiler).sort_stats("calls").print_stats("factorial")
PY

Our output showed 11/1 calls: 11 total invocations but one primitive, non-recursive entry. The slash does not mean failed calls or parallel calls. For cumulative per-call calculations, the profiler uses primitive calls so recursive descendants are not treated as independent top-level paths.

Call counts are often findings in their own right. An accidentally repeated parser may be individually fast and still dominate in aggregate. Conversely, replacing a million cheap calls with one expensive bulk call can reduce ncalls while increasing latency. Always retain time and outcomes alongside counts.

Experiment 5: measure the observer effect

Instrumentation is work. Measure it on the workload, not from folklore:

.venv/bin/python - <<'PY'
import cProfile
import timeit

def leaf(x):
    return x + 1

def workload():
    total = 0
    for _ in range(200_000):
        total = leaf(total)
    return total

def profiled():
    return cProfile.Profile().runcall(workload)

plain = timeit.repeat(workload, number=1, repeat=7)
observed = timeit.repeat(profiled, number=1, repeat=7)
print(f"plain best:    {min(plain):.4f}s")
print(f"profiled best: {min(observed):.4f}s")
print(f"factor:        {min(observed) / min(plain):.1f}x")
PY

We observed 0.0071 seconds plain and 0.0292 seconds profiled, about 4.1x slower. That factor belongs to this call-heavy workload. Profiler overhead is not a universal percentage and is not distributed uniformly between Python functions, C functions, and system waits.

Consequently, do not report profiled duration as production latency or use tiny differences inside a profile to choose between implementations. cProfile is designed for reasonable overhead and deterministic attribution, not benchmarking. It is still valuable when large patterns survive the distortion.

Experiment 6: separate CPU time from waiting

cProfile's default timer measures elapsed time. A profile can therefore contain waiting, but it cannot explain all waiting as usefully as it explains Python call paths. Compare wall and process clocks:

.venv/bin/python - <<'PY'
import time

def measure(label, operation):
    wall_start = time.perf_counter()
    cpu_start = time.process_time()
    operation()
    print(
        label,
        f"wall={time.perf_counter() - wall_start:.4f}s",
        f"cpu={time.process_time() - cpu_start:.4f}s",
    )

measure("CPU", lambda: sum(i * i for i in range(2_000_000)))
measure("sleep", lambda: time.sleep(0.1))
PY

Our CPU operation used about 0.0919 seconds wall and 0.0915 seconds process time. Sleep used about 0.1004 seconds wall but only 0.000035 seconds process time. Close wall and CPU totals suggest local computation. A large gap suggests sleep, I/O, scheduling, lock contention, or work delegated elsewhere.

For an I/O-bound service, combine Python profiling with request traces, database query logs, network metrics, and concurrency-aware load tests. Making the Python frames around a 300 ms database query twice as fast may save microseconds. Do not "fix" waiting by changing CPU code because it appears beside the wait in a cumulative call path.

Experiment 7: change the workload and watch the answer change

Profiles describe executions, not functions in isolation. Add this driver beside profile_words.py:

from profile_words import score_document

SHORT = "one two three four " * 10
LONG = "one two three four " * 10_000

for _ in range(10_000):
    score_document(SHORT, set())

for _ in range(10):
    score_document(LONG, set())

Profile it, then sort by calls and cumulative time:

.venv/bin/python -m cProfile -o shapes.prof workload_shapes.py
.venv/bin/python - <<'PY'
import pstats
s = pstats.Stats("shapes.prof").strip_dirs()
s.sort_stats("calls").print_stats("score_document")
s.sort_stats("cumulative").print_stats("normalize")
PY

Both phases process roughly the same number of characters, but one makes 10,000 top-level calls and the other makes 10. Cold-start effects, allocation patterns, fixed call costs, caches, and tail latency can differ. If production mostly receives short documents, a profile dominated by one giant document is not representative merely because total bytes match.

Capture distinct profiles for startup and steady state, cache hits and misses, successful and failing requests, and common versus worst-case payloads when those modes matter. Label each artifact with its input and environment.

Experiment 8: profile the diagnosis, benchmark the treatment

The first profile says normalization is repeated unchanged 20 times. Move invariant work out of the loop, but compare equivalent results without a profiler:

.venv/bin/python - <<'PY'
import timeit
from profile_words import normalize, score_document

document = "Python profiling finds repeated work and slow algorithms. " * 2_000
stop_words = {"and", "work"}

def before():
    return [score_document(document, stop_words) for _ in range(20)]

def score_words(words):
    counts = {}
    for word in words:
        if word not in stop_words:
            counts[word] = counts.get(word, 0) + 1
    return sorted(counts.items(), key=lambda item: (-item[1], item[0]))[:10]

def after():
    words = normalize(document)
    return [score_words(words) for _ in range(20)]

assert before() == after()
for candidate in (before, after):
    runs = timeit.repeat(candidate, number=1, repeat=7)
    print(candidate.__name__, [round(t, 4) for t in runs])
PY

This is the handoff: profile to hypothesize that repeated normalization matters; benchmark a production-relevant boundary to quantify the change. Whether pre-normalization is valid depends on semantics. If each pass uses different normalization rules or the text can mutate, the apparent invariant is not invariant.

Choosing another profiler

cProfile is deterministic: it instruments call events and reliably gives call relationships and counts, at the cost of perturbing execution. The pure-Python profile module exposes a similar interface but adds more overhead and is generally not the default choice.

Statistical profilers periodically sample stacks instead. They usually perturb a process less and can be attached to long-running production-like workloads, but short functions may never be sampled and results have sampling uncertainty. A line profiler attributes time to source lines, which is useful after a hot Python function is known; it adds instrumentation and may not illuminate time inside C extensions. These are categories, not interchangeable accuracy settings. Choose from the question and validate tool support for your Python version and deployment permissions.

A practical profiling protocol

  1. State the user-visible symptom and whether it concerns latency, throughput, CPU, or waiting.
  2. Record the executable, version, build, platform, input shape, cache state, and command.
  3. Reproduce the symptom without a profiler first.
  4. Profile the smallest complete representative boundary, while checking outputs.
  5. Inspect cumulative time, internal time, call counts, callers, and callees.
  6. Form a concrete hypothesis about removable work, not merely a hot function.
  7. Implement the smallest equivalent change and test correctness.
  8. Benchmark without profiling, then remeasure the end-to-end symptom.

Exercises

  1. Add a second caller of normalize, then use print_callers() to determine which caller contributes most cumulative time.
  2. Replace the call-heavy overhead workload with one call that performs the same arithmetic internally. Measure how the profiler factor changes and explain why it is workload-specific.
  3. Profile a program containing both sleep() and CPU work. Compare its profile with wall and process clocks, then identify what the profile cannot explain.
  4. Change document lengths and repetition counts while keeping total characters similar. Compare call counts and unprofiled timings.
  5. Take one hot path from an application, state its representative input and output assertion, and produce separate before/after benchmark vectors.

Keep this model

A profile is a map distorted by the act of drawing it. tottime shows direct work, cumtime shows owned call paths, and ncalls reveals repetition. None independently identifies a safe optimization. Representative workloads and caller context turn the table into a diagnosis; an unprofiled benchmark turns the diagnosis into a decision.

Primary sources