Profiling and Benchmarking Inference Systems

Lesson 8's compression material — pruning a network down, shrinking its weights — was still fundamentally a guess about where the model's time and memory were going, made before anyone actually looked. Every lesson before this one has, in fact, made that same guess implicitly: quantize the matmuls because they dominate FLOPs, fuse the layout conversions because they look wasteful, batch the decode step because the arithmetic says so. All of that reasoning is only as good as the model of the system it's built on, and Lesson 9 is about replacing the model with a measurement.

1. Why Intuition Fails at Predicting Bottlenecks

1.1 The FLOP-counting trap, one level up

Lesson 1 spent its opening sections dismantling a specific bad habit: counting the FLOPs in a kernel and assuming that number predicts wall-clock time, when arithmetic intensity and memory bandwidth were doing most of the actual work of determining speed. That lesson was about a single operator. The same trap reappears, almost unchanged, at the scale of an entire model graph — and it is, if anything, easier to fall into there, because at graph scale there's no single roofline chart to check yourself against, just a list of operators and a gut sense of which ones "sound expensive."

Picture a developer handed a small vision model to optimize: two convolutions doing the overwhelming majority of the network's arithmetic, bracketing a small data-dependent gather operation that reindexes activations based on a runtime-computed set of indices — the kind of op that shows up in attention masking, dynamic routing, or NMS-style post-processing. The convolutions carry something like 99% of the model's FLOPs on paper. The gather is a few thousand element copies. Every instinct built from counting arithmetic says: profile the convolutions, optimize the convolutions, the gather is noise. That instinct is reasonable, well-informed, and — as stated — wrong often enough that it isn't safe to act on without checking.

1.2 What profiling actually reveals when this exact case gets checked

Lesson 5, Part 2 worked through precisely this scenario in full, and it's worth pulling the numbers back out here because they're the cleanest illustration available of this chapter's opening claim. The gather operator wasn't supported by the NPU's operator set, so the runtime's placement pass put it on the CPU — sandwiching one CPU operator between two NPU convolutions: Conv1 (NPU) → Gather (CPU) → Conv2 (NPU). Each arrow crossing that CPU/NPU boundary is a device transition, and a device transition bundles a memory-domain copy, frequently a layout repack, and a synchronization handshake between two independently clocked pieces of silicon that don't share a common notion of "now."

Measured end to end, that three-operator sandwich cost 435 microseconds of wall-clock time. The two convolutions plus the gather itself — the actual arithmetic the model needs — accounted for about 90 microseconds of that, roughly 21% of the total. The remaining 79%, some 345 microseconds, was spent entirely on the two device transitions: repacking and copying data across the memory-domain boundary, and waiting on the synchronization handshake between the NPU and CPU schedulers, which turned out to dwarf even the byte-copying cost. A developer who trusted the FLOP count would have spent a week hand-tuning two convolutions that were never the problem, while a three-line placement fix — keeping the gather's neighbors from bouncing across the device boundary twice — was sitting there the whole time, invisible to anyone who didn't actually look at an operator-level trace.

1.3 A second invisible cost: the "free" reshape

Lesson 7 supplies a second version of the same failure mode, this time inside a single device rather than across two. A layout-conversion op — a transpose inserted wherever a producer's preferred tensor layout (say NHWC, favored by an NPU's channel-vectorized MAC array) doesn't match a consumer's preferred layout (say NCHW, favored by a GPU-lineage GEMM kernel) — reads to nowhere in the model's actual mathematics. It doesn't touch a weight, it doesn't compute a dot product, it just moves bytes from one stride order to another. Every instinct trained on "this isn't real computation" says it should be nearly free. It is exactly the opposite of free: a transpose over an entire activation tensor is a fully memory-bound pass, touching every byte with zero arithmetic to amortize the traffic against, and Lesson 7 noted it can rival the cost of the cheaper convolution sitting right next to it in the graph. An engineer optimizing by reading the graph definition, rather than a trace, has no way to see this op costing anything at all — on paper it's metadata; on the timeline it's real, scheduled, wall-clock time.

1.4 The general pattern

