Where the Time Goes

Optimizing without a profile is guessing, and the guess is almost always "the database." Chapter 1 followed a checkout and found 90 milliseconds inside the handler, the part of the request that is not Payrail's 400, and everyone who looked at that number assumed the queries owned it. When Marek measured it before the autumn on-sale, the queries owned 25. The other 65 were the process's own work: 30 milliseconds serializing a 60 KB response with the standard library's JSON encoder, 20 milliseconds of Pydantic validating a response the storage layer had already typed, and 15 milliseconds of the logger formatting a line that the sampler of Chapter 13 then threw away. None of that was in any trace, because none of it was a call.

This topic is the three tools that show where the time actually is, and the order to use them: the trace, for time spent waiting on a dependency; the profiler, for the gaps the trace cannot name; the query log, for the statement that is slow and the statement that runs a thousand times. Used in that order they took the checkout from 90 milliseconds to 32 without touching a query, and the last section is about knowing when 32 is enough.

The Trace First

The waterfall of Chapter 13 is where every performance question starts, because it is the only view that attributes the request's time by dependency: the rings, the pool wait, each statement, the Redis round trips, the Payrail call, and the spaces between them. Read for the checkout on a quiet afternoon, it shows a handler span of 90 milliseconds with two transaction bars inside it, 14 and 11 milliseconds, the idempotency key's Redis write at 1, the Payrail bar at 412 hanging outside the 90 because it is not the process's time, and then nothing. The bars add up to 25 of the handler's 90. The trace is exact about the 25 and silent about the rest.

The silence has a shape, and the shape is the lesson. Thirty-five milliseconds sit in gaps between bars, inside the span, where the process was demonstrably doing something and the trace does not know what; that is Chapter 1's unexplained 35, and Chapter 13 said to take it to the loop-lag gauge before touching a query. Thirty more sit after the last bar and before the span closes, which is the framework turning the handler's return value into bytes. A trace attributes time to calls, and CPU work is not a call. When the gaps and the tail add up to more than the bars, as they do here at 65 against 25, the next tool is not a slow-query log. It is a profiler.

The Profiler for the Gaps

A sampling profiler reads the process's call stack a hundred times a second from outside, without changing the code or restarting it, and reports which function the CPU was in each time. Marek attaches py-spy to one api process on staging during the load test of Chapter 12, at 3,000 requests a second, for 60 seconds, and the profile is 6,000 samples of what the loop was doing when it was not waiting. The attachment needs the ptrace capability on the container for the length of the run and nothing else. Under load is the only honest condition: a function that is 2 percent of the CPU at idle, because the process is mostly idle, is 30 percent at 3,000 a second, because at 3,000 a second the process is mostly that function.

$ py-spy record --pid 4182 --duration 60 --rate 100 --format speedscope -o checkout.json
$ py-spy top --pid 4182

  %Own   %Total  OwnTime  TotalTime  Function (filename)
 31.0%   31.0%   18.6s     18.6s    iterencode (json/encoder.py)          # the 60 KB response, char by char
 19.5%   22.0%   11.7s     13.2s    validate_python (pydantic_core)       # re-validating what storage typed
 14.0%   16.0%    8.4s      9.6s    format (logging/__init__.py)          # lines the sampler then drops
  9.0%   27.0%    5.4s     16.2s    _run (asyncio/events.py)              # the loop itself
  6.5%    6.5%    3.9s      3.9s    execute (psycopg/cursor_async.py)     # the driver, encoding parameters

The first command records a flame graph, the second is the same data as a live table, and the table is the finding. Thirty-one percent of the loop's CPU was the standard library's JSON encoder walking the 60 KB response one character at a time. Twenty percent was Pydantic validating the response model, which is the same validation the storage layer had already done when it built the typed order from the rows. Fourteen percent was the logging module formatting the order.created line with every field interpolated, before the sampling processor decided whether to keep it, and at 1 in 10 it kept one in ten. Nobody had considered serialization, because nobody thinks of returning JSON as work; at 3,000 requests a second it was the single largest thing the process did. The driver, which everyone had suspected, was 6.5 percent.

The flame graph adds what the table flattens: the path by which each function was reached. The encoder's 31 percent all hangs under the framework's response rendering, so the fix is one setting rather than fifty call sites; the validation hangs under the route's response_model, so the fix is per route; the formatting hangs under three specific log calls on the checkout path, so the fix is three lines. A profile that names the function without the path names a symptom.

The Query Log for the Database

The queries were 25 milliseconds and fine, and the way to know that rather than assume it is two settings on Postgres. The first, log_min_duration_statement = 100ms, writes every statement that took longer than 100 milliseconds to the server log with its duration and its text, which catches the slow. The second, the pg_stat_statements extension, keeps one row per distinct statement shape with its call count and its total and mean execution time, which catches the many: the statement that takes 0.4 milliseconds and runs 2,600 times a second is 1,040 milliseconds of the primary's time every second, and it never appears in the slow log. The statement-count assertion of Chapter 12 catches the same class of problem in the test suite, one route at a time; the extension catches it in production, across all of them.

