Total Run Latency

Description

Lesson 02 already calculated a total latency, but over a deliberately simple case: Sofía's run, with no error along the way. This lesson builds total_run_latency_ms's complete, correct version — the one that works over any run, including ones with one or more tool_uses rejected on validation along the way. And so the nuance sticks, it isn't just explained: the bug that happens if you ignore it gets demonstrated, with the exact numeric difference it produces.

Connection to the module

This is observability/latency_model.py's second piece, the one that rests directly on TOOL_LATENCY_MS (lesson 04). The rest of the module — percentiles in lesson 06, latency as a signal in lesson 07, the complete report in lesson 08 — uses total_run_latency_ms exactly as it stands at the end of this lesson, without touching it again.

Analogy: the taxi meter that doesn't charge for a red light

A properly calibrated taxi meter charges for the distance traveled, not for every attempt to start moving. If the light is red and the car isn't moving, the meter doesn't add those seconds to the trip — it only counts the time the car actually moved forward. A poorly calibrated meter, one that also charged for time stopped at every light, would be charging the passenger for time that never turned into distance traveled.

total_run_latency_ms has to behave like the properly calibrated meter. A tool_use rejected by check_input_v2 — like Ana's script's tier="premium" — is, exactly, the red light: the agent tried to request the tool, but dispatch_robust stopped it before the real Python function ever ran even once. Charging that attempt for latency would be as wrong as charging the passenger for the red light — it would add time that, in this guide's model, never happened.

Worked example: the complete function, and the bug it fixes

The complete version

import reservo_agent as ra

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


def total_run_latency_ms(history):
    """Suma la latencia modelada de cada tool que se EJECUTO de verdad.
    Un tool_use rechazado por validacion (is_error, sin ejecutar la funcion
    real) no le agrega latencia al run -- nunca llego a la tool."""
    latency_ms = 0
    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"]
    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"):
                name = tool_use_name.get(block["tool_use_id"])
                latency_ms += TOOL_LATENCY_MS.get(name, 0)
    return latency_ms

Read it in two passes, because that's how it's written: the first pass (for turn in history over assistant turns) builds tool_use_name, a tool_use_id -> tool name map, without summing anything yet. The second pass (for turn in history over user turns) walks the tool_results and sums the matching tool's latency only if that tool_result doesn't carry is_error. Both passes are needed because a tool_result knows its tool_use_id, but not the name of the tool that generated it — that name lives in an earlier turn's tool_use block, and tool_use_name is the bridge between the two.

Ana's canonical run, with its invalid tier

script_ana = [
    {"stop_reason": "tool_use", "content": [
        {"type": "tool_use", "id": "toolu_01", "name": "list_rooms", "input": {}}]},
    {"stop_reason": "tool_use", "content": [
        {"type": "tool_use", "id": "toolu_02", "name": "get_quote",
         "input": {"room": "Focus", "tier": "premium", "hours": 3}}]},
    {"stop_reason": "tool_use", "content": [
        {"type": "tool_use", "id": "toolu_03", "name": "get_quote",
         "input": {"room": "Focus", "tier": "pro", "hours": 3}}]},
    {"stop_reason": "tool_use", "content": [
        {"type": "tool_use", "id": "toolu_04", "name": "book_room",
         "input": {"room": "Focus", "tier": "pro", "hours": 3, "member": "Ana"}}]},
    {"stop_reason": "end_turn", "content": [
        {"type": "text", "text": "Reservé Focus pro por 3 horas para Ana. Total $60.00. Confirmación #1."}]},
]
final, history = ra.run_reservo_agent("Reserva Focus pro 3h para Ana", script_ana)
ra.print_trace(history)
print()
print("latencia total:", total_run_latency_ms(history), "ms")

What to expect:

  [0] user      pregunta: 'Reserva Focus pro 3h para Ana'
  [1] assistant tool_use(list_rooms): {}
  [2] user      tool_result: [{"room": "Focus", "rate_cents": 2500}, {"room": "Studio", "rate_cents": 4000}, {"room": "Boardroom", "rate_cents": 8000}]
  [3] assistant tool_use(get_quote): {'room': 'Focus', 'tier': 'premium', 'hours': 3}
  [4] user      tool_result [is_error]: 'tier'='premium' no está en enum ['basic', 'pro']
  [5] assistant tool_use(get_quote): {'room': 'Focus', 'tier': 'pro', 'hours': 3}
  [6] user      tool_result: {"price_cents": 6000}
  [7] assistant tool_use(book_room): {'room': 'Focus', 'tier': 'pro', 'hours': 3, 'member': 'Ana'}
  [8] user      tool_result: {"booking_id": 1, "confirmed": true}
  [9] assistant texto final: 'Reservé Focus pro por 3 horas para Ana. Total $60.00. Confirmación #1.'

