Profiling

The previous topic laid four regimes side by side across six lessons and counted what each one earned under which load. Its last lesson measured executor pools and left a question behind: so far which regime earns what has been counted — but how do I know which step is heavy in a program?

The question is not an empty one. Choosing a regime assumes you already know which kind the heavy step is — a CPU step or an I/O step. If the assumption is wrong, the choice is wrong too: adding a worker to a CPU-bound load only drops 80 ticks to 73. This lesson’s answer is: you do not know, you measure. And what is measured in this course is not time, it is call count.

The Deterministic Counter

Profiling is the work of recording how much a run spends in which part. There are two families of tool. A sampling profiler polls the run at regular intervals and notes where it is; what it collects is a sample, and it does not come out the same across two runs. A deterministic profiler, on the other hand, sees every call and every return; it misses nothing.

The standard library’s deterministic profiler collects two kinds of data: how many times a function was called, and how much time passed during those calls. This lesson’s table does not carry the second, and the reason fits in one sentence: when the same code runs twice on the same machine, the time columns come out different, the call count does not — it is the number that can be compared.

This has a consequence: we do not print the tool’s ready-made dump as is, because that dump also carries time columns. Instead, the collected record is opened and only the call count is read from each row. This looks like a restriction; as the lesson shows by the end, the number left over is enough to answer the whole question.

The record’s shape supports this directly. When the run ends, the tool holds one entry per function; the entry’s key is the triple that identifies the function — file, line, and name — and its value is a tuple of numbers about that function. The tuple’s first two fields are call counts: the non-recursive call count and the total call count. In a program without recursion the two are equal. The remaining fields concern time and are not read in this lesson.

The Hot Path

The hot path is the piece of code executed most often in a run. Its name can mislead: heat here has nothing to do with what the code does, it is about how many times it runs. A heavy function called once is not the hot path; a three-line function called hundreds of times is.

Finding the hot path by intuition means confusing the part of the code that looks long with the part that runs a lot. Length is eyeballed, call count is not eyeballed — it is counted. In this lesson the hot path is tied to a single metric: the most-called function.

This metric alone does not decide an optimization, but it narrows the search space. Most of a program’s functions get called a few times in a run; a handful get called hundreds of times. Rewriting a function from the first group is limited in its effect on the total by however many times it is called. Every step gained in a function from the second group comes back multiplied by the call count.

The Program Being Measured

We are not writing a new program for this measurement; we are measuring the shared definition’s scheduler. There is one obstacle: run is a single function, and it produces a single row in the profiler’s table. One row does not show a hot path.

So the body is split into named parts: select_active, is_cpu_step, advance, and run_tick, which runs a single tick. Behavior does not change — the split function returns the same quadruple as the original, across all twelve combinations of four regimes and three loads. The only thing that changes is the boundary count the tool can see.

From here comes profiling’s first rule: the tool only sees call boundaries. If a loop body is not a separate function, it has no row in the table. It is not the tool itself but the way the code is split that decides the measurement’s resolution.

We could have gathered the same numbers with hand-placed counters too: put an increment line at the top of every function and print it at the end. There are two differences. A hand-placed counter requires knowing where to look in advance; if we knew which one was the hot path, we would not need to measure in the first place. Second, counter lines get mixed into the code itself and have to be pulled out one by one when the measurement is done. The tool, by contrast, attaches from outside without changing the code and detaches the same way; the measured program stays identical to the written program.

The measurement’s assumptions:

• PE1 — The task set comes from the shared definition: eight tasks, ten steps per task, 80 steps total. The oracle is the setup itself; we know the total step count without measuring.
• PE2 — The split run returns the same quadruple as the original function. The split is not a rewrite, it is opening boundaries for measurement; the behavior of tasks and run is preserved.
• PE3 — The measured regime is the eight-worker, single-slot regime. Two loads are tried — I/O-bound and CPU-bound — and nothing but the load changes.
• PE4 — Only the call count is read from the record. Time fields are collected by the tool but not written down; had they been, they would be the one column that changed between the two runs.
• PE5 — Only this lesson’s own functions are taken into the table; calls to built-ins and the standard library are not counted.
• PE6 — The tool itself adds load to the run. This load does not change the call count, because the counter only counts calls, it does not produce new ones.

Measurement

"""Profiling: same work, two loads; call count shows the hot path."""

import cProfile
import pstats

SEED = 20260817
CPU, IO = "cpu", "io"


def make_rng(seed):
    state = seed % 2147483646 + 1

    def draw(n):
        nonlocal state
        state = (state * 48271) % 2147483647
        return state % n
    return draw


