Lesson 37 — Solutions: profiling

Exercise 1 — The baseline

The model output (500 reservations, one event):

         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__)
...

The output's hypothesis: 82% of the time (1.988/2.411) is in reservar, and INSIDE it 46% (0.912) in Money.__add__ — recomputing the total with Decimals on every checkout operation. It was NOT "the DB" nor "the serializer": intuition failed, the profile didn't.

The minimal improvement: accumulate in an internal Decimal during the checkout and build the Money ONCE at the end (or sum(amounts, Decimal(0)) → a single Money). Before/after: 2.411 → 1.512 s; Money.__add__ out of the top 3 (0.912 → 0.091). The same test, the same criterion: the measurement declares the victory, not the diff.

Exercise 2 — The N+1

The view with the disguise: 40 reservations → 83 queries (1 for reservations + 40 for tariffs + 40 for seats + 2 extras). The toolbar shows it with the time column: 412 ms in DB for a listing that should cost 2 queries and 40 ms.

The fix:

python

qs = (Reservation.objects.filter(user=user)
      .select_related("event__tariff")        # nested FK: one JOIN
      .prefetch_related("seats"))             # reverse FK: 1 query per batch
# 3 total queries, 44 ms

The quality index: queries/resource must not grow with the rows — it is O(1) in queries or there is an N+1.

.iterator() only changes the TRANSPORT (batched cursor, useful for 2M rows, 31): the queries remain N because each reserva.seats.all() fires its own SELECT. prefetch_related materializes the batch ONCE and the related manager reads from cache (reserva.seats.all() does NOT re-query when prefetched). The rule: iterator for memory, prefetch for queries — they don't replace each other.

Exercise 3 — The micro-profile

The numbers: str(uuid) 21.4 µs, f"{uuid}" 21.9 µs, uuid.hex 0.9 µs per iteration. Does it matter? In an endpoint with 1 conversion: no (0.02 ms). In a 100k-row CSV with 3 per row: a 6 s difference. The double lesson: "don't optimize this" AND "if the flow is massive, .hex is free". Data decides, not superstition.

line_profiler on calcular_total:

Line #  Hits   Time    % Time  Content
   12   500    118400  71.2%   tariff = Tariff.objects.get(event=self.event)   ← the query
   14   500     21400  12.9%   total = sum(...)

It is the N+1 again (71% in the query), not the Decimals' CPU (12.9%): the micro-profile keeps you from optimizing the Decimal when the cost is the DB. The cascading tools: cProfile locates the function, line_profiler the line, EXPLAIN (09) the query.

The snapshot:

python

def confirmar(self):
    self.total_amount = self.total()          # FROZEN: the price at purchase time (08)
    self.save(update_fields=["total_amount", "status"])

08's test (changing the tariff after confirming does NOT change the reservation's total) stays green: the denormalization is legal because it is a snapshot of the economic fact, not a cache of live data — the exact distinction separating this from 38's cache.

Exercise 4 — py-spy

The 3 workers' dumps during the plateau: worker-1 in recv (waiting for a request: normal), worker-2 in pg execute (the UPDATE: matches 36), worker-3 in the listing serializer's json.dumps (new finding: serializing 400 events per request — a candidate for more aggressive pagination, 39, or caching the whole response, 38).

The flamegraph: the wide stack is dominated by UPDATE seats... (55%) and behind it pg execute nests the pool wait (36's pool finding confirmed visually). New in the SVG: the listing's json.dumps is 12% of total CPU — invisible in a unit's cProfile (the data was 5 events; with 400 real ones, serialization weighs). Moral: the PROD profile with REAL data tells things the unit test can't.

The on-call with the dump: "worker-3 is in time.sleep invoked by enviar_recordatorio line 88 for 118 s; the task is 31's reminders one, it doesn't block the queue (prefetch=1) nor the DB (no active transaction in pg_stat_activity). Scheduled wait, not a bug: do NOT restart" — the dump turns "something is slow" into an informed decision.

Exercise 5 — The report

The report's structure (excerpt):

markdown

# Checkout profile — 2027-09
Baseline (k6, 200 plateau): p99 1.4s; breakdown: DB 55%, app 22%, gateway 18%.
Findings: [cProfile] Money.__add__ 46% of reservar(); [silk] N+1 in my-reservations (83q);
          [py-spy] bulk UPDATE (matches k6/36); gateway = remote latency.
Improvements: bulk UPDATE (-700ms p99), total_amount snapshot (-14ms), prefetch (-368ms listing).
NOT fixed: str(uuid) (0.02ms/req), listing json (12% CPU: 39's pagination addresses it).
Re-measurement: p99 640ms. Next: the listing's pagination.

The documented NON-improvements are worth as much as the fixed ones: they protect against the judgment-free "performance refactor" next time.

The PR template:

Improvement: [what]
Before: [p95/p99/queries — tool and date]
After:  [same criterion]
Cost:   [added complexity, invalidation, risk]
Revert: [how to undo it]

Five lines turning every optimization into versioned data (and in the "it didn't improve" case: the PR doesn't merge — a cache that doesn't improve gets rejected, 38).

Professor's summary

The measure→hypothesize→measure cycle with the SAME tool and criterion; a single measurement is an opinion.
cProfile locates the function, line_profiler the line, EXPLAIN the query; in prod only sampling (py-spy) — the prod flamegraph reveals what the unit test can't see.
Every improvement carries a measured before/after in the PR; NON-improvements get documented the same way.

Lesson 37 — Profiling