Logs, metrics and traces: what each one tells you

You have drawn a design. Then the interviewer asks: "It is 8 pm and checkout is slow. How will you find out why?" Nobody can look inside a running system. You can only read what it writes down.

A weak answer is "I will add logs". A strong answer names three kinds of record and says what each one is good for. It says which numbers to watch first. It also says how you follow one request across many servers.

At SDE-1 level you should name the three kinds and one use of each. At SDE-2 level you should pick the numbers to watch and read the path of one request. At SDE-3 level you should also say what each kind costs and how you keep that cost low.

Think of a hospital. A nurse writes a note each time something happens to a patient: "10:05, medicine given". A monitor beside the bed shows numbers such as heartbeat and temperature, drawn as a line over time. When a patient moves from reception to the lab, the scan and the doctor, one ticket goes along. Each place writes on the ticket how long it kept the patient.

A running system has the same three records. Finding out what a system does, by reading these records, is called observability. The notes are logs. The monitor numbers are metrics. The ticket is a trace.

Logs: what exactly happened

A log is a record of one event, written when the event happens. One event is one line.

Old logs are free text, such as payment failed for user 42. A person can read this, but a program cannot search it well. A structured log writes each event as one line of JSON (a text format of names and values). Every line uses the same names:

{"time":"20:05:10.750","level":"WARN","service":"payment","request_id":"4bf92f35","msg":"payment provider slow","provider_ms":2650}

• level says how serious the event is. ERROR means something failed. WARN means something odd happened, but the work finished. INFO is a normal event. DEBUG is extra detail for developers, and it is usually off in the live system, because it writes too many lines.
• request_id is a request ID: a unique code made when the request arrives. Every line about that request carries it. A search for the code returns every line of one request.

Never write passwords, tokens or card numbers in a log. Many people can read logs.

Logs answer: what exactly happened to this request? They have two weak points. They grow with traffic, and they are slow to count.

Metrics: how much, how often

A metric is one number that you measure again and again, for example every 15 seconds, and store with its time. The list of values over time is a time series. There are three common kinds:

• A counter only goes up (it returns to zero when the program restarts). Examples: total requests, total errors. To get a rate, subtract two readings and divide by the seconds between them.
• A gauge goes up and down. Examples: memory in use, CPU busy percent, open connections.
• A histogram counts how many requests fall into each time range. A range is called a bucket: up to 200 ms, up to 500 ms, and so on. Each count includes all the faster requests. From these counts you find p95 and p99 (lesson 4). For p95, find the bucket that holds the 95th request of each 100.

To get the p95 of many servers, add their bucket counts, then read the p95. Do not average the p95 values of the servers.

A metric can have labels: names and values that split it, such as route=/checkout and status=500. Each different combination of label values is its own time series. Cardinality is the number of different series. Suppose there are 10 routes and 5 status codes: 10 x 5 = 50 series. Add a user ID label for 1,000,000 users: 50 x 1,000,000 = 50,000,000 series. Each series costs memory and disk. So do not use user IDs or request IDs as labels. Put them in logs.

Metrics answer: how much, how often, since when? Their size depends on the number of series, not on the number of requests. They cannot tell you which request failed or why.

The four golden signals

You can measure hundreds of things. Google's Site Reliability Engineering (SRE) book names four to watch on any service:

1. Latency: the time to answer a request. Measure successful and failed requests apart. A fast error looks good, but it is a failure. Use percentiles (lesson 4).
2. Traffic: how much demand the service gets, for example requests per second.
3. Errors: the share of requests that fail. Count clear failures (status 500). Count answers with status 200 but wrong content. Count requests that break your own rule, such as "slower than 1 second".
4. Saturation: how full the service is. Measure the most limited resource, for example CPU busy percent, or open connections against their limit.

Together they answer four questions. Is it busy? Is it failing? Is it slow? How close is it to its limit?

Traces: where did the time go

A trace is the record of one request's whole path through the system. It is made of spans. A span is one step of work. It has a name, a start time, a duration, and a parent: the step that called it. The first span has no parent and is called the root.

How can one record follow a request from server to server? The first service makes a trace ID, a unique code. It sends the code to every service it calls, in a request header (lesson 7). Each service writes its spans with the same code. This is context propagation. Use the same code as the request ID, so one search finds the trace and its logs.

The W3C standard header is traceparent. It looks like 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01. The parts are: the version, the trace ID, the ID of the calling span, and flags. The trace ID has 32 hex characters (the digits 0 to 9 and the letters a to f). The span ID has 16. The flag 01 means the caller may have recorded this trace. If one service does not pass the header on, the trace breaks into two parts.

To read a trace, find the span with the largest own time. Own time is the span's duration minus the durations of its child spans. This works when the children run one after another.

Tracing every request costs CPU, network and storage. So systems often keep only some traces. This is sampling. Head sampling decides at the start of the request, for example "keep 1 in 100". It is cheap, but it can drop a rare slow or failed request, because the outcome is not known yet. Tail sampling decides after the request ends, so it can keep every error and every slow request. It costs more, because the spans must wait in memory until the request ends.

