Traces Across Boundaries

The buyer's checkout took 4 seconds. The log lines say the handler took 88 milliseconds and the Payrail call took 412, and no line in the request accounts for the other 3.5 seconds, because the time was spent in nobody's code: 3.2 seconds waiting for a connection from a pool with all 20 checked out, which no single log line would have named. A trace names it. A trace is one request's path as a tree of spans, each with a start, a duration and a set of attributes, propagated across process boundaries by one header, and the waterfall it draws is the picture Chapter 1 asked the reader to demand before guessing where a service is slow.

The service's job is small and specific: start the root span, propagate the context into every outbound call and every job payload, let the instrumentation libraries produce the spans that matter, add a few by hand, and put the right attributes on them. The storage and the viewer are the observability stack's, and Observability Deep Dive covers them. This topic is what the code has to do so that the waterfall exists, and what it shows that nothing else can.

Spans and the Tree

The root span is the request, started by the framework's instrumentation inside the middleware rings of Chapter 4 and ended when the response is written. Its children are everything the request waited on: the pool acquire, the transaction, each statement inside it, each Redis command, the Payrail call, the second transaction. Each child knows its parent, so the collector draws them as a tree, and a tree with time on the horizontal axis is a waterfall. The demonstrated waterfall is a 4-second checkout from 21:04 on the second on-sale night, with all 20 connections of the pool in use; the load test of Chapter 12 later put a number on that limit, 800 requests a second.

POST /orders                                    4,010 ms   # root span, api-01, trace 4bf92f35…
  rings: request id, access log, auth               6 ms
  db.pool.acquire                               3,214 ms   # every connection was busy: the 3.2 seconds
  db.tx  place order                               88 ms   # what the handler's own timer measured
    INSERT idempotency_keys                         3 ms
    SELECT holds ... FOR UPDATE                     5 ms
    INSERT orders                                   4 ms
    COMMIT                                         62 ms
  payrail.charge  POST /v1/charges                412 ms   # the span ends at the socket; Payrail's side is dark
  db.tx  mark paid, queue render                   71 ms
  (gaps between spans)                            219 ms   # the loop serving other requests

# worker-01, 21:06:57, same trace id, parent = the span that wrote the outbox row
  queue.wait                                  180,000 ms   # from the entry id's timestamp to the handler's start
  render_tickets                                4,100 ms   # a manual span around the thread-pool render
  send_tickets                                    300 ms   # the mail provider

Read it top to bottom. The rings took 6 milliseconds. Then a span named pool acquire took 3,214, and it is the widest bar on the screen: the request was waiting for one of 20 connections that were all inside other requests' transactions, which is Chapter 6's invisible number made visible. The transaction itself was 88 milliseconds, 62 of them the commit, which is what the handler's timer reported and why the log said the handler was fast. Payrail took 412. The second transaction, which marks the order paid and writes the outbox row for the render, took 71. And 219 milliseconds belong to no span at all, the gaps, which the last section is about. Three minutes, 180 seconds of queue wait, later, on a different host, the same trace continues with the render and the email, which is how the buyer's whole experience, from click to ticket, is one picture.

Propagation

A trace crosses a process boundary as one header, traceparent, defined by the W3C Trace Context specification that Chapter 2 introduced. Its value has four parts separated by hyphens: a version, 00; the trace id, 32 hexadecimal characters, the same for every span in the trace; the parent span id, 16 characters, the span that made this call; and flags, of which the one that matters is the sampled bit. The middleware reads it from the inbound request and starts the root span as a child of whatever the load balancer or the mobile app sent, or starts a new trace when there is none. The outbound client writes it into the Payrail call, so Payrail's own spans, if it keeps any, hang under Stagedoor's. And the checkout handler writes it into the outbox row's payload, inside the request, where the current span is the checkout's, so that when the worker claims the job three minutes later it extracts the context from the payload and starts its span as a child of the same trace.

The two boundaries that are not HTTP are the ones that get missed. The stream carries bytes, and a context variable does not survive being written to Redis, which is the same fact Chapter 4 stated for the request id: the header's value goes into the payload as a field, beside request_id, and the worker rebuilds both before it does anything else. Without that one field the render is a separate trace with a different id, an orphan that begins at the worker and explains nothing about the checkout that queued it, and the 3-minute queue-wait bar that Chapter 8 called unmistakable is not drawn at all. The demonstrated trace spans the API and the worker because the payload carried the header.

Instrumentation, Mostly Automatic

Almost none of the spans in the waterfall were written by hand. OpenTelemetry ships an instrumentation for each library Stagedoor uses: one for FastAPI, which starts the root span per request and reads the inbound traceparent; one for httpx, which starts a span per outbound call and injects the header; one for psycopg, which starts a span per statement with the statement's text as an attribute; one for the Redis client, which does the same per command. Four calls at startup, and the root, the statements, the Redis commands and the Payrail call exist. The service adds spans by hand only where the automatic ones are too coarse to answer a question: the seat-map rebuild of Chapter 9, which is 30 milliseconds of Python between two Redis commands, and the PDF render, which is 4 seconds in a thread the instrumentation cannot see into.

