Distributed Tracing

When there was one service, finding what was slow wasn't hard. Read the records in time order and the function that took too long showed up. Split into several services and that method stops working. Each service keeps only its own records, and there is no thread between them tying one request together.

Pagedeck was in that position. Opening a document took four seconds roughly one time in ten. Theo opened the records of all four services and each looked fine on its own: the document service at 200 milliseconds, the permission service at 80, the search service at 150. Those don't add to four seconds, and there was no way to find where the remaining 3.5 went. He wanted to follow one request through, and nothing in any service's records marked which lines belonged to the same request.

Distributed tracing solves that by attaching a unique ticket to each request. Make the ticket travel and the records that belong to one request join up, and once joined, the time per segment lands in one picture. What Theo found after adding it wasn't in any of the four services. The permission service was being called three times, and two of those calls were duplicates returning the same answer.

A ticket attaches to one request, and every segment that request passes through records its start and end under that ticket. Two words go with it: the whole journey of one request is a trace, and one segment inside it is a span.

1. Create the ticket. At the point a request first arrives, generate a unique string. If there's an API gateway — the layer that gathers several services' entrances into one — that's usually the starting point, since every request already passes through it.
2. Pass the ticket along. When one service calls another, the ticket rides in the request headers. If any service in the middle fails to pass it, everything after that breaks off. That is very nearly the only reason traces show up half-finished in practice.
3. Record spans. Per segment: start time, duration, which service, and whether it succeeded. Spans carry a parent-child relationship, so a permission lookup span hangs as a child under the document service span. Without that relationship, call order and nesting are invisible.
4. Attach the values you'll filter by as tags. Which user, which document, which version was running. If you later want to look at only the slow requests, the basis for selecting them has to be here already.
5. Store only some of it. Keeping every segment of every request produces more data than the service itself. So teams store 1 to 10 percent, and add a rule that requests which errored or ran slow get stored regardless of the sampling rate.

The viewing screen is usually horizontal bars stacked in layers. Bar length is elapsed time and the layer is call depth. What catches the eye there isn't one long bar but the same bar repeating three times, which is a shape a table of numbers hides completely.

The first use is finding what's slow, especially when the average looks healthy and one request in ten doesn't. Filter to the slow requests, open the picture, and which segment ate the time is visible at a glance. Metrics, observational data gathered as numbers along a time axis, only tell you the average moved; they can't tell you which segment of which request.

Three other places.

1. Incident response — when five services slow down at once, cause has to be separated from effect. Open a trace right after alerting fires — the mechanism that notifies an owner when a condition is crossed — and the direction of calls is visible, so the service blocked further back gets identified first. It's where incident management, the practice of recovering and preventing recurrence, saves its first ten minutes.
2. Confirming dependencies — the call relationships in a design document and the real ones differ more often than not. Collect traces and the actual call graph appears, usually with one call in it nobody remembers making.
3. Comparing before and after a release — put traces of the same request side by side across a deploy and which segment grew shows up. Looking only at total response time buries a 20-millisecond difference; segment by segment, one segment having doubled is obvious.

Some situations don't call for it. With a single service this machinery is too much: it costs instrumentation and storage while having no segments to join. Keeping good records is enough there.

"Let's open one slow request's trace. We need to see which segment first."

Look at per-segment timing instead of guessing the cause.

"There are three permission service spans. Two are the same call."

Spotting duplicate calls in the picture.

"The trace stops here. This service isn't passing the ticket."

Naming the segment where propagation is missing.

Theo's order of work was this: have the gateway create the ticket, fix all four services to pass it along, set sampling at 5 percent, and store everything that errored or ran past two seconds. It took four days, two of them spent on the search service that wasn't passing the ticket.

Removing the duplicate calls in document opening took slow requests from one in ten to one in a hundred. What earned more came next: two more duplicate calls of the same kind were plainly visible in the pictures for other screens.

The most common belief is that adding tracing removes the need for records. All the per-segment timing is visible, so it feels that way. But a trace tells you where the time went and not why. After learning the permission lookup took three seconds, what you need is what values it queried with and what error it threw, and that lives in the records. Carry the span's ticket into the records too and you can jump straight from the picture to that request's log lines.

The other common belief is that sampling means missing problems. Twenty requests going by for every one you keep is an uncomfortable trade. But what you're hunting is a repeating shape, not one specific request. If 2,000 requests a day are slow in the same segment, 5 percent still leaves 100, and 100 is more than enough for the shape to appear. What genuinely can't be missed is the rare error, and that gets caught by the separate rule that stores all of them.