Logs, metrics and traces: what each answers

When something goes wrong in production, you ask three kinds of question, and each kind of telemetry answers one of them well. Metrics answer how much and how often: how many requests arrive each second, what share of them fail, how long the slowest 1 % take. They are numbers kept over time, cheap enough to store for months and to alert on. Logs answer what exactly happened: one record per event, with the order ID, the error and the input that caused it. Traces answer where the time went: one request followed through every service it touched, as a tree of timed steps called spans. A trace ID travels with each request in the traceparent header and is written into every log line, and that shared ID lets you move from an alert to the slow service to the exact error.

This lesson builds all three into a small checkout system that you can run, follows one request through four services, and then counts what the two biggest cost levers, metric labels and trace sampling, do to the bill.

Three questions, three signals

OpenTelemetry, an open-source framework for producing and collecting telemetry, calls these outputs signals. It supports traces, metrics and logs, plus baggage, a set of key-value pairs passed along with a request (OpenTelemetry signals).

A metric is a number measured over time: a counter of requests that only goes up, a gauge such as the length of a queue, or a histogram that sorts request durations into buckets. Its cost depends on how many separate series it has, not on how much traffic it sees: a counter incremented a million times a second is still one number per series each time it is collected.

A log is a record of one event, written when it happens. Its strength is detail, because any field the code knows at that moment can go in, and its weakness is cost, because every request can write lines.

A trace is the path of one request through the system. Each service records at least one span, one timed operation with a name, a start and an end, the ID of its parent span and attributes. Spans that share a trace ID form one tree whose root has no parent (OpenTelemetry traces). A trace records every hop of a request, and keeping one for every request is expensive, which is why traces are usually sampled.

You rarely use one on its own. The usual path through an incident runs through all three: an alert on a metric fires, a trace from the bad minutes shows which hop is slow or failing, and the log lines that carry that trace’s ID say why.

One checkout through four services

The thread that ties the services together is the traceparent header of W3C Trace Context, a W3C Recommendation and the format OpenTelemetry propagates by default (context propagation). A value of version 00 has four fields separated by dashes: the version, a trace ID of 32 lowercase hexadecimal digits, a parent ID of 16 (the span ID of the caller), and two digits of flags whose lowest bit says whether the caller recorded the trace. IDs made only of zeros are invalid, and a receiver that finds an invalid header ignores it and starts a new trace. Every service sends the header on to the services it calls, with the same trace ID and its own span ID as the new parent ID (Trace Context).

The program below runs a checkout through a gateway, an orders service, an inventory service and a payments service, all in one process with a simulated clock, so it prints the same on every run. Each service handles a request the same way: it continues the trace from the incoming header or starts one, does its work, then records a span, updates two metrics and writes a JSON log line. Nine checkouts go through. One is slow, one fails because the card network never answers, and one comes from a client that sends a broken header.

// One checkout passes through four services: a gateway, an orders service, an inventory
// service and a payments service. Each one continues the caller's trace from the traceparent
// header (W3C Trace Context), records a span, writes JSON log lines and updates its RED metrics:
// a request counter by route and status code, and a duration histogram. A seeded random
// generator and a simulated clock make every run print the same.

let seed = 7;
function random() {
  // mulberry32: a small seeded generator, so IDs and timings repeat on every run
  seed = (seed + 0x6d2b79f5) | 0;
  let t = Math.imul(seed ^ (seed >>> 15), 1 | seed);
  t = (t + Math.imul(t ^ (t >>> 7), 61 | t)) ^ t;
  return ((t ^ (t >>> 14)) >>> 0) / 4294967296;
}
function randomHex(bytes) {
  let out = '';
  while (out.length < bytes * 2) out += Math.floor(random() * 256).toString(16).padStart(2, '0');
  return /^0+$/.test(out) ? randomHex(bytes) : out; // an ID of all zeros is invalid
}
const between = (lo, hi) => lo + Math.round(random() * (hi - lo));

let now = 0; // simulated milliseconds since the first request
const work = (ms) => {
  now += ms;
};

// ---- context: the traceparent header (version 00) ----------------------------------------
const TRACEPARENT = /^00-([0-9a-f]{32})-([0-9a-f]{16})-([0-9a-f]{2})$/;
function parseTraceparent(value) {
  const m = TRACEPARENT.exec(value ?? '');
  if (!m || /^0+$/.test(m[1]) || /^0+$/.test(m[2])) return null;
  return { traceId: m[1], parentId: m[2] };
}