def tasks(count=8, steps=10, io_share=7, seed=SEED):
    draw, result = make_rng(seed), []
    for i in range(count):
        result.append([IO if draw(10) < io_share else CPU for _ in range(steps)])
    return result


def select_active(remaining, workers):
    return [i for i, j in enumerate(remaining) if j][:workers]


def is_cpu_step(step):
    return step == CPU


def advance(remaining, i):
    remaining[i].pop(0)


def run_tick(remaining, workers, cpu_slots):
    active = select_active(remaining, workers)
    slots_left, advanced, cpu_steps, io_steps = cpu_slots, 0, 0, 0
    for i in active:
        if is_cpu_step(remaining[i][0]):
            if slots_left <= 0:
                continue
            slots_left -= 1
            cpu_steps += 1
        else:
            io_steps += 1
        advance(remaining, i)
        advanced += 1
    return advanced, cpu_steps, io_steps


def run(jobs, workers, cpu_slots):
    """Same result as the shared definition; body split into named parts."""
    remaining = [list(j) for j in jobs]
    tick = overlap = cpu_steps = io_steps = 0
    while any(remaining):
        advanced, ia, ga = run_tick(remaining, workers, cpu_slots)
        if not advanced:
            break
        cpu_steps += ia
        io_steps += ga
        tick += 1
        overlap += max(0, advanced - 1)
    return tick, overlap, cpu_steps, io_steps


TRACKED = ("run", "run_tick", "select_active", "is_cpu_step", "advance")


def count_calls(io_share, workers=8, slot=1):
    """Only call count is read; time columns are not taken."""
    j = tasks(io_share=io_share)
    profiler = cProfile.Profile()
    profiler.enable()
    result = run(j, workers, slot)
    profiler.disable()
    counts = {name: 0 for name in TRACKED}
    for (_, _, name), data in pstats.Stats(profiler).stats.items():
        if name in counts:
            counts[name] = data[1]
    return result, counts


io_result, io_counts = count_calls(7)
cpu_result, cpu_counts = count_calls(1)
print(f"{'function':<18s} {'I/O-bound':>22s} {'CPU-bound':>19s}")
for name in TRACKED:
    print(f"{name:<18s} {io_counts[name]:22d} {cpu_counts[name]:19d}")
print(f"{'total calls':<18s} {sum(io_counts.values()):22d} "
      f"{sum(cpu_counts.values()):19d}")
print()
print(f"I/O-bound : {io_result[0]} ticks, {io_result[1]} overlapping steps")
print(f"CPU-bound : {cpu_result[0]} ticks, {cpu_result[1]} overlapping steps")
print(f"advance calls in both runs: {io_counts['advance']} and "
      f"{cpu_counts['advance']}; oracle's total step count "
      f"{sum(len(x) for x in tasks())}")
print("is_cpu_step calls across three consecutive runs:",
      [count_calls(1)[1]["is_cpu_step"] for _ in range(3)])

function                        I/O-bound           CPU-bound
run                                     1                   1
run_tick                               31                  73
select_active                          31                  73
is_cpu_step                           136                 322
advance                                80                  80
total calls                           279                 549

I/O-bound : 31 ticks, 49 overlapping steps
CPU-bound : 73 ticks, 7 overlapping steps
advance calls in both runs: 80 and 80; oracle's total step count 80
is_cpu_step calls across three consecutive runs: [322, 322, 322]

The Row That Stays Equal

The most important row in the table is the one whose two columns are equal: advance is called 80 times under both loads. The oracle confirms this — the setup’s total step count is 80 and every step is taken exactly once. The work did not change.

The changing rows sit around this one. run_tick goes from 31 to 73, select_active the same way from 31 to 73, is_cpu_step rises from 136 to 322. Total calls, 279 to 549. The same 80 steps, nearly twice the calls.

From here comes the lesson’s central reading: call count does not count the work done, it counts the effort spent reaching it. 80 steps were taken in both runs; the difference is in how many times the question had to be asked to reach those 80 steps.

The row that stays equal has a second job: it verifies the measurement. advance coming out to 80 means a number known independently of the setup matches the profiler table. If it did not match, the thing to question would not be the table, it would be the tool or the split. Measuring a known number too is the cheapest way to test the measurement itself; once a row like this coming from the oracle is present in a profiler table, the remaining rows can be read with confidence.

Which One Is the Hot Path

The most-called function in both columns is is_cpu_step. This is the hot path, and what draws attention is that the number is larger than 80: 136 and 322. That means more than one call per step.

