Chapter 61 — Measure the Tail

The turn you remember is not the turn you measured

She has vitals now. The live line from chapter 49 prints a rolling average per stage, and across an evening those averages describe a machine in good health: transcription a little over four hundred milliseconds, the model answering in about a second, synthesis under three hundred. Then you ask her something ordinary and the kitchen goes quiet. Not every time. Perhaps one turn in ten, long enough that you say her name into the silence before the reply starts.

Both readings are correct, and that is the problem. An average is arithmetic over the whole window, so one four-second reply divided across a hundred fast ones moves the printed number by forty milliseconds. Forty milliseconds is invisible on a dashboard. Four seconds is not invisible to somebody standing in a room waiting for an answer. The measurement everyone reaches for first conceals stalls in proportion to how rare they are, and rare is exactly what a stall is.

So this chapter measures the other end of the distribution on purpose. Every stage gets a ceiling in milliseconds, and the number checked against that ceiling is the 95th percentile of recent samples, never the average. The 95th percentile, p95 from here on, is the value that 95 out of every 100 calls come in under: how slow she gets on a bad turn of the ordinary kind, several times an hour, not the once-a-week disaster.

Chapter 10 had you write your per-stage timings on paper before anything here was tuned. That page is why tonight's work has a target. What you build now says which of those numbers to attack first, and it disagrees with the usual guess.

A ceiling per stage, and a rank instead of a mean

▣ Build · stage 1 — the budget, written down as a contract

# labs/latency_budget.py
from dataclasses import dataclass

STAGES = ("stt", "llm", "tts", "arm")


@dataclass
class LatencyBudget:
    stt_ms: float = 1500.0
    llm_ms: float = 3000.0
    tts_ms: float = 800.0
    arm_ms: float = 600.0

    def for_stage(self, stage: str) -> float:
        return getattr(self, f"{stage}_ms")

    @property
    def total_ms(self) -> float:
        return sum(self.for_stage(s) for s in STAGES)


if __name__ == "__main__":
    budget = LatencyBudget()
    for stage in STAGES:
        print(f"  {stage:<4} {budget.for_stage(stage):>7.0f} ms")
    print(f"  {'turn':<4} {budget.total_ms:>7.0f} ms  (all four stages)")

$ uv run python labs/latency_budget.py
  stt     1500 ms
  llm     3000 ms
  tts      800 ms
  arm      600 ms
  turn    5900 ms  (all four stages)

These four numbers are a decision, not a description. Nothing measured them; you chose them by asking what a turn is allowed to cost before it stops feeling like a conversation. A dataclass makes that decision reviewable: someone can open the file and argue with the 800 for synthesis without reading any measurement code. total_ms is a @property so it cannot drift from its parts; store it as a fifth field and the day you loosen llm_ms the total quietly lies. for_stage pays one getattr to keep STAGES the only list of stage names here.

▣ Build · stage 2 — the percentile, and what it sees that the average does not

from collections import deque

SAMPLES = 200
MIN_SAMPLES = 20


class TailTracker:
    def __init__(self, budget: LatencyBudget) -> None:
        self.budget = budget
        self._samples: dict[str, deque[float]] = {
            s: deque(maxlen=SAMPLES) for s in STAGES
        }

    def record(self, stage: str, ms: float) -> None:
        self._samples[stage].append(ms)

    def percentile(self, stage: str, q: float) -> float:
        ranked = sorted(self._samples[stage])
        if not ranked:
            return 0.0
        idx = min(int(len(ranked) * q), len(ranked) - 1)
        return ranked[idx]

    def p95(self, stage: str) -> float:
        return self.percentile(stage, 0.95)

    def average(self, stage: str) -> float:
        window = self._samples[stage]
        return sum(window) / len(window) if window else 0.0


if __name__ == "__main__":
    tail = TailTracker(LatencyBudget())
    for ms in (380.0, 395.2, 402.4, 410.1, 415.6,
               421.3, 430.0, 444.8, 460.2, 2870.4):
        tail.record("stt", ms)
    print("stt over 10 turns")
    print(f"  avg {tail.average('stt'):8.1f} ms")
    print(f"  p50 {tail.percentile('stt', 0.50):8.1f} ms")
    print(f"  p95 {tail.p95('stt'):8.1f} ms")

$ uv run python labs/latency_budget.py
stt over 10 turns
  avg    663.0 ms
  p50    421.3 ms
  p95   2870.4 ms

