3 publicaciones etiquetados con "wec-inference"

+

La Parte 4 construyó un callback que enmascara la PII en lo que el gateway registra sin tocar lo que recibe quien llama. También señaló que la primera versión funcional usaba un cliente HTTP bloqueante dentro de un async def, y que eso costaba 200-350ms sobre cuatro peticiones secuenciales.

Ese post terminaba con una confesión: cuatro peticiones seguidas es la prueba equivocada. Un bucle de eventos bloqueado apenas se nota cuando nada más está esperando. El daño debería aparecer bajo concurrencia, y no lo habíamos medido.

Esta es esa medición, y el resultado es una forma más que un número. Con el cliente bloqueante, algunos lotes tardan muchas veces más de lo que deberían. Con el cliente asíncrono, ninguno. Las medianas apenas difieren, que es exactamente la razón por la que esto llega a producción sin que nadie lo note.

Aparecieron dos cosas que no estaban en el plan. El gateway no solo se vuelve lento — descarta peticiones. Y cuando lo hace, lo que expiró fue la llamada de enmascarado, mientras quien llama sigue recibiendo 200 OK. Eso significa que la garantía sobre la que se construyó la Parte 4 deja de cumplirse en silencio bajo carga.

Lo que necesitas​

• El gateway de la Parte 1, en marcha
• Presidio y el callback de registro de la Parte 4
• Una clave de la API de Inferencia de WEC — créala en el portal
• httpx en tu entorno de Python

Primero, averigua cuántos bucles de eventos tienes​

Todo lo que sigue depende de un número, y no es el número que da la documentación.

La CLI del proxy de LiteLLM tiene una opción --num_workers. La referencia publicada dice que su valor por defecto es "Number of logical CPUs in the system, or 4 if that cannot be determined." En una máquina de ocho núcleos eso significaría ocho procesos de trabajo, ocho bucles de eventos, y una llamada bloqueante atascando una octava parte de tu tráfico.

Pregúntale al host qué se está ejecutando realmente — desde fuera del contenedor, para que nada dentro de él pueda informar mal:

docker top llm-gateway

UID    PID       PPID      C  STIME  TTY  TIME      CMD
root   2477458   2477435   3  16:43  ?    00:01:19  /app/.venv/bin/python3 /app/.venv/bin/litellm --config /app/config.yaml --port 4000
root   2481091   2477458   0  16:44  ?    00:00:05  /opt/prisma/binaries/node_modules/prisma/query-engine-debian-openssl-3.0.x -p 53053

Figura 1. Un proceso de python ejecuta todo el proxy. La segunda entrada es Prisma, el cliente de base de datos, que no atiende peticiones.

Si --num_workers fuera mayor que uno verías varios procesos de python con el primero como padre. Confírmalo en el registro de arranque:

docker logs llm-gateway 2>&1 | grep -E "Started server process|Uvicorn running" | tail -2

INFO:     Started server process [1]
INFO:     Uvicorn running on http://0.0.0.0:4000 (Press CTRL+C to quit)

Figura 2. Un proceso de servidor. Este registro se acumula entre reinicios, así que tail -2 te mantiene mirando el actual.

Ahora pregúntale a la herramienta cuál es su valor por defecto:

docker exec llm-gateway litellm --help | grep -A5 "^  --num_workers"

  --num_workers INTEGER           Number of worker processes for uvicorn /
                                  gunicorn, or Granian worker processes
                                  (--workers). Default is 1 (from
                                  DEFAULT_NUM_WORKERS_LITELLM_PROXY). With
                                  --run_granian, use --granian_threads for
                                  runtime threads per worker.

Figura 3. El propio texto de ayuda de la herramienta: "Default is 1."

Eso es una cadena de ayuda. Como estamos a punto de contradecir la documentación publicada, tómalo también del código fuente — ajusta la versión de python en la ruta para que coincida con tu imagen:

docker exec llm-gateway grep -rn 'DEFAULT_NUM_WORKERS_LITELLM_PROXY' \
  /app/.venv/lib/python3.13/site-packages/litellm/constants.py

15:DEFAULT_NUM_WORKERS_LITELLM_PROXY = int(os.getenv("DEFAULT_NUM_WORKERS_LITELLM_PROXY", 1))

docker exec llm-gateway env | grep -i worker

Así que: un proceso, un bucle de eventos, compartido por cada petición en vuelo. Esa es la condición que convierte una llamada bloqueante de un impuesto en una caída.

Un script de carga​

Lanza N peticiones a la vez, cronometra cada una, informa el tiempo total del lote. El mensaje lleva PII para que el callback de enmascarado tenga trabajo real. Una petición fallida se cuenta en vez de dejar que abandone la ejecución — vas a necesitar eso.

"""Fire N chat completions at the gateway at once and report how long they take.

The message carries PII so the Presidio masking callback has real work to do.
A failed request is counted and reported, not allowed to abandon the batch.
"""
import asyncio
import os
import statistics
import sys
import time

import httpx

GATEWAY = "http://127.0.0.1:4000/v1/chat/completions"
KEY = os.environ["LITELLM_MASTER_KEY"]
MODEL = "qwen-small"
PROMPT = (
    "Priya Raghunathan called from 415-555-0134 about her invoice. "
    "Reply with exactly: ok"
)


async def one(client, i):
    start = time.perf_counter()
    try:
        r = await client.post(
            GATEWAY,
            headers={"Authorization": f"Bearer {KEY}"},
            json={
                "model": MODEL,
                "messages": [{"role": "user", "content": PROMPT}],
                "max_tokens": 5,
            },
        )
    except Exception as exc:
        return i, None, None, type(exc).__name__
    return i, r.status_code, time.perf_counter() - start, None


async def main():
    n = int(sys.argv[1])
    async with httpx.AsyncClient(timeout=120.0) as client:
        wall = time.perf_counter()
        results = await asyncio.gather(*(one(client, i) for i in range(n)))
        wall = time.perf_counter() - wall

    times = sorted(e for _, _, e, _ in results if e is not None)
    errors = [err for _, _, _, err in results if err]
    print(f"concurrency {n}  ok {len(times)}  failed {len(errors)}")
    if errors:
        print(f"  errors   {', '.join(sorted(set(errors)))}")
    print(f"  wall     {wall:.2f}s")
    if times:
        print(f"  fastest  {times[0]:.2f}s")
        print(f"  median   {statistics.median(times):.2f}s")
        print(f"  slowest  {times[-1]:.2f}s")


asyncio.run(main())

cd ~/llm-gateway && set -a && . ./.env && set +a
~/.venv/bin/python loadtest.py 8

concurrency 8  ok 8  failed 0
  wall     1.93s
  fastest  1.60s
  median   1.91s
  slowest  1.93s

Figura 4. Ocho a la vez, ninguna falló. Por sí solo este número todavía no significa nada.

Necesitas un control, o tus números no significan nada​

Aquí está la trampa. El gateway llama a un modelo por la red. Ese modelo tiene su propia latencia, su propia carga y sus propias malas tardes. Cuando un lote tarda doce segundos no puedes saber si tu gateway se atascó o si el upstream estaba ocupado — y si adivinas, vas a publicar una tontería.

Así que mide el upstream directamente, con el gateway fuera del camino. Copia el archivo y cambia las tres constantes de arriba:

cd ~/llm-gateway
cp loadtest.py loadtest_direct.py

GATEWAY = "https://inference.wiline.com/v1/chat/completions"
KEY = os.environ["WEC_API_KEY"]
MODEL = "Qwen2.5-3B-Instruct"

~/.venv/bin/python loadtest_direct.py 8

concurrency 8  ok 8  failed 0
  wall     1.15s
  fastest  1.05s
  median   1.10s
  slowest  1.15s