// ---- the three signals ----------------------------------------------------------------------
const spans = [];
const logLines = [];
const requestCounts = new Map(); // "service route code" -> count
const BOUNDS = [0.005, 0.01, 0.025, 0.05, 0.075, 0.1, 0.25, 0.5, 0.75, 1, 2.5, 5, 7.5, 10]; // seconds
const histograms = new Map(); // "service route" -> { buckets, sum, count }

function log(level, span, msg, fields = {}) {
  logLines.push({ t_ms: now, level, service: span.service, msg, trace_id: span.traceId, span_id: span.spanId, ...fields });
}
function count(service, route, code) {
  const key = `${service}\t${route}\t${code}`;
  requestCounts.set(key, (requestCounts.get(key) ?? 0) + 1);
}
function observe(service, route, seconds) {
  const key = `${service}\t${route}`;
  const h = histograms.get(key) ?? { buckets: BOUNDS.map(() => 0), sum: 0, count: 0 };
  BOUNDS.forEach((le, i) => {
    if (seconds <= le) h.buckets[i] += 1;
  });
  h.sum += seconds;
  h.count += 1;
  histograms.set(key, h);
}

// Every service handles a request the same way: continue or start the trace, do the work
// (which may call other services with a new traceparent), then record span, metrics and a log.
function serve(service, route, headers, handler) {
  const parent = parseTraceparent(headers.traceparent);
  const span = { service, route, traceId: parent ? parent.traceId : randomHex(16), spanId: randomHex(8), parentId: parent ? parent.parentId : null, start: now };
  if (headers.traceparent !== undefined && !parent) log('warn', span, 'invalid traceparent, started a new trace', { received: headers.traceparent });
  const outgoing = { traceparent: `00-${span.traceId}-${span.spanId}-01` };
  const code = handler(outgoing, span);
  span.end = now;
  span.code = code;
  spans.push(span);
  count(service, route, code);
  observe(service, route, (span.end - span.start) / 1000);
  log(code >= 500 ? 'error' : 'info', span, 'request finished', { route, code, duration_ms: span.end - span.start });
  return code;
}

function payments(headers, outcome, orderId) {
  return serve('payments', 'POST /charges', headers, (out, span) => {
    if (outcome === 'fail') {
      work(2000); // the card network never answers; the client gives up after 2 s
      log('error', span, 'card network timed out', { order_id: orderId, timeout_ms: 2000 });
      return 504;
    }
    work(outcome === 'slow' ? between(1150, 1250) : between(25, 45));
    return 201;
  });
}
function inventory(headers) {
  return serve('inventory', 'POST /reservations', headers, () => {
    work(between(8, 14)); // reserve the items in the cart
    return 201;
  });
}
function orders(headers, outcome) {
  return serve('orders', 'POST /orders', headers, (out) => {
    const orderId = `o-${randomHex(3)}`;
    work(between(3, 5)); // check the cart
    if (inventory(out) !== 201) return 409;
    const charged = payments(out, outcome, orderId);
    work(2);
    return charged === 201 ? 201 : 502;
  });
}
function gateway(headers, outcome) {
  return serve('gateway', 'POST /checkout', headers, (out) => {
    work(between(1, 2)); // check the session
    const code = orders(out, outcome);
    work(1);
    return code;
  });
}

// Nine checkouts: one slow, one failed, and one from a client that sends a broken header.
const plan = ['ok', 'ok', 'slow', 'ok', 'ok', 'fail', 'ok', 'ok', 'ok'];
plan.forEach((outcome, i) => {
  now = i * 3000;
  const headers = i === 8 ? { traceparent: `00-${'0'.repeat(32)}-${randomHex(8)}-01` } : {};
  gateway(headers, outcome);
});

// ---- 1. metrics: is something wrong, and how much? ---------------------------------------
console.log('== 1. Metrics (Prometheus text format) ==');
console.log('# TYPE http_server_requests_total counter');
const ORDER = ['gateway', 'orders', 'inventory', 'payments'];
const rows = [...requestCounts].map(([key, n]) => [...key.split('\t'), n]);
rows.sort((a, b) => ORDER.indexOf(a[0]) - ORDER.indexOf(b[0]) || a[2].localeCompare(b[2]));
for (const [service, route, code, n] of rows) {
  console.log(`http_server_requests_total{service="${service}",route="${route}",code="${code}"} ${n}`);
}
console.log('# TYPE http_server_request_duration_seconds histogram');
const g = histograms.get('gateway\tPOST /checkout');
const labels = 'service="gateway",route="POST /checkout"';
BOUNDS.forEach((le, i) => console.log(`http_server_request_duration_seconds_bucket{${labels},le="${le}"} ${g.buckets[i]}`));
console.log(`http_server_request_duration_seconds_bucket{${labels},le="+Inf"} ${g.count}`);
console.log(`http_server_request_duration_seconds_sum{${labels}} ${g.sum.toFixed(3)}`);
console.log(`http_server_request_duration_seconds_count{${labels}} ${g.count}`);