FastAPIInstrumentor.instrument_app(app)     # a root span per request; reads traceparent from the headers
HTTPXClientInstrumentor().instrument()      # a span per outbound call; writes traceparent into it
PsycopgInstrumentor().instrument()          # a span per statement, ending at the driver
RedisInstrumentor().instrument()            # a span per command

tracer = trace.get_tracer("stagedoor")

# in the checkout handler: the current span is the request's, so inject() writes its id
carrier = {}
inject(carrier)                             # {"traceparent": "00-4bf92f35…-00f067aa…-01"}
payload = {"order": order.public_id, "request_id": ctx.request_id, **carrier}

# in worker-01, three minutes later: rebuild the context, then one span by hand
parent = extract(job.payload)
with tracer.start_as_current_span("render_tickets", context=parent) as span:
    span.set_attribute("order.id", str(order.public_id))
    span.set_attribute("request.id", job.payload["request_id"])
    pdf = await asyncio.to_thread(render, order)   # never span.set_attribute("buyer.email", ...)

The first four lines are the whole automatic layer, run once when the process builds its service. Then the two halves of the boundary: in the handler, the inject call writes the current span's trace id and span id into a dictionary as the header, and the dictionary is merged into the job payload beside the request id; in the worker, the extract call reads the same fields back into a context, and the manual span for the render is started under it, so it is a child of the span that was current when the outbox row was written, with the same trace id. The two attributes on the span are the order's public id and the request id, which are the two keys a human searches by. The buyer's email is not on it, and the comment is a rule, not a reminder: a span attribute lives in the trace store for as long as the traces do, and the trace store is not where personal data is allowed to be. The seat-map rebuild gets the same treatment, a span by hand with the event id as its one attribute, and nothing else in the service starts a span in its own code.

Sampling

Every request traced at 3,000 a second is 3,000 traces a second, each of 10 to 15 spans, and on the on-sale night that is 40,000 spans a second into a collector that was sized for 2,000. Two strategies exist, and they are made in different places. Head sampling decides at the root, before anything is known about the request: keep 1 in 100, chosen by trace id so that the decision is the same on every hop, and carried in the sampled bit of the header so that Payrail and the worker make the same choice. It keeps the shape of the night, the ordinary checkouts at their ordinary width, and it throws away 99 percent of the errors and 99 percent of the slow requests, which are the traces anyone would read.

Tail sampling decides after the trace is complete, which only a collector can do, because the service that started the trace does not know how it ended on another host. The rule is: keep every trace that contains an error, keep every trace whose root exceeded 1 second, and keep 1 in 100 of the rest. That is the promise Chapter 1 made, a trace for every request that crosses a second, and it is what Stagedoor runs: the service sends everything with the sampled bit set, the collector holds each trace for 10 seconds after its first span arrives and then applies the rule. When there is no collector to decide, the service samples at the head at 1 percent and accepts that the interesting traces are mostly lost; that is the honest fallback, not a design.

Traces and Logs Together

The trace id is a field on every log line, added by the logger's processor of Topic 68 from the same context that carries the request id, and the request id is an attribute on the root span, put there by the middleware. That is two links in two directions and it is enough. The demonstrated jump starts at the payrail.charge line from the previous topic: a person searching for order 4471 finds the line, reads 412 milliseconds and wonders why the buyer waited 4 seconds, clicks the trace id on the line, and the viewer opens the waterfall above with the 3.2-second bar in it. The jump runs the other way as well: a slow span in a waterfall has the request id on its root, and the request id is the query that returns every line the request wrote.

The two links are what make the three signals one instrument instead of three tools. The metric says checkout P99 is 4 seconds at 21:04; the traces kept by the slow-request rule from 21:04 are the ones with the wide acquire bar; the log lines for any of them say which orders, and the transition lines say whether they completed. Without the ids the same investigation is three tabs, three time ranges and a guess about which trace was which buyer, and it takes the hour that the second on-sale night did not have.

What the Trace Cannot Show

The trace ends at the driver. The span for COMMIT is 62 milliseconds wide, and it says nothing about what Postgres did in those milliseconds, because the instrumentation wraps the call and not the engine; where the time went inside the database is EXPLAIN's question, and PostgreSQL Deep Dive Chapter 9 begins where this bar ends. The Payrail span is 412 milliseconds of a socket being open, and Payrail's side of it is dark unless Payrail returns its own trace, which most providers do not. And anything the instrumentation does not wrap is invisible: a computation in Python between two awaits, a lock waited on, a thread pool with all its threads busy, a DNS lookup inside a client that was not instrumented.

The gaps are the second most useful thing in a waterfall, after the widest bar. When 219 milliseconds of the checkout belong to no span, the honest reading is that the event loop was serving other requests between this request's awaits, which is the 35 milliseconds of Chapter 1 grown under load, and the loop-lag gauge of the previous topic is the number that confirms it. A waterfall whose gaps add up to more than its spans is a process that is CPU-bound or loop-bound, and no amount of tracing the calls will find the time, because the time is not in a call. The reader learns to ask, for every gap, what the process was doing there, and the answer is usually the topic Chapter 14 opens with.