Lección 37 — Perfilado

Stack: Django/DRF · Proyecto: TicketFlow Estado: Publicada — apertura del módulo de rendimiento Prerrequisito: Lección 36 — Pruebas de carga (k6)

Objetivos

1. Medir antes de optimizar: el ciclo medir→hipótesis→medir con las herramientas de perfilado de Python y Django.
2. Perfilado de queries: N+1, tiempos de query, y el costo escondido del ORM (serialización, cuenta de queries).
3. Perfilado de CPU y memoria en producción sin tumbarla: sampling, flamegraphs y la variable de entorno que apaga todo.

1. El ciclo: nunca optimices a ciegas

La regla de Knuth mal citada y bien usada: el 97% del tiempo se va en el 3% del código — encontrar ESE 3% es el trabajo del perfilado, no de la intuición. El ciclo del proyecto: (1) medir la línea base (k6 de la 36 o un test de perfil local); (2) perfil: dónde se va el tiempo (función, query, serialización); (3) UNA hipótesis ("el total() de ReservationSummary recalcula N veces"); (4) la mejora; (5) re-medir con la MISMA herramienta y criterio. Dos medidas = un dato; una medida sin después = una opinión. El anti-patrón: "voy a cachearlo" (38) antes de saber qué es lento — el caché mal puesto añade invalidación (el costo de la 38) SIN quitar el cuello real.

2. El micro-perfil: las herramientas de la caja Python

Para el test o el script de perfil local (nunca en prod el profiler intrusivo):

import cProfile, pstats

def test_perfil_resumen():
    r = preparar_reserva()
    pr = cProfile.Profile()
    pr.enable()
    for _ in range(1000):
        resumen(r)
    pr.disable()
    stats = pstats.Stats(pr).sort_stats("cumulative")
    stats.print_stats(12)          # top 12 por tiempo acumulado

El output dice la verdad incómoda: el 60% del tiempo de resumen() está en Money.__add__ por los decimales (la 08) o en el str(uuid) repetido. Complementos: timeit para el micro (¿f"{x}" vs str(x) importa? casi nunca: mide antes de discutir), line_profiler (@profile línea a línea: el bucle que nadie sospechaba), y py-spy (más abajo, el que sí entra en prod). La regla de lectura de cProfile: mira cumulative para encontrar la FUNCIÓN culpable y tottime para el interno — el 80% de los hallazgos están en las 3 primeras filas.

3. El perfil de queries: donde Django esconde el 70%

En una API DRF típica, el 70% de la latencia es BD+ORM. Las herramientas: connection.queries con DEBUG (dev only), y sobre todo django-debug-toolbar (dev) y silk (dev/staging): cuentan queries por request y marcan los duplicados. El hallazgo modelo del proyecto:

# ANTES: 1 + N queries (el N+1 del 09, en la vista de listado)
for reserva in Reservation.objects.filter(user=user):
    total += reserva.total()           # → reserva.event Tariff: query por fila

# DESPUÉS: 1 query
qs = (Reservation.objects.filter(user=user)
      .select_related("event")         # FK: JOIN
      .prefetch_related("seats"))      # M2M/reverse: segunda query, no N

El perfilado de la query honesta: EXPLAIN (ANALYZE, BUFFERS) (09) SOBRE la query que el ORM emite (.query es una aproximación; silk/toolbar te da la SQL real), con el SETTING de datos realista. Y el costo escondido del ORM: la SERIALIZACIÓN — el DRF serializer de 400 filas con SerializerMethodField que consulta por fila es el N+1 con otro disfraz; el perfil de silk lo marca como "queries dentro de to_representation".

4. Perfilado en producción: sin tumbarla

El profiler intrusivo (cProfile) en prod es un DoS propio: bloquea el event loop y duplica la CPU. Las alternativas adultas: py-spy (sampling sobre el proceso VIVO, ~1-3% overhead, sin instrumentar código: py-spy dump --pid para ver dónde está colgado un worker AHORA, py-spy record --pid -o flame.svg --duration 60 para el flamegraph del worker lento). El flamegraph se lee del ancho: la barra ancha = tiempo; la pila call se lee de abajo arriba; y el hallazgo se reporta con el SVG adjunto (46 lo coloca junto a las métricas).

py-spy record --pid $(pgrep -f "gunicorn.*worker") -o /tmp/checkout-flame.svg --duration 60 --subprocesses

Y el tercer nivel: el perfilado continuo (pyroscope/otel, 46): sampling permanente con overhead mínimo, con el histórico "¿qué cambió en el flamegraph entre el deploy 42 y el 43?" — la regresión de rendimiento se ve como la de errores. La regla de datos (23): los flamegraphs NO contienen payloads, solo funciones: seguros para el repo de incidencias.

5. El caso completo: el p99 del checkout

Ejemplo real del ciclo: k6 marca p99 de checkout 1.4 s (36); el desglose por endpoint acusa POST /reservations; py-spy en la meseta muestra el flamegraph: 55% en pg execute (el UPDATE masivo del 36, ya medido), 22% en resumen() → Money.__add__ (el micro-perfil de §2 lo confirma: 1.2 ms × 12 llamadas = 14 ms/petición), 18% en pasarela (remoto, 32/54). El plan ordenado por impacto: (1) bulk UPDATE (ganado: -700 ms); (2) el total() precalculado en la fila al confirmar (denormalización justificada: el snapshot de precio de la 08) → -14 ms y menos CPU de Python; (3) la pasarela: timeout + breaker (54), no es perfilable localmente. Tres tools (k6, py-spy, cProfile) una historia: medir → localizar → arreglar → re-medir.

Autoevaluación

1. Describe el ciclo medir→hipótesis→medir y por qué "voy a cachearlo" antes de medir es el error que paga la 38.
2. En cProfile, ¿qué te dice cumulative y qué tottime? ¿Dónde están el 80% de los hallazgos?
3. El N+1 "con disfraz": ¿cómo se manifiesta en el serializer de DRF y qué herramienta lo marca?
4. ¿Por qué cProfile en prod es un DoS propio y qué tres alternativas hay (con su costo y su uso)?
5. En el caso del checkout: ¿qué herramienta produjo cada hallazgo y por qué el orden del plan importa?

Continúa con los ejercicios. Las solutions.md solo tras intentarlo.