Chapter 28 — Timing the Pipeline

The measurement that scrolls away

Back in chapter 10 you timed the voice loop by hand: time.perf_counter() wrapped around every stage, a printed line per turn, and your per-stage numbers written down on paper as the baseline this book keeps promising to beat. That was a measurement. It was not instrumentation. The prints had no timestamps, so you could not line them up against anything else that happened; they had no severity, so a routine timing line and a fatal error looked identical; and they vanished the moment the terminal scrolled, so a stall you saw once at breakfast was gone by the time you went looking after lunch.

Volume 3 has been changing her from the inside: prosody control, a mood that moves, a plan store, a simulated body. Every one of those changes can slow a stage, and "she feels sluggish today" is not a bug report. When a reply takes three seconds instead of one, you need two answers fast: which stage, and exactly when. A print() can answer neither, and the usual patch (more prints, then commenting them out for the demo, then back in when it breaks again) means editing pipeline code every time you change your mind about visibility.

So this chapter's rule: observability bolts on beside the code, never into it — a structured logger records what happened, when, and how badly, and a decorator times any stage without touching a line of the stage's own logic. The functions that make her listen, think, and speak will never know they are being watched. That is the point.

Logger, then decorator, then the error path

▣ Build · stage 1 — replace print with a structured logger

# labs/timing.py
import logging

logging.basicConfig(
    level=logging.DEBUG,
    format="%(asctime)s [%(levelname)s] %(name)s: %(message)s",
)
logger = logging.getLogger("glados")

logger.info("debug session started")
logger.debug("loading voice pipeline")

$ uv run python labs/timing.py
2026-08-21 21:04:11,314 [INFO] glados: debug session started
2026-08-21 21:04:11,314 [DEBUG] glados: loading voice pipeline

Same two messages a print would carry, plus the three fields a print never does: a timestamp (%(asctime)s), a severity (%(levelname)s), and the name of the logger that spoke (%(name)s). Each comes from the format string, filled in per record, so every line in the project now answers "when" and "how serious" for free. The level=logging.DEBUG argument sets the floor: records below the configured level are dropped, and that single number is what will later separate an investigation from a quiet production run.

▣ Build · stage 2 — a @timed decorator that measures any stage

import time
from functools import wraps

def timed(func):
    @wraps(func)
    def wrapper(*args, **kwargs):
        start = time.perf_counter()
        result = func(*args, **kwargs)
        elapsed = (time.perf_counter() - start) * 1000
        logger.debug(f"{func.__name__} completed in {elapsed:.1f}ms")
        return result
    return wrapper

@timed
def transcribe_stub(audio_file: str) -> str:
    time.sleep(0.01)   # stands in for Whisper
    return "Hello, GLaDOS."

print(transcribe_stub("heard.wav"))

$ uv run python labs/timing.py
2026-08-21 21:04:11,358 [DEBUG] glados: transcribe_stub completed in 10.2ms
Hello, GLaDOS.

A decorator is a function that takes a function and returns a replacement: @timed above the definition means transcribe_stub = timed(transcribe_stub), so every call now routes through wrapper, which starts a clock, calls the original, and logs the difference. The stub sleeps ten milliseconds and reports 10.2; yours will land a fraction off, because the sleep and the clock both carry scheduler jitter. Two details are load-bearing. perf_counter() is a monotonic clock built for durations; time.time() is a wall clock that NTP or a daylight-saving jump can move backward mid-measurement, which is fine for "when" and wrong for "how long". And @wraps(func) copies the original function's identity (name, docstring, signature) onto the wrapper; the failure box below is what happens the day you skip it.

▣ Build · stage 3 — log the traceback, then re-raise

import traceback

def timed(func):
    @wraps(func)
    def wrapper(*args, **kwargs):
        start = time.perf_counter()
        try:
            result = func(*args, **kwargs)
            elapsed = (time.perf_counter() - start) * 1000
            logger.debug(f"{func.__name__} completed in {elapsed:.1f}ms")
            return result
        except Exception as e:
            logger.error(f"{func.__name__} failed: {e}")
            logger.debug(traceback.format_exc())
            raise
    return wrapper

