Where Did the Time Go?

A user reports that posting a message took four seconds. When Courtyard was one machine, in Part I, you would have looked at that machine, at its logs and its resource gauges, and found the slow part, because there was one place to look.

Today that request entered at the gateway of Chapter 15, which called the chat service, which called the accounts service for the sender’s name and the groups service for membership, and then the fan-out system of Chapter 11, which put a job on the queue of Chapter 17, while a notification service was told, and each of those touched a database or a cache. Eleven services, across two regions, on dozens of machines, for one message post. Somewhere in there, four seconds went. You would like to know which machine, and which call.

You look at the chat service’s logs. They say that it received the post request, called accounts, called groups, called fan-out, and returned, with no timings that indict anyone; it was waiting on the services it called. You look at accounts, which answered in two milliseconds, and at groups, which is also fine. You could look at all eleven, one at a time, correlating by hand, guessing which log line in each corresponds to this request among the thousands each machine handled in those four seconds, and before that you would need to know they were involved at all, and find each one’s logs, in two regions. It is hopeless. No single machine knows where the time went, because each one saw only its own slice, and nothing connects the slices. The resource that has run out is knowability, the ability to answer the question of what happened to this request, and it ran out silently, chapters ago. Every chapter since Chapter 6, as Courtyard spread across machines, made the system a little less knowable, and nobody noticed until a request got slow and there was no way to find out why.

The problem is that the eleven slices are not connected, so you connect them. When a request enters at the gateway, you give it a unique identifier, a random string such as req-8a3f.... Then you carry that identifier through every call the request causes. The gateway passes it to the chat service, in a header, since headers, from Part I Chapter 18, are where metadata rides; the chat service passes it on to accounts and groups and fan-out, which pass it to their databases and into their queue messages, so that the jobs of Chapter 17 carry it too. Every machine that does any work for this request knows its identifier, because the identifier was handed down the whole call graph.

Now you have every machine record what it did for that identifier, with timing. The chat service records that for req-8a3f it handled a post in 3,900 milliseconds, spent mostly waiting on fan-out. The fan-out service records 3,850 milliseconds for req-8a3f, spent mostly waiting on the database. The database records a fan-out write for req-8a3f that took 3,800 milliseconds. Collect all the records bearing the same identifier from all eleven machines into one place and you can see the whole request: every service it touched, how long each one took, and who called whom. The four seconds has a location, the database write in fan-out. You found it not by looking at any one machine but by reassembling the request from the fragments each machine contributed.

Let’s make this precise. Each fragment, meaning one service’s work on one request, is a span. It has a start time, a duration, a service name, and, most importantly, a parent, the span that caused it. The gateway’s span is the root. The chat service’s span is its child. Accounts, groups, and fan-out are children of chat, and the database write is a child of fan-out. The parent links turn the flat list of fragments into a tree, and the tree, laid out on a timeline, is a trace: a waterfall showing how the request flowed through the system and where the time went, with each span nested under the one that spawned it.

This is distributed tracing, the identifier is a trace ID, and the practice of building systems you can understand from the outside is observability, the property that you can answer questions about what your system did without having predicted the questions in advance. Everything since Chapter 6 needed this and lacked it. The load balancer, the services, the regions, and the queues all made the system more capable and less observable, and tracing is what pays that debt back. The realisation to carry away is that at scale you cannot understand a request by looking at a machine. You have to reconstruct it from fragments, and that only works if you planned for it by threading the identifier through from the start.

Tracing answers the question of where a request spent its time. There are two other questions, and they need two other tools, and confusing the three is a common mistake.

Metrics answer whether something is wrong, and how much. They are numbers aggregated over time: requests per second, error rate, latency percentiles, the loop lag of Part I Chapter 15, the gauges of Chapter 1, the fan-out queue depth of Chapter 17. Metrics are cheap to collect and cheap to keep, and they are what you watch, on a dashboard or in an alert that fires when the error rate crosses a line. They tell you that the system is unhealthy and roughly where, but not why any single request was slow. Metrics are the smoke alarm.

Traces answer where, along this request’s path, the time or the error happened, which is the waterfall above. You reach for a trace once the metrics have told you that something is wrong, to find which hop is the problem. Traces are the map.

Logs answer what exactly happened at this point. A log is the detailed record a service writes, such as “user 91 not authorized for group 12”, with the actual error and the specific values. Logs have the detail that metrics and traces lack, but there are billions of lines of them and no structure across machines, which is why you do not start with logs. You start with a metric, which says something is wrong; you narrow with a trace, which says this service and this hop; and then you read the logs for that hop, for that trace ID, to see what went wrong. The trace ID ties them together. A good log line carries the trace ID, so that from a slow span you can jump straight to the log lines for that request on that machine.

Recording a span in every service for every request is a great deal of data. At millions of requests a second, across eleven services each, the traces alone could outweigh the real traffic, which is Chapter 16’s lesson again: your reactions to load are themselves load, and observability is a reaction. So you sample, keeping full traces for a fraction of requests, one in a thousand, say, which is enough to understand the system’s behaviour statistically without recording everything. The subtlety is that you usually want to keep the interesting ones, every error and every slow request, so the sampling is biased. You always trace failures and outliers and sample the boring successes. And the sampling decision has to be consistent across the whole request. Either all eleven services trace this request or none of them do, decided once at the gateway and carried in the same header as the trace ID, or you end up with useless partial traces. Metrics, being aggregates, are cheap and kept for everything; traces, being detailed, are sampled; logs are voluminous and increasingly sampled or aggregated as well. What you keep is a budget, and you spend it on what you are most likely to need.

Nothing new breaks in this chapter, since what it adds is the ability to see breakage rather than a way of causing it, but observability is now itself critical infrastructure, and it has failure modes of its own. A trace ID that is not propagated through some service leaves a hole in every trace that passes through it; a service that does not pass the header is invisible, and finding that out is a puzzle in itself. Sampling that is too aggressive means that the one request you needed was not kept. And the observability system is a dependency which, when it is down, leaves you blind at just the moment you are most likely to need it. An outage with no visibility is the nightmare, so the observability stack has to be more reliable than the thing it observes. There is a cost in discipline too. Every service and every team, in the sense of Chapter 13, has to propagate the trace ID and emit spans, or the trace has gaps. Observability is a property of the whole system, and one team’s omission blinds everyone downstream of it. So the eighteenth revision of Courtyard threads a trace ID through every call and reassembles the fragments of each request into traces, alongside metrics for detection and logs for detail, and accepts that observability is now critical infrastructure with which every service must cooperate, sampled to bound its cost, and built to outlive the system it watches.