Lesson 026 · Phase 1, Foundations

Observability Basics: Logs, Metrics and Traces

What each of the three instruments throws away, why one label can delete a whole dashboard, and the number almost nobody draws that catches the outages the other numbers miss.

20 min read

Lesson 26 · 26 published · 90 planned

On this page
The systems in this lessonUsed here: Marlow Books, Stagefront, and Galewatch.

Made up for this course and reused from lesson to lesson so their numbers become familiar. None of them exist. All three

Marlow Books · A small online bookshop
Four people, one server and one Postgres database. About 40 requests a second on a normal day and ten times that in the week before Christmas. The one box that the early lessons stress until it breaks.
Stagefront · An event ticketing service
Quiet most of the time, then a stadium show goes on sale at 10:00 and two hundred thousand people press the same button in the same minute. Oversold seats are a lawsuit, so correctness matters as much as speed.
Galewatch · Telemetry for wind farms
Nine hundred turbines, a reading every two seconds, over links that drop for hours in bad weather and come back with a backlog. Dashboards that lag by seconds, reports that scan a year.

Marlow Books is a four person online bookshop that exists only in this course. In July its founder measured something properly for the first time, which is lesson 025's story, and liked it enough to want more. In August he added metrics to the shop.

It took an afternoon. Eleven counters, a latency histogram, five tidy graphs on one page, and a small managed service that fetched the numbers off every application process every fifteen seconds, which is what a scrape is. One of the counters was book_page_views_total, and because the interesting question about a bookshop is which books people read, he labelled it with the ISBN.

For ten days it was lovely. The counter carried about eighty thousand distinct ISBNs, which is what ten days of real customers reading real books comes to, and under a tenth of the catalogue.

The robot came back at twenty to eleven on a Saturday night.

You have met the search engine crawler twice. Lesson 008 clocked it at about forty distinct ISBNs a second while it evicted the bestsellers out of a 256 megabyte cache, and lesson 010 watched it discover 120,000 publisher page URLs over a weekend. It walks in bursts, and for those ten days it had been quiet. Forty a second into a catalogue of 1.2 million titles is thirty thousand seconds of walking, which is eight hours and twenty minutes: it started at 22:40 and it was done by seven on Sunday morning, and by then the counter had a series for every title in the shop. The content delivery network lesson 022 put in front of those pages is no help against a robot that asks each URL exactly once, which is lesson 022's finding at its extreme: a request with no second asker behind it cannot hit a cache anywhere.

A metrics endpoint renders every series as a line of text. book_page_views_total{isbn="9780140449136"} 3 is about sixty bytes with the newline. So:

1,200,000 series x 60 bytes  = 72 MB per process, per scrape
8 processes x 72 MB          = 576 MB every 15 seconds
576 MB / 15 s                = 38 MB/s, about 307 megabits

In words, since those three lines are the whole accident. The endpoint that had been serving five megabytes was serving seventy two. Lesson 006 put four application processes on each of Marlow's two boxes, so eight were being scraped, which is 576 megabytes of text every fifteen seconds, or 38 megabytes a second, sustained, to watch a shop that serves forty requests a second. The fastest transfer this shop has ever recorded is lesson 025's 73 megabytes a second, a base backup limited by the wire between two machines. The monitoring was on course to run at half of that, permanently, as background noise.

It never got the chance, because the scrape had a ten second timeout, and the endpoint never had to reach 72 megabytes to miss it. Three and a bit hours into the walk it was carrying half a million series, 29 megabytes to generate and ship inside ten seconds, and it stopped making it.

A scrape that times out does not store a partial reading. It stores nothing: not the ISBN counter, not the request rate, not the error count, not the histogram. One expensive question on that endpoint took every cheap question down with it, and the shop's brand new dashboard went blank at about two on the Sunday morning and stayed blank until Monday, when the founder assumed the monitoring service had broken and eventually found out that he had.

The memory was the quieter half: 1.2 million series at roughly 200 bytes of label text and counter apiece is 240 megabytes a process, a gigabyte on each box, and it went unnoticed only because lesson 005's resize had already bought 64 gigabytes. The one mercy of the weekend is that the scrapes stopped before most of those series ever reached the service, so the invoice for 1.2 million never arrived.

