Distributed Tracing Infrastructure

The metric was collected, the log was stored, and the cost of both was worked out. The latency curve’s rise is visible too. What is not visible is the path a single request behind that curve took across five services: which span it waited in, which call was retried, which service was never called at all. None of these three questions has an answer in the metric buckets or the log lines; both count the event, not the request.

Distributed tracing has three parts. A span record is the record of one unit of work: its own id, its parent span’s id, the service name, the start, the duration. Context propagation carries the request’s id from call to call; if it is not carried, the tree splits into five separate pieces. The collector writes span records to the trace store, and the store groups records by trace id: a time series store is indexed by time, a trace store is indexed by id; a metric record is written once a minute, a span record once per span.

A Request’s Tree

The model generates one hour of traffic on the regional measurement network; the generator is written in code, it is fiction, not a measurement.

// trace/model.mjs — MODEL of one hour of traffic on the regional measurement network (fiction). Each
// request passes through five services; each span is one record: id, parent, service, start, duration,
// error, attempt. MD1: the call graph is fixed — gateway calls read and billing, read calls validate,
// billing calls workorder. MD2: a span's own duration is baseline + noise, error rate per mille. MD3: for
// some requests, read answers from cache and validate is never called. MD4: some workorder calls time out
// and retry once. MD5: some requests are slow; slowness accumulates in a single span.
export const SEED = 20260802, REQUESTS = 24000, MINUTES = 60;
export const SERVICES = ["gateway", "read", "validate", "billing", "workorder"];
export const PROFILE = { gateway: [4, 2, 0], read: [18, 6, 2], validate: [26, 9, 3],
  billing: [31, 11, 4], workorder: [44, 15, 9] };
export const SKIP = 0.11, RETRY = 0.06, SLOW = 0.02, TIMEOUT = 120;

export function generate() {
  let s = SEED;
  const r = () => ((s = (s * 1664525 + 1013904223) >>> 0) / 2 ** 32);
  const jitter = (name) => { const [t, g] = PROFILE[name]; return Math.max(1, Math.round(t + (r() * 2 - 1) * g)); };
  const traces = [];
  for (let i = 0; i < REQUESTS; i += 1) {
    const t0 = Math.floor(r() * MINUTES * 60000), spans = [];
    let seq = 0;
    const addSpan = (parent, service, start, duration, error, attempt) =>
      (spans.push({ id: (seq += 1), parent, service, start, duration, error, attempt }), seq);
    const slowSpan = r() < SLOW ? (r() < 0.6 ? "workorder" : SERVICES[1 + Math.floor(r() * 4)]) : null;
    const factor = slowSpan ? 8 + Math.floor(r() * 13) : 1;
    const stretch = (name, d) => (name === slowSpan ? d * factor : d);
    const skipped = r() < SKIP, verifyDuration = skipped ? 0 : stretch("validate", jitter("validate"));
    const readOwn = stretch("read", jitter("read"));
    const readDuration = readOwn + (skipped ? 0 : verifyDuration + 2);
    const retried = r() < RETRY, workorderDuration = stretch("workorder", jitter("workorder"));
    const workorderTotal = workorderDuration + (retried ? TIMEOUT + 2 : 0);
    const billingDuration = stretch("billing", jitter("billing")) + workorderTotal + 2;
    const billingStart = PROFILE.gateway[0] + readDuration + 2;
    const root = addSpan(0, "gateway", 0, billingStart + billingDuration, false, 1);
    const read = addSpan(root, "read", PROFILE.gateway[0], readDuration, false, 1);
    if (!skipped) addSpan(read, "validate", PROFILE.gateway[0] + readOwn + 1, verifyDuration, false, 1);
    const billing = addSpan(root, "billing", billingStart, billingDuration, false, 1);
    let wStart = billingStart + 2;
    if (retried) { addSpan(billing, "workorder", wStart, TIMEOUT, true, 1); wStart += TIMEOUT + 2; }
    addSpan(billing, "workorder", wStart, workorderDuration, r() < PROFILE.workorder[2] / 1000, retried ? 2 : 1);
    traces.push({ traceId: `trace-${(i + 1).toString(36).padStart(4, "0")}`, t0, total: billingStart + billingDuration,
      spans, skipped, retried, slowSpan });
  }
  return traces;
}
// A span's own duration: span duration minus the duration of its children.
export const ownTime = (trace, a) =>
  a.duration - trace.spans.filter((c) => c.parent === a.id).reduce((x, c) => x + c.duration, 0);

