Module 4: Measuring Latency Honestly

Mini-Project: A Latency Report

Description

Seven lessons built, separately, every piece of this module: what latency gets measured (lesson 02), why it's modeled instead of measured with the real clock (lesson 03), TOOL_LATENCY_MS as fixed data (lesson 04), a run's total sum with its nuance on rejected tool_uses (lesson 05), p50/p95 percentiles over a batch (lesson 06), and latency as an operational signal with its per-tool breakdown (lesson 07). This mini-project brings them all together into observability/latency_model.py: two dataclassesLatencyReport per run, BatchLatencyReport for the whole batch — and the functions that build them, run over the same batch of twelve runs that accompanied lessons 06 and 07.

With this, observability/latency_model.py sits alongside observability/run_logger.py (Module 2) and observability/cost_calculator.py (Module 3) — the three operations-layer pieces Module 5 is going to use, without building anything again, for the regression gate.

Connection to the module

This is the synthesis of the module's eight lessons. observability/latency_model.py doesn't invent any new technique: it reuses TOOL_LATENCY_MS from lesson 04, total_run_latency_ms's logic from lesson 05, the percentile function from lesson 06, and the per-tool breakdown from lesson 07 — all together, in two reusable data structures, run over a real batch.


Worked example: observability/latency_model.py, complete

The pieces you already know, in a single file

import math
import statistics
from collections import Counter
from dataclasses import dataclass

import reservo_agent as ra

TOOL_LATENCY_MS = {
    "list_rooms": 40,
    "get_quote": 25,
    "book_room": 120,
    "cancel_booking": 90,
}


def executed_tool_names(history):
    """Devuelve, en orden, los nombres de las tools que de verdad se
    ejecutaron en un run (tool_result sin is_error) -- lección 05/07."""
    tool_use_name = {}
    for turn in history:
        if turn["role"] != "assistant" or not isinstance(turn["content"], list):
            continue
        for block in turn["content"]:
            if block["type"] == "tool_use":
                tool_use_name[block["id"]] = block["name"]
    names = []
    for turn in history:
        if turn["role"] != "user" or not isinstance(turn["content"], list):
            continue
        for block in turn["content"]:
            if block["type"] == "tool_result" and not block.get("is_error"):
                names.append(tool_use_name.get(block["tool_use_id"]))
    return names


def total_run_latency_ms(tool_calls):
    """Suma la latencia modelada de las tools que de verdad se ejecutaron
    -- lección 05."""
    return sum(TOOL_LATENCY_MS.get(name, 0) for name in tool_calls)


def percentile(sorted_values, p):
    """Percentil nearest-rank -- lección 06. Siempre devuelve un valor
    que un run real produjo."""
    n = len(sorted_values)
    rank = math.ceil(p / 100 * n)
    rank = max(1, min(rank, n))
    return sorted_values[rank - 1]

None of this is new — these are, literally, the same four functions from lessons 05, 06, and 07, copied unchanged into this single file.

The two dataclasses: per run, and per batch

@dataclass
class LatencyReport:
    """Todo lo que este modulo puede decir de la latencia de UN run."""
    run_id: int
    question: str
    tool_calls: list
    total_latency_ms: int


@dataclass
class BatchLatencyReport:
    """El resumen de latencia de un LOTE completo de runs."""
    n_runs: int
    p50_ms: int
    p95_ms: int
    mean_ms: float
    tool_ms_totals: dict
    dominant_tool: str


def build_latency_report(run_id, question, history):
    tool_calls = executed_tool_names(history)
    return LatencyReport(
        run_id=run_id, question=question, tool_calls=tool_calls,
        total_latency_ms=total_run_latency_ms(tool_calls),
    )