Marek reads the extension's table sorted by total time rather than by mean, and the order is the lesson. The seat-map read is at the top, with a mean of 0.41 milliseconds and 18 million calls: the statement the cache of Chapter 9 exists to keep off the primary, and its total says how much of the primary's day it still owns. The hold's update and the checkout's two inserts are next, each a few milliseconds and hundreds of thousands of calls. The organizer report is fifth, 48 milliseconds each and 31,000 calls, and it is the only one that would appear in the slow log at all if its threshold were lowered. What to do about a slow statement, the plan, the missing index, the sort that spills, is PostgreSQL Deep Dive's Chapter 9 and EXPLAIN; the service's part is to know which statement it is, how often it runs, and whether the answer is an index or a cache.

The Fixes, in Order of Return

Three findings, three fixes, applied one at a time with the profile re-run after each, in the order of what each one would return. The JSON encoder first, because it was the biggest: orjson, a serializer written in Rust that produces bytes rather than a string and handles UUIDs, datetimes and dataclasses natively, installed as the framework's default response class. Thirty milliseconds became 4. The response validation second: the route that used to hand a typed order back to the framework to validate against a response model now returns the response directly, built from the value the storage layer already typed, and Pydantic runs once at the boundary on the way in, as Chapter 3 placed it, and not again on the way out. Twenty became 2. The log line third: the sampling processor moved to the front of the processor chain, so a line that will be dropped is dropped before anything renders it, and the fields are passed as fields rather than interpolated into a string. Fifteen became 1.

app = FastAPI(default_response_class=ORJSONResponse)          # 30 ms -> 4, every route at once

@router.post("/orders", status_code=201, response_model=None)   # storage typed it; do not validate it twice
async def place_order(req: PlaceOrder, ctx: Ctx) -> ORJSONResponse:
    order = await ctx.svc.orders.place(ctx.principal, req)
    return ORJSONResponse(order.as_public(), status_code=201)   # 20 ms -> 2

processors = [
    sample(keep_errors=True, keep_ratio=0.1),   # first: a dropped line is never rendered
    add_request_context, redact_secrets,
    JSONRenderer(serializer=orjson.dumps),      # last: 15 ms -> 1 on the lines that are kept
]

Three changes, none of them to a query. The first line swaps the encoder for every route in one place, which is what the flame graph's path said was possible. The route keeps its request model, because the request is untrusted bytes and Chapter 3's rule holds, and drops its response model, because the value it returns was typed by the storage layer of Chapter 4 and validating it again buys nothing but 20 milliseconds. The processor list puts the sampler first, so that on a night that logs 3,000 events a second the 2,700 that will not be kept cost a dictionary lookup and nothing else. The checkout's handler went from 90 milliseconds to 32, the queries stayed at 25, and the database noticed no difference at all, because nothing about it changed.

Cheap Wins and Their Limits

Three more changes were on the list, each already argued for in an earlier chapter, and each was made only after being measured. The Payrail client of Chapter 10 keeps one connection open across charges; before it did, every checkout paid a TCP and TLS handshake of 100 milliseconds to Payrail's edge, which Chapter 2 priced and which the trace showed as a bar named connect under every charge. The organizer report selected every column of events and orders where the response needed six; selecting the six, as Chapter 6 said a mapper should be made to do, cut 48 milliseconds to 31 by moving fewer bytes through the driver and fewer rows' worth of columns through the encoder. And the seat map, 60 KB on every one of 2,600 reads a second, is stored in Redis compressed with zstd at 8 KB, as Chapter 9 arranged, so that the wire from redis-01 carries 21 MB a second instead of 156, and the 2 milliseconds of decompression on the loop are cheaper than the bytes.

The one that did not survive was a per-request cache of the organizer row, which saved 0.3 milliseconds on a path already under 40 and added a place for the multi-tenancy rules of Chapter 5 to be wrong. It was measured, it did not move the number, and it was reverted, which is the rule for every optimization on this list: the change that cannot show its return on the dashboard is a change that made the code worse for nothing. A micro-benchmark is not that dashboard. orjson is 10 times faster than the standard encoder in isolation and it was 7 times faster in the checkout, because the checkout was also validating, logging and waiting, and the encoder's share of the request was the only share it could shrink. The request is the unit of measurement, and a benchmark of one function is a hypothesis about the request, not a result.

When to Stop

The SLO of Chapter 13 says when: 99.9 percent of checkouts under 800 milliseconds, over 30 days. A checkout whose own work takes 32 milliseconds, with Payrail's 400 on top, has 360 milliseconds of headroom against the objective under ordinary load and is done. The seat map at 8 milliseconds is done. The week that would take the checkout from 32 to 30 is a week not spent on the hold path, which at 19:00:00 on the on-sale night is the path that is not done, and Topic 75 is what that week bought instead. A hot path is finished when it is inside its objective with room for the night's load, and not before, and not after.

Two rules follow. The profile is re-run after every change to a hot path, because the second-biggest cost is now the biggest and the ranking that justified the last fix is stale the moment it lands; after the encoder fix the validation was the top of the table, and after that the driver's parameter encoding was, at 6.5 percent, which is where Marek stopped. And every number in this topic is a number under load, from the trace at 3,000 a second and the profile during the ramp, because the checkout at idle was 90 milliseconds and looked like a database problem, and the same checkout at 3,000 a second was a serialization problem that only the profile could see.