// ---- 2. traces: where did the time go in the slowest checkout? ---------------------------
const roots = spans.filter((s) => s.parentId === null);
const slowest = roots.filter((s) => s.code < 500).reduce((a, b) => (b.end - b.start > a.end - a.start ? b : a));
const total = slowest.end - slowest.start;
console.log(`\n== 2. Trace ${slowest.traceId} (the slowest successful checkout) ==`);
console.log('span                              starts at   lasts  own time');
const trace = spans.filter((x) => x.traceId === slowest.traceId).sort((a, b) => a.start - b.start);
const depth = (s) => (s.parentId === null ? 0 : 1 + depth(trace.find((p) => p.spanId === s.parentId)));
for (const s of trace) {
  const children = trace.filter((c) => c.parentId === s.spanId).reduce((sum, c) => sum + (c.end - c.start), 0);
  const own = s.end - s.start - children;
  const name = `${'  '.repeat(depth(s))}${s.service} ${s.route}`.padEnd(32);
  const share = `${Math.round((own / total) * 100)} %`.padStart(5);
  console.log(`${name}${String(s.start - slowest.start).padStart(6)} ms${String(s.end - s.start).padStart(6)} ms${String(own).padStart(6)} ms ${share}`);
}

// ---- 3. logs: what exactly happened in the failed checkout? ------------------------------
const failed = roots.find((s) => s.code >= 500);
console.log(`\n== 3. Error lines with trace_id ${failed.traceId} (the failed checkout) ==`);
for (const line of logLines.filter((l) => l.trace_id === failed.traceId && l.level === 'error')) console.log(JSON.stringify(line));

// ---- 4. an edge case: a header that breaks the rules --------------------------------------
console.log('\n== 4. Warnings ==');
for (const line of logLines.filter((l) => l.level === 'warn')) console.log(JSON.stringify(line));

== 1. Metrics (Prometheus text format) ==
# TYPE http_server_requests_total counter
http_server_requests_total{service="gateway",route="POST /checkout",code="201"} 8
http_server_requests_total{service="gateway",route="POST /checkout",code="502"} 1
http_server_requests_total{service="orders",route="POST /orders",code="201"} 8
http_server_requests_total{service="orders",route="POST /orders",code="502"} 1
http_server_requests_total{service="inventory",route="POST /reservations",code="201"} 9
http_server_requests_total{service="payments",route="POST /charges",code="201"} 8
http_server_requests_total{service="payments",route="POST /charges",code="504"} 1
# TYPE http_server_request_duration_seconds histogram
http_server_request_duration_seconds_bucket{service="gateway",route="POST /checkout",le="0.005"} 0
http_server_request_duration_seconds_bucket{service="gateway",route="POST /checkout",le="0.01"} 0
http_server_request_duration_seconds_bucket{service="gateway",route="POST /checkout",le="0.025"} 0
http_server_request_duration_seconds_bucket{service="gateway",route="POST /checkout",le="0.05"} 1
http_server_request_duration_seconds_bucket{service="gateway",route="POST /checkout",le="0.075"} 7
http_server_request_duration_seconds_bucket{service="gateway",route="POST /checkout",le="0.1"} 7
http_server_request_duration_seconds_bucket{service="gateway",route="POST /checkout",le="0.25"} 7
http_server_request_duration_seconds_bucket{service="gateway",route="POST /checkout",le="0.5"} 7
http_server_request_duration_seconds_bucket{service="gateway",route="POST /checkout",le="0.75"} 7
http_server_request_duration_seconds_bucket{service="gateway",route="POST /checkout",le="1"} 7
http_server_request_duration_seconds_bucket{service="gateway",route="POST /checkout",le="2.5"} 9
http_server_request_duration_seconds_bucket{service="gateway",route="POST /checkout",le="5"} 9
http_server_request_duration_seconds_bucket{service="gateway",route="POST /checkout",le="7.5"} 9
http_server_request_duration_seconds_bucket{service="gateway",route="POST /checkout",le="10"} 9
http_server_request_duration_seconds_bucket{service="gateway",route="POST /checkout",le="+Inf"} 9
http_server_request_duration_seconds_sum{service="gateway",route="POST /checkout"} 3.661
http_server_request_duration_seconds_count{service="gateway",route="POST /checkout"} 9

