feat(observability): every wide event carries the recent event-loop lag

Production showed multi-second windows where every response — routes,
RSC payloads, static assets — waited together while handler durations
stayed under half a second: the process stalled, and nothing
route-shaped could name it. A self-rescheduling tick now records how
late it fires; a tick past the stall threshold emits its own
event_loop_stall background event, and every wide event carries the
recent worst lag so the first request finishing after a stall is
annotated with it. Measured via a timeout chain rather than
perf_hooks.monitorEventLoopDelay — the histogram's sampling timer races
a sibling read-and-reset interval in the same timers phase and the
stall sample can vanish into the reset window.

src/instrumentation.ts

@@ -3,6 +3,14 @@ import type { Instrumentation } from "next";
 export async function register() {
   // Only start the worker on the Node.js server runtime (not Edge, not build)
   if (process.env.NEXT_RUNTIME === "nodejs") {
+    // Every Node process watches its own event loop — web-only
+    // containers included; a stall report from the process serving
+    // requests is the whole point.
+    const { startEventLoopLagMonitor } = await import(
+      "@/lib/observability/event-loop-lag"
+    );
+    startEventLoopLagMonitor();
+
     const { shouldRunWorker } = await import("@/lib/process-type");
     // Web-only container — the dedicated worker service runs the queues.
     if (!shouldRunWorker()) return;

src/lib/logging/event-builder.ts

@@ -131,6 +131,16 @@ export class WideEventBuilder {
   /** Request/Operation beenden, Duration berechnen */
   finish(httpStatus?: number): this {
     this.event.duration_ms = Math.round(performance.now() - this.startTime);
+    // Event-Loop-Lag des letzten Sampling-Fensters anheften, falls der
+    // Monitor laeuft. Bewusst ueber den Global-Slot statt Import gelesen:
+    // dieser Builder wird in die Edge-Runtime gebuendelt, wo perf_hooks
+    // nicht existiert — der Slot ist dort einfach leer.
+    const lag = (
+      globalThis as unknown as {
+        [key: symbol]: { loop_max_ms: number; loop_p99_ms: number };
+      }
+    )[Symbol.for("healthlog.eventLoopLag")];
+    if (lag) this.event.runtime = lag;
     if (httpStatus !== undefined && this.event.http) {
       this.event.http.status = httpStatus;
     }

src/lib/logging/types.ts

@@ -89,6 +89,15 @@ export interface WideEvent {
     result?: Record<string, unknown>;
   };
 
+  // Prozess-Zustand zum Abschlusszeitpunkt (nur Node-Runtime; siehe
+  // observability/event-loop-lag.ts — das letzte Sampling-Fenster der
+  // Event-Loop-Verzoegerung, damit der erste Request nach einem Stall
+  // den Stall mitfuehrt)
+  runtime?: {
+    loop_max_ms: number;
+    loop_p99_ms: number;
+  };
+
   // Fehler-Details
   error?: {
     type: string;

src/lib/observability/__tests__/event-loop-lag.test.ts

@@ -0,0 +1,90 @@
+import { afterEach, describe, expect, it, vi } from "vitest";
+
+import {
+  EVENT_LOOP_LAG_GLOBAL,
+  eventLoopLagSnapshot,
+  startEventLoopLagMonitor,
+} from "../event-loop-lag";
+
+/**
+ * The monitor's job is self-documentation of process stalls: a tick
+ * that fires late because the loop was blocked must (a) publish the lag
+ * on the global slot every wide event reads, and (b) emit the dedicated
+ * stall callback when the lag crosses the threshold. The loop is
+ * blocked for real (busy-wait) — fake timers would defeat the thing
+ * being measured.
+ */
+
+const STARTED = Symbol.for("healthlog.eventLoopLag.started");
+
+type Slots = {
+  [EVENT_LOOP_LAG_GLOBAL]?: unknown;
+  [STARTED]?: boolean;
+};
+
+function resetMonitorGlobals() {
+  const slots = globalThis as unknown as Slots;
+  delete slots[EVENT_LOOP_LAG_GLOBAL];
+  delete slots[STARTED];
+}
+
+function blockLoopFor(ms: number) {
+  const until = performance.now() + ms;
+  while (performance.now() < until) {
+    // busy-wait — a deliberate, real event-loop stall
+  }
+}
+
+const sleep = (ms: number) => new Promise((r) => setTimeout(r, ms));
+
+afterEach(() => {
+  resetMonitorGlobals();
+});
+
+describe("event-loop lag monitor", () => {
+  it("publishes the lag and reports a stall crossing the threshold", async () => {
+    resetMonitorGlobals();
+    const stalls: Array<{ lag_ms: number }> = [];
+    startEventLoopLagMonitor({
+      tickIntervalMs: 25,
+      stallThresholdMs: 80,
+      emitStall: (s) => stalls.push(s),
+    });
+
+    // Let a first tick establish the chain, then block the loop long
+    // enough that the next tick fires far past its schedule.
+    await sleep(40);
+    blockLoopFor(200);
+    await sleep(60);
+
+    const snapshot = eventLoopLagSnapshot();
+    expect(snapshot).not.toBeNull();
+    expect(snapshot!.loop_max_ms).toBeGreaterThanOrEqual(80);
+    expect(stalls.length).toBeGreaterThanOrEqual(1);
+    expect(stalls[0].lag_ms).toBeGreaterThanOrEqual(80);
+  });
+
+  it("stays quiet below the threshold", async () => {
+    resetMonitorGlobals();
+    const stalls: unknown[] = [];
+    startEventLoopLagMonitor({
+      tickIntervalMs: 25,
+      stallThresholdMs: 5_000,
+      emitStall: (s) => stalls.push(s),
+    });
+
+    await sleep(80);
+
+    expect(eventLoopLagSnapshot()).not.toBeNull();
+    expect(stalls).toHaveLength(0);
+  });
+
+  it("is idempotent — a second start never stacks a second timer chain", () => {
+    resetMonitorGlobals();
+    const setTimeoutSpy = vi.spyOn(global, "setTimeout");
+    startEventLoopLagMonitor({ emitStall: () => {} });
+    startEventLoopLagMonitor({ emitStall: () => {} });
+    expect(setTimeoutSpy).toHaveBeenCalledTimes(1);
+    setTimeoutSpy.mockRestore();
+  });
+});

src/lib/observability/event-loop-lag.ts

@@ -0,0 +1,133 @@
+import { WideEventBuilder } from "@/lib/logging/event-builder";
+import { emitIfSampled } from "@/lib/logging/transports";
+
+/**
+ * Event-loop lag monitor — the instance-level "was the PROCESS stalled"
+ * signal that per-request durations cannot carry.
+ *
+ * Motivation: production showed multi-second windows where every
+ * response — API routes, RSC payloads, even static assets — waited
+ * together while the handler durations logged in the same window stayed
+ * under half a second. That shape means the Node event loop itself (or
+ * its host) stopped turning; no per-route metric can name the culprit
+ * because nothing route-shaped is slow. This monitor (a) emits a
+ * dedicated wide event whenever a tick fires late enough to call a
+ * stall, (b) publishes the recent worst lag for every wide event to
+ * carry, so the first request finishing after a stall is annotated
+ * with it.
+ *
+ * Measurement: a self-rescheduling timeout records how late each tick
+ * fired versus its scheduled instant. A blocked loop cannot fire the
+ * tick, so the stall length lands in the very next tick's lag. This is
+ * deliberately NOT `perf_hooks.monitorEventLoopDelay` — its internal
+ * sampling timer races a sibling read-and-reset interval inside the
+ * same timers phase, and the stall sample can vanish into the window
+ * that was just reset (reproduced under vitest).
+ *
+ * The snapshot is published on a `globalThis` slot rather than imported
+ * by the event builder: the builder is bundled into the Edge-runtime
+ * proxy, and reading a global keeps the dependency one-directional
+ * (monitor → global ← builder) and edge-safe by construction.
+ */
+
+export interface EventLoopLagSnapshot {
+  /** Worst tick lag (ms) across the recent snapshot horizon. */
+  loop_max_ms: number;
+  /** Lag (ms) of the most recent tick. */
+  loop_last_ms: number;
+}
+
+export const EVENT_LOOP_LAG_GLOBAL = Symbol.for("healthlog.eventLoopLag");
+
+/**
+ * 250 ms ticks: fine enough that any stall ≥ the 500 ms threshold MUST
+ * delay a tick (a stall can hide from a coarse cadence by fitting
+ * between two fires), cheap enough to run always — four unref'd timer
+ * wakeups per second. The snapshot horizon keeps the worst lag of the
+ * last ~2 s so the first requests finishing after a stall carry it.
+ */
+const TICK_INTERVAL_MS = 250;
+const STALL_THRESHOLD_MS = 500;
+const SNAPSHOT_HORIZON_TICKS = 8;
+const STARTED = Symbol.for("healthlog.eventLoopLag.started");
+
+type GlobalSlots = {
+  [EVENT_LOOP_LAG_GLOBAL]?: EventLoopLagSnapshot;
+  [STARTED]?: boolean;
+};
+
+export interface EventLoopLagMonitorOptions {
+  tickIntervalMs?: number;
+  stallThresholdMs?: number;
+  /** Test seam — replaces the wide-event emit. */
+  emitStall?: (stall: { lag_ms: number; tick_interval_ms: number }) => void;
+}
+
+function defaultEmitStall(stall: {
+  lag_ms: number;
+  tick_interval_ms: number;
+}): void {
+  const evt = new WideEventBuilder("background");
+  evt.setBackground({ task_name: "event_loop_stall", result: stall });
+  evt.elevateLevel("warn");
+  evt.finish();
+  emitIfSampled(evt.toJSON());
+}
+
+/**
+ * Start the monitor. Idempotent per process — hot reload in dev and the
+ * dual web+worker boot path both call it without stacking timers. The
+ * timeout chain is unref'd so it never holds the process open.
+ */
+export function startEventLoopLagMonitor(
+  options: EventLoopLagMonitorOptions = {},
+): void {
+  const slots = globalThis as unknown as GlobalSlots;
+  if (slots[STARTED]) return;
+  slots[STARTED] = true;
+
+  const {
+    tickIntervalMs = TICK_INTERVAL_MS,
+    stallThresholdMs = STALL_THRESHOLD_MS,
+    emitStall = defaultEmitStall,
+  } = options;
+
+  const recentLags: number[] = [];
+  let scheduledAt = performance.now() + tickIntervalMs;
+
+  const tick = () => {
+    const now = performance.now();
+    const lagMs = Math.max(0, now - scheduledAt);
+
+    recentLags.push(lagMs);
+    if (recentLags.length > SNAPSHOT_HORIZON_TICKS) recentLags.shift();
+    slots[EVENT_LOOP_LAG_GLOBAL] = {
+      loop_max_ms: Math.round(Math.max(...recentLags) * 10) / 10,
+      loop_last_ms: Math.round(lagMs * 10) / 10,
+    };
+
+    if (lagMs >= stallThresholdMs) {
+      emitStall({
+        lag_ms: Math.round(lagMs),
+        tick_interval_ms: tickIntervalMs,
+      });
+    }
+
+    scheduledAt = performance.now() + tickIntervalMs;
+    const timer = setTimeout(tick, tickIntervalMs);
+    timer.unref();
+  };
+
+  const timer = setTimeout(tick, tickIntervalMs);
+  timer.unref();
+}
+
+/**
+ * Recent worst tick lag, or null before the first tick (and on runtimes
+ * where the monitor never starts, e.g. Edge). Read by the wide-event
+ * builder via the global slot — see the module header.
+ */
+export function eventLoopLagSnapshot(): EventLoopLagSnapshot | null {
+  const slots = globalThis as unknown as GlobalSlots;
+  return slots[EVENT_LOOP_LAG_GLOBAL] ?? null;
+}