if (import.meta.filename === process.argv[1]) {
  const traces = generate(), spanCount = traces.reduce((x, z) => x + z.spans.length, 0);
  console.log(`seed ${SEED}, ${REQUESTS} requests, ${spanCount} spans, ${SERVICES.length} services, ${MINUTES} minutes`);
  console.log(`validation skipped ${traces.filter((z) => z.skipped).length}, retried call ` +
    `${traces.filter((z) => z.retried).length}, slow request ${traces.filter((z) => z.slowSpan).length}`);
  const o = traces.find((z) => z.retried && z.slowSpan === "workorder" && !z.skipped);
  console.log(`\ntrace tree — ${o.traceId} (${o.total} ms)`);
  const printSpan = (parent, indent) => o.spans.filter((x) => x.parent === parent).forEach((a) => {
    console.log(`${indent}${a.service.padEnd(14 - indent.length)}${String(a.duration).padStart(6)} ms` +
      `  own ${String(ownTime(o, a)).padStart(4)} ms  attempt ${a.attempt}${a.error ? "  timeout" : ""}`);
    printSpan(a.id, indent + "  ");
  });
  printSpan(0, "");
}

seed 20260802, 24000 requests, 118794 spans, 5 services, 60 minutes
validation skipped 2624, retried call 1418, slow request 477

trace tree — trace-008m (889 ms)
gateway          889 ms  own    6 ms  attempt 1
  read            47 ms  own   16 ms  attempt 1
    validate      31 ms  own   31 ms  attempt 1
  billing        836 ms  own   44 ms  attempt 1
    workorder    120 ms  own  120 ms  attempt 1  timeout
    workorder    672 ms  own  672 ms  attempt 2

The indentation shows the bond. The root span took 889 ms, its own work 6 ms. The billing span took 836 ms, its own work 44 ms — the rest passed waiting on the workorder call, and that call was made twice; the first attempt timed out at 120 ms. None of this can be read from a single duration metric: without the parent-child bond, 889 ms is just a number.

Eleven Questions, Three Views

Three views are produced from the same events: minute-by-minute metric buckets, one log line per span, trace trees. The questions are put to all three in the same form; if a view does not carry the required field, the search returns empty and no answer is written.