Both examples share a structure worth naming explicitly, because it recurs constantly and it's the whole reason this chapter exists: the cost of an operation is not visible from its position in the model definition, its FLOP count, or its apparent semantic weight. It is visible only from measuring the system actually executing the graph, on the actual hardware, with the actual runtime's actual placement and layout decisions in effect. "Where does the time go" is an empirical question about a specific compiled artifact running on specific silicon, not a question that can be answered by staring at a model architecture diagram — no matter how many years of experience inform the stare. This is also why "premature optimization" is a real hazard specific to this field in a way it might not be in general application programming: optimizing the wrong operator doesn't just waste engineering time, it can consume a meaningful fraction of a project's compute or power budget chasing a number that was never the bottleneck.

2. Wall-Clock Timing vs. Hardware Performance Counters

2.1 What a wall-clock timer actually measures

A wall-clock measurement — wrapping a region of code in start = now(), running it, then reading end = now() — reports elapsed real time: the actual number of seconds that passed on a clock on the wall, full stop. That sounds like exactly what you want, and for the question "how long did the user wait," it is. But it is an extremely noisy signal for the question "why did it take that long," because elapsed real time is a sum of everything that happened during that interval, not just the computation being measured:

OS scheduling. The kernel can preempt the measured thread to run something else — another process, an interrupt handler, a kernel housekeeping task — for some number of milliseconds, and that time is included in the wall-clock delta even though the thread wasn't doing the work being profiled.
Contention from other processes. On a shared machine — a CI runner, a cloud VM with noisy neighbors, a phone running a dozen background apps — other processes competing for the same cores, caches, and memory bandwidth inflate the measured time without the code under test having changed at all.
Thermal throttling. Sustained load raises die temperature; once a thermal limit is hit, the hardware itself lowers clock frequency to stay within its power/thermal envelope (this is DVFS, covered properly in Lesson 10), and every wall-clock measurement taken after that point is measuring a slower chip than the one the first measurement saw — for the same code, the same input, the same everything else.
Power-management transitions. Cores waking from a low-power idle state to service a request pay a real, sometimes multi-millisecond, latency penalty before running at full clock — a cost that has nothing to do with the algorithm and everything to do with how recently the core was busy.

None of these are bugs in the measurement — they're all real, and a user waiting on a response experiences all of them exactly as much as they experience the "real" computation. That's precisely why wall-clock time remains the correct metric for the question "is the system fast enough for its users." It is simply the wrong tool, on its own, for the question "which specific mechanism is making it slow," because it can't distinguish "the ALU is doing useful work at full rate" from "the core is stalled waiting on a cache line" from "the OS just descheduled this thread for 2ms" — all three produce the exact same symptom in a wall-clock trace: a number that's bigger than expected.

2.2 What a hardware performance counter actually measures

A hardware performance counter is a small register built directly into the processor's performance-monitoring unit (PMU) that increments in response to a specific, low-level hardware event, counted at the cycle level rather than the wall-clock level. Unlike a wall-clock timer, which is a software abstraction layered on top of a system clock, a performance counter is watching the actual execution pipeline. Representative counters, all directly readable through tools like Linux perf:

Cycles — the number of clock cycles the core actually spent executing (or, separately, stalled) during the measured region.
Instructions retired — the number of instructions that completed execution, as distinct from instructions merely issued or speculatively executed and later discarded.
L1/L2/L3 cache misses — how many memory accesses had to be serviced from a slower level of the memory hierarchy because the requested data wasn't found in a faster, closer cache.
Memory bandwidth utilization — the actual bytes per second moving across the memory bus during the measured interval, as a fraction of the hardware's peak bandwidth.
Branch mispredictions — how often the CPU's speculative-execution guess about which way a branch would go turned out to be wrong, forcing a pipeline flush.
Stall cycles — cycles in which the core was ready to execute an instruction but couldn't, because it was waiting on a dependency, a memory access, or a functional unit.

These counters answer a fundamentally different question than a wall-clock timer. They don't tell you how much real time passed; they tell you what the processor's execution pipeline was actually doing, cycle by cycle, largely independent of OS scheduling noise or which other processes happen to be running (though not fully independent — shared caches and shared memory bandwidth mean a noisy neighbor can still show up as extra cache misses, which is itself useful information). The classic diagnostic pattern, restated precisely: CPU utilization ≈ 40%, L2 cache miss rate high points at a memory/locality problem — the core is frequently idle because it's waiting on data. CPU utilization ≈ 100%, SIMD/vector-unit utilization low points at a vectorization problem — the core is fully busy, but doing scalar work a vectorized kernel could have done many elements at a time. Performance counters are what turns "it's slow" into "it's slow because the processor is stalling on memory," which is the difference between a diagnosis and a symptom.