The reason is in the scheduler itself. Every task looked at in a tick calls this function — the one that gets to advance and the one turned back for lack of a slot alike. Under the I/O-bound load, most steps do not want a slot, tasks run out early, and the total looks stay at 136. Under the CPU-bound load, the single slot turns back everyone but one task every tick; the turned-back task sits without running out, gets looked at again on the next tick, and every look costs one call. The gap between them is 186 calls.

The split tests this explanation. Under the I/O-bound run, the average look per tick is 136/31, that is 4.39; under the CPU-bound run, 322/73, that is 4.41. The two numbers are nearly the same. So the number of tasks looked at in a tick is barely affected by the load; what produces the difference entirely is tick count. The hot path gets its heat not from something inside itself but from how many rounds it runs.

This corrects a common mistake about the hot path: the most-called function itself does not have to be flawed. is_cpu_step is a three-line, single-comparison function; there is nothing in it to fix. What calls it 322 times is the slot constraint outside it. The hot path is not the cause, it is the indicator.

The run_tick and select_active rows say something separate: their values are exactly equal to the tick count — 31 and 73. The profiler table gave the tick count without ever counting ticks. This is not a coincidence; both functions are called exactly once per tick. The rule is: a function’s call count is the count of the event that function represents. What the measurement counts is decided not by the tool itself but by how the code is split — and that means the decision to write a function named run_tick was a measurement decision.

The last row shows determinism: when the same run is repeated three times, is_cpu_step calls come out 322, 322, 322. Had the time columns been taken, all three would have differed.

The Observer’s Effect

The deterministic tool has a cost: at every call boundary the counter kicks in, updates the record, and hands control back. A program running under a profiler is not the same as the program running without one. This is a known flaw of measurement tools, and it leaks straight into the result in a table that measures time — small, frequently called functions look heavier than they are, because the counter’s own load gets added to their share.

Call count is not affected by this flaw, and the reason is in the definition itself: the counter counts calls, it does not produce them. is_cpu_step is called exactly 322 times whether the counter is present or not, because what calls it is not the tool’s presence but the content of the task list. This is one of the rare cases where the measurement tool does not change what it observes — and it is the second reason this course counts steps instead of time.

A practical result follows from this: a program’s call breakdown can be taken once under a profiler and treated as valid for subsequent runs too. The same cannot be said for a time breakdown.

What Call Count Does Not Say

The table’s first row shows this limit: run was called only 1 time. A reading that looks at call count alone would count it as the coldest function; yet the entire run passes inside it. Calling a function once does not mean it came cheap.

The second limit is coverage. Everything outside the TRACKED tuple — built-in calls, list operations, formatting — does not enter the table. They ran too; they were not counted. A profiler table cannot be read without saying what it tracks, and this lesson’s table tracks five functions.

The third limit is the most important one. Call count gives how many times a function ran, not what that running cost. advance was called 80 times; each of those 80 calls removes one item from the front of a list, and that work’s cost depends on the list’s length. Call count does not show this. For that, a different number is needed — how many objects get created, and how many stay alive.

Metric Design Is Not This Lesson’s Subject

The Observability and Reliability course and the Observability and Operations course established metric design: which metric to collect, how to name it, which threshold triggers an alert. Not repeated here, a reference is enough.

The difference is one of direction. Metric design chooses beforehand: what will be collected is decided before the run starts, and what was not collected cannot be brought back later. Profiling reads afterward: once the run ends, the call breakdown is opened and which function was hot comes out of it. One is an operations tool, the other a diagnostic tool; both can exist in the same program and neither substitutes for the other.

Summary

• A deterministic profiler sees every call and every return; of the two kinds of data it collects, call count stays the same across repeated runs, the time fields change — this is why only call count is written into the table.
• The hot path is the code that is called the most; it is defined by call count, not length, and cannot be known without measuring.
• The tool only sees call boundaries; if a body is not a separate function, it has no row in the table. The way the code is split decides the measurement’s resolution.
• The same 80-step job ends with 80 advance calls under both loads, but total calls rise from 279 to 549: what is counted is not the work, it is the effort spent reaching it.
• The hot path is is_cpu_step; its calls rise from 136 to 322 because the single slot leaves every task it turns back to be looked at again on the next tick.

Next Step

Call count tells how many times a function ran. There is something it does not tell: how many objects were standing at the same time during that run. advance was called 80 times under both loads, but was the structure the task lists occupy in memory the same in both runs — and if the same 80 steps were held in a different container, how many objects would exist? The next lesson looks at this question, and again it counts not bytes but objects.