Observability is three things, and logs are one

Answering “is checkout slower this week than last week” took forty minutes of grepping and produced a number nobody trusted. The system logged everything — forty gigabytes a day, every request, every query, every exception — and could not answer a question about a trend, because a log line is an event and a trend is an aggregate.

The symptom

$ zcat /var/log/app/2020-10-1*.gz | grep 'checkout' 
    | awk '{print $NF}' | sort -n | tail -1
8241

# eight seconds. once. and:
#   which day?          — the filename, roughly
#   how often?          — another pass
#   which percentile?   — a third
#   was it one customer? — the line does not say

$ du -sh /var/log/app/
412G	/var/log/app/

Every question requires a full scan of a large amount of compressed text, and each scan answers exactly one question. That is not a logging problem — the logs are fine — it is an attempt to compute aggregates from an event store.

Why it happens

Logging is the first thing any system gets and it works well enough for a long time. When a new question arrives the natural response is to log more, because logging is the tool that is already there — and every increment is individually reasonable.

What accumulates is a system where three different kinds of question are being answered by one mechanism that is well suited to one of them. Separating the three is not adding a tool; it is noticing which questions were being asked.

The fix

The three, and what each one cannot do

metrics  aggregates over time. cheap and bounded, and blind to
         any ONE request.   → "slower than last week?"
logs     discrete events with detail. expensive at volume, and
         not cheaply aggregated.  → "what happened to order 88104"
traces   one request across services. shows WHERE the time went,
         for sampled requests only.  → "why was THAT one 8s"

all three. a log line cannot be a metric, because counting
them means reading them all.

The cardinality distinction is what makes them genuinely different rather than three views of the same data. A metric has bounded cardinality by construction, which is why it can be stored for two years in a few gigabytes; a log line has unbounded detail, which is why it cannot.

Metrics, with labels chosen carefully

$histogram = $registry->getOrRegisterHistogram(
    'app',
    'http_request_duration_seconds',
    'request duration',
    ['method', 'route', 'status'],
    [0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10]
);

// the ROUTE, not the URL. /orders/{id}, never /orders/88104.
$histogram->observe(
    $durationSeconds,
    [$request->getMethod(), $route->uri(), (string) $response->getStatusCode()]
);

Using the route pattern rather than the path is the single most important decision here, and getting it wrong is how people end up with a Prometheus instance holding four million series. Every distinct label combination is a separate time series stored forever, so a label containing an order id is a series per order.

The bucket boundaries have to be chosen before any data exists and cannot be changed retroactively — a histogram re-bucketed loses its history. Choosing them around the thresholds that matter, rather than around a neat progression, is what makes the percentile queries useful later.

# the forty-minute question, in one line
histogram_quantile(0.95,
  sum(rate(app_http_request_duration_seconds_bucket{route="/checkout"}[5m]))
  by (le)
)

# and the comparison to last week, which grep cannot do at all
... offset 7d

Logs, reduced to what only logs can answer

// before: a line per request, per query, per cache hit
Log::info('checkout started', ['user' => $user->id]);
Log::info('cart loaded', ['items' => $cart->count()]);
Log::info('shipping calculated', ['ms' => $ms]);
Log::info('payment authorised', ['ref' => $ref]);

// after: one structured line at the boundary, plus
// anything genuinely exceptional
Log::info('checkout completed', [
    'trace_id' => $trace->id(),
    'order_id' => $order->id,
    'user_id'  => $user->id,
    'duration_ms' => $ms,
    'payment_ref' => $ref,
]);

The timing information moved to the metric and the per-step narration became a trace, which leaves the log doing what only it can — recording the specific facts about one business event, with the identifiers needed to answer a customer question.

The trace_id in the log line is the join between the three. A slow request shows in the metric, the trace shows which span was slow, and the log line for the same trace id has the order and customer — which is the workflow the separation is for.

$ du -sh /var/log/app/
38G	/var/log/app/      # was 412G, and retention went 14d → 90d

Traces, and the sampling decision

// the propagation is the whole mechanism: an incoming
// header, or a new root
$traceId = $request->header('X-Trace-Id') ?: bin2hex(random_bytes(16));

// and it goes out on every call this request makes
$client->request('POST', $url, [
    'headers' => [
        'X-Trace-Id'  => $traceId,
        'X-Parent-Id' => $spanId,
    ],
]);

Propagating the identifier is the part that has to be right everywhere; the collection and storage can be changed later. A service that drops the header breaks the trace at that point and produces two disconnected traces, which looks like two unrelated slow requests.

sampling, and why head-based is not enough:

  1% of everything   cheap. and the eight-second request is
                     almost certainly not in the 1%.
  100% of errors     requires deciding AFTER the request, so
  and of slow ones   spans must be buffered until it ends —
                     which is tail-based sampling.

what shipped: 1% head-based, a forced trace on a debug header,
and 100% on the two routes that mattered most.

Tail-based sampling is the right answer and it needs a collector holding spans in memory until a trace completes, which is infrastructure this system did not have in 2020. The compromise — a low baseline plus complete coverage on the routes that matter — is much cheaper and covers the actual investigations.

The forced-trace header is worth building early: it turns “reproduce it and I will look” into a single request with a header, and it needs a permission check so that it is not a way for anybody to make the system trace everything.

Verifying it worked

# the original question, answered in one query
$ curl -sG http://prometheus:9090/api/v1/query 
    --data-urlencode 'query=histogram_quantile(0.95, sum(rate(
      app_http_request_duration_seconds_bucket{route="/checkout"}[7d]
    )) by (le))' | jq -r '.data.result[0].value[1]'
1.84

# and the same, a week earlier
1.79

# cardinality, which is the thing that breaks this setup
$ curl -s http://prometheus:9090/api/v1/status/tsdb 
    | jq -r '.data.seriesCountByMetricName[:3][]'
{"name":"app_http_request_duration_seconds_bucket","value":3128}
{"name":"app_db_query_duration_seconds_bucket","value":712}

The series count is the metric to watch on the monitoring itself, and it deserves an alert. A deploy that adds a label containing something unbounded takes Prometheus from three thousand series to three million overnight, and the failure is the monitoring system running out of memory during an incident.

Forty minutes to one query is the outcome, and the second number — the week-earlier comparison — is the one that was previously impossible rather than merely slow.

What this costs

Three systems to run instead of one, and three places to look during an incident. That is a real cost and the mitigation is the trace_id join plus a dashboard that links out to both others, so that the workflow is one path rather than three searches.

The cardinality trap is the thing that will eventually cause an incident, because nothing in the code makes a bad label look bad — ['user_id' => $user->id] reads exactly like a good label. A lint rule over the metric registrations, and a hard limit configured in Prometheus, are worth more than the convention that nobody will remember under pressure.