Figura 5. Las mismas ocho peticiones con el gateway quitado. Esta es la referencia contra la que se lee cada número del gateway.

Ahora ejecuta las dos intercaladas, no una después de la otra, para que un minuto lento del upstream no caiga entero sobre una sola versión:

#!/bin/bash
# Interleave gateway runs with direct-to-upstream control runs so an upstream
# slowdown cannot be mistaken for a gateway effect.
set -a; . ./.env; set +a
REPS=5

# A restart takes longer than it looks. Firing requests at a port that is not
# answering yet produces instant failures that have nothing to do with the callback.
printf 'waiting for the gateway'
for _ in $(seq 1 60); do
  curl -sf http://127.0.0.1:4000/health/liveliness >/dev/null 2>&1 && break
  printf '.'; sleep 2
done
curl -sf http://127.0.0.1:4000/health/liveliness >/dev/null 2>&1 || { echo " never came up — aborting"; exit 1; }
echo " up"

# Do not trust a label passed on the command line — ask the gateway which callback
# it actually loaded. A mislabelled run is worse than no run.
LABEL=$(docker logs llm-gateway 2>&1 | grep '\[scrubber\]' | tail -1 | sed 's/.*loaded: //')
if [ -z "$LABEL" ]; then echo "cannot determine loaded callback — aborting"; exit 1; fi
echo "callback in use: $LABEL"

summarise() {
  awk '/^concurrency/{failed=$6} /wall/{wall=$2} END{printf "%s", wall; if (failed+0 > 0) printf "(%d failed)", failed}'
}

# The first request after a restart pays for imports and connection pools, which
# has nothing to do with the callback. Warm both paths before recording anything.
~/.venv/bin/python loadtest.py 4 >/dev/null 2>&1
~/.venv/bin/python loadtest_direct.py 4 >/dev/null 2>&1

for n in 8 16; do
  for i in $(seq 1 $REPS); do
    g=$(~/.venv/bin/python loadtest.py $n | summarise)
    d=$(~/.venv/bin/python loadtest_direct.py $n | summarise)
    echo "$LABEL N=$n rep=$i gateway=$g direct=$d"
  done
done

Tres detalles de ahí no son decoración, y cada uno costó una ejecución perdida para aprenderlo:

Espera al gateway. Un docker compose restart puede tardar más de diez segundos, y lanzar peticiones a un puerto que todavía no escucha produce fallos instantáneos — gateway=0.03s(8 failed) — que parecen un resultado catastrófico y no significan nada.

Se niega a aceptar una etiqueta tuya. Lee el callback cargado del registro del gateway. Pasa blocking por la línea de comandos mientras está cargado el callback asíncrono y vas a medir el mismo código dos veces, no ver diferencia, y concluir que aquí no hay nada. Eso pasó dos veces escribiendo este post.

Descarta una pasada de calentamiento. El primer lote tras un reinicio paga las importaciones y los pools de conexión, y llega de tres a seis veces más lento que el siguiente, sin importar qué callback esté cargado.

Haz que cada versión se anuncie​

Estás a punto de comparar dos versiones de un archivo, y necesitas certeza sobre cuál está activa. El registro de arranque de LiteLLM lista los callbacks de éxito y de fallo pero no litellm_settings.callbacks, y no hay un endpoint que los informe — /get/config/callbacks responde 200 con {"detail":"Not Found"}.

Así que haz que cada versión diga su propio nombre al importarse, donde no cuesta nada por petición:

# last line of scrubber.py
print("[scrubber] loaded: async httpx.AsyncClient", flush=True)

# last line of scrubber_blocking.py
print("[scrubber] loaded: blocking httpx.Client", flush=True)

Monta los dos archivos y cambia con una línea de configuración:

    volumes:
      - ./config.yaml:/app/config.yaml:ro
      - ./scrubber.py:/app/scrubber.py:ro
      - ./scrubber_blocking.py:/app/scrubber_blocking.py:ro
      - ./recognizers.json:/app/recognizers.json:ro