latencia total: 185 ms

185, not 210. Turn [4] carries [is_error] — that get_quote with tier="premium" never ran get_quote's real function, because check_input_v2 stopped it first. The real total is list_rooms (40) + the get_quote that did run (25) + book_room (120) = 185 — the rejected get_quote, even though it appears in the trace as a complete tool_use, with its own turn and its own tool_result, contributes not a single millisecond.

The bug, demonstrated with a real numeric difference

It's worth seeing, run for real, what would happen if total_run_latency_ms didn't check is_error — summing every tool_use's latency, regardless of whether its tool_result came back marked as an error:

def total_run_latency_ms_wrong(history):
    """INCORRECTA -- suma la latencia de CADA tool_use, sin chequear
    is_error. Se define aqui solo para medir el bug, nunca se usa en el
    resto de esta guia."""
    total_ms = 0
    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":
                total_ms += TOOL_LATENCY_MS.get(block["name"], 0)
    return total_ms


wrong = total_run_latency_ms_wrong(history)
correct = total_run_latency_ms(history)
print("version incorrecta (cuenta TODO tool_use):", wrong, "ms")
print("version correcta (solo lo ejecutado)      :", correct, "ms")
print("diferencia                                :", wrong - correct, "ms")

What to expect:

version incorrecta (cuenta TODO tool_use): 210 ms
version correcta (solo lo ejecutado)      : 185 ms
diferencia                                : 25 ms

A 25 ms difference — exactly get_quote's latency, the tool the tier="premium" attempt tried to call and never got to run. This difference isn't an extreme or rare case: any run where the model (concept) makes a mistake once and self-corrects — the central robustness pattern agent-fundamentals M7 built — is going to inflate its total latency if the counting function doesn't tell "attempted" apart from "executed." With a single rejected attempt the difference is 25 ms; with several rejected attempts in a row — something that can happen if the model takes a while to converge on a valid argument — the incorrect version could inflate total latency well above what the run actually cost in time.

Why latency doesn't change even when the number of steps does

Module 1 already confirmed this, and it's worth repeating here with this module's precise vocabulary: a run's total latency depends solely on the sequence of tools that actually ran, never on the number of turns in history. Ana's run has ten turns in its history — more than Sofía's run, which has eight — but its total latency (185) is identical to Sofía's (185), because both, in the end, run exactly the same real sequence: list_rooms, one valid get_quote, book_room. A rejected tool_use adds turns to the trace — it costs space in history, it costs an is_error tool_result someone has to read — but it doesn't add real time, because check_input_v2 is a local Python function, not a call that takes time.

Common mistakes

1. Summing a tool_use's latency without checking its tool_result. This is, precisely, the bug this lesson just demonstrated with total_run_latency_ms_wrong — an easy mistake to make if you forget history records both the attempts that failed and the ones that succeeded.

2. Confusing "validation rejected" with "tool that failed while running." They're two different things. A tool_use rejected by check_input_v2 (like tier="premium") never runs the real function — zero latency. A tool that does run but returns an unexpected business result (for example, cancel_booking with an id that doesn't exist) did get to run the real function — the distinction between both cases matters for understanding what TOOL_LATENCY_MS really measures.

3. Thinking fewer turns in history always means less latency. No — as the previous section confirmed, Ana's run has more turns than Sofía's and yet the same total latency. The number of turns measures the trace's complexity; latency measures the modeled time of the tools that actually ran. Related signals, but not interchangeable.

4. Forgetting .get(name, 0) when looking things up in TOOL_LATENCY_MS inside total_run_latency_ms. If a new tool got registered in the system without also being added to this dictionary, bracket access (TOOL_LATENCY_MS[name]) would blow up the entire function with a KeyError — exactly the same mistake lesson 04 already warned about, now with consequences for the module's central function.

5. Writing a new version of total_run_latency_ms that rebuilds tool_use_name with a single for, mixing both passes. It's tempting to "simplify" by combining both walks into a single for turn in history, but that only works if every tool_use always appears before its matching tool_result in history — which is true in this guide, but mixing both responsibilities into a single loop makes the code more fragile against any future change to turn order.