== 2. Trace 8191296535d0dcbca8fd9bbcf47d3a95 (the slowest successful checkout) ==
span                              starts at   lasts  own time
gateway POST /checkout               0 ms  1245 ms     2 ms   0 %
  orders POST /orders                1 ms  1243 ms     6 ms   0 %
    inventory POST /reservations     5 ms    10 ms    10 ms   1 %
    payments POST /charges          15 ms  1227 ms  1227 ms  99 %

== 3. Error lines with trace_id b1d5092eb7e448d7a452181bfdb14184 (the failed checkout) ==
{"t_ms":17014,"level":"error","service":"payments","msg":"card network timed out","trace_id":"b1d5092eb7e448d7a452181bfdb14184","span_id":"4858cbd2ddc6b5dd","order_id":"o-2b8413","timeout_ms":2000}
{"t_ms":17014,"level":"error","service":"payments","msg":"request finished","trace_id":"b1d5092eb7e448d7a452181bfdb14184","span_id":"4858cbd2ddc6b5dd","route":"POST /charges","code":504,"duration_ms":2000}
{"t_ms":17016,"level":"error","service":"orders","msg":"request finished","trace_id":"b1d5092eb7e448d7a452181bfdb14184","span_id":"e10708f0eb7b93b4","route":"POST /orders","code":502,"duration_ms":2015}
{"t_ms":17017,"level":"error","service":"gateway","msg":"request finished","trace_id":"b1d5092eb7e448d7a452181bfdb14184","span_id":"12846dc729bd2b3d","route":"POST /checkout","code":502,"duration_ms":2017}

== 4. Warnings ==
{"t_ms":24000,"level":"warn","service":"gateway","msg":"invalid traceparent, started a new trace","trace_id":"619d3f106639c329521855efe395badc","span_id":"033235697627745e","received":"00-00000000000000000000000000000000-62c5465ea9c38abd-01"}

Read the output in the order an engineer on call would:

1. The metrics say that something is wrong, and roughly where. One checkout in nine ended with a 502 at the gateway, matching one 502 from orders and one 504 from payments. The duration histogram, in the text format Prometheus collects, counts each request in every bucket whose upper bound le it fits under (exposition formats): seven checkouts took 75 ms or less and two between 1 and 2.5 seconds. The mean, 3.661 ÷ 9 ≈ 0.41 seconds, describes none of the nine.
2. The trace says where the time went. In the slowest checkout that succeeded, payments spent 1,227 of the 1,245 ms, while the gateway and orders spent 2 and 6 ms of their own. A span’s own time is its duration minus the time spent in its children, so the span with the largest own time is the place to look.
3. The logs say what happened. The error lines that carry the failed checkout’s trace ID include the one in which payments recorded that the card network timed out after 2,000 ms, with the order ID. That order ID sits in a log line, where it costs one field, and in no metric label, where it would create a series for every order.
4. The edge case. A client sent a trace ID made only of zeros. The gateway ignored the header, as the standard requires, started a new trace and logged what it had received, so the broken client can be found.

Logs that a program can search

A structured log line is a set of named fields, usually one JSON object per line, rather than a sentence meant for a person. A query can then ask for level equal to error and service equal to payments within one minute instead of matching text, and a field that is missing is plain to see. In the example, t_ms stands in for the time because the clock is simulated; a real service writes the full UTC time.

Every line should say when it happened (in UTC, with the time zone written down), where (the service and its version), what (a level and a short message), and in which context (the trace ID and the span ID). OpenTelemetry’s log data model has a field for each, with TraceId and SpanId taken from W3C Trace Context beside the timestamp, the severity and the body (logs data model). Two rules keep logs from becoming a liability:

• Keep secrets and personal data out. OWASP’s logging cheat sheet lists what should usually not be written to a log directly, among them passwords, session identifiers, access tokens, encryption keys, database connection strings, payment card data and sensitive personal data, which are removed, masked or hashed first (OWASP).
• Encode what users send. A value with a line break inside can forge an extra line in a plain-text log. JSON writes the break as \n inside a string, and OWASP asks for carriage returns and line feeds in event data to be sanitised before they reach a log.

