Distributed Tracing

The correlation id says which services a request passed through, and the metrics give a fixed-cost summary. Neither says one thing: how the durations nest inside one another. Where inside the loan request did the catalog call start, did it run at the same time as the membership branch, in which call did the waiting happen. This lesson writes the signal that builds that structure.

A trace is the shared record of all the work an external request gives birth to; a span is a single piece of that record — the time between one piece of work’s start and finish, and its link to its parent span. The span here is entirely separate from the query range covered in the data access lessons: there, a range was the lower and upper bound of a key set; here it is a piece of work’s start and finish point in time. Propagation is carrying the context across the process boundary; where it is missing, the trace breaks.

The Trace Context

The context is made of three values: the trace’s id, the parent span’s id, and whether it was sampled. All three travel in a single header, because the only thing that can cross to the other side of the boundary is the request itself.

// trace.mjs — trace context and span; the context travels in a header, the span is written to a file
import { appendFileSync } from "node:fs";
export const HEADER = "x-trace";
export const parseContext = (value) => {         // "<traceId>|<parent span>|<sampled>"
  if (!value) return null;
  const [traceId, parent, s] = value.split("|");
  return { traceId, parent, sampled: s === "1" };
};
export const buildContext = (c) => `${c.traceId}|${c.parent}|${c.sampled ? 1 : 0}`;
export const hash = (s) => {                     // hash that spreads ids evenly; the sampling decision rests on it
  let h = 2166136261;
  for (const c of s) { h ^= c.charCodeAt(0); h = Math.imul(h, 16777619) >>> 0; }
  return h;
};
export const samplingDecision = (traceId, rate) => hash(traceId) % 1000 < rate * 1000;

export class Trace {
  constructor(file, service) { this.file = file; this.service = service; this.no = 0; }
  start(name, context) {
    return { traceId: context.traceId, span: `${this.service}${(this.no += 1)}`, parent: context.parent,
      name, t0: performance.now(), sampled: context.sampled };
  }
  finish(a) {
    if (!a.sampled) return;                      // an unsampled span is never written
    appendFileSync(this.file, JSON.stringify({ trace: a.traceId, span: a.span, parent: a.parent,
      service: this.service, name: a.name, duration: Math.round(performance.now() - a.t0) }) + "\n");
  }
}

TL4 — the sampling decision is made only at the root and carried with the context. Rationale: if the decision were made separately at every service, some spans of the same trace would be recorded and others would not, and half-traces would be indistinguishable from complete ones. Making the decision at the root ensures every recorded trace is whole; its cost is what the next section measures.

Carrying the Context Across the Boundary

The service does three things: parses the context from the incoming header, becomes the root and produces the trace id and the sampling decision if no context arrived, and updates the context with its own span id before putting it in the header when it calls downstream. The notification call site from the previous lessons still does not carry the context here either.

// service4.mjs — <name> <port> [downstream...]; the trace context crosses the process boundary; long-lived process
import { createServer } from "node:http";
import { writeFileSync } from "node:fs";
import { Trace, HEADER, parseContext, buildContext, samplingDecision } from "./trace.mjs";
const [name, port, ...downstream] = process.argv.slice(2);
const NOTIFICATION = "9405";
const file = `trace-${name}.txt`; writeFileSync(file, "");
const trace = new Trace(file, name);
let rate = 1;
const wait = (ms) => new Promise((c) => setTimeout(c, ms));
const url = (p, u) => `http://127.0.0.1:${p}/work?member=${u.get("member")}&copy=${u.get("copy")}`;

createServer(async (req, res) => {
  const u = new URL(req.url, "http://y").searchParams;
  if (req.url.startsWith("/rate")) {             // set the rate and empty the trace file
    rate = Number(u.get("value")); writeFileSync(file, ""); res.end("done"); return;
  }
  const member = u.get("member"), copy = Number(u.get("copy"));
  let context = parseContext(req.headers[HEADER]);
  if (!context) {                                // root: the trace id and sampling decision are given here
    const traceId = `${name}-${copy}`;
    context = { traceId, parent: "", sampled: samplingDecision(traceId, rate) };
  }
  const a = trace.start(`${name}/work`, context);
  await wait(name === "catalog" && copy % 5 === 0 ? 40 : 3);
  let status = name === "fee" && member === "4023" ? 402 : 200;
  for (const p of downstream) {
    const headers = p === NOTIFICATION ? {}       // the notification call site does not carry the context
      : { [HEADER]: buildContext({ ...context, parent: a.span }) };
    const y = await fetch(url(p, u), { headers });
    if (y.status !== 200) status = y.status;
  }
  trace.finish(a);
  res.statusCode = status; res.end("done");
}).listen(Number(port));

When the notification service receives a request with no context, it takes itself for the root and opens its own trace. The result is not a missing span, it is an extra trace: the loan request’s trace ends at four spans, and the notification work stands as a separate trace that connects to nothing.

Measurement

The query tool reads the trace files and groups spans by trace id. Traces that begin with the loan id are real traces; ones that begin with the notification id are broken traces. The definition of a problem request lives in the code: copies whose number is a multiple of five come from the slow shelf, and one of the four members gets an error for an unpaid fee.

// query4.mjs — <rate>; trace integrity and the sampling rate's effect on problem requests
import { readFileSync, statSync } from "node:fs";
const SERVICES = ["loan", "membership", "catalog", "fee", "notification"];
const N = 100;
const problematic = (n) => n % 5 === 0 || (n - 1) % 4 === 2;   // slow shelf or unpaid fee
const rate = process.argv[2];
const spans = SERVICES.flatMap((s) =>
  readFileSync(`trace-${s}.txt`, "utf8").split("\n").filter(Boolean).map((l) => JSON.parse(l)));