def build_batch_report(reports):
    latencies = sorted(r.total_latency_ms for r in reports)
    tool_ms_totals = Counter()
    for r in reports:
        for name in r.tool_calls:
            tool_ms_totals[name] += TOOL_LATENCY_MS[name]
    dominant_tool = max(tool_ms_totals, key=lambda name: tool_ms_totals[name])
    return BatchLatencyReport(
        n_runs=len(reports),
        p50_ms=percentile(latencies, 50),
        p95_ms=percentile(latencies, 95),
        mean_ms=round(statistics.mean(latencies), 1),
        tool_ms_totals=dict(tool_ms_totals),
        dominant_tool=dominant_tool,
    )

LatencyReport is this module's minimal unit: a run, its question, which tools it actually ran, and its total latency. BatchLatencyReport is a complete batch's synthesis: how many runs, p50, p95, the average, the per-tool millisecond breakdown, and which tool dominates — literally, lessons 06 and 07 turned into a single structure.

The complete batch, end to end

Reuse, unchanged, lessons 06 and 07's same batch of twelve runs:

def tu(id_, name, input_):
    return {"type": "tool_use", "id": id_, "name": name, "input": input_}


def step(*blocks):
    return {"stop_reason": "tool_use", "content": list(blocks)}


def end(text):
    return {"stop_reason": "end_turn", "content": [{"type": "text", "text": text}]}


batch = [
    ("Cuánto cuesta Focus basic 2h", [
        step(tu("t01", "get_quote", {"room": "Focus", "tier": "basic", "hours": 2})),
        end("Focus basic 2h cuesta $50.00.")]),
    ("Qué salas hay disponibles", [
        step(tu("t01", "list_rooms", {})),
        end("Tenemos Focus, Studio y Boardroom.")]),
    ("Reserva Studio basic 1h para Luis", [
        step(tu("t01", "get_quote", {"room": "Studio", "tier": "basic", "hours": 1})),
        step(tu("t02", "book_room", {"room": "Studio", "tier": "basic", "hours": 1, "member": "Luis"})),
        end("Reservé Studio basic 1h para Luis. Confirmación #1.")]),
    ("Cancela la reserva 1", [
        step(tu("t01", "cancel_booking", {"id": 1})),
        end("Cancelé la reserva #1.")]),
    ("Reserva Boardroom pro 1h para Sofía, con la lista primero", [
        step(tu("t01", "list_rooms", {})),
        step(tu("t02", "get_quote", {"room": "Boardroom", "tier": "pro", "hours": 1})),
        step(tu("t03", "book_room", {"room": "Boardroom", "tier": "pro", "hours": 1, "member": "Sofía"})),
        end("Reservé Boardroom pro 1h para Sofía. Confirmación #2.")]),
    ("Cotiza Focus premium y luego pro 3h", [
        step(tu("t01", "get_quote", {"room": "Focus", "tier": "premium", "hours": 3})),
        step(tu("t02", "get_quote", {"room": "Focus", "tier": "pro", "hours": 3})),
        end("Focus pro 3h cuesta $60.00.")]),
    ("Reserva Focus pro 3h para Ana, con corrección", [
        step(tu("t01", "list_rooms", {})),
        step(tu("t02", "get_quote", {"room": "Focus", "tier": "premium", "hours": 3})),
        step(tu("t03", "get_quote", {"room": "Focus", "tier": "pro", "hours": 3})),
        step(tu("t04", "book_room", {"room": "Focus", "tier": "pro", "hours": 3, "member": "Ana"})),
        end("Reservé Focus pro 3h para Ana. Confirmación #3.")]),
    ("Reserva y cancela Studio pro 2h para Diego", [
        step(tu("t01", "book_room", {"room": "Studio", "tier": "pro", "hours": 2, "member": "Diego"})),
        step(tu("t02", "cancel_booking", {"id": 4})),
        end("Reservé y cancelé Studio pro 2h para Diego.")]),
    ("Compara Focus pro y Boardroom pro 2h", [
        step(tu("t01", "get_quote", {"room": "Focus", "tier": "pro", "hours": 2})),
        step(tu("t02", "get_quote", {"room": "Boardroom", "tier": "pro", "hours": 2})),
        end("Focus pro 2h cuesta $40.00 y Boardroom pro 2h cuesta $128.00.")]),
    ("Reserva Boardroom basic 1h para Carla, con horas inválidas primero", [
        step(tu("t01", "book_room", {"room": "Boardroom", "tier": "basic", "hours": 0, "member": "Carla"})),
        step(tu("t02", "book_room", {"room": "Boardroom", "tier": "basic", "hours": 1, "member": "Carla"})),
        end("Reservé Boardroom basic 1h para Carla. Confirmación #5.")]),
    ("Qué salas hay y cuánto cuesta Studio pro 4h", [
        step(tu("t01", "list_rooms", {})),
        step(tu("t02", "get_quote", {"room": "Studio", "tier": "pro", "hours": 4})),
        end("Studio pro 4h cuesta $128.00.")]),
    ("Reserva Focus pro 3h para Marta y luego cancela", [
        step(tu("t01", "list_rooms", {})),
        step(tu("t02", "get_quote", {"room": "Focus", "tier": "pro", "hours": 3})),
        step(tu("t03", "book_room", {"room": "Focus", "tier": "pro", "hours": 3, "member": "Marta"})),
        step(tu("t04", "cancel_booking", {"id": 6})),
        end("Reservé y cancelé Focus pro 3h para Marta.")]),
]