2.3 Why you need both, using the exact roofline framework from Lesson 1

Wall-clock timing and performance counters aren't competing tools — they answer complementary halves of the same investigation, and the cleanest way to see why is to reconnect both to the Roofline model Lesson 1 derived. Recall the setup: an operator's arithmetic intensity AI (FLOP/byte) determines whether it should be memory-bound or compute-bound on a given piece of hardware, relative to that hardware's ridge point AI* = P_peak / B_memory. The Roofline bound, Achieved FLOP/s ≤ min(P_peak, B_memory × AI), is a theoretical ceiling — the best a kernel with that arithmetic intensity could possibly do on that hardware, assuming perfect overlap and no other stalls.

Wall-clock time is what tells you whether a kernel is anywhere near that ceiling at all. Take two convolutions, both computed (from their shapes, per Lesson 1's method) to have an arithmetic intensity comfortably above the device's ridge point — both, on paper, should be compute-bound, saturating the ALUs, running close to P_peak. Time them both. The first finishes in the roughly 40ms the roofline bound predicts for its FLOP count at P_peak. The second takes 400ms — ten times longer, despite an essentially identical theoretical AI and an essentially identical FLOP count. Wall-clock time alone tells you something is wrong with the second convolution. It cannot tell you what — the number 400ms carries no information about mechanism, only about magnitude.

This is exactly where performance counters answer the question wall-clock time raised but can't resolve. Reading the first convolution's counters: SIMD/vector-unit utilization near 100%, instructions retired per cycle near the core's issue width, stall cycles low. That kernel is doing exactly what its arithmetic intensity predicted — compute-bound, correctly saturating the ALUs, living up to its position on the roofline chart. Reading the second convolution's counters tells a completely different story: cycles are high but instructions retired are low, L2 and L3 cache miss rates are elevated, and ALU/SIMD utilization sits at a fraction of the first kernel's. The theoretical arithmetic intensity — computed from the shapes, assuming perfect data reuse — was correct. The achieved arithmetic intensity, what the implementation is actually managing in practice, is much lower, because a tiling or blocking decision somewhere in the kernel isn't keeping the working set resident in cache the way the theoretical derivation assumed. This is precisely Lesson 1's warning that arithmetic intensity is a property of an implementation, not of an operator in the abstract, showing up as a measurable, diagnosable fact rather than an abstract caveat: two kernels with identical theoretical AI can sit at wildly different points on the same roofline chart, and only a performance counter — not a stopwatch — can tell you which one has actually gotten there.

The short version, worth keeping as a rule of thumb: wall-clock time tells you whether there's a problem. Performance counters tell you what kind of problem it is. Skipping straight to counters without a wall-clock baseline means drowning in event data with no sense of which numbers matter; skipping counters and staring only at wall-clock time means knowing something is slow without any path to a fix beyond guessing.

2.4 Wall-clock vs. performance counters, side by side

Dimension	Wall-clock timing	Hardware performance counters
What it measures	Elapsed real time between two timestamps	Specific hardware events (cycles, cache misses, instructions retired) counted by the PMU
Includes OS scheduling noise	Yes, unavoidably	Mostly no — counts pipeline-level events, not scheduler decisions
Includes thermal throttling / DVFS effects	Yes — a throttled chip produces a bigger wall-clock number for identical code	Indirectly — cycle counts stay accurate per-cycle, but the mapping from cycles to real time changes with clock frequency
Tells you that something is slow	Yes, directly	Only indirectly, via ratios like stalls/cycle
Tells you why something is slow	No — a big number carries no mechanism	Yes — cache-miss rate, SIMD utilization, and stall cycles point at a specific hardware behavior
Typical tools	`time`, in-process timers, framework-level `Profiler` context managers	Linux `perf stat`/`perf record`, NVIDIA Nsight Compute, vendor PMU APIs
Overhead	Very low (a couple of timestamp reads)	Low for counting (`perf stat`), higher for sampling/tracing modes (Section 3.2)
Right question to ask with it	"Is this within budget?"	"Which resource is the bottleneck?"

3. Profiling Pitfalls in Depth

Measuring a system correctly is harder than it looks, and the three failure modes below account for the overwhelming majority of profiling numbers that get published, believed, and acted on despite being wrong.

3.1 Cold-Start and Warm-Up Effects

The first few executions of almost any real inference pipeline are not representative of the steady state the system will actually run in for the other 99.99% of its lifetime, because a cluster of one-time costs is bundled into those first few runs:

JIT compilation. Runtimes like TorchScript, XLA, or ONNX Runtime with graph-optimization passes enabled often defer some compilation or kernel-selection work until the first actual execution, rather than at model-load time — the first inference call pays for work every subsequent call gets for free.
Cache warming. Weights, activations, and the instructions of the kernels themselves start out absent from every level of the cache hierarchy. The first pass through the model pulls all of that from DRAM (or worse, from disk, if weights are memory-mapped and not yet paged in); subsequent passes find much of it already resident in L2/L3.
Memory allocation. A first-touch page fault — the OS zeroing and mapping a physical page the first time a virtual address is written — has real, non-trivial latency, and a memory allocator's internal bookkeeping (arena growth, free-list construction) is disproportionately active on its first few calls.
Device and driver warm-up. On a GPU or NPU specifically, the first kernel launch after process start can trigger driver-level context creation, JIT compilation of device code from an intermediate representation, and clock-speed ramp-up from an idle power state — none of which recur on the second launch.

The result is a warm-up curve that looks dramatically different from the steady state it eventually settles into:

Run  1:  100 ms   ██████████████████████████████████████████████████
Run  2:   34 ms   █████████████████
Run  3:   16 ms   ████████
Run  4:   11 ms   █████▌
Run  5:   10 ms   █████
Run  6:   10 ms   █████
Run  7:   10 ms   █████
  ...              (steady state: ~10 ms per run, from here on)
Run 50:   10 ms   █████

A single-measurement benchmark that reports Run 1's 100ms as "the model's inference latency" has, in fact, measured mostly JIT compilation and cache population, not the steady-state execution the deployed system will actually experience on every request after the first. The gap here isn't a rounding error — a 10x difference between cold and warm is common, and depending on how much JIT and driver work a given runtime defers, 100x is not exotic for the very first call on a freshly loaded model. The fix is procedural, not clever: run a fixed number of discarded warm-up iterations before starting to record any measurement at all, and pick that number empirically per system, by watching for the run-to-run variance to flatten out (as in the curve above, roughly by run 5–6) rather than assuming a fixed count like "always discard 3" will be enough on every platform. Always state, explicitly, in any reported benchmark number, whether it includes or excludes warm-up — "10ms inference latency" is not a complete claim without also saying "measured after N warm-up iterations," because the same system can honestly report either 10ms or 100ms depending entirely on which question was actually asked.

3.2 Profiler Overhead — the Observer Effect

A profiler is itself a program running on the same hardware as the thing it's measuring, and instrumenting or observing execution is never entirely free. This creates a genuine tradeoff between two families of profiling technique, and picking the wrong one for the question at hand produces numbers that are precise and wrong at the same time.

Sampling profilers interrupt the running program at a fixed frequency — say, every millisecond, or every N cycles via a hardware performance-counter overflow interrupt — and record where execution currently is (which instruction, which call stack) at each interrupt. Linux perf record's default mode works this way. The overhead is low, typically in the low single-digit percent, because most of the program's execution is left completely undisturbed between samples; only the interrupt-and-record cost at each sample point perturbs anything. The cost of that low overhead is statistical rather than exact accuracy: a function that runs for 50 microseconds between two sample points might never get sampled at all, and the resulting time-in-function estimates are a statistical inference from however many samples landed inside that function, not an exact accounting. For long-running, hot code paths this converges to an accurate picture quickly; for rare, short-lived operations it can miss them, or badly under- or over-estimate their cost, purely from sampling variance.

Instrumenting (tracing) profilers insert explicit measurement code — a timestamp read at entry and exit of every traced region — directly into (or around) the code being measured, producing an exact record of when every instrumented call started and ended, with no statistical uncertainty about what happened. Nsight Systems' NVTX ranges and ONNX Runtime's built-in operator-level tracing both work this way at the operator granularity. The cost is that every single instrumented call now pays the overhead of that instrumentation — at minimum a clock read and a write to a trace buffer — and for operators fast enough that the instrumentation cost is a meaningful fraction of the operator's own runtime, the measured time is no longer a clean reading of the original system; it's a reading of the original system plus the profiler, and the two are entangled. This is a real instance of the general observer effect: instrumenting fine-grained enough regions can slow the whole pipeline down by a measurable amount, occasionally enough to shift which resource is the bottleneck, or to change cache and scheduling behavior enough that the "measured" numbers don't quite match what would have happened unobserved.

The practical resolution most real profiling tools ship with is exactly the two-mode split above, applied deliberately rather than by accident: use a low-overhead sampling profiler for the first pass, to find which region of the code deserves attention at all without perturbing the system's overall behavior, then switch to fine-grained, exact instrumentation — accepting its higher overhead — only on the specific narrowed-down region that first pass identified, where the extra precision is actually worth paying for. Nsight Systems is explicitly built around this workflow: get a low-overhead, whole-application timeline first, then reach for Nsight Compute's much more invasive, much more detailed per-kernel instrumentation only on the specific kernel the timeline flagged as worth a closer look.

3.3 Single-Run Noise

A single measurement of anything running on real hardware is close to meaningless, because every source of variance discussed in Section 2.1 is a random, run-to-run effect rather than a fixed offset that could just be subtracted out:

CPU frequency scaling (DVFS). Modern cores dynamically adjust clock frequency based on thermal headroom, power budget, and recent utilization (the full mechanism is Lesson 10's subject) — the same code can execute measurably faster or slower purely because of which frequency state the core happened to be in when the measurement started, with no relationship to the code itself.
Thermal throttling. A chip that has been under sustained load for several minutes is running hotter than one that just woke from idle, and a hot chip has less thermal headroom before it's forced to throttle — meaning the tenth consecutive benchmark iteration can be legitimately slower than the first, independent of any cache-warming effect, purely from accumulated heat.
OS scheduling jitter. Timer interrupts, other runnable processes, and kernel housekeeping tasks compete for the same cores, and any one of them landing during a measured interval adds a variable, unpredictable amount of time to that specific run.
Background processes. Anything else sharing the machine — a backup daemon, another user's job on a shared server, a browser tab doing something unrelated on a workstation — contends for cache space and memory bandwidth in ways that vary from second to second.

None of these are exotic edge cases; they are the normal operating conditions of every real computer, all the time. A benchmark script that runs the target code once, prints the elapsed time, and calls the number "the latency" has measured one arbitrary draw from a distribution shaped by all four effects above, not a stable property of the system. Two consequences follow directly, and both are load-bearing for how any credible benchmark has to be structured: first, every benchmark needs many repeated measurements, not one, with the warm-up iterations from Section 3.1 discarded before recording begins; second, the distribution of those repeated measurements — not just their average — is the actual object worth reporting, which is exactly where Section 4 picks up.

4. Benchmarking Methodology: Why Percentiles Beat the Mean

4.1 A worked distribution where the mean lies

Consider a serving system benchmarked over 1,000 requests, with per-request latency shaped by three distinct regimes rather than one: a steady-state fast path most requests take, a moderately slow path some requests take (say, a request that lands just as a batch is filling, echoing Lesson 6's queueing-delay derivation), and a rare, badly slow path a small number of requests take (a garbage-collection pause in a managed-runtime serving stack, or a cold-cache eviction on a device under memory pressure).

970 requests →   8 ms   (steady-state execution)
 25 requests →  40 ms   (batch-queueing delay, moderate)
  5 requests → 600 ms   (GC pause / cache-eviction stall, rare)

The mean across all 1,000 requests:

mean = (970 × 8ms + 25 × 40ms + 5 × 600ms) / 1000
     = (7,760 + 1,000 + 3,000) / 1000
     = 11,760 / 1000
     = 11.76 ms

A dashboard reporting "average latency: 11.76ms" against an 8ms steady-state baseline looks, at a glance, close enough to fine — a 47% increase over the fast path, easy to wave off as normal system noise. Now sort the same 1,000 measurements and read off percentiles instead:

sorted latencies (ascending), positions 1–1000:
 
positions    1 – 970   → 8 ms     (the steady-state bulk)
positions  971 – 995   → 40 ms    (the moderate tail)
positions  996 – 1000  → 600 ms   (the severe tail)
 
p50  (position  500) →   8 ms
p95  (position  950) →   8 ms
p99  (position  990) →  40 ms   ← 5x the median
p999 (position  999) → 600 ms   ← 75x the median

The median and p95 are both a reassuring 8ms — most requests are genuinely fast, and any benchmark that only looked at the middle of the distribution would report a perfectly healthy system. p99 quietly reveals that the top 1% of requests are five times slower than typical. p99.9 reveals something the mean actively hid: the worst-affected requests aren't a little slower, they're seventy-five times slower — 600ms against an 8ms baseline, a difference a 11.76ms average number gives no hint of at all. The mean is not wrong, exactly; it is an honest average of a distribution that a single scalar cannot faithfully summarize, because that distribution is not remotely symmetric or well-behaved — it's dominated by a small, heavy right tail, precisely the shape produced by pause-based and queueing-based latency sources rather than steady, evenly-distributed noise.

4.2 Why the tail matters more than the mean for real systems

The reason this isn't just a statistics curiosity is the argument Dean and Barroso's influential "The Tail at Scale" makes precisely: at the scale of a real service, "rare" tail events are not rare from the system's point of view, because a system serving many requests per second guarantees that some fraction of users hits the tail continuously, not occasionally. If p99.9 is 600ms, and the service handles even a modest 10,000 requests per second, roughly ten requests every second are landing in that 600ms bucket — not as a once-a-day anomaly, but as a steady, ongoing stream of badly served users, indistinguishable in volume from a real outage to anyone experiencing it.

The effect compounds sharply once a single user-facing request depends on more than one backend call, which is the normal shape of any non-trivial service rather than an edge case. If a single downstream call has a 1% chance of landing in a slow tail, and a user-facing request fans out to, say, 100 such calls in parallel (a search request touching many shards, an ensemble model querying several sub-models, a page assembling several microservice responses) — the probability that the whole request avoids the tail on every single one of those 100 calls is (1 - 0.01)^100 ≈ 0.366, meaning roughly 63% of user-facing requests are affected by at least one slow backend call, even though any individual call is slow only 1% of the time. Tail latency at the component level becomes median latency at the aggregate level once enough components are involved — which is precisely why Dean and Barroso frame tail tolerance as a first-class systems-design problem rather than a statistical footnote, and why, for an inference-serving system in particular, reporting p50 alone is close to reporting nothing about the experience a meaningful fraction of real users actually have.

4.3 Why averaging across runs is misleading in the same way

The same trap reappears in a subtler form when reporting benchmark results across multiple runs of an experiment rather than across requests within one run. Averaging five separate benchmark runs' mean latencies together — five different means, further averaged into one number — compounds Section 4.1's problem instead of fixing it: if even one of those five runs happened to catch a thermal-throttling episode, a co-located noisy-neighbor process, or an unusually GC-heavy stretch (Section 3.3's sources of run-to-run variance), that one contaminated run's inflated mean drags the reported "average of averages" upward in a way that hides which specific run was the outlier and why. The methodologically sound approach is to pool every individual measurement from every run into one combined distribution — after discarding each run's own warm-up iterations — and report percentiles over that pooled distribution, exactly as in Section 4.1, rather than averaging pre-averaged numbers that have already thrown away the shape of the underlying data.

4.4 What to actually report

Putting Sections 4.1 through 4.3 together, a benchmark result that can actually be trusted and acted on reports, at minimum: the number of measurements taken (large enough that p99 and p99.9 are meaningfully populated — a 100-sample benchmark literally cannot produce a stable p99.9 estimate, since that would require averaging over less than one data point at that percentile), whether and how many warm-up iterations were discarded, and the distribution itself — p50, p95, p99, and, for latency-sensitive production systems, p99.9 — rather than a single mean. A single number, however carefully measured, cannot distinguish "this system is fast for everyone" from "this system is fast for 97% of requests and unacceptable for the rest," and for anyone actually operating the service, that distinction is usually the entire question that matters.