Ten samples, three numbers, three stories. Nine of those calls landed between 380 and 461 milliseconds, and the median says so: 421. The average says 663, a figure describing no call that actually happened, the fast cluster with a tenth of the slow one stirred in. Only p95 reports the 2,870 somebody sat through. All three came from the same samples; nothing was hidden from the average. Averaging did the hiding.

Two details in percentile carry the weight. sorted() comes first because a percentile is a position in ranked data, and rank says nothing about the order things arrived in. The window is per stage this time: chapter 49 kept one 120-slot buffer with every stage mixed in, which serves an average you filter by name and cannot serve a rank, because how many of those slots hold synthesis times is anybody's guess. Ranking needs a known count of one kind of thing.

◆ Note — the standard library has percentiles too

statistics.quantiles(data, n=100) returns the 99 cut points of a distribution, and quantiles(data, n=100)[94] is a defensible p95. It interpolates between neighbouring samples, so its answer usually sits between two calls she actually made. Both conventions are in wide use; monitoring systems mostly report the one built here, nearest-rank, where the value returned is a latency that really occurred and you can go find its log line. Reach for the standard library version when you want p99 on small windows, where interpolation is kinder than truncation.

From a number to a verdict

▣ Build · stage 3 — keep the raw samples, then judge them

import json
import time
from pathlib import Path

LATENCY_LOG = Path("glados/data/latency.jsonl")


def append_sample(stage: str, ms: float, path: Path = LATENCY_LOG) -> None:
    path.parent.mkdir(parents=True, exist_ok=True)
    with path.open("a") as f:
        f.write(json.dumps({"t": time.time(), "stage": stage,
                            "ms": round(ms, 1)}) + "\n")


def load_samples(path: Path) -> list[tuple[str, float]]:
    if not path.exists():
        return []
    rows = []
    for line in path.read_text().splitlines():
        if line.strip():
            row = json.loads(line)
            rows.append((row["stage"], float(row["ms"])))
    return rows


    # added to MetricsCollector.measure from chapter 49:
    #     ms = (time.perf_counter() - start) * 1000
    #     self.record_latency(stage, ms)
    #     append_sample(stage, ms)

One line of wiring, and it goes where the timing already happens. The context manager that feeds the live average now also writes the raw measurement to disk, so samples outlive the window they passed through. A ring buffer is a view of the present; a tail you want to argue about next week has to live somewhere durable. One line per stage per turn is four lines a conversation, small enough to leave running all evening and big enough to rotate eventually.

    def check(self, stage: str) -> dict:
        ceiling = self.budget.for_stage(stage)
        p95 = self.p95(stage)
        n = len(self._samples[stage])
        if n < MIN_SAMPLES:
            verdict = f"thin ({n} samples)"
        elif p95 > ceiling:
            verdict = f"OVER by {p95 - ceiling:.1f}"
        else:
            verdict = "ok"
        return {
            "n": n,
            "avg_ms": round(self.average(stage), 1),
            "p95_ms": round(p95, 1),
            "budget_ms": ceiling,
            "verdict": verdict,
        }

$ uv run python labs/latency_budget.py   # one evening on the bench; your session will differ
stage     n    avg ms    p95 ms   budget  verdict
stt     200     431.6    1042.8     1500  ok
llm     200    1183.4    4270.5     3000  OVER by 1270.5
tts     200     268.9     512.4      800  ok
arm      14     402.1    1180.6      600  thin (14 samples)

Read the llm row twice. Its average is 1,183 milliseconds against a ceiling of 3,000, a stage that looked healthy every time anyone glanced at the dashboard, and its p95 is 4,270: one reply in twenty takes over four seconds. That row is the pause in the kitchen, and staring at averages was never going to produce it. The thin verdict on arm does a different job. She moves rarely, 14 samples cannot rank anything, and printing a confident 1,180 would invent precision the data has not earned. Thin is not a pass; it means come back with more samples.

▣ Build · stage 4 — the report as a file, not a printout

# labs/latency_budget.py — the assembled module
import json
import time
from collections import deque
from dataclasses import dataclass
from pathlib import Path

STAGES = ("stt", "llm", "tts", "arm")
SAMPLES = 200
MIN_SAMPLES = 20
LATENCY_LOG = Path("glados/data/latency.jsonl")
PERF_REPORT = Path("docs/performance_report.json")


@dataclass
class LatencyBudget:
    stt_ms: float = 1500.0
    llm_ms: float = 3000.0
    tts_ms: float = 800.0
    arm_ms: float = 600.0

    def for_stage(self, stage: str) -> float:
        return getattr(self, f"{stage}_ms")

    @property
    def total_ms(self) -> float:
        return sum(self.for_stage(s) for s in STAGES)