const traces = new Map();
for (const a of spans) { if (!traces.has(a.trace)) traces.set(a.trace, []); traces.get(a.trace).push(a); }
const roots = [...traces.keys()].filter((k) => k.startsWith("loan"));
const broken = [...traces.keys()].filter((k) => k.startsWith("notification"));
const complete = roots.filter((k) => traces.get(k).length === 4).length;
const caught = roots.filter((k) => problematic(Number(k.split("-")[1]))).length;
const total = Array.from({ length: N }, (_, i) => i + 1).filter(problematic).length;
const bytes = SERVICES.reduce((t, s) => t + statSync(`trace-${s}.txt`).size, 0);
console.log(`${rate.padStart(5)}${String(spans.length).padStart(9)}${String(roots.length).padStart(5)}` +
  `${String(complete).padStart(8)}${String(broken.length).padStart(10)}${`${caught}/${total}`.padStart(12)}` +
  `${`%${Math.round((100 * caught) / total)}`.padStart(7)}` +
  `${String(spans.length ? Math.round(bytes / spans.length) : 0).padStart(12)}`);

cat > run.mjs <<'EOF'
const MEMBER = ["4021", "4022", "4023", "4024"];      // 4023 is the member with an unpaid fee
const PORT = [9401, 9402, 9403, 9404, 9405];
for (const rate of ["1.00", "0.50", "0.10", "0.02"]) {
  for (const p of PORT) await fetch(`http://127.0.0.1:${p}/rate?value=${rate}`);
  for (let i = 1; i <= 100; i += 1)
    await fetch(`http://127.0.0.1:9401/work?member=${MEMBER[(i - 1) % 4]}&copy=${i}`);
  await new Promise((c) => setTimeout(c, 100));
  const { execSync } = await import("node:child_process");
  process.stdout.write(execSync(`node query4.mjs ${rate}`).toString());
}
EOF
node service4.mjs fee 9404 &
node service4.mjs catalog 9403 &
node service4.mjs notification 9405 &
node service4.mjs membership 9402 9404 &
node service4.mjs loan 9401 9402 9403 9405 &
sleep 1

printf '%5s%9s%5s%8s%10s%12s%7s%12s\n' rate spans root whole broken caught pct "bytes/span"
node run.mjs
pkill -f "node service4.mjs"

 rate    spans root   whole    broken      caught    pct  bytes/span
 1.00      500  100     100       100       40/40   %100         113
 0.50      233   46      46        49       18/40    %45         115
 0.10       35    7       7         7        2/40     %5         115
 0.02        8    2       2         0        0/40     %0         111

The Broken Trace and the Cost of Sampling

The first row shows that the context truly crosses the boundary: a hundred external requests, a hundred traces, and every one of them whole — four spans. The loan span sits at the top, the membership and catalog spans sit below it, and the fee span sits below membership. The “where did the waiting happen” question the previous lessons could not answer now lives in the record’s own structure.

Right beside it there are a hundred broken traces. Because the notification call site does not carry the context, every piece of work in that service opens its own root: a hundred separate, single-span traces for a hundred requests. This is why the measure matters — a broken trace does not look like missing data, it looks like extra data. Two hundred traces sit in the records, and nothing says that a hundred of them are really part of the other hundred. Someone trying to follow a request’s path would conclude that notification was never called at all.

The bottom three rows give the cost of the sampling rate. When the rate is halved, the spans written drop from five hundred to two hundred thirty-three; at a tenth, to thirty-five; at one in fifty, to eight. Volume falls roughly in step with the rate, and the size per span stays close to a fixed range of 111–115 bytes: sampling changes the count of the record, not its size.

What gets lost in exchange is in the columns on the right. All forty problem requests were caught only at full sampling. At the fifty-percent rate, eighteen of the forty problem requests were caught; at a tenth, two; at one in fifty, none. The numbers come out in the same neighborhood as the rate itself, and that is exactly this lesson’s finding: a sampling decision made at the root does not favor the problem request. The decision is made at the start of the request, before it is known whether it will slow down or fail, so problem requests get thinned out by the rate just like every other request. Sampling at two percent does not mean “I am keeping two percent of the traces,” it means “I will never see ninety-eight percent of the problems.”

Making the sampling decision at the root did buy one thing: every recorded trace is whole. At the fifty-percent rate, all forty-six of the forty-six traces written have four spans. Had the decision been made separately at each service, the same volume would have produced far more traces, but half of them would be half-traces — and a half-trace, like a broken trace, makes the data misleading.

Summary

• The trace context is made of three values (trace id, parent span, sampling decision) and crosses the process boundary in a single header; at full sampling, 100 requests turned into 100 whole traces and 400 linked spans.
• The one call site that does not carry the context produced 100 broken traces; a broken trace does not show up as missing data, it shows up as extra, unlinked traces.
• The sampling rate lowers volume roughly in step with the rate: 500, 233, 35, and 8 spans; the size per span stayed close to a fixed range of 111–115 bytes.
• A sampling decision made at the root does not favor the problem request: of 40 problem requests, the number caught was 40, 18, 2, and 0 in turn.
• Making the decision at the root ensured every recorded trace was whole: at every rate, all the traces written had four spans.

Next Step

All three signals are now produced in code, but each still follows its own path. The logger writes to its own file, the metrics sit behind an endpoint, the spans fall into another file; where each one gets written is buried inside the service code. This ties the application code to a single way of collecting telemetry: if the write destination changes, all five services have to be searched. The next lesson cuts that tie and designs an interface. What gets measured is a single thing: how many files get touched when the collector implementation changes.