litellm_settings:
  callbacks: ["scrubber.instance"]          # or scrubber_blocking.instance

sed -i 's/scrubber.instance/scrubber_blocking.instance/' config.yaml
docker compose restart litellm

El script del experimento imprime el callback cargado como primera línea, así que cada ejecución lleva su propia prueba de lo que midió.

Los números​

./run_experiment.sh

Con el cliente asíncrono:

callback in use: async httpx.AsyncClient
async httpx.AsyncClient N=8 rep=1 gateway=0.98s direct=1.09s
async httpx.AsyncClient N=8 rep=2 gateway=0.86s direct=0.80s
async httpx.AsyncClient N=8 rep=3 gateway=0.92s direct=0.96s
async httpx.AsyncClient N=8 rep=4 gateway=0.78s direct=0.85s
async httpx.AsyncClient N=8 rep=5 gateway=0.90s direct=0.82s
async httpx.AsyncClient N=16 rep=1 gateway=1.61s direct=1.49s
async httpx.AsyncClient N=16 rep=2 gateway=1.65s direct=1.26s
async httpx.AsyncClient N=16 rep=3 gateway=1.28s direct=1.35s
async httpx.AsyncClient N=16 rep=4 gateway=1.33s direct=1.42s
async httpx.AsyncClient N=16 rep=5 gateway=1.77s direct=1.56s

Figura 6. El cliente asíncrono. Cada número del gateway está junto a su control, en los dos niveles de concurrencia. Nada destaca porque nada pasó.

Después cambia el callback y ejecuta lo mismo:

waiting for the gateway up
callback in use: blocking httpx.Client
blocking httpx.Client N=8 rep=1 gateway=1.20s direct=0.93s
blocking httpx.Client N=8 rep=2 gateway=0.96s direct=0.83s
blocking httpx.Client N=8 rep=3 gateway=0.92s direct=0.86s
blocking httpx.Client N=8 rep=4 gateway=0.73s direct=0.90s
blocking httpx.Client N=8 rep=5 gateway=1.70s direct=0.90s
blocking httpx.Client N=16 rep=1 gateway=70.18s direct=2.00s
blocking httpx.Client N=16 rep=2 gateway=1.75s direct=1.70s
blocking httpx.Client N=16 rep=3 gateway=2.33s direct=1.78s
blocking httpx.Client N=16 rep=4 gateway=2.88s direct=1.49s
blocking httpx.Client N=16 rep=5 gateway=5.14s direct=1.19s

Figura 7. El cliente bloqueante. Mismo script, misma carga, una palabra distinta en el código. La columna de control se mantiene entre 1,19 y 2,00s en todo momento.

Figura 8. Cada lote de las Figuras 6 y 7 en un eje logarítmico. El control se mantiene en una banda estrecha en los cuatro grupos. Las ejecuciones asíncronas se quedan con él. Dos bloqueantes lo abandonan.

Lee primero las filas asíncronas. En N=8 la mediana del gateway es 0,90s y la del control 0,85s. El callback, con todas sus idas y vueltas a Presidio, desaparece dentro de la latencia del propio modelo.

Ahora la fila bloqueante en N=8. Mediana de 0,96s contra un control de 0,90s. Eso es 0,06s. Si midieras medianas y desplegaras, dirías que está bien — y el peor lote de esas mismas cinco tardó 1,70s mientras su propio control tardó 0,90s.

En N=16 deja de esconderse. La mediana sube a 2,88s contra 1,70s, y la cola se sale del gráfico.

No solo se vuelve lento. Descarta peticiones.​

Antes de añadir el conteo de fallos al script de carga, una ejecución bloqueante murió del todo:

httpx.RemoteProtocolError: Server disconnected without sending a response.

Dos de diez lotes de esa ejecución perdieron peticiones así. Cero lotes asíncronos lo hicieron nunca. El gateway no estuvo lento para esos clientes. Les colgó.