reports = []
for i, (question, script) in enumerate(batch, start=1):
    final, history = ra.run_reservo_agent(question, script)
    reports.append(build_latency_report(i, question, history))

print("=== LatencyReport por run ===")
for r in reports:
    print(f"run {r.run_id:2}: {r.total_latency_ms:4} ms  tools={r.tool_calls}")

batch_report = build_batch_report(reports)
print()
print("=== BatchLatencyReport ===")
print("n_runs        :", batch_report.n_runs)
print("p50_ms        :", batch_report.p50_ms)
print("p95_ms        :", batch_report.p95_ms)
print("mean_ms       :", batch_report.mean_ms)
print("tool_ms_totals:", batch_report.tool_ms_totals)
print("dominant_tool :", batch_report.dominant_tool)

What to expect:

=== LatencyReport por run ===
run  1:   25 ms  tools=['get_quote']
run  2:   40 ms  tools=['list_rooms']
run  3:  145 ms  tools=['get_quote', 'book_room']
run  4:   90 ms  tools=['cancel_booking']
run  5:  185 ms  tools=['list_rooms', 'get_quote', 'book_room']
run  6:   25 ms  tools=['get_quote']
run  7:  185 ms  tools=['list_rooms', 'get_quote', 'book_room']
run  8:  210 ms  tools=['book_room', 'cancel_booking']
run  9:   50 ms  tools=['get_quote', 'get_quote']
run 10:  120 ms  tools=['book_room']
run 11:   65 ms  tools=['list_rooms', 'get_quote']
run 12:  275 ms  tools=['list_rooms', 'get_quote', 'book_room', 'cancel_booking']

=== BatchLatencyReport ===
n_runs        : 12
p50_ms        : 90
p95_ms        : 275
mean_ms       : 117.9
tool_ms_totals: {'get_quote': 225, 'list_rooms': 200, 'book_room': 720, 'cancel_booking': 270}
dominant_tool : book_room

You already saw every figure in this report, separately, in an earlier lesson — the difference is that it now lives in two reusable objects (LatencyReport, BatchLatencyReport), built by two functions (build_latency_report, build_batch_report) any later module in this guide can import and call, without rewriting any of these four base functions.


What this report still doesn't do

