Módulo 4: Medir latencia con honestidad

Latencia total del run

Siguiente →

Descripción

La lección 02 ya calculó una latencia total, pero sobre un caso simple a propósito: el run de Sofía, sin ningún error en el camino. Esta lección construye la versión completa y correcta de total_run_latency_ms — la que funciona sobre cualquier run, incluidos los que tienen uno o más tool_use rechazados por validación en el camino. Y para que el matiz quede grabado, no solo se explica: se demuestra el bug que ocurre si se ignora, con la diferencia numérica exacta que produce.

Conexión con el módulo

Esta es la segunda pieza de observability/latency_model.py, la que se apoya directamente sobre TOOL_LATENCY_MS (lección 04). El resto del módulo —percentiles en la lección 06, la latencia como señal en la lección 07, el reporte completo en la lección 08— usa total_run_latency_ms tal como queda en esta lección, sin volver a tocarla.

Analogía: el taxímetro que no cobra el semáforo en rojo

Un taxímetro bien calibrado cobra por el trayecto recorrido, no por cada intento de arrancar. Si el semáforo está en rojo y el auto no se mueve, el taxímetro no suma esos segundos al viaje —solo cuenta el tiempo en que el auto de verdad avanzó—. Un taxímetro mal calibrado, que cobrara también el tiempo parado en cada semáforo, le cobraría al pasajero por un tiempo que nunca se tradujo en distancia recorrida.

total_run_latency_ms tiene que comportarse como el taxímetro bien calibrado. Un tool_use rechazado por check_input_v2 —como el tier="premium" del guion de Ana— es, exactamente, el semáforo en rojo: el agente intentó pedir la tool, pero dispatch_robust lo detuvo antes de que la función real de Python se ejecutara siquiera una vez. Cobrarle latencia a ese intento sería tan incorrecto como cobrarle al pasajero por el semáforo — sumaría tiempo que, en el modelo de esta guía, nunca ocurrió.

Ejemplo trabajado: la función completa, y el bug que corrige

La versión completa

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

Léela en dos pasadas, porque así está escrita: la primera pasada (for turn in history sobre los turnos assistant) construye tool_use_name, un mapa de tool_use_id -> nombre de la tool, sin sumar nada todavía. La segunda pasada (for turn in history sobre los turnos user) recorre los tool_result y suma la latencia de la tool correspondiente solo si ese tool_result no trae is_error. Las dos pasadas hacen falta porque un tool_result conoce su tool_use_id, pero no el nombre de la tool que lo generó — ese nombre vive en el bloque tool_use de un turno anterior, y tool_use_name es el puente entre ambos.

El run canónico de Ana, con su tier inválido

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")

