The Life of One Request

A buyer clicks "hold seat 14C" and 180 milliseconds later sees a countdown. Following those milliseconds through every layer they touch (the TLS handshake, the load balancer, the socket accept, the parse, the auth check, the pool checkout, the UPDATE, the commit, the serialize, the write back) is the fastest way to learn where a service spends its time and where it can lose the answer. This book returns to this one request in a dozen chapters, and it is worth walking it slowly once.

The numbers below are Stagedoor's, measured from a trace on an ordinary evening, not during on-sale. Roughly 40 milliseconds happen before the process sees a byte, 10 go on parsing and the middleware rings, 90 are spent in the database, 5 on the way out, and 35 are unexplained until Topic 04 explains them.

Before the Process Sees Anything

The browser resolves stagedoor.example, opens a TCP connection to the load balancer, and completes a TLS handshake with it. On a 20-millisecond round trip that is two round trips, the 40 milliseconds the service never sees, before a single byte of the request has been sent, and it is paid per connection rather than per request — which is why keep-alive and HTTP/2 in Chapter 2 matter more to a mobile buyer than any optimization inside the handler. The load balancer terminates TLS, picks api-01, and forwards plain HTTP over the private network. The bytes of POST /events/8812/seats/14C/hold land in a socket buffer on api-01, and the service's clock has not started.

Accept, Parse, Route

The event loop accepts the connection and the HTTP parser turns the bytes into a method, a path, headers and a body. The router matches the path to hold_seat and the framework builds the handler's arguments from the request: event_id from the path, label from the path, the body into a typed model. A body that is not valid JSON is a 400 here; a body that parses but fails the model is a 422 here. Neither reaches domain code. Chapter 3 is about making that boundary the only place untyped data ever exists.

The Rings Around the Handler

Between the router and the handler sit half a dozen middleware rings, and the order they run in is a design decision. The first assigns a request id and starts the request context. The access-log ring records that a request began. The metrics ring starts a timer. The rate limiter checks this buyer's bucket. The authentication ring verifies the bearer token and puts a Principal in the context. Chapter 4 explains why the rate limiter must run before the expensive authentication check, and why the access log has to sit outside both of them, so that it still records the final status when an inner ring short-circuits with a 429.

The Handler and the Store

The handler calls svc.holds.create, the domain function that owns the rule. It checks out a connection from the pool, opens a transaction, locks the seat row, checks the status, updates it to held, inserts the holds row with an expiry ten minutes out, and commits. Ninety of the 180 milliseconds are here, and sixty-one of those ninety are the commit — the moment pg-primary writes the transaction to its write-ahead log and waits for the disk to confirm.

span  db.pool.acquire        2 ms   # a free connection was waiting
span  db.tx                  88 ms
  span  SELECT ... FOR UPDATE   4 ms
  span  UPDATE seats            3 ms
  span  INSERT holds            2 ms
  span  COMMIT                 61 ms   # fsync on pg-primary
  (unattributed)              18 ms   # the loop was serving other requests

Read the trace bottom-up and two things stand out. The queries themselves are trivial; the commit is the cost, and it is the cost of durability, which is the one thing nobody wants to give up on a seat hold. And eighteen milliseconds inside the transaction belong to no query at all. That is the event loop switching to other requests between the handler's awaits, and it is the first hint that concurrency in this service is a shared resource rather than a free one.

The Way Back

The domain function returns a Hold. The handler converts it to a response model, the framework serializes it to JSON, the status code is 201, and the bytes are written to the socket. The connection stays open for the buyer's next request. Five milliseconds, and the least interesting part of the picture — until you notice that the work is already committed before the first byte of the response leaves the process.

That gap is the whole reason Chapter 7 exists. If the buyer's Wi-Fi hands off between two access points right here, the hold is real, the seat is held, the countdown is running on the server, and the buyer's screen shows a spinner that will time out. The browser retries. The service sees a second POST for a seat that is now held by the same buyer, and what happens next depends entirely on whether the service can recognize a repeat. Stagedoor could not, and that is how one buyer was charged twice on the night of the spring on-sale.

Where the Time Went

Forty milliseconds of network the service cannot see. Ten of parsing and rings. Ninety in the database, sixty-one of them the commit. Five to answer. That leaves thirty-five milliseconds unexplained, and the honest label for them is "the event loop was busy with somebody else." Under on-sale load that number is the one that grows, because every other request on the instance is competing for the same loop. Topic 04 explains the mechanism; Chapter 14 measures it as loop lag and puts it on the dashboard.

The habit this topic is meant to leave behind is a simple one. Before guessing where a service is slow, ask for the waterfall. Every "the database is slow" that turned out to be a pool wait, a DNS lookup on every request, or a PDF render sitting on the loop cost a week that one trace would have saved — and Chapter 13 shows how to have that trace for every request that crosses a second of latency.