He deleted the label on Monday and the graphs came back in fifteen seconds.

And the question he had added it for, which books are popular, was answered that afternoon by one group by over the orders table: six years of the answer sitting there the whole time, answering the better version of the question. Bought, rather than looked at.

Three instruments, and what each one throws away

A log line is a record of one event with whatever context you chose to attach to it. Marlow's nginx access log is one: a line per request, with a path, a status, a byte count and a duration.

A metric is a number about a population, sampled over time. Requests a second. The 99th percentile of page latency. Bytes free on the volume.

A trace is one request's path through the system, with a timing for each step, stitched together because every hop passed along the same id.

The textbook stops there, with three tools for three jobs, and it leaves out the thing that actually decides which one you reach for. Each of the three is defined by what it discards, and the discarding is the point.

A metric discards which request. The moment you add 1 to a counter, the identity of the thing that caused it is gone forever, and that is exactly why a counter costs the same at forty requests a second as at four hundred. You bought the cheapness with the identity.

A log line discards the relationship between requests. Two lines written during the same page load look like two unrelated events, and they stay that way until somebody puts an id on both.

A trace keeps the relationship and discards most of the requests, because nobody can afford to keep them all.

So you pick an instrument by deciding what you can afford to forget, and the failure mode of each one is the thing it forgot. Marlow's older instruments read cleanly in that frame. Lesson 003's nine dollar uptime monitor fetches the home page once a minute from Singapore and throws away everything else, which is why it reported 99.99% for a December whose checkout-weighted number was 99.80%. Lesson 010's slow query log keeps one query and throws away the request it belonged to, which is why the buyers' reorder view, 201 queries and a hundred milliseconds of round trips, has never put a single line in it.

A metric is cheap until you label it

A log's cost is proportional to traffic and independent of detail. Marlow at forty requests a second is 3.5 million requests a day, so a 300 byte access line each is about a gigabyte a day. At the Christmas peak of 400 a second, if it held for a day, it is 34.6 million lines and ten gigabytes, and if you log every statement as well, lesson 010's reorder view multiplies its own share by 201.

A metric's cost runs the other way: independent of traffic, proportional to detail. Incrementing a counter ten million times stores no more than incrementing it once. What a metric costs is series, one stored time series per distinct combination of label values, and cardinality is how many of those combinations there are. Cardinality multiplies.

page_views_total{path, status, box}
   12 paths x 5 statuses x 2 boxes        = 120 series
   ... + isbn                              x 1,200,000

Twelve paths, five statuses and two boxes is a hundred and twenty series, which is nothing. Add the ISBN and you have multiplied it by 1.2 million. The shop only created the 1.2 million it actually saw, which is the merciful case and still enough to delete the dashboard.

So: a label's cost is the number of values it can take, not the number you expect to see. The founder expected a few thousand popular titles. The catalogue had an opinion, and the robot went and got it.

The labels that do this are all identifiers of one thing: an ISBN, a customer id, a session id, an order id, a URL with a query string in it, and the worst of the lot, an error message with a row id inside the text. Lesson 022 made this exact mistake one radius out, when April's newsletter put utm_source in the cache key and every link became an object nine edges had never seen. Same error, two instruments, and both times the fix was an allowlist rather than better judgment.

The test is short. If the question is about one identifiable thing, it is not a metrics question. It is a log line, a row in a table, or a query against data you already have.

The legitimate labels are the ones with a small, fixed set of values you could write on a napkin: the endpoint, the status class, the box. That last one earns its keep in a way that is easy to miss.

Every dashboard averages

Lesson 002 said set your alerts and targets on percentiles, never on averages, and that lesson owns the argument. What it could not say yet is where the averaging actually happens. Everybody looks at the time axis. It happens across the machines.

Go back to Marlow's February. Lesson 006 had box B's virtual disk degrade so that everything box B served went from about 4 milliseconds to 400, giving it a hard ceiling of 120 requests a second. Least connections found that ceiling on its own and settled box B at 120 while box A took the other 280, and lesson 006 signed off the incident with the shop staying up "at a slightly worse average".

Do the arithmetic that sentence skipped.