Qué esperar:

  [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, no 210. El turno [4] trae [is_error] — ese get_quote con tier="premium" nunca ejecutó la función real de get_quote, porque check_input_v2 lo detuvo primero. El total real es list_rooms (40) + el get_quote que sí se ejecutó (25) + book_room (120) = 185 — el get_quote rechazado, aunque aparece en la traza como un tool_use completo, con su propio turno y su propio tool_result, no aporta ni un milisegundo.

El bug, demostrado con una diferencia numérica real

Vale la pena ver, ejecutado, qué pasaría si total_run_latency_ms no chequeara is_error — sumando la latencia de cada tool_use, sin importar si su tool_result vino marcado como 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")

Qué esperar:

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

25 ms de diferencia — exactamente la latencia de get_quote, la tool que el tier="premium" intentó llamar y nunca llegó a ejecutar. Esta diferencia no es un caso extremo ni poco frecuente: cualquier run donde el modelo (concepto) se equivoca una vez y se auto-corrige —el patrón central de robustez que agent-fundamentals M7 construyó— va a inflar su latencia total si la función de conteo no distingue "se intentó" de "se ejecutó". Con un solo intento rechazado la diferencia es 25 ms; con varios intentos rechazados seguidos —algo que puede pasar si el modelo tarda en converger a un argumento válido—, la versión incorrecta podría inflar la latencia total muy por encima de lo que el run realmente costó en tiempo.

Por qué la latencia no cambia aunque el número de pasos sí

Esto ya lo confirmó el Módulo 1, y vale la pena repetirlo aquí con el vocabulario preciso de este módulo: la latencia total de un run depende únicamente de la secuencia de tools que se ejecutaron de verdad, nunca del número de turnos en history. El run de Ana tiene diez turnos en su historial —más que el run de Sofía, que tiene ocho— pero su latencia total (185) es idéntica a la de Sofía (185), porque ambos ejecutan, al final, exactamente la misma secuencia real: list_rooms, un get_quote válido, book_room. Un tool_use rechazado agrega turnos a la traza —cuesta espacio en history, cuesta un tool_result [is_error] que alguien tiene que leer— pero no agrega tiempo real, porque check_input_v2 es una función de Python local, no una llamada que tarda.

Errores comunes

  1. Sumar la latencia de un tool_use sin chequear su tool_result. Este es, con precisión, el bug que esta lección acaba de demostrar con total_run_latency_ms_wrong — un error fácil de cometer si se olvida que history registra tanto los intentos que fallaron como los que tuvieron éxito.

  2. Confundir "validación rechazada" con "tool que falló al ejecutarse". Son dos cosas distintas. Un tool_use rechazado por check_input_v2 (como el tier="premium") nunca ejecuta la función real — cero latencia. Una tool que sí se ejecuta pero devuelve un resultado de negocio inesperado (por ejemplo, cancel_booking con un id que no existe) sí llegó a correr la función real — la distinción entre ambos casos importa para entender qué mide de verdad TOOL_LATENCY_MS.

  3. Pensar que menos turnos en history siempre significa menos latencia. No — como confirmó la sección anterior, el run de Ana tiene más turnos que el de Sofía y, sin embargo, la misma latencia total. El número de turnos mide la complejidad de la traza; la latencia mide el tiempo modelado de las tools que de verdad corrieron. Son señales relacionadas, pero no intercambiables.

  4. Olvidar el .get(name, 0) al buscar en TOOL_LATENCY_MS dentro de total_run_latency_ms. Si una tool nueva se registrara en el sistema sin agregarse también a este diccionario, un acceso con corchetes (TOOL_LATENCY_MS[name]) haría que la función entera reventara con un KeyError — exactamente el mismo error que la lección 04 ya advirtió, ahora con consecuencias sobre la función central del módulo.

  5. Escribir una nueva versión de total_run_latency_ms que reconstruya tool_use_name con un solo for, mezclando las dos pasadas. Es tentador "simplificar" combinando ambos recorridos en un único for turn in history, pero eso solo funciona si cada tool_use siempre aparece antes que su tool_result correspondiente en history — que es cierto en esta guía, pero mezclar ambas responsabilidades en un solo bucle hace el código más frágil frente a cualquier cambio futuro en el orden de los turnos.

Ejercicios

Ejercicio 1: Calcula la diferencia del bug sobre un run con dos rechazos (Fácil)

Diseña un guion donde book_room sea rechazado dos veces por hours inválido (hours=0) antes de tener éxito con hours=1. Calcula la latencia con total_run_latency_ms y con total_run_latency_ms_wrong, y confirma la diferencia.

Ver solución 
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")

Salida esperada:

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

Explicación: la versión correcta cuenta solo el book_room que de verdad se ejecutó (120 ms). La versión incorrecta cuenta las tres llamadas a book_room —dos rechazadas por check_input_v2 (hours=0 y hours=-1, ambas por debajo del minimum de 1) y una exitosa—, así que suma 120 * 3 = 360. La diferencia (240 ms, dos veces la latencia de book_room) crece con cada intento rechazado adicional — un modelo con el bug se vuelve más y más inexacto cuantos más reintentos de auto-corrección haga el modelo (concepto) antes de acertar.

Ejercicio 2: Confirma que la latencia no cambia si el run tiene éxito al primer intento (Medio)

Ejecuta el mismo guion del Ejercicio 1, pero sin los dos intentos rechazados —solo book_room con hours=1, directo—. Confirma que total_run_latency_ms y total_run_latency_ms_wrong dan el mismo resultado en este caso.

Ver solución 
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")

Salida esperada:

correcta  : 120 ms
incorrecta: 120 ms

Explicación: cuando no hay ningún tool_use rechazado en el camino, las dos versiones coinciden exactamente — el bug de total_run_latency_ms_wrong solo se manifiesta cuando history contiene al menos un tool_result con is_error. Esto explica por qué un bug así puede pasar desapercibido durante mucho tiempo en un sistema real: si la mayoría de los runs de prueba tienen éxito al primer intento, ambas versiones dan el mismo número, y la diferencia solo aparece el día en que un run real necesita auto-corregirse.

Ejercicio 3: Diseña un run donde la versión incorrecta subestime la latencia, no la sobreestime (Difícil)

Todos los ejemplos de esta lección muestran a total_run_latency_ms_wrong sobreestimando la latencia (dando un número más alto que el correcto). ¿Existe algún guion, con las cuatro tools de Reservo, donde la versión incorrecta dé un número menor al correcto? Razona la respuesta antes de intentar construir un ejemplo.

Ver solución

No existe. total_run_latency_ms_wrong suma la latencia de todos los tool_use, sin excepción; total_run_latency_ms suma solo un subconjunto de esos mismos tool_use —los que no tienen is_error—. Sumar sobre un subconjunto de valores no negativos (todas las latencias en TOOL_LATENCY_MS son positivas) nunca puede dar un resultado mayor que sumar sobre el conjunto completo — en el peor caso (cuando no hay ningún rechazo), ambas dan exactamente el mismo número, como confirmó el Ejercicio 2; en cualquier otro caso, la versión incorrecta solo puede sobreestimar o empatar, nunca subestimar. Confírmalo con código, probando con el guion de dos rechazos del Ejercicio 1:

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")

Explicación: este es un caso donde razonar sobre la estructura del código —"un subconjunto de valores no negativos nunca supera a su superconjunto"— es más confiable que intentar construir un contraejemplo, porque el contraejemplo, matemáticamente, no puede existir mientras cada valor de TOOL_LATENCY_MS sea positivo.

Resumen y siguiente paso

  • Construimos total_run_latency_ms completa: dos pasadas sobre history, la primera para mapear tool_use_id -> nombre, la segunda para sumar solo los tool_result sin is_error.
  • Ejecutamos sobre el run canónico de Ana y confirmamos, de nuevo, 185 ms — el get_quote rechazado por tier="premium" no aporta nada al total.
  • Demostramos el bug, ejecutado: una versión que no chequea is_error da 210 ms para el mismo run — 25 ms de más, exactamente la latencia de la tool que nunca se ejecutó.
  • Confirmamos, con un argumento estructural (Ejercicio 3), que este bug solo puede sobreestimar la latencia, nunca subestimarla — información útil para reconocerlo si alguna vez aparece en un sistema real.

Siguiente lección: 06 — Percentiles: p50 y p95. Con la latencia de un run ya resuelta, escalamos a un lote de doce runs reales y respondemos la pregunta que un promedio solo no puede responder: ¿qué tan lenta es la experiencia del cliente que peor la pasa?

Recursos adicionales

  1. Anthropic — Tool use (function calling) overview — La forma exacta de tool_use/tool_result/is_error sobre la que se construye total_run_latency_ms.
  2. Python — comprensión de listas y diccionarios — La base de las dos pasadas sobre history que arma esta función.
  3. Anthropic — Implement tool use — El flujo completo de validar antes de ejecutar, la razón de fondo por la que un tool_use rechazado nunca llega a costar tiempo real.
  4. Python 3.14 — What's New — La versión con la que se ejecutó cada cálculo, correcto e incorrecto, de esta lección.
← Anterior`TOOL_LATENCY_MS` como dato fijoSiguiente →Percentiles: p50 y p95