Logs are also the signal whose cost follows traffic most directly. Suppose a checkout system serves 2,000 requests a second and each of four services writes one 400-byte line per request: 2,000 × 4 × 400 bytes is 3.2 MB a second, or about 276 GB a day (3.2 MB × 86,400 seconds). Kept for 30 days, that is about 8.3 TB before compression, for a single line per service per request. One debug line inside a loop multiplies it again, which is one reason production services often log at the info level or above. Prometheus’s instrumentation guide suggests pairing each line of logging code with a counter, so a dashboard can show how often an interesting message appears without a search through the logs (Prometheus instrumentation).

Metrics: counters, histograms and the RED method

Prometheus, an open-source monitoring system and time-series database, defines four metric types (metric types):

• A counter only goes up, and resets to zero when the process restarts, so what you read from it is its rate: requests per second, errors per second.
• A gauge goes up and down: the length of a queue, the memory in use, the connections open now.
• A histogram counts observations into buckets, each with an upper bound le, and keeps their sum and count. Percentiles are estimated from the buckets, and the histograms of many instances can be added together when their buckets match.
• A summary computes quantiles inside each process. Quantiles cannot be averaged or added across instances, so Prometheus advises a histogram whenever you will need to aggregate (histograms and summaries).

Which metrics to start with has two well-known answers. The RED method, created by Tom Wilkie, asks for three numbers for every service: the rate of requests, the errors among them and the duration they take (Rate, Errors, Duration) (RED method). The USE method of Brendan Gregg asks for three for every resource, such as a processor, a disk or a connection pool: its utilisation, its saturation and its errors (USE method). The four golden signals of Google’s SRE book, latency, traffic, errors and saturation, are RED with saturation added. The book also advises measuring the latency of failed requests apart from that of successful ones, since a flood of fast failures can make latency look better than it is (SRE book).

Names and units follow conventions that make metrics comparable. Prometheus asks for base units such as seconds and bytes, a unit suffix, and _total at the end of a counter’s name (naming). OpenTelemetry’s semantic conventions define the duration of an HTTP request on the server as a histogram in seconds, with 14 recommended bucket boundaries from 5 ms to 10 s, and require its http.route attribute to be the low-cardinality route template, never the raw path (HTTP metrics).

The bucket boundaries decide what a histogram can tell you exactly. It gives the precise share of requests that finished within 300 ms only if 0.3 seconds is one of its boundaries; otherwise the answer is interpolated, and a healthy service can look close to missing its objective (histograms and summaries). The recommended boundaries include 0.25 and 0.5 but not 0.3, so a service whose objective is 300 ms should add that boundary.

Cardinality: every label combination is a series

A label adds a dimension to a metric: the same request counter split by route, status code or region. Prometheus identifies every time series by its metric name and its labels, and changing any label value creates a new series (data model). The number of series of a metric is therefore the number of label combinations that occur, at most the product of the number of values of each label. Prometheus also attaches the job and instance labels to everything it collects, so every copy of a service keeps its own copy of every series (jobs and instances).

The script replays a seeded log of 50,000 requests to a shop’s API and counts the series that four label designs create on one request counter, then on a duration histogram:

"""How many time series does one request counter create? Four label designs, one seeded log.

Every distinct combination of label values is its own time series. The script replays a log of
50,000 requests to a shop's API and counts the combinations each label design produces as the
traffic grows.
"""

import random

rng = random.Random(42)

ROUTES = ["GET /products/{id}", "GET /search", "GET /cart", "POST /cart/items",
          "POST /orders", "GET /orders/{id}", "POST /payments", "GET /health"]
ROUTE_WEIGHTS = [30, 25, 12, 10, 6, 8, 5, 4]
CODES = [200, 201, 304, 400, 401, 404, 429, 500, 502, 503]
CODE_WEIGHTS = [850, 40, 30, 20, 10, 25, 5, 10, 5, 5]
PODS = [f"pod-{n}" for n in range(1, 13)]  # 12 copies of the service


def request():
    """One request of the log: its route, the raw URL path, status code, pod and user."""
    route = rng.choices(ROUTES, ROUTE_WEIGHTS)[0]
    path = route.split(" ", 1)[1]
    if "{id}" in path:
        path = path.replace("{id}", str(rng.randint(1, 400_000)))
    code = rng.choices(CODES, CODE_WEIGHTS)[0]
    return {"route": route, "path": path, "code": code, "class": f"{code // 100}xx",
            "pod": rng.choice(PODS), "user": f"u{rng.randint(1, 2_000_000)}"}


