Lesson 37 — Profiling · The Professor

Stack: Django/DRF · Project: TicketFlow Status: Published — opening the performance module Prerequisite: Lesson 36 — Load testing (k6)

Objectives

Measure before optimizing: the measure→hypothesize→measure cycle with Python's and Django's profiling tools.
Query profiling: N+1, query times, and the ORM's hidden cost (serialization, query count).
CPU and memory profiling in production without knocking it over: sampling, flamegraphs and the environment variable that turns everything off.

Knuth's badly-quoted, well-used rule: 97% of the time goes into 3% of the code — finding THAT 3% is profiling's job, not intuition's. The project's cycle: (1) measure the baseline (36's k6 or a local profiling test); (2) profile: where the time goes (function, query, serialization); (3) ONE hypothesis ("ReservationSummary's total() recomputes N times"); (4) the improvement; (5) re-measure with the SAME tool and criterion. Two measurements = one data point; one measurement without an after = an opinion. The anti-pattern: "I'll cache it" (38) before knowing what is slow — a badly placed cache adds invalidation (38's cost) WITHOUT removing the real bottleneck.

2. The micro-profile: the Python toolbox

For the test or local profiling script (never the intrusive profiler in prod):

python

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 by cumulative time

The output tells the uncomfortable truth: 60% of resumen()'s time is in Money.__add__ over the decimals (08) or in the repeated str(uuid). Complements: timeit for the micro (does f"{x}" vs str(x) matter? almost never: measure before arguing), line_profiler (@profile line by line: the loop nobody suspected), and py-spy (below, the one that does enter prod). The cProfile reading rule: look at cumulative to find the guilty FUNCTION and tottime for the inner one — 80% of the findings are in the first 3 rows.

3. The query profile: where Django hides 70%

In a typical DRF API, 70% of latency is DB+ORM. The tools: connection.queries with DEBUG (dev only), and above all django-debug-toolbar (dev) and silk (dev/staging): they count queries per request and flag the duplicates. The project's model finding:

python

# BEFORE: 1 + N queries (09's N+1, in the listing view)
for reserva in Reservation.objects.filter(user=user):
    total += reserva.total()           # → reserva.event Tariff: a query per row

# AFTER: 1 query
qs = (Reservation.objects.filter(user=user)
      .select_related("event")         # FK: JOIN
      .prefetch_related("seats"))      # M2M/reverse: a second query, not N

The honest query profiling: EXPLAIN (ANALYZE, BUFFERS) (09) ON the query the ORM actually emits (.query is an approximation; silk/toolbar hands you the real SQL), with the realistic-data setting. And the ORM's hidden cost: SERIALIZATION — the 400-row DRF serializer with a SerializerMethodField querying per row is the N+1 in another disguise; silk's profile flags it as "queries inside to_representation".

4. Profiling in production: without knocking it over

The intrusive profiler (cProfile) in prod is your own DoS: it blocks the event loop and doubles CPU. The grown-up alternatives: py-spy (sampling over the LIVE process, ~1-3% overhead, no code instrumentation: py-spy dump --pid to see where a worker is stuck RIGHT NOW, py-spy record --pid -o flame.svg --duration 60 for the slow worker's flamegraph). The flamegraph is read by width: the wide bar = time; the call stack reads bottom-up; and the finding gets reported with the SVG attached (46 places it next to the metrics).

bash

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

And the third level: continuous profiling (pyroscope/otel, 46): permanent sampling with minimal overhead, with the history "what changed in the flamegraph between deploy 42 and 43?" — the performance regression shows up like the error one. The data rule (23): flamegraphs contain NO payloads, only functions: safe for the incident repo.

5. The complete case: the checkout's p99

A real cycle example: k6 marks checkout p99 1.4 s (36); the per-endpoint breakdown accuses POST /reservations; py-spy on the plateau shows the flamegraph: 55% in pg execute (36's bulk UPDATE, already measured), 22% in resumen() → Money.__add__ (§2's micro-profile confirms it: 1.2 ms × 12 calls = 14 ms/request), 18% at the gateway (remote, 32/54). The plan ordered by impact: (1) bulk UPDATE (won: -700 ms); (2) total() precomputed on the row at confirmation (justified denormalization: 08's price snapshot) → -14 ms and less Python CPU; (3) the gateway: timeout + breaker (54), not locally profileable. Three tools (k6, py-spy, cProfile), one story: measure → localize → fix → re-measure.

Self-assessment

Describe the measure→hypothesize→measure cycle and why "I'll cache it" before measuring is the mistake 38 makes you pay for.
In cProfile, what does cumulative tell you and what does tottime? Where are 80% of the findings?
The N+1 "in disguise": how does it show up in the DRF serializer and which tool flags it?
Why is cProfile in prod your own DoS, and what are the three alternatives (with their cost and use)?
In the checkout case: which tool produced each finding and why does the plan's order matter?

Continue with the exercises. The solutions only after trying it yourself.

Lesson 37 — Profiling