Pregúntale al gateway qué cree que pasó:

docker logs llm-gateway 2>&1 | grep -c "httpcore/_sync"
docker logs llm-gateway 2>&1 | grep -A1 "httpx.ReadTimeout" | tail -4

77
INFO:     172.22.0.1:47566 - "POST /v1/chat/completions HTTP/1.1" 200 OK
--
httpx.ReadTimeout: timed out
INFO:     172.22.0.1:52870 - "POST /v1/chat/completions HTTP/1.1" 200 OK

Figura 9. httpcore/_sync aparece 77 veces. El cliente asíncrono produciría _async. Y el timeout está entre dos líneas 200 OK.

Ese _sync es la huella. Prueba que la llamada que falla es la llamada bloqueante a Presidio y no otra cosa de la pila. El error completo nombra a quien llama:

LiteLLM:ERROR: logging_worker.py:103 - LoggingWorker error: timed out
  File ".../httpcore/_sync/connection_pool.py", line 236, in handle_request
  httpcore.ReadTimeout: timed out

Ahora mira lo que lo rodea. 200 OK. Las peticiones tuvieron éxito. Lo que falló fue el enmascarado.

Esa es la parte en la que vale la pena detenerse, porque toda la promesa de la Parte 4 era que la PII llega a tus rastros ya enmascarada. Bajo carga, con el cliente bloqueante, la llamada de enmascarado expira contra su propio límite de diez segundos mientras quien llama recibe un éxito normal. Nada en la respuesta te dice que la garantía dejó de cumplirse. Tendrías que estar leyendo el stderr del gateway para saberlo.

Qué está pasando en realidad​

httpx.Client dentro de un async def no cede el control. Cuando el callback llama a Presidio, el hilo que ejecuta el bucle de eventos se queda en una lectura de socket hasta que Presidio responde, y durante ese tiempo el bucle no atiende nada — ni la llamada al modelo de otra petición, ni una respuesta que vuelve. Es un solo bucle, como confirmaste al principio.

Cada petición dispara varias de estas llamadas: los mensajes, la copia en el objeto de registro estándar, y la respuesta. Así que bajo concurrencia las peticiones no se solapan. Se ponen en fila, y la espera de cada una es la suma del tiempo de Presidio de todas las anteriores. Por eso el efecto no es un impuesto constante — depende de cuántas peticiones lleguen mientras el bucle está retenido, que es también la razón por la que los números son irregulares en vez de uniformemente peores.

Pasada cierta profundidad de cola, las esperas superan el propio timeout=10.0 del scrubber y el enmascarado se rinde, mientras las conexiones de cliente que esperan sobre un bucle congelado se caen. La mediana lo esconde todo porque a la mayoría de los lotes les toca suerte. La cola es la verdad.

Arreglarlo​

El arreglo es el que adoptó la Parte 4, y esta es la evidencia a su favor: httpx.AsyncClient con await, que cede el bucle mientras Presidio trabaja.

diff scrubber.py scrubber_blocking.py

26,27c26,27
<     async with httpx.AsyncClient(timeout=10.0) as client:
<         r = await client.post(f"{ANALYZER}/analyze", json={"text": text, "language": "en"})
---
>     with httpx.Client(timeout=10.0) as client:
>         r = client.post(f"{ANALYZER}/analyze", json={"text": text, "language": "en"})

Dos palabras y un await. Esa es toda la diferencia entre la Figura 6 y la Figura 7.

Más workers no es el arreglo, y la documentación explica por qué mejor de lo que podríamos nosotros. Sobre --timeout_worker_healthcheck, describiendo --num_workers > 1:

"the supervisor process pings each worker; a worker that does not respond within this window (for example because its event loop is blocked by synchronous work) is killed with SIGKILL and replaced."