Exercises

Exercise 1: Calculate the bug's difference over a run with two rejections (Easy)

Design a script where book_room gets rejected twice for invalid hours (hours=0) before succeeding with hours=1. Calculate the latency with total_run_latency_ms and with total_run_latency_ms_wrong, and confirm the difference.

script_dos_rechazos = [
    {"stop_reason": "tool_use", "content": [
        {"type": "tool_use", "id": "toolu_01", "name": "book_room",
         "input": {"room": "Studio", "tier": "basic", "hours": 0, "member": "Nico"}}]},
    {"stop_reason": "tool_use", "content": [
        {"type": "tool_use", "id": "toolu_02", "name": "book_room",
         "input": {"room": "Studio", "tier": "basic", "hours": -1, "member": "Nico"}}]},
    {"stop_reason": "tool_use", "content": [
        {"type": "tool_use", "id": "toolu_03", "name": "book_room",
         "input": {"room": "Studio", "tier": "basic", "hours": 1, "member": "Nico"}}]},
    {"stop_reason": "end_turn", "content": [
        {"type": "text", "text": "Reservé Studio basic 1h para Nico."}]},
]
final, history = ra.run_reservo_agent("Reserva Studio basic 1h para Nico", script_dos_rechazos)
correct = total_run_latency_ms(history)
wrong = total_run_latency_ms_wrong(history)
print("correcta :", correct, "ms")
print("incorrecta:", wrong, "ms")
print("diferencia:", wrong - correct, "ms")

correcta : 120 ms
incorrecta: 360 ms
diferencia: 240 ms

Exercise 2: Confirm latency doesn't change if the run succeeds on the first attempt (Medium)

Run Exercise 1's same script, but without the two rejected attempts — just book_room with hours=1, directly. Confirm total_run_latency_ms and total_run_latency_ms_wrong give the same result in this case.

script_directo = [
    {"stop_reason": "tool_use", "content": [
        {"type": "tool_use", "id": "toolu_01", "name": "book_room",
         "input": {"room": "Studio", "tier": "basic", "hours": 1, "member": "Nico"}}]},
    {"stop_reason": "end_turn", "content": [
        {"type": "text", "text": "Reservé Studio basic 1h para Nico."}]},
]
final, history = ra.run_reservo_agent("Reserva Studio basic 1h para Nico", script_directo)
print("correcta  :", total_run_latency_ms(history), "ms")
print("incorrecta:", total_run_latency_ms_wrong(history), "ms")

correcta  : 120 ms
incorrecta: 120 ms

Exercise 3: Design a run where the incorrect version underestimates latency, not overestimates it (Hard)

Every example in this lesson shows total_run_latency_ms_wrong overestimating latency (giving a higher number than the correct one). Does any script exist, with Reservo's four tools, where the incorrect version gives a number lower than the correct one? Reason about the answer before trying to build an example.

correct = total_run_latency_ms(history)  # el history del Ejercicio 1, si sigue en memoria
# wrong siempre es >= correct, para cualquier history posible en esta guía
print("¿wrong siempre es >= correct?", "Sí, por construcción -- suma sobre un superconjunto")

Summary and next step

• We built the complete total_run_latency_ms: two passes over history, the first to map tool_use_id -> name, the second to sum only the tool_results without is_error.
• We ran it over Ana's canonical run and confirmed, again, 185 ms — the get_quote rejected for tier="premium" contributes nothing to the total.
• We demonstrated the bug, run for real: a version that doesn't check is_error gives 210 ms for the same run — 25 ms too many, exactly the latency of the tool that never ran.
• We confirmed, with a structural argument (Exercise 3), that this bug can only overestimate latency, never underestimate it — useful information for recognizing it if it ever shows up in a real system.

Next lesson: 06 — Percentiles: p50 and p95. With a run's latency now solved, we scale up to a batch of twelve real runs and answer the question an average alone can't answer: how slow is the experience of the customer having the worst time?

Additional resources

1. Anthropic — Tool use (function calling) overview — The exact tool_use/tool_result/is_error shape total_run_latency_ms is built on.
2. Python — list and dict comprehensions — The foundation of this function's two passes over history.
3. Anthropic — Implement tool use — The complete flow of validating before running, the underlying reason a rejected tool_use never gets to cost real time.
4. Python 3.14 — What's New — The version every calculation, correct and incorrect, in this lesson ran on.