Distributed tracing
Where the time goes: every step of a request as a span.
What it is
A log line says a request took 900 ms; a trace says which part. Each piece of work is a span: a name, a start, a duration, attributes, and the span it ran inside. The request is the root (a server span), the middleware steps are children, and every database query is a client span, so the trace is a tree you can draw as a timeline. Spans share the request's trace id, the same id as its log line, and a traceparent header carries it into the next service, so one trace can cross services and platforms. The API lab records spans with a small tracer of its own and ships them to Grafana Tempo over OpenTelemetry.
When to use it
- Finding out why a request is slow, not just that it is
- Following one action through several services
- Seeing what a cold start, a retry or an extra query costs
1. Send a request, draw its trace
Try the leaderboard on Cloudflare Workers from your browser, then from this site's server. From your browser the Worker runs in the Cloudflare city nearest you; if that's far from Virginia, where the database is, the SELECT scores span is nearly the whole request: distance, not slow code. From this site's server (in Washington, D.C.) the Worker runs next door to the database and the same query takes a few milliseconds. On a fresh Vercel instance you may also catch db.ensure-schema: thirteen queries a cold start spends creating tables that already exist.
The bars show waiting, not computing: on Workers the clock only moves across I/O. A trace that crosses services, like a webhook delivery (the request that sends it, each delivery attempt, and the receiving request inside it), is one trace too, joined by the traceparent header.
Show code · src/app/traces/Waterfall.tsx
"use client";
import { useState } from "react";
import { cx } from "@/components/ui";
import type { TraceSpan } from "@/lib/grafana";
// A trace as a waterfall: one row per span, indented under its parent, with a
// bar showing when it ran and for how long, on the trace's own timeline.
type Row = TraceSpan & { depth: number };
/** Depth-first order: each span followed by its children, earliest first. */
function rows(spans: TraceSpan[]): Row[] {
const ids = new Set(spans.map((s) => s.spanId));
const children = new Map<string | null, TraceSpan[]>();
for (const s of spans) {
// A parent that isn't in the trace (the caller didn't send its own span) counts as no parent.
const parent = s.parentSpanId && ids.has(s.parentSpanId) ? s.parentSpanId : null;
children.set(parent, [...(children.get(parent) ?? []), s]);
}
const out: Row[] = [];
const walk = (parent: string | null, depth: number) => {
for (const s of (children.get(parent) ?? []).sort((a, b) => a.startMs - b.startMs)) {
out.push({ ...s, depth });
walk(s.spanId, depth + 1);
}
};
walk(null, 0);
return out;
}
const COLOURS = { server: "bg-accent", client: "bg-sky-600", internal: "bg-violet-600", other: "bg-muted" } as const;
const ms = (v: number) => (v >= 100 ? `${Math.round(v)} ms` : `${v.toFixed(1)} ms`);
export function Waterfall({ spans }: { spans: TraceSpan[] }) {
const [open, setOpen] = useState<string | null>(null);
const list = rows(spans);
const end = Math.max(...spans.map((s) => s.startMs + s.durationMs), 0.001);
return (
<div className="grid grid-cols-[minmax(0,1fr)] gap-1" data-testid="waterfall">
<div className="flex justify-between text-xs text-muted"><span>0 ms</span><span>{ms(end)}</span></div>
<ol className="m-0 list-none p-0">
{list.map((s) => (
<li key={s.spanId} className="border-b border-line py-1">
<button
type="button"
className="grid w-full cursor-pointer grid-cols-[minmax(0,2fr)_minmax(0,3fr)] items-center gap-2 bg-transparent text-left"
aria-expanded={open === s.spanId}
onClick={() => setOpen(open === s.spanId ? null : s.spanId)}
>
<span className="min-w-0 truncate font-mono text-xs" style={{ paddingLeft: `${s.depth * 12}px` }}>
{s.error && <span className="text-danger" aria-label="failed">✕ </span>}{s.name}
</span>
<span className="relative block h-4" aria-hidden="true">
<span
className={cx("absolute top-0.5 h-3 rounded-sm", s.error ? "bg-danger" : COLOURS[s.kind])}
style={{ left: `${(s.startMs / end) * 100}%`, width: `max(2px, ${(s.durationMs / end) * 100}%)` }}
/>
</span>
</button>
<span className="sr-only">{s.kind} span, starts at {ms(s.startMs)}, takes {ms(s.durationMs)}</span>
{open === s.spanId && (
<dl className="m-0 mt-1 grid grid-cols-[max-content_minmax(0,1fr)] gap-x-3 rounded bg-code px-2 py-1 font-mono text-xs">
<dt className="text-muted">duration</dt><dd className="m-0">{ms(s.durationMs)} (from {ms(s.startMs)})</dd>
<dt className="text-muted">kind</dt><dd className="m-0">{s.kind}</dd>
{s.platform && <><dt className="text-muted">platform</dt><dd className="m-0">{s.platform}{s.region ? ` · ${s.region}` : ""}</dd></>}
{s.error && <><dt className="text-muted">error</dt><dd className="m-0 break-all text-danger">{s.error}</dd></>}
{Object.entries(s.attributes).map(([k, v]) => (
<div key={k} className="contents"><dt className="text-muted">{k}</dt><dd className="m-0 break-all">{String(v)}</dd></div>
))}
</dl>
)}
</li>
))}
</ol>
{/* A key, not a status: each entry says what a colour means. */}
<p className="m-0 flex flex-wrap gap-x-3 gap-y-1 text-xs text-muted">
<span className="font-semibold">Colours:</span>
<span><span className="mr-1 inline-block h-2 w-3 rounded-sm bg-accent" />the request (server);</span>
<span><span className="mr-1 inline-block h-2 w-3 rounded-sm bg-sky-600" />a query or outgoing call (client);</span>
<span><span className="mr-1 inline-block h-2 w-3 rounded-sm bg-violet-600" />a step inside the API;</span>
<span><span className="mr-1 inline-block h-2 w-3 rounded-sm bg-danger" />red: a span that failed</span>
</p>
</div>
);
}
Show code · src/lib/grafana.ts
// Reading telemetry back from Grafana Cloud, on the server. The query
// addresses aren't secret; the read-only token (GRAFANA_READ_TOKEN, an access
// policy with logs/traces/metrics:read and no write scopes) is set only in
// this site's production environment. Without it, every function here
// throws NotConfigured and the pages say so.
const LOKI = { url: "https://logs-prod-042.grafana.net", user: "1842184" };
const TEMPO = { url: "https://tempo-prod-30-prod-us-east-3.grafana.net/tempo", user: "1836485" };
const PROM = { url: "https://prometheus-prod-66-prod-us-east-3.grafana.net/api/prom", user: "3693039" };
export class NotConfigured extends Error {
constructor() { super("Grafana isn't configured here (no GRAFANA_READ_TOKEN)."); }
}
const auth = (user: string) => {
const token = process.env.GRAFANA_READ_TOKEN;
if (!token) throw new NotConfigured();
return `Basic ${btoa(`${user}:${token}`)}`;
};
export type LogEntry = { ts: string; line: Record<string, unknown> };
type LokiStreams = { data: { resultType: "streams"; result: { stream: Record<string, string>; values: [string, string][] }[] } };
type LokiMatrix = { data: { resultType: "matrix" | "vector"; result: { metric: Record<string, string>; values?: [number, string][]; value?: [number, string] }[] } };
async function loki<T>(path: string, params: Record<string, string>): Promise<T> {
const res = await fetch(`${LOKI.url}/loki/api/v1/${path}?${new URLSearchParams(params)}`, {
headers: { authorization: auth(LOKI.user) },
signal: AbortSignal.timeout(10_000),
cache: "no-store",
});
if (!res.ok) throw new Error(`Loki answered ${res.status}: ${(await res.text()).slice(0, 200)}`);
return res.json() as Promise<T>;
}
const nanos = (msAgo: number) => `${Date.now() - msAgo}000000`;
/** Log lines (newest first) matching a LogQL stream query, from the last `minutes`. */
export async function findLines(query: string, minutes = 30, limit = 20): Promise<LogEntry[]> {
const body = await loki<LokiStreams>("query_range", { query, start: nanos(minutes * 60_000), end: nanos(0), limit: String(limit), direction: "backward" });
return body.data.result
.flatMap((s) => s.values)
.sort((a, b) => (a[0] < b[0] ? 1 : -1))
.map(([ns, text]) => {
let line: Record<string, unknown>;
try { line = JSON.parse(text); } catch { line = { text }; }
return { ts: new Date(Number(ns.slice(0, -6))).toISOString(), line };
});
}
/** A LogQL metric query, evaluated once now: one number per series. */
export async function instant(query: string) {
const body = await loki<LokiMatrix>("query", { query, time: nanos(0) });
return body.data.result.map((r) => ({ labels: r.metric, value: Number(r.value?.[1] ?? NaN) }));
}
/** The stream every line of the API lab is in. */
export const API_STREAM = '{service_name="api-feature-lab"}';
// ---- Traces (Tempo) ---------------------------------------------------------
export type TraceSpan = {
spanId: string; parentSpanId: string | null; name: string;
kind: "server" | "client" | "internal" | "other";
/** Milliseconds from the start of the trace, and how long it took. */
startMs: number; durationMs: number;
error: string | null;
platform: string | null; region: string | null;
attributes: Record<string, string | number | boolean>;
};
type OtlpValue = { stringValue?: string; intValue?: string | number; doubleValue?: number; boolValue?: boolean };
type OtlpSpan = {
spanId: string; parentSpanId?: string; name: string; kind?: number | string;
startTimeUnixNano: string; endTimeUnixNano: string;
attributes?: { key: string; value: OtlpValue }[];
status?: { code?: number | string; message?: string };
};
type OtlpTrace = { resourceSpans?: OtlpResourceSpans[]; batches?: OtlpResourceSpans[] };
type OtlpResourceSpans = { resource?: { attributes?: { key: string; value: OtlpValue }[] }; scopeSpans?: { spans?: OtlpSpan[] }[]; instrumentationLibrarySpans?: { spans?: OtlpSpan[] }[] };
const plain = (v: OtlpValue) => v.stringValue ?? (v.intValue !== undefined ? Number(v.intValue) : v.doubleValue ?? v.boolValue ?? "");
const attrs = (list: { key: string; value: OtlpValue }[] = []) => Object.fromEntries(list.map((a) => [a.key, plain(a.value)]));
/** Tempo's JSON may give ids as hex or (protobuf style) base64: always hex here. */
export function hexId(id: string | undefined) {
if (!id) return null;
if (/^[0-9a-f]+$/i.test(id) && (id.length === 16 || id.length === 32)) return id.toLowerCase();
return [...atob(id)].map((ch) => ch.charCodeAt(0).toString(16).padStart(2, "0")).join("");
}
const KINDS: Record<string, TraceSpan["kind"]> = { "1": "internal", "2": "server", "3": "client", SPAN_KIND_INTERNAL: "internal", SPAN_KIND_SERVER: "server", SPAN_KIND_CLIENT: "client" };
const isError = (code: number | string | undefined) => code === 2 || code === "STATUS_CODE_ERROR";
/** Flatten Tempo's answer into spans with times relative to the trace's start. */
export function flattenTrace(trace: OtlpTrace): TraceSpan[] {
const raw = (trace.resourceSpans ?? trace.batches ?? []).flatMap((rs) => {
const resource = attrs(rs.resource?.attributes);
return (rs.scopeSpans ?? rs.instrumentationLibrarySpans ?? []).flatMap((ss) => (ss.spans ?? []).map((sp) => ({ sp, resource })));
});
if (raw.length === 0) return [];
const ns = (v: string) => BigInt(v);
const t0 = raw.reduce((min, { sp }) => (ns(sp.startTimeUnixNano) < min ? ns(sp.startTimeUnixNano) : min), ns(raw[0].sp.startTimeUnixNano));
const ms = (v: bigint) => Number(v) / 1e6;
return raw.map(({ sp, resource }) => ({
spanId: hexId(sp.spanId)!,
parentSpanId: hexId(sp.parentSpanId),
name: sp.name,
kind: KINDS[String(sp.kind ?? "")] ?? "other",
startMs: ms(ns(sp.startTimeUnixNano) - t0),
durationMs: ms(ns(sp.endTimeUnixNano) - ns(sp.startTimeUnixNano)),
error: isError(sp.status?.code) ? sp.status?.message ?? "error" : null,
platform: (resource["cloud.platform"] as string) ?? null,
region: (resource["cloud.region"] as string) ?? null,
attributes: attrs(sp.attributes),
})).sort((a, b) => a.startMs - b.startMs);
}
/** One trace by id, or null if Tempo doesn't have it (yet). */
export async function getTrace(traceId: string): Promise<TraceSpan[] | null> {
const res = await fetch(`${TEMPO.url}/api/v2/traces/${traceId}`, {
headers: { authorization: auth(TEMPO.user), accept: "application/json" },
signal: AbortSignal.timeout(10_000),
cache: "no-store",
});
if (res.status === 404) return null;
if (!res.ok) throw new Error(`Tempo answered ${res.status}: ${(await res.text()).slice(0, 200)}`);
const body = (await res.json()) as { trace?: OtlpTrace } & OtlpTrace;
const spans = flattenTrace(body.trace ?? body);
return spans.length ? spans : null;
}
// ---- Metrics (Prometheus API, Grafana Mimir) --------------------------------
type PromResult = { metric: Record<string, string>; value?: [number, string]; values?: [number, string][] };
async function prom(path: string, params: Record<string, string>): Promise<PromResult[]> {
const res = await fetch(`${PROM.url}/api/v1/${path}?${new URLSearchParams(params)}`, {
headers: { authorization: auth(PROM.user) },
signal: AbortSignal.timeout(10_000),
cache: "no-store",
});
if (!res.ok) throw new Error(`Prometheus answered ${res.status}: ${(await res.text()).slice(0, 200)}`);
return ((await res.json()) as { data: { result: PromResult[] } }).data.result;
}
/** A PromQL query evaluated now: one number per series. */
export async function promInstant(query: string) {
return (await prom("query", { query })).map((r) => ({ labels: r.metric, value: Number(r.value?.[1] ?? NaN) }));
}
/** A PromQL query over the last `hours`, one point per `stepSec`. */
export async function promRange(query: string, hours: number, stepSec: number) {
const end = Math.floor(Date.now() / 1000);
return (await prom("query_range", { query, start: String(end - hours * 3600), end: String(end), step: String(stepSec) }))
.map((r) => ({ labels: r.metric, points: (r.values ?? []).map(([t, v]) => [t * 1000, Number(v)] as [number, number]) }));
}
/** The label sets of the series a selector matches in the last hour (to see what exists). */
export async function promSeries(selector: string) {
const end = Math.floor(Date.now() / 1000);
const res = await fetch(`${PROM.url}/api/v1/series?${new URLSearchParams({ "match[]": selector, start: String(end - 3600), end: String(end) })}`, {
headers: { authorization: auth(PROM.user) }, signal: AbortSignal.timeout(10_000), cache: "no-store",
});
if (!res.ok) throw new Error(`Prometheus answered ${res.status}: ${(await res.text()).slice(0, 200)}`);
return ((await res.json()) as { data: Record<string, string>[] }).data;
}
/** Metric names matching a pattern (e.g. every traces_spanmetrics_* metric). */
export async function promNames(pattern: string) {
const end = Math.floor(Date.now() / 1000);
const res = await fetch(`${PROM.url}/api/v1/label/__name__/values?${new URLSearchParams({ "match[]": `{__name__=~"${pattern}"}`, start: String(end - 3600), end: String(end) })}`, {
headers: { authorization: auth(PROM.user) }, signal: AbortSignal.timeout(10_000), cache: "no-store",
});
if (!res.ok) throw new Error(`Prometheus answered ${res.status}: ${(await res.text()).slice(0, 200)}`);
return ((await res.json()) as { data: string[] }).data;
}
The tracer itself is in the API lab: observe.ts (spans) and db/client.ts (a span per query).