Con un worker no hay supervisor, así que un bucle bloqueado se atasca. Con varios, un worker bloqueado es eliminado y todo lo que tenía en vuelo muere en vez de esperar. Ninguna de las dos cosas arregla el trabajo sincrónico sobre un bucle de eventos. Arregla la llamada.

Lo que no probamos​

Cinco repeticiones por celda bastan para mostrar que existe un atasco al lado de un control estable. No bastan para caracterizar la distribución — con qué frecuencia, con qué gravedad, o cómo escala más allá de N=16. Si ejecutas esto en producción, ejecútalo más tiempo y mira los percentiles.

No probamos --num_workers > 1, respuestas en streaming, ni un Presidio lento o remoto en lugar de un contenedor local sano.

Lo que el timeout te cuesta en realidad​

La preocupación obvia, cuando la llamada de enmascarado expira en una petición que devolvió 200 OK, es que la carga sin enmascarar acabe igualmente en el rastro. No es así.

Carga sostenida — seis rondas de veinticuatro peticiones concurrentes, cada una con un nombre y un número de teléfono — produjo 77 timeouts de enmascarado en el registro del gateway. De las 144 peticiones, 62 rastros llegaron a Langfuse y 82 no llegaron nunca. Los 62 estaban correctamente enmascarados. Ninguno llevaba un nombre en claro.

Así que el fallo no es un fallo de privacidad. Es un fallo de observabilidad, y silencioso: bajo carga sostenida más de la mitad del tráfico simplemente no se registra, mientras cada cliente recibe un éxito normal. Si estás leyendo el volumen de rastros como aproximación del tráfico, o contando con los rastros para una pista de auditoría, esa brecha es lo que hay que vigilar — y es invisible desde el lado de la respuesta.

Lecturas adicionales​

• Parte 4 — rastros limpios, respuestas intactas — el callback medido aquí
• Parte 3 — enmascarar PII en el gateway — la configuración de Presidio
• Observa producción con Langfuse — donde aterrizan estos rastros

++

Tienes dos agentes. Uno reserva citas. Otro gestiona facturación.

Llega un ticket que necesita los dos: cambia la fecha de mi instalación, y mi factura parece incorrecta. Así que lo envías a los dos.

El primero reserva el martes. El segundo ve que la cuenta está en mora y la congela. Los dos terminan casi en el mismo momento, y los dos guardan lo que decidieron.

Solo se guarda uno de ellos. ¿Cuál? El que terminó primero — que depende de lo lenta que estuviera una llamada de API ese día. Así que reservas una cita en una cuenta congelada, o congelas una cuenta a la que acabas de prometerle un ingeniero. Después parece que se tomó una única decisión limpia.

La Parte 1 construyó un agente que ejecuta sus pasos en un orden fijo. Este post tiene varios: un supervisor que elige quién trabaja en qué, un agente que pasa el trabajo a otro a mitad de camino, y dos agentes puestos en el camino del otro a propósito — para descubrir qué hace LangGraph cuando no están de acuerdo.

++

Tu agente lleva cuarenta segundos trabajando en la petición de un cliente. Ha leído el ticket, ha consultado la cuenta y ha revisado los calendarios de tres ingenieros. Está a punto de reservar la cita.

Entonces el proceso muere. Un despliegue que sale, el host que se queda sin memoria, alguien que reinicia el contenedor — da igual cuál de ellos.

El agente no continúa donde lo dejó, porque no hay nada desde donde continuar. Todo lo que aprendió vivía en variables dentro de un proceso que ya no existe. El cliente sigue esperando. Ejecútalo de nuevo y pagas todo ese trabajo por segunda vez. Y la parte que más debería preocuparte: nadie puede decir si la cita se reservó en el último segundo antes de morir.

Un agente es un modelo dentro de un bucle. Como script de Python normal, ese bucle es exactamente igual de frágil que el proceso que lo contiene.

Aquí construimos uno que guarda su estado en Postgres después de cada paso, para que una caída no cueste nada.