// trace/question.mjs — three views are produced from the same events: minute-by-minute metric
// buckets, one log line per span, trace trees. Eleven questions are asked of all three; if a view
// does not carry the required field, the search returns empty and no answer is written.
import { generate, ownTime, REQUESTS } from "./model.mjs";
const traces = generate(), BUCKETS = [25, 50, 100, 200, 400, 800, 1600, Infinity], THRESHOLD = 400;
// MD6 (assumption): the metric bucket and the log line carry no request id; the span carries an
// error flag, not the error message.
const METRIC = new Map(), LOG = [], MESSAGES = ["timeout", "connection refused", "invalid read"];
for (const z of traces) for (const a of z.spans) {
  const k = `${a.service}|${Math.floor((z.t0 + a.start) / 60000)}`;
  let o = METRIC.get(k);
  if (!o) METRIC.set(k, (o = { n: 0, errors: 0, buckets: new Array(BUCKETS.length).fill(0) }));
  o.n += 1; o.errors += a.error ? 1 : 0; o.buckets[BUCKETS.findIndex((b) => a.duration <= b)] += 1;
  LOG.push({ service: a.service, duration: a.duration, error: a.error,
    message: a.error ? MESSAGES[(a.duration + a.attempt) % 3] : "ok" });
}
const p95 = (x) => x.slice().sort((a, b) => a - b)[Math.floor(x.length * 0.95)];
const mostCommon = (m) => [...m].sort((a, b) => b[1] - a[1])[0];
const countBy = (arr, f) => arr.reduce((m, x) => m.set(f(x), (m.get(f(x)) || 0) + 1), new Map());
const root = [...METRIC].filter(([x]) => x.startsWith("gateway|")).map(([, o]) => o);
const gatewayLog = LOG.filter((l) => l.service === "gateway"), slowTraces = traces.filter((z) => z.total > THRESHOLD);
const slowestSpan = (z) => z.spans.slice().sort((a, b) => ownTime(z, b) - ownTime(z, a))[0];
const avgTotal = (f) => { const g = traces.filter(f); return g.reduce((x, z) => x + z.total, 0) / g.length; };
const percent = (a, b) => `${(a / b * 100).toFixed(a / b < 0.1 ? 2 : 0)}%`;
// the reported slow request: the one request whose id we happen to have
const TARGET = traces.filter((z) => z.slowSpan && z.retried)[0], ID = TARGET.traceId;
const noMetric = () => METRIC.get(ID) ?? null;                 // buckets are not looked up by id
const noLog = () => LOG.find((l) => l.trace === ID) ?? null;   // the row carries no trace field

const QUESTIONS = [
  ["request duration p95", () => { const t = root.reduce((a, o) => a.map((v, i) => v + o.buckets[i]),
    BUCKETS.map(() => 0)), n = t.reduce((a, b) => a + b, 0); let s = 0;
    for (let i = 0; ; i += 1) if ((s += t[i]) >= n * 0.95) return `<=${BUCKETS[i]} ms`; },
    () => `${p95(gatewayLog.map((l) => l.duration))} ms`, () => `${p95(traces.map((z) => z.total))} ms`],
  ["error rate", () => percent([...METRIC.values()].reduce((a, o) => a + o.errors, 0),
    [...METRIC.values()].reduce((a, o) => a + o.n, 0)),
    () => percent(LOG.filter((l) => l.error).length, LOG.length),
    () => percent(traces.reduce((x, z) => x + z.spans.filter((a) => a.error).length, 0), LOG.length)],
  [`requests over ${THRESHOLD} ms`, () => root.reduce((a, o) => a + o.buckets[5] + o.buckets[6] + o.buckets[7], 0),
    () => gatewayLog.filter((l) => l.duration > THRESHOLD).length, () => slowTraces.length],
  [`${ID}: which span is slow`, noMetric, noLog, () => slowestSpan(TARGET).service],
  [`${ID}: slow span's share`, noMetric, noLog, () => percent(ownTime(TARGET, slowestSpan(TARGET)), TARGET.total)],
  [`${ID}: retried call`, noMetric, noLog, () => { const d = TARGET.spans.find((a) => a.attempt > 1);
    return d ? `${d.service} x${d.attempt}` : "none"; }],
  [`${ID}: was validate called`, noMetric, noLog,
    () => (TARGET.spans.some((a) => a.service === "validate") ? "yes" : "no")],
  ["most common slow span in slow requests", noMetric, noLog,
    () => { const [name, n] = mostCommon(countBy(slowTraces, (z) => slowestSpan(z).service)); return `${name} ${percent(n, slowTraces.length)}`; }],
  ["how much faster is a request with validation skipped", noMetric, noLog,
    () => `${(avgTotal((z) => !z.skipped) - avgTotal((z) => z.skipped)).toFixed(0)} ms`],
  ["most common error message", () => null, () => mostCommon(countBy(LOG.filter((l) => l.error), (l) => l.message))[0],
    () => null],
  ["the query inside the slow span", () => null, () => null,
    () => TARGET.spans.find((a) => a.parent === slowestSpan(TARGET).id && a.service === slowestSpan(TARGET).service) ?? null],
];