It's worth precisely naming this mini-project's limits, because each one is, exactly, what another module in this guide adds afterward:

  • It doesn't persist to any file. BatchLatencyReport lives in memory, in this Python session — unlike Module 2's RUN_LOG.jsonl, which does write to disk. Correlating a LatencyReport with run_logger.py's trace_id is possible — both identify the same run — but this lesson doesn't do it explicitly; it remains a natural integration for Module 8's capstone.
  • It doesn't decide anything. It reports p95_ms=275 and dominant_tool="book_room", but doesn't compare that figure against any threshold, nor does it pass or fail any gate. That is, precisely, Module 5's job: taking exactly these figures and turning them into a pass/fail criterion.
  • It doesn't react to a tool that fails consistently. If book_room started failing on 90% of its calls across several runs, this report would keep calculating its latency normally for the calls that did succeed — it has no mechanism at all for "cutting off" traffic toward a tool that stopped responding. That's Module 6's circuit breaker.

None of these three limits is an oversight — it is, precisely, the correct scope for a module that measures, not one that decides or hardens. Modules 5 and 6 exist because measuring is a discipline distinct from acting on what's measured.


Common mistakes

  1. Thinking observability/latency_model.py replaces observability/cost_calculator.py or observability/run_logger.py. No — all three pieces coexist, each one answering a distinct question (what happened, how much it cost, how long it took), and Module 5 is going to use them together, not one in place of another.

  2. Calculating tool_ms_totals by summing LatencyReport.total_latency_ms instead of walking each report's tool_calls. total_latency_ms is the sum per run; for the per-tool breakdown, you have to walk each LatencyReport's tool_calls again — summing every run's total_latency_ms just gives you, again, the grand total, with no breakdown at all.

  3. Building BatchLatencyReport before having every LatencyReport from the batch. percentile needs the complete, sorted list of latencies — calling it with a partial batch (for example, inside the same for that's still generating the reports) would give a p50/p95 calculated over less data than the batch actually has.

  4. Forgetting dominant_tool gets calculated over total milliseconds, not over the number of calls. Lesson 07 already demonstrated it: get_quote gets called more times than any other tool, but book_room is this report's dominant_tool, precisely because max(tool_ms_totals, key=...) compares milliseconds, not counts.

  5. Thinking this mini-project needs a trace_id or a logger to be useful. It doesn't need one for this module's goal — measuring latency — although integrating it with Module 2's trace_id would be a natural improvement in a real system. This mini-project is deliberately self-sufficient, so it's clear what the latency layer contributes on its own, before combining it with the others.


Exercises

Exercise 1: Add a thirteenth run and recalculate the BatchLatencyReport (Easy)

In a new process — so BOOKINGS starts empty and the hardcoded ids in batch (cancel_booking with id=1, id=4, id=6) keep pointing to the correct bookings, without carrying over any booking from an earlier run of this same module — add a new run to batch that only calls list_rooms (40 ms), rebuild the reports list by running batch_extendido end to end, and recalculate build_batch_report. Does dominant_tool change?

See solution
batch_extendido = batch + [
    ("Qué salas hay, otra vez", [
        step(tu("t01", "list_rooms", {})),
        end("Tenemos Focus, Studio y Boardroom.")]),
]
reports_extendidos = []
for i, (question, script) in enumerate(batch_extendido, start=1):
    final, history = ra.run_reservo_agent(question, script)
    reports_extendidos.append(build_latency_report(i, question, history))

batch_report_extendido = build_batch_report(reports_extendidos)
print("n_runs        :", batch_report_extendido.n_runs)
print("tool_ms_totals:", batch_report_extendido.tool_ms_totals)
print("dominant_tool :", batch_report_extendido.dominant_tool)

Expected output:

n_runs        : 13
tool_ms_totals: {'get_quote': 225, 'list_rooms': 240, 'book_room': 720, 'cancel_booking': 270}
dominant_tool : book_room

Explanation: list_rooms rises from 200 to 240 ms (5 * 40 + 1 * 40), but stays well below book_room (720 ms) — dominant_tool doesn't change. A single additional run, with the cheaper of the two read tools, doesn't carry enough weight to displace a tool that already dominates by such a wide margin.

Exercise 2: Find the run whose latency is closest to the batch average (Medium)

Using batch_report.mean_ms and the reports list, find which LatencyReport has the total latency closest to the batch average (117.9 ms).

See solution
mas_cercano = min(reports, key=lambda r: abs(r.total_latency_ms - batch_report.mean_ms))
print(f"run {mas_cercano.run_id}: {mas_cercano.total_latency_ms} ms -- {mas_cercano.question}")

Expected output:

run 10: 120 ms -- Reserva Boardroom basic 1h para Carla, con horas inválidas primero

Explanation: 120 ms is barely 2.1 ms from the average (|120 - 117.9| = 2.1), the smallest distance among the batch's twelve runs — closer, even, than run 3 (145 ms, 27.1 away) or run 4 (90 ms, 27.9 away). It's worth noting the run closest to the average (run 10, 120 ms) isn't the same as the p50 run (run 4, 90 ms, calculated in lesson 06) — the average and the median are two different "center" measures, sensitive to different things, and there's no guarantee they'll coincide in the same run.

Exercise 3: Design a runs_above_p95 function that filters the batch (Hard)

Write a runs_above_p95(reports, batch_report) function that returns the list of LatencyReports whose total_latency_ms is greater than or equal to the batch's p95_ms. Run it over reports and batch_report, and explain what it means, operationally, for that list to have more than one element in a batch of twelve runs.

See solution
def runs_above_p95(reports, batch_report):
    return [r for r in reports if r.total_latency_ms >= batch_report.p95_ms]


sospechosos = runs_above_p95(reports, batch_report)
for r in sospechosos:
    print(f"run {r.run_id}: {r.total_latency_ms} ms -- {r.question}")

Expected output:

run 12: 275 ms -- Reserva Focus pro 3h para Marta y luego cancela

Explanation: with p95_ms=275 and a single run (12) reaching exactly that value, the list has one single element — consistent with what lesson 06 already explained: with twelve runs, p95 almost always coincides with the batch's slowest run, so "at or above p95" almost never describes more than one run. In a real production batch, with hundreds or thousands of runs, this same function would return, by definition, roughly 5% of all runs — the exact group of "worst cases" an operations team would want to review first if something starts feeling slow for some customers.


Summary and next step

  • We built a complete observability/latency_model.py: TOOL_LATENCY_MS, total_run_latency_ms, percentile, and two dataclassesLatencyReport per run, BatchLatencyReport per batch — that bring the previous seven lessons together into a single reusable artifact.
  • We ran it over lessons 06 and 07's same batch of twelve runs, and confirmed, again, every figure: p50=90, p95=275, mean=117.9, dominant_tool="book_room" (720 of 1415 total ms).
  • We precisely named this mini-project's three limits — it doesn't persist, it doesn't decide, it doesn't react to consistent failures — and which module each one belongs to.
  • With this, Module 4 closes. Alongside observability/run_logger.py (Module 2) and observability/cost_calculator.py (Module 3), this guide now has the three "measure" pieces complete: what happened, how much it cost, how long it took.

Next module: Module 5 — Regression Evals as a Production Gate. With cost and latency now measured, and observability now built, this module turns those signals into an automatic criterion: a harness that runs a fixed set of cases and fails the build if the agent chose the wrong tool, if the output schema doesn't validate, or if cost or latency spiked above a threshold — never a semantic judgment, always a literal comparison against an expected value.


Additional resources

  1. Python — dataclassesLatencyReport and BatchLatencyReport, this mini-project's two central structures.
  2. Python — statisticsstatistics.mean, used in build_batch_report for the batch average.
  3. Python — collections.Counter — The structure behind tool_ms_totals, accumulated over each LatencyReport in the batch.
  4. Anthropic — Building effective agents — On why measuring an agentic system — cost, latency, failure rate — is a discipline that always precedes any decision to optimize or harden it.
  5. Python 3.14 — What's New — The version every line of code in this module ran on, from lesson 01 through this mini-project's close.