--- title: Profiling source: 'https://academia.sh/en/courses/python-concurrency/profiling' course: 'Concurrency and Performance' language: en updated: '2026-08-17T18:10:25+00:00' license: 'CC BY-SA 4.0' --- # Profiling A deterministic profiler gives the call count, not time columns; the same 80-step job is advanced 80 times under both loads, but the hot-path function is called 136 times under the I/O-bound load and 322 times under the CPU-bound load. 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 ```python """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**.