120 requests x 400 ms  =  48,000 ms
280 requests x   4 ms  =   1,120 ms
49,120 ms / 400 requests = 123 ms average

A hundred and twenty three milliseconds, fleet-wide, and not one box on the premises is anywhere near it. Box A is at 4 and box B is at 400. Thirty percent of requests are taking 400 milliseconds, so the median is 4 and the p75 is 400, which is a graph you would notice from another room. The average is the one number in the building that makes a half-dead fleet look mildly unwell, and it is what every default dashboard shows you, because a single line on a chart is an average by construction.

One label with two values fixes it. Split by box and box B's own median is 400 milliseconds, on its own line, screaming.

And you cannot average percentiles, which is why a metrics library hands you histogram buckets rather than a tidy p99 per box: to get the fleet's figure you add the buckets and find the percentile in the sum. Two p99s averaged together is a number with no definition.

The storage version is lesson 025's, so take it as placed. Galewatch, which collects a reading every two seconds from each of its wind turbines, spread four and a half terabytes over the sixteen machines lesson 013 sized: the average shard is 281 gigabytes and Kilmore Sands is 700. Buy identical machines able to hold the biggest shard and you have bought 11.2 terabytes to store four and a half. The fleet disk graph reads 40 percent full. The machine under Kilmore Sands is full. Graph the maximum of anything you buy per machine. The mean is the number nobody's machine has.

And then the one that is not about averaging at all. Lesson 024 left it here explicitly: one of Galewatch's eighteen machines goes quiet, nineteen farms answer perfectly, and the fleet roll-up shows nothing, because a scatter-gather, one query fanned out to every machine at once, finishes when its slowest leg does. An answer that does not say what it is missing is a lie with a chart on it. Put the denominator on the tile. Nineteen of twenty farms.

The same hole is in every metric you will ever graph, and it arrives in a smaller disguise: a missing measurement and a measurement of zero look identical on almost any graph, and they mean opposite things. Marlow's blank Sunday was not zero traffic. Lesson 021's 429 line, flat at zero for six and a half months, was not evidence that nobody was being refused. It was evidence that the line was drawn, and nobody could have told a working counter from one that had never been wired up.

The number nobody draws

Two shorthands cover most of what a service should be emitting.

RED, for a service: the request rate, the error rate, and the duration distribution, per endpoint. USE, for a resource: how utilised it is, how much work is queued behind it, and its error count. A pool, a disk, a CPU, a link.

RED is the customer's experience of your service. USE is a resource's experience of itself. The gap between them is where queueing lives, which is lesson 001's knee: a resource can be at 70% while the thing in front of it is already falling over, because what got worse was the waiting and not the work.

Now take Marlow's Sunday from lesson 010, the crawler weekend, and hold both frameworks against it. USE saw something: box A at 76% CPU across sixteen cores. RED had two of its three green: forty requests a second arriving, a quiet Tuesday's traffic, and every one of them returning 200. The third is duration, which would have been screaming and which nobody was measuring. And orders came in about a fifth below a normal Sunday, with no alert anywhere and the founder away from the laptop until a buyer messaged at 09:14 on Monday.

The one line that would have gone red is the one almost nobody draws.

Orders a minute. The shop has counted orders since the day it opened, in a table, with a timestamp on every row, so turning that into a graph is a count, a group by and about four minutes of work. It is the only instrument here that cannot be green while the product is broken, for the straightforward reason that it is the product.

Every system has one. Stagefront, the event ticketing service in this course where a stadium show goes on sale at exactly 10:00 and two hundred thousand people press the same button, has tickets confirmed a second. Galewatch has readings landed per farm per minute, which is also, neatly, what lesson 024's dead roll-up was supposed to show.

It gets skipped for an organisational reason rather than a technical one. CPU belongs to whoever runs the machines and latency to whoever wrote the service, while orders a minute belongs to nobody, so it lands on nobody's dashboard. At a four person shop both of those people are the same person, and it still did not get drawn.

The honest catch: you cannot threshold a business number, because it is seasonal and noisy and Sunday is not Tuesday. You compare it with the same hour last week instead, which is a harder graph to build and the one that would have caught a fifth of a Sunday on the Sunday.

A slow page made of fast queries