DESIGNS = {
    "route, status class": lambda r: (r["route"], r["class"]),
    "route, status, pod": lambda r: (r["route"], r["code"], r["pod"]),
    "route, status, user ID": lambda r: (r["route"], r["code"], r["user"]),
    "raw URL path, status": lambda r: (r["path"], r["code"]),
}
BOUNDS = {
    "route, status class": f"{len(ROUTES) * 4:,}",
    "route, status, pod": f"{len(ROUTES) * len(CODES) * len(PODS):,}",
    "route, status, user ID": "none",
    "raw URL path, status": "none",
}
CHECKPOINTS = [1_000, 10_000, 50_000]

seen = {name: set() for name in DESIGNS}
counts = {name: [] for name in DESIGNS}
for n in range(1, CHECKPOINTS[-1] + 1):
    r = request()
    for name, labels in DESIGNS.items():
        seen[name].add(labels(r))
    if n in CHECKPOINTS:
        for name in DESIGNS:
            counts[name].append(len(seen[name]))

print("Series of one request counter, by label design")
print(f"{'requests seen':24}" + "".join(f"{c:>9,}" for c in CHECKPOINTS) + "   upper bound")
for name in DESIGNS:
    print(f"{name:24}" + "".join(f"{c:>9,}" for c in counts[name]) + f"{BOUNDS[name]:>14}")

# A duration histogram with OpenTelemetry's 14 recommended boundaries exposes 15 buckets
# (the last is +Inf) plus _sum and _count for every combination: 17 series each.
PER_HISTOGRAM = 14 + 1 + 2
print(f"\nThe same labels on a duration histogram ({PER_HISTOGRAM} series per combination), "
      f"after {CHECKPOINTS[-1]:,} requests:")
for name in DESIGNS:
    print(f"{name:24}{counts[name][-1] * PER_HISTOGRAM:>12,}")

Series of one request counter, by label design
requests seen               1,000   10,000   50,000   upper bound
route, status class            29       32       32            32
route, status, pod            222      636      896           960
route, status, user ID        999    9,994   49,911          none
raw URL path, status          425    3,833   18,833          none

The same labels on a duration histogram (17 series per combination), after 50,000 requests:
route, status class              544
route, status, pod            15,232
route, status, user ID       848,487
raw URL path, status         320,161

The first two designs are bounded. Route and status class reached all 32 combinations by the 10,000th request and stayed there; route, status code and pod, with 12 pods, gave 896 series after 50,000 requests, close to its bound of 960. The last two designs grow with traffic and never stop. A user ID label created 49,911 series from 50,000 requests, almost one per request, and the raw URL path, with an order or product ID inside it, created 18,833. On a histogram, each combination costs 17 series, so the user ID design reached 848,487 series from requests that would take a busy API less than a minute to serve.

That is the reason behind the rules. Prometheus’s naming guide says never to use labels for values with high cardinality, such as user IDs, email addresses or other unbounded sets (naming). Its instrumentation guide suggests keeping the cardinality of most metrics below 10, keeping the few that exceed it to a handful across the whole system, and looking for another approach when a metric could pass 100 (instrumentation). Label values should come from a small, known set: the route template, the method, the status code or its class, the region. Detail about one request belongs in log lines and span attributes, which are stored once per event rather than once per combination.

Sampling: keeping the traces that matter

Without sampling, tracing stores every span of every request. At 2,000 requests a second with about 7.5 spans each, as in the sampling example below, that is 15,000 spans a second, or about 1.3 billion a day. Most of them describe healthy requests that look alike, so services usually keep only some traces.

• Head sampling decides when the trace starts, before anything about the request is known. OpenTelemetry’s specification describes a consistent way to decide: the last 56 bits of the trace ID are the randomness, and a trace is kept when that number is at least $(1 - p) \times 2^{56}$ for a sampling probability p (probability sampling). Every service that sees the same trace ID reaches the same decision, and the sampled flag in traceparent carries it downstream. It is cheap, but it cannot promise to keep the traces that contain errors (sampling).
• Tail sampling decides after all the spans of a trace have arrived, so it can keep every trace with an error, every slow trace and a share of the rest (sampling).

The script generates 20,000 traces, 1 % of them with an error and 2 % slower than a second, and applies three policies:

"""Head and tail sampling on 20,000 seeded traces: what each policy keeps.

Each trace has a random 128-bit trace ID, 3 to 12 spans, a 1 % chance of an error and a 2 %
chance of being slow. Head sampling decides from the trace ID alone, before anything is known
about the request; tail sampling decides after the whole trace has arrived.
"""

import random