console.log(`${"question".padEnd(54)}${"metric".padStart(12)}${"log".padStart(22)}${"trace".padStart(15)}`);
const n = [0, 0, 0];
for (const [label, ...f] of QUESTIONS) {
  const y = f.map((fn) => { const v = fn(); return v === null || v === undefined ? "-" : String(v); });
  y.forEach((v, i) => { if (v !== "-") n[i] += 1; });
  console.log(`${label.padEnd(54)}${y[0].padStart(12)}${y[1].padStart(22)}${y[2].padStart(15)}`);
}
const notInMetricOrLog = QUESTIONS.filter(([, o, g]) => (o() ?? null) === null && (g() ?? null) === null);
console.log(`\n${REQUESTS} requests, ${QUESTIONS.length} questions — metric ${n[0]}, log ${n[1]}, trace ${n[2]}`);
console.log(`unanswered by metric and log ${notInMetricOrLog.length} questions — answered by trace ` +
  `${notInMetricOrLog.filter(([, , , z]) => (z() ?? null) !== null).length}, answered by none ` +
  `${QUESTIONS.filter(([, ...f]) => f.every((fn) => (fn() ?? null) === null)).length}`);

question                                                    metric                   log          trace
request duration p95                                      <=400 ms                248 ms         248 ms
error rate                                                   1.38%                 1.38%          1.38%
requests over 400 ms                                           411                   411            411
trace-0024: which span is slow                                   -                     -           read
trace-0024: slow span's share                                    -                     -            45%
trace-0024: retried call                                         -                     -   workorder x2
trace-0024: was validate called                                  -                     -            yes
most common slow span in slow requests                           -                     -  workorder 82%
how much faster is a request with validation skipped             -                     -          27 ms
most common error message                                        -    connection refused              -
the query inside the slow span                                   -                     -              -

24000 requests, 11 questions — metric 3, log 4, trace 9
unanswered by metric and log 7 questions — answered by trace 6, answered by none 1

The first three questions are answered by all three views, but not at the same resolution: the metric view says <=400 ms for p95, the real value is 248 ms — the bucket boundary lumps everything between 200 and 400 into one cell. The question is answered, but the answer is not enough to decide on; that is a different defect from being unanswered.

The next four questions look at one reported request; the search returns empty in two views, because neither the bucket nor the log line carries a trace id. In request trace-0024, the longest own duration is in the read span (45% of the total duration), the workorder call was made twice, validate was called. The set-level question and the single-request question give different answers: in 82% of the 411 requests over 400 ms the slow span was the workorder, which was not the case in the reported request.

The last two questions draw the boundary of tracing. Only the log carries the error message; the span holds an error flag, not the text. The query inside the slow span, though, is not answered by any of the three views: instrumentation does not open a span at that depth. Six of the seven questions were answered by the trace; the reason the seventh stays unanswered is not collection but instrumentation depth.

Bytes per Span

// trace/cost.mjs — the byte cost per span and the root sampling decision are scanned. Record size comes
// from the real record; no compression. TRACE_ONLY: count of questions answered only by the trace view.
import { generate, REQUESTS } from "./model.mjs";
const traces = generate(), THRESHOLD = 400, TRACE_ONLY = 6, perDayMB = (b) => (b * 24 / 1e6).toFixed(1);
const spanCount = traces.reduce((x, z) => x + z.spans.length, 0);
const traceBytes = traces.reduce((x, z) => x + z.spans.reduce((y, a) =>
  y + JSON.stringify({ trace: z.traceId, ...a }).length, 0), 0);
