Distributed tracing

A request to a modern backend is rarely handled by one process. A checkout passes through a gateway, an order service, an inventory service, a payment provider and a queue, and when it takes two seconds, the logs of each service show only their own part. Distributed tracing records the whole journey as one structure, so the question "where did the two seconds go?" has a picture for an answer.

#Traces and spans

A trace is one request's journey. It is made of spans, each one timed piece of work — an incoming HTTP request, a database query, a call to another service — with:

• a trace id, the same for every span in the trace
• a span id of its own
• a parent span id, which is what builds the tree
• a start time, a duration, a name, and attributes such as the HTTP route, the status code, or the database statement

Here is a checkout, recorded by a small hand-written tracer so the mechanism is visible — spans with ids and parents, exactly the data a real tracer keeps. The waterfall is drawn from the spans' own start times and durations:

context propagated everywhere:
  trace bba3bf02…
    POST /checkout                            197 ms  ███████████████████████████████████████
      validate cart                             6 ms  █
      inventory: reserve                      109 ms   █████████████████████
        inventory: SELECT stock FOR UPDATE     90 ms       ██████████████████
      payment: charge                          45 ms                         █████████
      email: send confirmation                 25 ms                                   █████

The answer to "why is checkout slow?" is on the screen: more than half of it is one SELECT … FOR UPDATE in the inventory service, waiting on a row lock. No log line says that, because each log line knows only its own duration. The tree, and the fact that the spans are nested and sequential rather than parallel, is what makes it obvious.

#Propagation: the context crosses the wire

For inventory's span to appear inside checkout's trace, inventory must be told which trace it is part of. That is context propagation, and the standard format is the W3C Trace Context traceparent header:

traceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01
             │  │                                │                └ flags: 01 = sampled
             │  │                                └ the caller's span id — the callee's parent
             │  └ trace id, 16 bytes
             └ version

Every hop has to carry it, including the asynchronous ones:

In a Spring Boot 3 service, Micrometer Tracing with an OpenTelemetry or Brave bridge does all of this for the instrumented clients and servers: RestClient and WebClient write the header, the server side reads it, Spring Kafka carries it in record headers when observation is enabled, and JDBC spans come from a data-source proxy. The same library puts traceId and spanId into the logging MDC, which is what links a trace to its log lines — the structured logging lesson's correlation id, with a standard format.

#Where the context is lost

Automatic propagation covers the clients and servers the library knows about. It does not cover a thread you hand work to yourself. The same checkout, with the confirmation email submitted to a thread pool without carrying the context:

context not carried onto the pool thread:
  trace 9aec32bd…
    POST /checkout                            182 ms  ████████████████████████████████████
      validate cart                             5 ms  █
      inventory: reserve                      111 ms   ██████████████████████
        inventory: SELECT stock FOR UPDATE     94 ms      ██████████████████
      payment: charge                          40 ms                         ████████
  trace 5c0779d4…
    email: send confirmation                   20 ms  ████

The email span did not disappear. It started a new trace of its own, with no parent, because the pool thread had no current span. In a tracing UI, checkout now looks faster and complete, and a separate one-span trace for an email sits among millions of others with nothing to connect it back. A failure in that email is invisible from the checkout that caused it.

This is the same thread-hop problem as the MDC, and it has the same fix: capture the context when the work is submitted and restore it on the worker. Micrometer's context-propagation library wraps executors to do it; a raw new Thread, a custom executor or a callback from a non-instrumented library each need it done explicitly.

#Sampling, and the traces you needed

Recording every span of every request is expensive at scale. Tracing systems sample, and when they decide matters more than the rate.

Head sampling decides at the start of the request: keep 10%, or 1%, and tell downstream services through the sampled flag so the whole trace is kept or dropped together. It is cheap and consistent. It is also blind, because at the start nobody knows whether this request will fail.

Tail sampling buffers the spans and decides after the trace is complete: keep every trace with an error, every trace slower than a threshold, and a small random share of the rest. The OpenTelemetry Collector has a tail-sampling processor for exactly this.

A million requests, 0.1% of which fail, and 0.2% of which are slow — seeded, so it repeats exactly:

1,000,000 requests, 1003 failed
head sampling 1%:                         kept 9,873 traces, of which failed: 13
tail sampling: all errors, all slow, 1% of the rest: kept 13,008 traces, of which failed: 1003

Head sampling at 1% kept 13 of the 1,003 failures. When someone investigates an incident, 98.7% of the failed requests have no trace. Tail sampling kept every failure and every slow request, for about a third more storage than head sampling used.

The cost of tail sampling is operational: something must hold every span of every in-flight trace until it completes, which means a collector tier with memory sized for your traffic and your longest trace. Spring Boot's default sampling probability is 10%, a head-sampling decision, which is reasonable for development and worth revisiting before relying on traces for incidents.

#What goes on a span

Spans are the place for the high-cardinality detail that metrics cannot hold: the order id, the customer tier, the SQL statement, the downstream status code, the retry attempt. One value per span costs almost nothing extra, and it turns "p99 checkout latency is up" into "p99 is up for orders with more than 50 lines, in the inventory reservation span".

The rules from the logging lessons still apply — no secrets, tokens or personal data in attributes — and so does the metrics lesson's advice in reverse: a trace answers "what happened to this request"; the dashboard answers "what is happening to all of them". Each is the wrong tool for the other's question.