rng = random.Random(7)
N = 20_000
SLOW_MS = 1_000

traces = []
for _ in range(N):
    slow = rng.random() < 0.02
    traces.append({
        "trace_id": rng.getrandbits(128),
        "spans": rng.randint(3, 12),
        "error": rng.random() < 0.01,
        "ms": rng.uniform(1_000, 4_000) if slow else rng.uniform(20, 300),
    })


def keep_by_trace_id(trace_id, p):
    """Consistent probability sampling: the last 56 bits of the trace ID decide, so every
    service that sees the same trace ID makes the same decision."""
    randomness = trace_id & (2**56 - 1)
    threshold = round((1 - p) * 2**56)
    return randomness >= threshold


POLICIES = {
    "keep everything": lambda t: True,
    "head: 10 % by trace ID": lambda t: keep_by_trace_id(t["trace_id"], 0.10),
    "tail: errors, slow, 5 % of rest": lambda t: t["error"] or t["ms"] > SLOW_MS
    or keep_by_trace_id(t["trace_id"], 0.05),
}

errors = sum(t["error"] for t in traces)
slow = sum(t["ms"] > SLOW_MS for t in traces)
print(f"{'policy':33}{'traces':>8}{'spans':>9}{'errors kept':>14}{'slow kept':>12}")
for name, keep in POLICIES.items():
    kept = [t for t in traces if keep(t)]
    print(f"{name:33}{len(kept):>8,}{sum(t['spans'] for t in kept):>9,}"
          f"{sum(t['error'] for t in kept):>7} of {errors}{sum(t['ms'] > SLOW_MS for t in kept):>5} of {slow}")

# What goes wrong when each of three services flips its own coin instead of reading the
# trace ID: a trace stays complete only when all three coins agree to keep it.
coins = random.Random(11)
complete = sum(all(coins.random() < 0.10 for _ in range(3)) for _ in traces)
same = sum(keep_by_trace_id(t["trace_id"], 0.10) for t in traces)
print("\nComplete three-service traces kept at 10 %:")
print(f"  every service reads the trace ID {same:>7,}")
print(f"  each service flips its own coin  {complete:>7,}")

policy                             traces    spans   errors kept   slow kept
keep everything                    20,000  149,381    187 of 187  414 of 414
head: 10 % by trace ID              1,978   14,928     14 of 187   37 of 414
tail: errors, slow, 5 % of rest     1,575   11,828    187 of 187  414 of 414

Complete three-service traces kept at 10 %:
  every service reads the trace ID   1,978
  each service flips its own coin       18

Head sampling kept almost exactly 10 % of the traces, and with them only 14 of the 187 traces with an error: the traces you most want are dropped as often as any other, because the decision was made before anything went wrong. Tail sampling stored fewer spans than head sampling, 11,828 against 14,928, and kept every error and every slow trace. The last lines show why a head decision must come from the trace ID, or travel in the sampled flag: when three services each flip their own 10 % coin, only 18 traces out of 20,000 are complete in all three, against 1,978 when every service reads the same trace ID.

Tail sampling has its own price: a stateful component that holds every span until the trace is complete. The OpenTelemetry Collector’s tail sampling processor decides after a wait of 30 seconds by default, and needs all the spans of a trace to reach the same collector instance (tail sampling processor). By Little’s law, 15,000 spans a second held for 30 seconds means about 450,000 spans in memory at any moment. And a service with little traffic may not need sampling at all: OpenTelemetry’s guide counts tens of small traces a second or fewer as a reason not to sample (sampling).

A starting kit for a new service

1. A request counter and a duration histogram for every route, labelled with the route template and the status code, in seconds, with a bucket boundary at the latency objective.
2. Structured log lines that carry trace_id and span_id, with UTC timestamps, nothing secret in them, and a counter beside every log statement that matters.
3. Trace context on every hop. Read traceparent, send it on with every outgoing call, and carry it across queues, where OpenTelemetry records handing work to the queue as a producer span and processing it later as a consumer span (traces).
4. USE metrics for every resource with a limit: processors, memory, disks and pools such as database connections.
5. A series budget. Before a new label ships, multiply the series the metric has now by the number of values the label can take.
6. A sampling policy that keeps every error and every slow trace, or no sampling while traffic is low.

Practice

00-5d1c3e8a9f0b4a7c2e6d8f1a3b5c7d9e-a1b2c3d4e5f60718-01

def parse_traceparent(value):
    """The trace ID, parent ID and sampled flag of a version-00 traceparent, or None if it is invalid."""
    # Replace this line with your code.
    return None


