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 dataclasses — LatencyReport 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.
BatchLatencyReportlives in memory, in this Python session — unlike Module 2'sRUN_LOG.jsonl, which does write to disk. Correlating aLatencyReportwithrun_logger.py'strace_idis 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=275anddominant_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_roomstarted failing on90%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
-
Thinking
observability/latency_model.pyreplacesobservability/cost_calculator.pyorobservability/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. -
Calculating
tool_ms_totalsby summingLatencyReport.total_latency_msinstead of walking each report'stool_calls.total_latency_msis the sum per run; for the per-tool breakdown, you have to walk eachLatencyReport'stool_callsagain — summing every run'stotal_latency_msjust gives you, again, the grand total, with no breakdown at all. -
Building
BatchLatencyReportbefore having everyLatencyReportfrom the batch.percentileneeds the complete, sorted list of latencies — calling it with a partial batch (for example, inside the sameforthat's still generating the reports) would give a p50/p95 calculated over less data than the batch actually has. -
Forgetting
dominant_toolgets calculated over total milliseconds, not over the number of calls. Lesson 07 already demonstrated it:get_quotegets called more times than any other tool, butbook_roomis this report'sdominant_tool, precisely becausemax(tool_ms_totals, key=...)compares milliseconds, not counts. -
Thinking this mini-project needs a
trace_idor a logger to be useful. It doesn't need one for this module's goal — measuring latency — although integrating it with Module 2'strace_idwould 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 twodataclasses—LatencyReportper run,BatchLatencyReportper 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"(720of1415total 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) andobservability/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
- Python —
dataclasses—LatencyReportandBatchLatencyReport, this mini-project's two central structures. - Python —
statistics—statistics.mean, used inbuild_batch_reportfor the batch average. - Python —
collections.Counter— The structure behindtool_ms_totals, accumulated over eachLatencyReportin the batch. - 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.
- 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.