console.log(`${spanCount} spans, ${(traceBytes / spanCount).toFixed(0)} bytes per span, ` +
  `${(traceBytes / REQUESTS).toFixed(0)} bytes per request (${(spanCount / REQUESTS).toFixed(1)} spans), ${perDayMB(traceBytes)} MB per day`);

const hash = (s) => { let h = 7; for (const c of s) h = (h * 31 + c.charCodeAt(0)) >>> 0; return h; };
const slowTraces = traces.filter((z) => z.total > THRESHOLD), reportedId = traces.filter((z) => z.slowSpan && z.retried)[0].traceId;
console.log(`\n${"ratio".padEnd(7)}${"recorded traces".padStart(18)}${"MB/day".padStart(8)}` +
  `${"captured".padStart(10)}${"slow missed".padStart(13)}${"MB/question".padStart(14)}  reported request`);
for (const n of [1, 2, 5, 20, 100]) {
  const keep = (z) => hash(z.traceId) % n === 0, kept = traces.filter(keep), bytes = traceBytes / REQUESTS * kept.length;
  console.log(`${`1/${n}`.padEnd(7)}${String(kept.length).padStart(18)}${perDayMB(bytes).padStart(8)}` +
    `${String(slowTraces.filter(keep).length).padStart(10)}` +
    `${String(slowTraces.length - slowTraces.filter(keep).length).padStart(13)}` +
    `${(+perDayMB(bytes) / TRACE_ONLY).toFixed(1).padStart(14)}  ${kept.some((z) => z.traceId === reportedId) ? "recorded" : "not recorded"}`);
}

118794 spans, 111 bytes per span, 549 bytes per request (4.9 spans), 316.0 MB per day

ratio     recorded traces  MB/day  captured  slow missed   MB/question  reported request
1/1                 24000   316.0       411            0          52.7  recorded
1/2                 12001   158.0       209          202          26.3  not recorded
1/5                  4801    63.2        84          327          10.5  not recorded
1/20                 1204    15.9        16          395           2.6  not recorded
1/100                 241     3.2         2          409           0.5  not recorded

A request costs 4.9 spans and 549 bytes; 111 bytes per span, 316.0 MB per day. Each of the six questions answered only by the trace costs 52.7 MB at this scale. The sampling ratio divides the volume directly: at 1/20 it drops to 15.9 MB, the cost per question to 2.6 MB. The cost sits in the right-hand columns — 395 of the 411 slow requests go unrecorded. The decision is made at the root, before the outcome is known, so no request is kept because it turned out to be slow; whether the reported request happens to be on hand is a matter of the die.

The cost of an unanswered question is read from here. When “which span is slow” cannot be answered, the intervention looks at all five services at once; with a trace, there is exactly one span to look at. When the question goes unanswered because of sampling, the cost is not divided evenly: at 1/20, the question stays unanswered for 96% of slow requests.

Summary

• A trace tree is the parent-child bond between spans; without the bond, the total duration is just a number.
• Of the eleven questions, the metric view answered 3, the log view 4, the trace view 9; of the 7 questions the metric and log could not answer, 6 were answered by the trace.
• One question was answered by none of the three views — the query inside the slow span; what is missing is not collection but instrumentation depth.
• The cost of tracing is measured by span count: 111 bytes per span, 316.0 MB per day, 52.7 MB per question answered only by the trace.
• Sampling at 1/20, decided at the root, cuts volume to 15.9 MB but leaves 395 of the 411 slow requests unrecorded; which request survives has nothing to do with the question’s importance.

Next Step

In this lesson, the span records of five services merged into a single tree, because all of them used the same field names: service, duration, attempt. In a real network this merge does not happen on its own; five teams write their own naming, one keeps duration in milliseconds and another in microseconds, the same concept splits into three names, and two spans placed side by side cannot be compared. The next lesson defines a shared telemetry convention field by field and counts its cost: how many questions become answerable in exchange for how many fields and how many service changes, and how many services stay incompatible.