def next_hop(value, span_id):
    """The traceparent for an outgoing call: the same trace, with span_id as the new parent ID."""
    # Replace this line with your code.
    return ""

from traceparent import next_hop, parse_traceparent

TRACE = "5d1c3e8a9f0b4a7c2e6d8f1a3b5c7d9e"
PARENT = "a1b2c3d4e5f60718"
SPAN = "0f1e2d3c4b5a6978"
HEADER = f"00-{TRACE}-{PARENT}-01"


def raises_value_error(call):
    try:
        call()
    except ValueError:
        return True
    return False


def test_parses_a_valid_header():
    """a valid header gives its trace ID, parent ID and sampled flag"""
    assert parse_traceparent(HEADER) == {"trace_id": TRACE, "parent_id": PARENT, "sampled": True}


def test_sampled_is_the_lowest_bit():
    """00 is not sampled; 01 and 09 are"""
    assert parse_traceparent(f"00-{TRACE}-{PARENT}-00")["sampled"] is False
    assert parse_traceparent(f"00-{TRACE}-{PARENT}-09")["sampled"] is True


def test_rejects_invalid_headers():
    """zero IDs, capitals, version ff, a missing field, extra text and an empty value are invalid"""
    for bad in [
        f"00-{'0' * 32}-{PARENT}-01",
        f"00-{TRACE}-{'0' * 16}-01",
        f"00-{TRACE.upper()}-{PARENT}-01",
        f"ff-{TRACE}-{PARENT}-01",
        f"00-{TRACE}-{PARENT}",
        f"00-{TRACE}-{PARENT}-01-extra",
        "",
    ]:
        assert parse_traceparent(bad) is None, bad


def test_next_hop_keeps_the_trace():
    """the outgoing header keeps the trace ID and names the caller's span as the parent"""
    assert next_hop(HEADER, SPAN) == f"00-{TRACE}-{SPAN}-01"


def test_next_hop_sends_only_the_sampled_bit():
    """flags 09 go out as 01, and 00 stays 00"""
    assert next_hop(f"00-{TRACE}-{PARENT}-09", SPAN) == f"00-{TRACE}-{SPAN}-01"
    assert next_hop(f"00-{TRACE}-{PARENT}-00", SPAN) == f"00-{TRACE}-{SPAN}-00"


def test_next_hop_refuses_bad_input():
    """an invalid incoming header or span ID raises ValueError"""
    assert raises_value_error(lambda: next_hop(f"00-{'0' * 32}-{PARENT}-01", SPAN))
    assert raises_value_error(lambda: next_hop(HEADER, "0" * 16))
    assert raises_value_error(lambda: next_hop(HEADER, "0F1E2D3C4B5A6978"))

Interview questions

Warm-up (fresher to mid level): logs, metrics and traces: what does each one answer, and why do services need all three? Metrics answer how much and how often: request rates, error shares and latency percentiles over time. They cost little per request, so they suit dashboards, alerts and trends, but they cannot say which request failed or why. Logs answer what exactly happened in one event, with its details: the error, the order, the input. Traces answer where the time went in one request across services, as a tree of timed spans. Each fills a blind spot of the others: a metric alert says something is wrong, a trace from that period shows which hop is slow or failing, and the log lines that carry the trace’s ID explain why. A shared trace ID, passed in the traceparent header and written into every log line, is what joins them.

Warm-up (fresher to mid level): why should a user ID never be a label on a metric, and where should it go instead? Every distinct combination of label values is a separate time series, and user IDs have no bound: the label creates a series for almost every user, multiplied by every other label and, on a histogram, by every bucket. A metrics system’s memory and cost grow with the number of series, so one such label can multiply them many times over. Labels should take their values from a small, known set, such as route templates, status codes and regions. Per-user detail belongs where it is stored once per event instead: in log lines and span attributes, which can be searched by user ID when needed.

Key takeaways

• Metrics answer how much and how often, logs what exactly happened, traces where the time went; the path from an alert to its cause usually uses all three.
• The traceparent header carries the trace ID and the caller’s span ID to every service, and writing the trace ID into each log line joins logs to traces.
• Use RED metrics for services and USE metrics for resources, keep durations in histograms with a bucket boundary at your objective, and look at percentiles, not means.
• Every label combination is a separate series: label with route templates and status codes, never user IDs, order IDs or raw paths.
• Head sampling by trace ID is cheap and consistent but drops errors as often as anything else; tail sampling keeps every error and slow trace, at the cost of holding spans in memory until it decides.