Lesson 010 named this problem and told you to count statements per request. This is the lesson that owns the instrument.

A trace works by generating an id at the edge, passing it down every call, and having each hop write a span: a name, a start, a duration, and which span it hangs off. The waterfall picture is what people remember. The valuable part is the id, because with it you can find every line belonging to one request across every machine that touched it, which is precisely the relationship a log throws away.

Now an opinion, and a slightly unfashionable one. Marlow has two boxes, one database and a queue. It does not need a tracing system and I would argue against installing one this year. What it needs is two more numbers on every access log line: how many statements that request ran, and how many milliseconds it spent waiting on Postgres. That is a trace one level deep, it costs an afternoon, and it is the difference between knowing and not knowing. The reorder view would have shown up as statements=201 db_ms=141 on a line the founder reads every week.

The full apparatus earns its money once a page is assembled from five services, because a duration per hop is then the only way to know which of the five to look at. Lesson 002 gave the reason it turns urgent: fan one page load out into sixty calls and a one in a hundred slow call becomes a coin flip. The slowest leg is the page, and nothing but a trace says which leg it was.

Sampling is the limit, and it is a real one. You keep one request in a hundred because you cannot afford to keep them all, and the path that disappears is the rare one. Lesson 024 put it better than I can: a partition invents no new failures, it takes the small numbers out of the ones you already had. Lesson 019 found seventeen December card charges with no order behind them. Seventeen events in a month, at one percent sampling, is an expected zero point one seven traces. You will never see them.

Which is why rare paths need an instrument of a different kind, and this course has been quietly building them. Lesson 018's job_runs table, one row per scheduled run, which turned eleven days of silence into five and a half hours. Lesson 019's idempotency_keys table and its committed pending rows, which turn a discrepancy that waits until January into a row a sweeper finds in two minutes. Lesson 012's heartbeat row, still not installed, which is what makes a lag graph stop lying at four in the morning.

The cheapest observability in this course has been a table. Not one of those is a monitoring product, every one of them is queryable a year later, and they exist because somebody wrote down that a thing was supposed to happen before it happened.

What an alert is for

Lesson 018 built the best alert in the course and derived it from a question nobody asks. Not "what value looks bad" but "how late may this be before somebody should be woken up". For Marlow's monthly publisher payout the answer is six hours, because a publisher waiting a day is annoyed and a publisher waiting eleven days is asking whether the shop is solvent. Set the check earlier than the deadline by however long a fix takes, and it lands at 06:00.

Generalise it and you have something to hold every alert against: a threshold should read back as a sentence about a person. Somebody has been waiting more than six hours for money. Somebody's email is more than ten minutes late, which is lesson 017's rule about alerting on the age of the oldest message rather than its depth, and age qualifies because it is denominated in the same unit as the promise.

Now hold lesson 001's alert up to that test: fire when traffic passes 120 requests a second. It is not a sentence about anybody. It was picked on the Friday the podcast nearly killed the shop, against a box that could serve about 200 pages a second, and Christmas week now runs at 400. So it fires all day, every day, for the one week of the year that matters, and nobody has looked at it in years.

Three alerts most systems lack, all of them from incidents in this course. Something is late, which needs a deadline written down beside the schedule. Something has stopped arriving, which no instrument inside the building can see, because lesson 018 is right that the absence of an event is not an event. Something is refusing people, with a meaning attached in advance, so that lesson 021's fifteen refusals a minute reads as an outage at 10:05 instead of at 11:20 after twelve hundred customers have already been turned away.

And fire each of them on purpose, once, before you need it. A signal that has never moved is untested, and you cannot tell a healthy zero from a disconnected wire by looking at it. That is lesson 025's argument about rehearsing a failover, at a much smaller radius and for a much smaller price.

Then the limit, which is the flattest thing here and the truest. An instrument you add after an incident answers last week's question. Marlow's monitoring is a museum of its own outages: an uptime monitor bought the month before the December it misreported, a slow query log from the Monday after the crawler, a lag graph from the replica, a job_runs table from the eleven days. Every one arrived a week late and every one was the right thing to build. The single exception is the one to notice. Lesson 017's age alert went onto the email queue when the queue did, before anything had gone wrong with it, and that is the instrument which caught a broken consumer in eleven minutes.