class TailTracker:
    def __init__(self, budget: LatencyBudget) -> None:
        self.budget = budget
        self._samples: dict[str, deque[float]] = {
            s: deque(maxlen=SAMPLES) for s in STAGES
        }

    def record(self, stage: str, ms: float) -> None:
        self._samples[stage].append(ms)

    def percentile(self, stage: str, q: float) -> float:
        ranked = sorted(self._samples[stage])
        if not ranked:
            return 0.0
        idx = min(int(len(ranked) * q), len(ranked) - 1)
        return ranked[idx]

    def p95(self, stage: str) -> float:
        return self.percentile(stage, 0.95)

    def average(self, stage: str) -> float:
        window = self._samples[stage]
        return sum(window) / len(window) if window else 0.0

    def check(self, stage: str) -> dict:
        ceiling = self.budget.for_stage(stage)
        p95 = self.p95(stage)
        n = len(self._samples[stage])
        if n < MIN_SAMPLES:
            verdict = f"thin ({n} samples)"
        elif p95 > ceiling:
            verdict = f"OVER by {p95 - ceiling:.1f}"
        else:
            verdict = "ok"
        return {
            "n": n,
            "avg_ms": round(self.average(stage), 1),
            "p95_ms": round(p95, 1),
            "budget_ms": ceiling,
            "verdict": verdict,
        }

    def save_report(self, path: Path) -> dict:
        path.parent.mkdir(parents=True, exist_ok=True)
        report = {
            "generated": round(time.time()),
            "budget_total_ms": self.budget.total_ms,
            "stages": {s: self.check(s) for s in STAGES},
        }
        path.write_text(json.dumps(report, indent=2))
        return report


def load_samples(path: Path) -> list[tuple[str, float]]:
    if not path.exists():
        return []
    rows = []
    for line in path.read_text().splitlines():
        if line.strip():
            row = json.loads(line)
            rows.append((row["stage"], float(row["ms"])))
    return rows


def main() -> None:
    tail = TailTracker(LatencyBudget())
    for stage, ms in load_samples(LATENCY_LOG):
        tail.record(stage, ms)
    print(f"{'stage':<6}{'n':>5}{'avg ms':>10}{'p95 ms':>10}{'budget':>9}  verdict")
    for stage in STAGES:
        r = tail.check(stage)
        print(f"{stage:<6}{r['n']:>5}{r['avg_ms']:>10.1f}"
              f"{r['p95_ms']:>10.1f}{r['budget_ms']:>9.0f}  {r['verdict']}")
    report = tail.save_report(PERF_REPORT)
    over = [s for s in STAGES if report["stages"][s]["verdict"].startswith("OVER")]
    print(f"wrote {PERF_REPORT}: {len(over)} stage(s) over budget")


if __name__ == "__main__":
    main()

$ uv run python labs/latency_budget.py   # tail of the same run
wrote docs/performance_report.json: 1 stage(s) over budget