The decorator's job is to record, not to decide. On failure it writes one ERROR line naming the stage, files the full traceback at DEBUG where an investigator can find it, and then re-raises with a bare raise, which rethrows the original exception with its original traceback intact. To every caller the stage behaves exactly as if the decorator were not there; the alternative (catching and returning None) converts a loud crash into a quiet wrong answer three stages downstream, which is a strictly worse bug.

▣ Build · stage 4 — the full file, logging to console and disk at once

# labs/timing.py — full file
import logging
import time
import traceback
from functools import wraps
from pathlib import Path

LOG_PATH = Path("glados/data/debug.log")
LOG_PATH.parent.mkdir(parents=True, exist_ok=True)

logging.basicConfig(
    level=logging.DEBUG,
    format="%(asctime)s [%(levelname)s] %(name)s: %(message)s",
    handlers=[
        logging.FileHandler(LOG_PATH),
        logging.StreamHandler(),
    ],
)
logger = logging.getLogger("glados")

def timed(func):
    @wraps(func)
    def wrapper(*args, **kwargs):
        start = time.perf_counter()
        try:
            result = func(*args, **kwargs)
            elapsed = (time.perf_counter() - start) * 1000
            logger.debug(f"{func.__name__} completed in {elapsed:.1f}ms")
            return result
        except Exception as e:
            logger.error(f"{func.__name__} failed: {e}")
            logger.debug(traceback.format_exc())
            raise
    return wrapper

@timed
def transcribe_stub(audio_file: str) -> str:
    time.sleep(0.01)
    return "Hello, GLaDOS."

@timed
def llm_stub(text: str) -> str:
    time.sleep(0.02)
    return "Oh. It's you."

def main() -> None:
    logger.info("debug session started")
    text = transcribe_stub("heard.wav")
    reply = llm_stub(text)
    logger.info(f"reply: {reply}")

if __name__ == "__main__":
    main()

$ uv run python labs/timing.py   # the same lines land in glados/data/debug.log
2026-08-21 21:04:11,395 [INFO] glados: debug session started
2026-08-21 21:04:11,405 [DEBUG] glados: transcribe_stub completed in 10.2ms
2026-08-21 21:04:11,425 [DEBUG] glados: llm_stub completed in 20.1ms
2026-08-21 21:04:11,425 [INFO] glados: reply: Oh. It's you.

Two handlers on one logger: StreamHandler for the console you are watching now, FileHandler for the record that survives the scroll. The stubs are deliberate; they prove the pattern with near-deterministic timings before you spend it on the real thing. Decorating your actual loop is one line per stage and zero edits inside any of them, and once you do, the flaky stall you could never catch live becomes a grep through debug.log for the turn where one stage's milliseconds spiked.

◆ Note — two habits of the logging module worth knowing on day one

logging.basicConfig() only acts if the root logger has no handlers yet; a second call is silently ignored. If your format never takes effect, some import configured logging before you did, and the fix is to configure first or attach handlers explicitly. And log records go to stderr by default, not stdout, so your log lines and your print() output can arrive interleaved oddly when both are redirected. Add glados/data/debug.log to .gitignore while you are here: runtime state, not source.

Why this works: a severity level is a filter

It reads like a label, [DEBUG] versus [INFO], but the level is a comparison that runs on every call: each record carries a numeric severity, the logger holds a threshold, and records below the threshold are discarded before the message is even formatted. That ordering matters. Flip the configured level to logging.INFO and every logger.debug call in the project becomes a cheap no-op; the timing lines vanish from console and file alike without a single call site changing. Verbosity stops being something you edit and becomes something you configure.

That is also why the severity chosen at each call site is a design decision and not decoration. Timing lines are debug because they are for a developer hunting a bottleneck; session milestones are info because an operator watching a healthy run should see them; failures are error because nobody gets to filter those out by accident. You are choosing, per line, which audience will ever read it. The pattern generalizes past logging: the same bolt-on-beside idea gives you retry decorators, cache decorators, and permission checks later in this book, all wrapping stages that never learn they were wrapped.

