The Professor
Índice Índice del curso

Módulo 8 · Rendimiento y caché

Lección 37 — Perfilado

Medir antes de optimizar: dónde se va realmente el tiempo.

Publicada
En esta lección
  1. Ejercicio 1 — La línea base
  2. Ejercicio 2 — El N+1
  3. Ejercicio 3 — El micro-perfil
  4. Ejercicio 4 — py-spy
  5. Ejercicio 5 — El informe
  6. Resumen del profesor

Ejercicio 1 — La línea base

  1. El output modelo (500 reservas, un evento):
         1204512 function calls (1120004 primitive) in 2.411 seconds
ncalls    tottime  percall  cumtime  filename:lineno(function)
500       0.812    0.0016   1.988    services.py:88(reservar)
6000      0.641    0.0001   0.912    money.py:31(__add__)
12000     0.233    0.0000   0.244    {built-in method builtins.str}
1500      0.121    0.0001   0.301    uuid.py:278(__str__)
...
  1. La hipótesis del output: el 82% del tiempo (1.988/2.411) está en reservar, y DENTRO el 46% (0.912) en Money.__add__ — el recálculo del total con Decimals por cada operación del checkout. NO era "la BD" ni "el serializer": la intuición falló, el perfil no.
  1. La mejora mínima: acumular en Decimal interno durante el checkout y construir el Money UNA vez al final (o sum(amounts, Decimal(0)) → un solo Money). Antes/después: 2.411 → 1.512 s; Money.__add__ del top 3 (0.912 → 0.091). El mismo test, el mismo criterio: la medida es la que declara la victoria, no el diff.

Ejercicio 2 — El N+1

  1. La vista con el disfraz: 40 reservas → 83 queries (1 de reservas + 40 de tarifas + 40 de seats + 2 de extras). El toolbar lo muestra con la columna de tiempo: 412 ms en BD para un listado que debería costar 2 queries y 40 ms.
  1. El fix:
python
qs = (Reservation.objects.filter(user=user)
      .select_related("event__tariff")        # FK anidada: un JOIN
      .prefetch_related("seats"))             # reverse FK: 1 query por lote
# 3 queries totales, 44 ms

El índice de calidad: queries/recurso no debe crecer con las filas — es O(1) en queries o hay un N+1.

  1. .iterator() solo cambia el TRANSPORTE (cursor por lotes, útil para 2M filas, la 31): las queries siguen siendo N porque cada reserva.seats.all() dispara su SELECT. prefetch_related materializa el lote UNA vez y el related manager lee del cache (reserva.seats.all() NO re-querya si hay prefetch). La regla: iterator para memoria, prefetch para queries — no se sustituyen.

Ejercicio 3 — El micro-perfil

  1. Los números: str(uuid) 21.4 µs, f"{uuid}" 21.9 µs, uuid.hex 0.9 µs por iteración. ¿Importa? En un endpoint con 1 conversión: no (0.02 ms). En un CSV de 100k filas con 3 por fila: 6 s de diferencia. La lección doble: "no optimices esto" Y "si el flujo es masivo, .hex es gratis". El dato decide, no la superstición.
  1. El line_profiler en calcular_total:
Line #  Hits   Time    % Time  Content
   12   500    118400  71.2%   tariff = Tariff.objects.get(event=self.event)   ← la query
   14   500     21400  12.9%   total = sum(...)

Es el N+1 de nuevo (71% en la query), no la CPU de los Decimals (12.9%): el micro-perfil te evita optimizar el Decimal cuando el costo es la BD. Las herramientas en cascada: cProfile localiza la función, line_profiler la línea, EXPLAIN (09) la query.

  1. El snapshot:
python
def confirmar(self):
    self.total_amount = self.total()          # FROZEN: el precio del momento de compra (08)
    self.save(update_fields=["total_amount", "status"])

El test de la 08 (cambiar la tarifa después de confirmar NO cambia el total de la reserva) sigue en verde: la denormalización es legal porque es un snapshot del hecho económico, no un cache de un dato vivo — la distinción exacta que separa esto de la caché de la 38.

Ejercicio 4 — py-spy

  1. Los dumps de 3 workers durante la meseta: worker-1 en recv (esperando request: normal), worker-2 en pg execute (el UPDATE: coincide con la 36), worker-3 en json.dumps del serializer de listado (hallazgo nuevo: la serialización del listado de 400 eventos por request — candidato a paginación más agresiva, 39, o caché de la respuesta completa, 38).
  1. El flamegraph: la pila ancha domina UPDATE seats... (55%) y detrás pg execute anida el pool wait (el hallazgo del pool del 36 confirmado visualmente). Lo nuevo del SVG: el json.dumps del listado es el 12% de la CPU total — invisible en cProfile de unitaria (los datos eran 5 eventos; con 400 reales, la serialización pesa). Moraleja: el perfil de PROD con datos REALES cuenta cosas que la unitaria no puede.
  1. El on-call con el dump: "worker-3 está en time.sleep invocado por enviar_recordatorio línea 88 desde hace 118 s; la tarea es la de recordatorios del 31, no bloquea la cola (prefetch=1) ni la BD (sin transacción activa en pg_stat_activity). Espera programada, no bug: NO reiniciar" — el dump convierte "algo va lento" en una decisión informada.

Ejercicio 5 — El informe

  1. La estructura del informe (extracto):
markdown
# Perfil del checkout — 2027-09
Línea base (k6, meseta 200): p99 1.4s; desglose: BD 55%, app 22%, pasarela 18%.
Hallazgos: [cProfile] Money.__add__ 46% de reservar(); [silk] N+1 en mis-reservas (83q);
           [py-spy] UPDATE masivo (coincide con k6/36); pasarela = latencia remota.
Mejoras: bulk UPDATE (-700ms p99), snapshot total_amount (-14ms), prefetch (-368ms listado).
NO arregladas: str(uuid) (0.02ms/req), json listado (12% CPU: la paginación 39 lo aborda).
Re-medición: p99 640ms. Próximo: paginación del listado.

Las NO-mejoras documentadas valen tanto como las arregladas: protegen del "refactor de rendimiento" sin criterio la próxima vez.

  1. La plantilla del PR:
Mejora: [qué]
Before: [p95/p99/queries — herramienta y fecha]
After:  [mismo criterio]
Costo:  [complejidad añadida, invalidación, riesgo]
Revert: [cómo se deshace]

Cinco líneas que convierten cada optimización en un dato versionado (y en el caso de "no mejoró": el PR no se mergea — el caché que no mejora se rechaza, la 38).

Resumen del profesor

  • El ciclo medir→hipótesis→medir con la MISMA herramienta y criterio; una sola medición es una opinión.
  • cProfile localiza la función, line_profiler la línea, EXPLAIN la query; en prod solo sampling (py-spy) — el flamegraph de prod revela lo que la unitaria no ve.
  • Toda mejora lleva before/after medido en el PR; las NO-mejoras se documentan igual.

^ arriba