Topic 38

Why Tracing

Tracing

A checkout request at Harborline touches five processes before the customer sees a confirmation. web terminates the browser call, bookings reserves the seat against db-01, checks the session in cache-01, and calls payments, which talks to the card processor. When that request takes 9 seconds, the question is not whether it was slow — Chapter 5's histogram already says so — but where the time went across those hops, and neither metrics nor logs can answer it.

A trace is the record of one request's full path, timed at every boundary it crosses. This chapter builds that third signal for Harborline, and by its last topic the trace exists that ends the Saturday mystery. First, the case for why the two signals you already have cannot do the job.

One Request, Five Services

Walk the checkout path once, slowly: the browser hits web, web calls bookings on port 8000, and bookings fans out mid-request — a session lookup in cache-01, an INSERT into db-01, then a synchronous call to payments on 8002. That is five network boundaries inside one user-visible operation, and every one of them is a place latency can hide. The rule that makes this hard: a caller's duration is the sum of its own work plus every downstream wait, so bookings reporting 9 seconds tells you the time passed through bookings, not that bookings spent it.

The Structural Blindness of Metrics

Metrics are aggregates. harborline_checkout_duration_seconds says the p99 hit 9 s on Saturday morning, which is exactly what a histogram is for — but the histogram earned its cheapness by throwing the individual request away at observation time. There is no bucket you can open to find the one checkout that took 9,310 ms; there are only counts of how many requests landed in each latency range.

Slicing by job does not rescue you. Each service self-reports latency that includes its downstream waits, so bookings at 9 s and payments at 190 ms is consistent with the problem living in bookings code, in the network, in db-01, or in cache-01 — the aggregate cannot say which hop inside one request ate the budget. Per-service latency panels look like request visibility and are not.

The Structural Blindness of Logs

Logs have the opposite problem: full detail, no connective tissue. On the slow Saturday, the two most relevant lines in Loki look like this — and even with the shared request_id joining them, nothing in them says who waited on whom, or for how long.

# bookings, on app-01
{"ts":"09:12:41.310","svc":"bookings","request_id":"c81f","msg":"checkout completed","duration_ms":9310}
# payments, on app-02
{"ts":"09:12:41.170","svc":"payments","request_id":"c81f","msg":"charge ok","duration_ms":190}

Reconstructing the path by timestamp fails precisely when you need it. At 200 concurrent checkouts the lines from every request interleave, and the clocks on app-01 and app-02 drift enough that "the payments line nearest in time" is routinely a different customer's charge. Chapter 7 gave each line rich local detail and a shared request_id; what the lines still lack is timing structure — parent, child, and where the clock ran.

The Trace

A trace renders one request as a timed tree: a root span covering the whole checkout, and a child span for every downstream call — the cache-01 lookup, the db-01 INSERT, the payments charge. Laid out as a waterfall, the 9,310 ms total decomposes visually, and 9,020 ms of it sits in a single bar inside bookings. The "where did the time go" question is answered by construction, not by correlation: the tree structure is recorded when the request runs, so there is nothing to reconstruct afterward.

The Third Signal's Question

This completes the book's division of labor. Metrics say something is wrong — cheap, aggregated, alertable. Logs say what happened at that moment — one event, full detail. Traces say where in the request path it happened — one request, timed across every service it touched. Traces are also the most expensive signal per request, which is why Topic 42 exists to control that bill; you pay the premium because they answer the question the cheap signals structurally cannot.

What each signal structurally sees
Metrics
That something is wrong. Aggregated counts — the p99 hit 9 s — cheap and alertable, but the individual request is discarded at observation time.
Logs
What happened at one moment. Full local detail per line, but no shared identity to tie five services' lines to the same request.
Traces
Where in the path the time went. One request timed at every boundary — answering by construction what the other two cannot.

The Saturday Mystery, One Signal Short

Take stock of where seven chapters have left Mara. Chapters 5 and 6 proved the complaint real: weekend checkout p99 breaches the 500 ms target, visibly, on a dashboard. Chapter 7's logs named the error — connection pool timeout — but not where the time went inside each request; plenty of slow checkouts still complete, just late. She has when and how bad. She does not have where, and this chapter builds the signal that finishes the job.

Common Mistakes
  • Reconstructing request flow by grepping timestamps across five services' logs — at 200 concurrent checkouts the lines interleave, app-01 and app-02 clocks drift, and the "match" you find is a different customer's request.
  • Adding per-service latency panels and calling it request visibility — each service self-reports time that includes its downstream waits, so bookings at 9 s and payments at 180 ms still doesn't say whether the 9.1 s gap is bookings code, the network, or a queue.
  • Logging entry/exit lines with durations in every service as a homemade trace — you rebuild tracing badly, pay Loki for every request at 100% retention, and still reconstruct parent-child timing by hand from timestamps that skew across hosts.
  • Expecting traces to replace metrics for alerting — traces are sampled and per-request, so computing a p99 or an error ratio from them is slow and incomplete; the alert (Chapter 9) stays on the metric.
Best Practices
  • Reach for a trace when the question contains "across" — across services, across a queue, across a retry — and keep single-service questions on metrics and logs, which are cheaper to store and query.
  • Instrument the request path end to end before trusting any trace — a trace that covers only bookings shows one span and answers nothing about the payments hop.
  • Keep the three signals joined by shared identity — service.name matching the Prometheus job label, and the trace_id written into every log line — so Topic 43's metric-to-trace-to-logs jump works without re-typing timestamps.
  • Start tracing on the highest-value path first: Harborline traces checkout before search, because checkout latency is money and the Saturday mystery lives there.
Comparable toolsSaaS Datadog APM / New Relic / Dynatrace — the cross-service view as flagship productAWS X-Ray — the AWS-native equivalentErrors Sentry — traces requests from the error-tracking sideOpen source Jaeger & Zipkin — the lineage this chapter builds on

Knowledge Check

Saturday's p99 for harborline_checkout_duration_seconds shows 9 s. Why can't the histogram say where those 9 seconds went?

  • Histograms track averages, so tail latency like a 9 s request is invisible to them
  • Aggregation discarded the individual request; only bucket counts remain
  • The 15 s scrape interval is too coarse to capture a request that only took 9 s
  • Prometheus silently drops observations that exceed the largest bucket boundary

Why does matching log lines across services by timestamp fail as a way to reconstruct one request's path?

  • Loki stores lines out of order, which makes timestamps unreliable at query time
  • Log timestamps are truncated to whole seconds, too coarse to match on
  • Concurrent requests interleave and clocks drift between hosts
  • Each service logs in its own timezone and the conversion loses precision

Mara needs to know whether a 9 s checkout spent its time in bookings code, in the payments call, or waiting on db-01 — within that one request. Which signal answers this?

  • Per-service p99 latency panels, compared side by side
  • The bookings error logs, filtered to the slow minute
  • A trace of that request
  • A per-service request counter sliced by job

For the same checkout, payments reports 190 ms while bookings reports 9.2 s. What explains the gap?

  • Network latency between app-01 and app-02 accounts for the missing time
  • bookings' self-reported duration includes all its downstream waits
  • payments drops its slowest requests from the histogram, hiding its real latency
  • Clock skew between the hosts inflates the bookings measurement

You got correct