$ head -12 docs/performance_report.json
{
  "generated": 1787389241,
  "budget_total_ms": 5900.0,
  "stages": {
    "stt": {
      "n": 200,
      "avg_ms": 431.6,
      "p95_ms": 1042.8,
      "budget_ms": 1500.0,
      "verdict": "ok"
    },
    "llm": {

The printed table is for you, tonight. The JSON is for the version of you who changes something next week and needs to know whether it helped: keep a copy before every tuning attempt and "did that actually work?" becomes a diff of two p95 columns instead of a feeling about the last few replies. load_samples reads the whole log while the deques keep the last 200 per stage, so the file is the archive, the window is the ranking, and maxlen trims for free.

Why this works: rank, resolution, and a sum that is not a sum

A percentile is an index into sorted data, and that is the entire mechanism. Sort the window ascending and the value at position int(n * q) has roughly a q fraction of the samples at or below it. For 200 samples and q = 0.95, that is index 190: the tenth-largest measurement in the window. The min(idx, n - 1) clamp exists for the boundary, where q = 1.0 would index one past the end of the list.

Window size sets the resolution of the answer, and this is the part people skip. With 20 samples, int(20 * 0.95) is 19, the last element, so p95 is the maximum and one freak call defines it. With 40 samples the index is 38, the second largest. Only around a hundred samples does the 95th percentile become an interior value with several measurements above it, stable enough to compare week to week. Both constants in the file follow from that: MIN_SAMPLES = 20 refuses to report below the floor, and SAMPLES = 200 puts the index ten measurements down from the top.

One trap left, and it is arithmetic. The four ceilings add up to a turn budget of 5,900 milliseconds, so it is tempting to add the four measured p95 values the same way and call that a turn's p95. Adding them assumes every stage has its bad moment on the same turn, which is close to never; the sum of the tails bounds the tail of the sum loosely. When the end-to-end number is what you care about, time the whole turn as its own stage and rank those samples directly.

⚠ Worked failure — every stage passes and she still stalls

This is the version of the bug that raises nothing at all. The tracker is built, the report says ok across the board, and the pauses continue. Here is the code that produces it, one word away from correct:

    def percentile(self, stage: str, q: float) -> float:
        ranked = list(self._samples[stage])     # BUG: arrival order, not rank
        if not ranked:
            return 0.0
        idx = min(int(len(ranked) * q), len(ranked) - 1)
        return ranked[idx]


tail = TailTracker(LatencyBudget())
for ms in (2870.4, 380.0, 395.2, 402.4, 410.1,
           415.6, 421.3, 430.0, 444.8, 460.2):
    tail.record("stt", ms)
print(f"stt p95 {tail.p95('stt'):8.1f} ms  (budget 1500)")
print(f"stt max {max(tail._samples['stt']):8.1f} ms")

$ uv run python labs/latency_budget.py
stt p95    460.2 ms  (budget 1500)
stt max   2870.4 ms

Those two lines cannot both be right. A percentile is a value drawn from the samples, and for ten of them the p95 index is 9, the last position in the ranking, so p95 must equal the maximum. It reads 460.2 against a maximum of 2,870.4, so whatever position 9 addresses, it is not a rank. Without sorted() the index addresses arrival order, here the tenth call that happened to come in. The lesson survives past this file: a statistic computed on unordered data never fails, it answers, and a confident wrong number outlives an exception by months.

Checkpoint, and the last file she generates about herself

✓ Checkpoint — what you can now do

I can compute the p95 index for windows of 10, 40 and 200 samples, and say which measurement each one lands on.
I can explain why a window mixing four stages together can carry an average but cannot carry a rank.
I know my own llm p95 against its ceiling, and how far the average was from it.
Shown a p95 lower than the largest sample in the same window, I can name the cause without reading the rest of the file.
I can say why four stage ceilings add to a turn budget while four measured p95s do not add to a turn's p95.
I can defend MIN_SAMPLES = 20 as a statement about resolution instead of a magic number.

⚡ Exercises — try first, then reveal

Exercise 1 — three numbers instead of one. Add p50 and p99 to every row of the report, then read the three percentiles for llm together. Do they say the model got slower, or that a few calls stall?

Both are one line each on top of percentile; the reading is the interesting half. A bench evening gave p50 1,010, p95 4,270 and p99 6,840. The typical reply is fast and a small group of them is enormous, so the model is not uniformly slow, and swapping it for a smaller one trades quality to fix the wrong thing. Group the slow turns and they share a trait, usually a long conversation history or a reply that ran on for paragraphs. The knobs that move that p95 are the context you send and the reply length you allow.

Exercise 2 — measure the turn, then check the arithmetic. Record the full turn as a fifth stage called turn, run twenty conversations, and compare its p95 against the sum of the stage p95 values.

Add "turn" to STAGES with a ceiling, wrap the whole turn in the same measurement seam, print both figures. On the bench the three per-stage tails summed to 5,825.7 while the measured turn p95 was 4,980.3, roughly fifteen percent lower: the stages have their bad moments on different turns. Watch the gap close when you run her on a loaded machine, where stages start stalling together.

Exercise 3 — make the budget refuse. Have the script exit non-zero when any stage is over budget, so a shell script can gate on it. Confirm with echo $?.

sys.exit(1 if over else 0) at the end of main is the whole change; run it against the evening's log and you get the table, then 1. A budget that only prints is a suggestion. With an exit code it is a gate, and the same command drops into a script that refuses to restart the service on a build whose tail got worse. Decide what thin should do before wiring it anywhere: a fresh log has no samples, and a gate that passes on no data passes on everything.

Her software can describe itself now: what components exist, what commands she answers to, how the parts depend on each other, what her acceptance criteria were, and as of tonight how slow she gets on a bad minute. Five files, five scripts, one machine. The next chapter gathers them into a single record of the build, the document you would hand to somebody taking her over, and closes the software half of this project before the body arrives.