There is no way to get ahead of that by adding more instruments, because the next failure is in the part you have not thought about. What you can do is instrument shapes rather than incidents, which means rate, errors and duration for every endpoint, utilisation and queueing for every resource you pay for, one business counter, a denominator on every rolled-up tile, and an id on every log line so that any two of them can be joined later.

You will still be blind to the next one. The number that says whether your monitoring is any good is not how many dashboards you have. It is how long the last five incidents took to notice, and at Marlow that figure runs from ten minutes to eleven days.

Recap

Each instrument is defined by what it throws away. A metric throws away which request, and buys its cheapness with that: a counter costs the same at 400 requests a second as at 40. A log line throws away the relationship between requests until you put an id on them. A trace keeps the relationship and throws away most requests. Pick by deciding what you can afford to forget.

A log's cost follows traffic; a metric's cost follows cardinality. A gigabyte a day of access lines at 40 requests a second, ten at 400, while a counter stores nothing extra however often you increment it. What it stores is one time series per distinct combination of label values, so a label's cost is the number of values it can take, not the number you expect to see, and the values multiply. An ISBN took Marlow from 120 series to 1.2 million, and because a timed-out scrape stores nothing at all, one expensive question deleted every cheap one beside it.

Every dashboard averages, and it averages across machines. Marlow's February pair ran at 4 milliseconds and 400 and reported 123, a figure no box in the building was anywhere near. One label with two values fixes it. Percentiles cannot be averaged; add the histogram buckets and find the percentile in the sum. For anything bought per machine, graph the maximum, because the mean is the number nobody's machine has.

A missing measurement and a measurement of zero look identical, and mean opposite things. Blank graphs are not quiet traffic and a flat 429 line is not a shop refusing nobody. Put the denominator on every rolled-up tile, because an answer that does not say what it is missing is a lie with a chart on it.

RED for a service, USE for a resource, and one number for the product. Rate, errors and duration per endpoint; utilisation and queueing per resource; and the thing the business already counts, which at Marlow is orders a minute. That one would have caught a Sunday running a fifth light while every request returned 200 and the CPU sat at 76%, and it is the only instrument that cannot be green while the product is broken. Compare it with the same hour last week rather than thresholding it.

A slow page is usually made of fast queries. Two hundred and one queries at a fifth of a millisecond never trip a slow query log set at 200, which is why the instrument is a statement count and a database time on every request, and why a trace's id matters more than its waterfall. Sampling erases rare paths, so rare paths get a row instead: the cheapest observability in this course has been a table.

An alert comes from a tolerance, not from a number somebody liked. Ask how late this may be before a human should be woken, then subtract the length of a fix. Marlow's payout is six hours and the check is at 06:00. Fire every alert once on purpose, because a signal that has never moved is untested. And accept that an instrument added after an incident answers last week's question, so instrument the shapes and judge yourself on how long the last five took to notice.

Check your understanding

  1. Support asks for a customer_id label on Marlow's request counter so they can see one customer's errors. Using lesson 007's figures, work out roughly how many series that creates and say what you would build instead.

  2. Suppose the crawler had walked the catalogue at four distinct ISBNs a second rather than forty. Work out how long the walk takes, when the scrape starts failing relative to the founder's working day, and whether the slower robot makes the incident better or worse.

  3. Stagefront sells out a stadium show in the ten minutes after 10:00. Name one RED metric, one USE metric and one business number for those ten minutes, and for each say what value would make you stop the sale.

  4. Galewatch's fleet roll-up is a scatter-gather over eighteen machines. Design the tile: say what it shows when all eighteen answer, when one is missing and when six are missing, and which of the three should page somebody.

  5. Take a service you have worked on and write the deadline for one scheduled job in it, in hours, as a sentence about a person. Then say what the alert currently fires on and how far apart the two are.

Next lesson

027 Failure Is Normal: Designing for Partial Outages. Today was about seeing which part of a system is broken while the rest of it works; next lesson is about building the thing so that the working part keeps taking money, and deciding in advance which features are allowed to disappear.

Finished reading?

Marking a lesson done keeps your place on the course index. It is stored only in this browser.

Tip: use the ← and → keys to move between lessons.