The three work together. A metric shows that something is wrong. A trace shows which step is slow. A log line shows why. Tools do this work: Prometheus for metrics, and OpenTelemetry, a toolkit that creates and collects all three.

We use the food-ordering app of lesson 3. At 8 pm, users say that checkout is slow.

Assumptions (made up to teach with):

• The checkout service has 4 servers. In one minute it handled 12,000 requests. Of these, 180 failed with status 500.
• The request counter read 120,000 at 20:00:00 and 132,000 at 20:01:00.
• The goal is p99 under 1,000 ms.
• The histogram for this minute is in the table.
• The CPU of the 4 servers is 40% busy.
• The request counter has two labels: route (10 values) and status (5 values).
• Each request writes 3 log lines of 500 bytes. We use this rate for the whole day, to keep the arithmetic simple.

Step 1: the four signals, from metrics.

• Traffic: (132,000 - 120,000) / 60 = 12,000 / 60 = 200 requests per second.
• Errors: 180 / 12,000 = 0.015 = 1.5%.
• Latency: p50 is the 6,000th request, so it is in the first bucket: 200 ms or less. p95 is the 0.95 x 12,000 = 11,400th request. The 11,100 count is too small and 11,500 is enough, so p95 is between 500 and 1,000 ms. p99 is the 0.99 x 12,000 = 11,880th request. 11,800 is too small, so p99 is between 2,000 and 5,000 ms. The goal of 1,000 ms is broken. Also 12,000 - 11,500 = 500 requests, 500 / 12,000 = 4.2%, took more than 1 second.
• Saturation: CPU is 40%.

So checkout is failing and slow, and the servers are not the limit. The metrics do not show which step is slow.

Step 2: one slow request, from a trace. We find a request with duration_ms above 2,000 in the logs. Then we open its trace.

Own times:

• POST /checkout: 3,000 - (60 + 2,700 + 120) = 3,000 - 2,880 = 120 ms.
• charge payment: 2,700 - 2,650 = 50 ms.
• call payment provider: 2,650 ms, with no children. That is 2,650 / 3,000 = 88% of the request.

This answers the predict box. 120 ms is not inside any of the three steps. It is the root's own work and the small gaps between steps. We open the 2,700 ms step first, and then its child.

Step 3: the reason, from the logs. We search the request ID of this trace (shortened to 8 characters here):

{"time":"20:05:10.750","level":"WARN","service":"payment","request_id":"4bf92f35","msg":"payment provider slow","provider_ms":2650}
{"time":"20:05:11.000","level":"INFO","service":"checkout","request_id":"4bf92f35","status":200,"duration_ms":3000,"msg":"checkout done"}

The payment provider took 2,650 ms to answer. The cause is outside our servers.

Step 4: the cost of each record.

• Logs: 200 requests per second x 3 lines x 500 bytes = 300,000 bytes per second. 300,000 x 86,400 seconds = 25,920,000,000 bytes, about 26 GB a day.
• Traces, head sampling at 1%: 200 x 0.01 = 2 traces per second. Of the 180 failed requests in the minute, only about 1.8 are kept.
• Traces, tail sampling that keeps every failed request and every request over 1,000 ms: at most 180 + 500 = 680 per minute. It is fewer if some requests are both failed and slow. That is 680 / 12,000 = 5.7% of requests.
• Metrics: 10 x 5 = 50 series, whatever the traffic.

• Logs solve the question "what exactly happened to this request". They cost space that grows with traffic (about 26 GB a day here) and they are slow to count. I would keep log lines short and turn off DEBUG. I would change to sampling the routine lines if the volume costs too much.
• Metrics solve a cheap, quick view of the whole service. They cost all detail about one request, and they need few labels. I would change to logs or traces when the question is about one user or one request.
• Traces solve the question "which step is slow". They cost work in every service, because each one must pass the trace ID on. Sampling also means that some requests have no trace. I would change from head to tail sampling when rare errors matter more than the extra cost.

"Logs are enough. I can count errors by searching them." A counter gives the error rate in one subtraction. The same answer from 26 GB of log lines is slow and costly. Use metrics to count and logs to explain.

"The p95 of the whole system is the average of each server's p95." Server A handles 900 requests, all of 100 ms. Server B handles 100 requests, all of 1,000 ms. The two p95 values are 100 ms and 1,000 ms, and their average is 550 ms. The 1,000 requests together have 100 slow ones. The 950th request, which is the p95, takes 1,000 ms. Add the bucket counts instead.

"A trace appears by itself, and tracing every request is free." A service must pass the trace ID on. If one service does not, the trace breaks. Tracing every request costs work, so most systems sample.

1. Name the four golden signals. Which of logs, metrics and traces answers "which step of this request is slow"?
2. A histogram for 20,000 requests shows these counts. Up to 100 ms: 17,000. Up to 300 ms: 19,200. Up to 1,000 ms: 19,800. Up to 3,000 ms: 20,000. In which bucket are p95 and p99?
3. A teammate adds user_id as a label on the request counter. There are 20 routes, 4 status codes and 500,000 users. How many series is that? What do you do instead?