feat(chord): telemetry from pages and workers stored by the server, who a span was for

The four telemetry gaps (rows on commits, chord.host, microsecond times, a read-only store) and: pages record and
send span batches over their link to the server's ingest object (checked, capped, rate-limited, stamped browser and
with the link's principal); workers send theirs too, so the server is the store's only writer; principalAttributes
lets an app choose what a span records about its principal. The tutorial shows a real page's click traced to the
worker, with the trace viewer.

packages/telemetry/CHANGELOG.md

@@ -2,6 +2,10 @@
 
 ## [Unreleased]
 
+### Added
+
+- `telemetryNow()`, the span clock: wall-clock milliseconds at microsecond resolution from `performance.now()` anchored to `Date.now()`, anchored anew when the two part by more than 10 ms. The in-memory adapter stamps span starts with it (span times rounded to the microsecond), and `renderTrace` prints lengths of time to the microsecond.
+
 ### Fixed
 
 - `renderTrace` escapes control characters (C0, C1, DEL) as `\uXXXX` in span and event names, trace and span ids of links, attribute keys and error names and messages, so ids taken from another process's carrier never reach a terminal or viewer raw.

packages/telemetry/src/index.ts

@@ -29,12 +29,16 @@ export interface SpanOptions {
 
 export type SpanStatus = { status: "ok" } | { status: "error"; error?: { name: string; message: string } };
 
-/** A settled span snapshot, independent of the recording adapter. Event times are relative to span start. */
+/**
+ * A settled span snapshot, independent of the recording adapter. Times are milliseconds at microsecond resolution;
+ * event times are relative to span start.
+ */
 export interface StoredSpan {
 	readonly id: string;
 	readonly traceId: string;
 	readonly parentId?: string;
 	readonly name: string;
+	/** Wall-clock milliseconds since the epoch (`telemetryNow`). */
 	readonly startedMs: number;
 	readonly endedMs: number;
 	readonly attributes: SpanAttributes;
@@ -462,4 +466,4 @@ export type {
 	RecordedTelemetryMeasurement,
 	RecordedTelemetrySpan,
 } from "./memory.ts";
-export { InMemoryTelemetryContext } from "./memory.ts";
+export { InMemoryTelemetryContext, telemetryNow } from "./memory.ts";

packages/telemetry/src/memory.ts

@@ -94,6 +94,37 @@ function carrierId(carrier: Readonly<TelemetryCarrier>): string {
 	return `${carrier["pi-memory-scope"]}:${carrier["pi-memory-span"]}`;
 }
 
+// The clock of span times: wall-clock milliseconds at microsecond resolution, from the monotonic high-resolution
+// clock anchored to the wall clock (`telemetryNow`, also Chord's SQLite store's).
+
+/**
+ * How far the anchored clock may part from `Date.now()` before it is anchored anew: more than `Date.now()`'s own
+ * truncation to whole milliseconds, less than any step worth following (a wall clock set, a sleep the monotonic clock
+ * did not count).
+ */
+const TOLERANCE_MS = 10;
+
+/** The wall-clock time of `performance.now()`'s zero; `performance.timeOrigin` until the first step is followed. */
+let anchor = performance.timeOrigin;
+
+/**
+ * Now as milliseconds since the epoch, rounded to the microsecond: `performance.now()` (monotonic, sub-millisecond)
+ * plus an anchor to the wall clock. While the two agree within 10 ms, times in one process keep their order and
+ * spacing to the microsecond; past that the clock follows `Date.now()` again, at whole milliseconds. Every adapter
+ * of this package and Chord's SQLite store stamp span starts with it, so their times agree.
+ */
+export function telemetryNow(): number {
+	const clock = performance.now();
+	const wall = Date.now();
+	if (Math.abs(anchor + clock - wall) > TOLERANCE_MS) anchor = wall - clock;
+	return microseconds(anchor + clock);
+}
+
+/** `ms` rounded to the microsecond, as span times are. */
+function microseconds(ms: number): number {
+	return Math.round(ms * 1000) / 1000;
+}
+
 // Identity survives settlement without exposing backend IDs on the generic context contract.
 const contextCarriers = new WeakMap<TelemetryContext, TelemetryCarrier>();
 
@@ -141,7 +172,7 @@ function createSpan(
 	}
 	const id = state.nextSpanId++;
 	return {
-		startedMs: Date.now(),
+		startedMs: telemetryNow(),
 		clock: performance.now(),
 		id,
 		parentId: parent?.localId ?? null,
@@ -212,7 +243,7 @@ async function startInMemorySpan<T>(
 			if (recordedSpan.settled) return;
 			recordedSpan.events.push({
 				name,
-				timeMs: performance.now() - recordedSpan.clock,
+				timeMs: microseconds(performance.now() - recordedSpan.clock),
 				attributes: copyAttributes(attributes),
 			});
 		},
@@ -240,7 +271,7 @@ async function startInMemorySpan<T>(
 		throw error;
 	} finally {
 		recordedSpan.settled = true;
-		recordedSpan.endedMs = recordedSpan.startedMs + performance.now() - recordedSpan.clock;
+		recordedSpan.endedMs = microseconds(recordedSpan.startedMs + performance.now() - recordedSpan.clock);
 		recordedSpan.endSequence = state.nextEndSequence++;
 	}
 }

packages/telemetry/src/render.ts

@@ -9,6 +9,11 @@ function escaped(text: string): string {
 	return text.replace(CONTROL, (char) => `\\u${char.charCodeAt(0).toString(16).padStart(4, "0")}`);
 }
 
+/** `ms` rounded to the microsecond, as the adapters record span times. */
+function microseconds(ms: number): number {
+	return Math.round(ms * 1000) / 1000;
+}
+
 function formatAttributes(attributes: Readonly<SpanAttributes> = {}): string {
 	return Object.entries(attributes)
 		.map(([key, value]) => ` ${escaped(key)}=${JSON.stringify(value)}`)
@@ -16,8 +21,9 @@ function formatAttributes(attributes: Readonly<SpanAttributes> = {}): string {
 }
 
 /**
- * Render stored spans as a chronological forest, treating absent parents as roots. Control characters in ids, names,
- * attribute keys and error messages are escaped (attribute values are JSON).
+ * Render stored spans as a chronological forest, treating absent parents as roots. Lengths of time are milliseconds to
+ * the microsecond. Control characters in ids, names, attribute keys and error messages are escaped (attribute values
+ * are JSON).
  */
 export function renderTrace(spans: readonly StoredSpan[]): string {
 	const byId = new Map(spans.map((span) => [span.id, span]));
@@ -46,10 +52,12 @@ export function renderTrace(spans: readonly StoredSpan[]): string {
 			}
 		}
 		lines.push(
-			`${indent}${escaped(span.name)}${formatAttributes(span.attributes)} (${span.endedMs - span.startedMs}ms)${error}`,
+			`${indent}${escaped(span.name)}${formatAttributes(span.attributes)} (${microseconds(span.endedMs - span.startedMs)}ms)${error}`,
 		);
 		for (const event of span.events) {
-			lines.push(`${indent}  · ${escaped(event.name)}${formatAttributes(event.attributes)} (+${event.timeMs}ms)`);
+			lines.push(
+				`${indent}  · ${escaped(event.name)}${formatAttributes(event.attributes)} (+${microseconds(event.timeMs)}ms)`,
+			);
 		}
 		for (const link of span.links) {
 			const ids = `trace ${escaped(link.traceId)} span ${escaped(link.spanId)}`;

packages/telemetry/test/render.test.ts

@@ -141,6 +141,15 @@ describe("renderTrace", () => {
 		expect(rendered.endsWith(`${"  ".repeat(1999)}1999 (10ms)`)).toBe(true);
 	});
 
+	it("renders lengths of time to the microsecond, as the adapters record them", () => {
+		const root = span("root", {
+			startedMs: 1_793_789_452_816.123,
+			endedMs: 1_793_789_452_816.431,
+			events: [{ name: "half", timeMs: 0.15400000002, attributes: {} }],
+		});
+		expect(renderTrace([root])).toBe("root (0.308ms)\n  · half (+0.154ms)");
+	});
+
 	it("renders an empty input as an empty string", () => {
 		expect(renderTrace([])).toBe("");
 	});

packages/telemetry/test/store.test.ts

@@ -1,5 +1,5 @@
 import { afterEach, describe, expect, it, vi } from "vitest";
-import { InMemoryTelemetryContext, type TelemetrySpan } from "../src/index.ts";
+import { InMemoryTelemetryContext, type TelemetrySpan, telemetryNow } from "../src/index.ts";
 import { telemetryStoreConformance } from "./store-conformance.ts";
 
 afterEach(() => vi.restoreAllMocks());
@@ -42,6 +42,23 @@ describe("in-memory store snapshots", () => {
 		expect(telemetry.getSpans()[0]).not.toHaveProperty("startedMs");
 	});
 
+	it("stamps starts with telemetryNow: spans of one millisecond apart to the microsecond, in their order", async () => {
+		vi.spyOn(Date, "now").mockReturnValue(1000);
+		const clock = vi.spyOn(performance, "now").mockReturnValue(100);
+		const telemetry = new InMemoryTelemetryContext();
+		await telemetry.startSpan({ name: "first" }, () => {
+			clock.mockReturnValue(100.25);
+		});
+		await telemetry.startSpan({ name: "second" }, () => {
+			clock.mockReturnValue(100.5);
+		});
+		const spans = (await telemetry.findTraces()).traces.flatMap((trace) => trace.spans);
+		expect(spans.map(({ name, startedMs, endedMs }) => [name, startedMs, endedMs])).toEqual([
+			["second", 1000.25, 1000.5],
+			["first", 1000, 1000.25],
+		]);
+	});
+
 	it("maps raw metric measurements to count-one rows without exposing private timing in getMetrics", async () => {
 		vi.spyOn(Date, "now").mockReturnValue(20_001);
 		const telemetry = new InMemoryTelemetryContext();
@@ -80,3 +97,32 @@ describe("in-memory store snapshots", () => {
 		expect(fresh.status).toEqual({ status: "error", error: { name: "Expected", message: "original" } });
 	});
 });
+
+describe("telemetryNow", () => {
+	it("counts sub-millisecond steps of the monotonic clock while the wall clock stays in its millisecond", () => {
+		vi.spyOn(Date, "now").mockReturnValue(50_000);
+		const clock = vi.spyOn(performance, "now").mockReturnValue(1000.25);
+		const first = telemetryNow();
+		clock.mockReturnValue(1000.2504);
+		expect(telemetryNow() - first).toBeCloseTo(0, 6);
+		clock.mockReturnValue(1000.7512);
+		expect(telemetryNow() - first).toBeCloseTo(0.501, 6);
+		expect(Number.isInteger(telemetryNow() * 1000)).toBe(true);
+	});
+
+	it("follows a step of the wall clock (set, or a sleep the monotonic clock did not count) past 10 ms", () => {
+		// Far from the anchor any earlier call left: anchored anew, at the wall clock's millisecond.
+		const wall = vi.spyOn(Date, "now").mockReturnValue(80_000);
+		const clock = vi.spyOn(performance, "now").mockReturnValue(1000);
+		expect(telemetryNow()).toBe(80_000);
+		clock.mockReturnValue(1003.5);
+		wall.mockReturnValue(80_005);
+		// Within 10 ms the anchored clock keeps its own spacing.
+		expect(telemetryNow()).toBe(80_003.5);
+		clock.mockReturnValue(1004);
+		wall.mockReturnValue(3_650_004);
+		expect(telemetryNow()).toBe(3_650_004);
+		clock.mockReturnValue(1004.125);
+		expect(telemetryNow()).toBe(3_650_004.125);
+	});
+});