From 954701b5f3c3dc82009ba9c1ee0e1d20e82b8edc Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marc-Andr=C3=A9=20Bombeck?= Date: Fri, 12 Jun 2026 20:58:30 +0200 Subject: [PATCH] feat(observability): every wide event carries the recent event-loop lag MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 | 8 ++ src/lib/logging/event-builder.ts | 10 ++ src/lib/logging/types.ts | 9 ++ .../__tests__/event-loop-lag.test.ts | 90 ++++++++++++ src/lib/observability/event-loop-lag.ts | 133 ++++++++++++++++++ 5 files changed, 250 insertions(+) create mode 100644 src/lib/observability/__tests__/event-loop-lag.test.ts create mode 100644 src/lib/observability/event-loop-lag.ts diff --git a/src/instrumentation.ts b/src/instrumentation.ts index b55797577..95eb33211 100644 --- a/src/instrumentation.ts +++ b/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; diff --git a/src/lib/logging/event-builder.ts b/src/lib/logging/event-builder.ts index cde3abd27..68d9ec18f 100644 --- a/src/lib/logging/event-builder.ts +++ b/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; } diff --git a/src/lib/logging/types.ts b/src/lib/logging/types.ts index 4df10e555..6c42befbe 100644 --- a/src/lib/logging/types.ts +++ b/src/lib/logging/types.ts @@ -89,6 +89,15 @@ export interface WideEvent { result?: Record; }; + // 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; diff --git a/src/lib/observability/__tests__/event-loop-lag.test.ts b/src/lib/observability/__tests__/event-loop-lag.test.ts new file mode 100644 index 000000000..860116190 --- /dev/null +++ b/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(); + }); +}); diff --git a/src/lib/observability/event-loop-lag.ts b/src/lib/observability/event-loop-lag.ts new file mode 100644 index 000000000..d5106564b --- /dev/null +++ b/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; +}