⚠ Worked failure — the stage registry with one entry

Volume 3's discipline says stages should be discoverable, so you build a registry keyed by each function's own name. But this version of timed was written without @wraps:

def timed(func):
    def wrapper(*args, **kwargs):          # no @wraps(func) here
        start = time.perf_counter()
        result = func(*args, **kwargs)
        elapsed = (time.perf_counter() - start) * 1000
        logger.debug(f"{func.__name__} completed in {elapsed:.1f}ms")
        return result
    return wrapper

registry = {fn.__name__: fn for fn in (transcribe_stub, llm_stub)}
print("registered stages:", list(registry))

$ uv run python labs/timing.py
registered stages: ['wrapper']

Two stages went in; one came out, and no error said so. Every function this decorator touches is literally replaced by a function named wrapper, so the dict comprehension computes the same key twice and the second stage silently overwrites the first. The cruel part is that the timing log looked correct the whole time: inside the closure, func is the original, so func.__name__ logs the right name even while the decorated object's name is wrong from the outside. Symptom to cause: a dict built from names is missing entries, so print the names; both say wrapper, so the identity was lost at decoration; @wraps(func) copies it back, and the registry holds two stages again.

Checkpoint, on the record

✓ Checkpoint — what you can now do

I can name the three fields a log line carries that a print never does, and point to where each lives in the format string.
I can write out what @timed expands to, and explain why the decorated stage's own logic never changes.
I know why durations come from perf_counter() and timestamps from the wall clock, and what an NTP adjustment does to the wrong choice.
I can defend log-then-bare-raise: the decorator records, the caller still decides, and nothing is swallowed.
I know what @wraps copies, which code breaks without it, and why the timing log alone would never have exposed the bug.
I can switch the whole project between investigation and production output by changing one level, with zero call-site edits.

⚡ Exercises — try first, then reveal

Exercise 1 — the level as an environment variable. Make the log level configurable via GLADOS_LOG_LEVEL, defaulting to INFO. Run the full file both ways and diff what appears.

Read the variable and translate the name to a constant with getattr(logging, os.environ.get("GLADOS_LOG_LEVEL", "INFO").upper(), logging.INFO), passed as level=. Under the default, both completed in ...ms lines disappear and the two INFO lines survive; under GLADOS_LOG_LEVEL=DEBUG you get all four. Same file, same code, two audiences, and the third argument to getattr means a typo in the variable degrades to INFO instead of crashing at import.

Exercise 2 — a stage that fails on purpose. Add a tts_stub that raises FileNotFoundError("voice model not found"), decorate it, and call it from a try/except in main. Predict every log line before you run.

Four things, in order: an ERROR line naming tts_stub and the message, the full traceback at DEBUG, and then whatever your handler does, because the bare raise delivered the exception to main intact. If you log a recovery line (logger.info("recovered: continuing without audio")) you have the whole story of a failure and its handling in one file, timestamped, which is exactly what you will want the first time she goes mute at 2 a.m.

Exercise 3 — find the real bottleneck. Have the decorator also store each duration in a STAGE_TIMINGS dict keyed by function name, then decorate your actual voice loop's stages and print the slowest after a real conversation.

STAGE_TIMINGS[func.__name__] = elapsed inside the wrapper, then max(STAGE_TIMINGS, key=STAGE_TIMINGS.get) after the run. On a CPU-only machine the synthesis stage should win, and now the ranking comes from the machine instead of your memory. Compare against the paper numbers you wrote down in chapter 10: the baseline you measured by hand is now collected automatically on every turn, and note that this registry only works because @wraps gives each stage its real name as the key.

One loose end, and it is deliberate: debug.log grows on every run and nothing ever trims it. A file that only grows is a disk failure on a schedule, slow enough to forget about and certain enough to arrive. Next chapter meets the same problem where it bites hardest, sensor readings that accumulate forever, and builds a log that keeps the last N entries and quietly lets go of the rest.