diff --git a/server/src/event-loop-stall-monitor.test.ts b/server/src/event-loop-stall-monitor.test.ts new file mode 100644 index 00000000000..303630709d3 --- /dev/null +++ b/server/src/event-loop-stall-monitor.test.ts @@ -0,0 +1,160 @@ +import { afterEach, describe, expect, it, vi } from "vitest"; +import { + classifyEventLoopStall, + startEventLoopStallMonitor, + type EventLoopStall, +} from "./event-loop-stall-monitor.js"; + +const waitFor = async (predicate: () => boolean, timeoutMs = 5_000) => { + const deadline = Date.now() + timeoutMs; + while (!predicate()) { + if (Date.now() > deadline) throw new Error("timed out waiting for the stall report"); + await new Promise((resolve) => setTimeout(resolve, 10)); + } +}; + +const blockWithCpu = (ms: number) => { + const until = Date.now() + ms; + let spin = 0; + while (Date.now() < until) spin += 1; + return spin; +}; + +// Blocks the main thread without using CPU, like a sync read on a stalled disk +// or a sync child process. +const blockOffCpu = (ms: number) => { + Atomics.wait(new Int32Array(new SharedArrayBuffer(4)), 0, 0, ms); +}; + +describe("event-loop stall monitor", () => { + const stops: Array<() => void> = []; + afterEach(() => { + while (stops.length > 0) stops.pop()!(); + vi.useRealTimers(); + }); + + const start = (options: Parameters[0]) => { + const monitor = startEventLoopStallMonitor(options); + stops.push(monitor.stop); + return monitor; + }; + + it("records a main-thread CPU block with its duration and CPU time", async () => { + const stalls: EventLoopStall[] = []; + const caused = () => stalls.filter((stall) => stall.stallMs >= 700); + start({ log: (stall) => stalls.push(stall), intervalMs: 20, thresholdMs: 250, probes: { readCgroupThrottledUsec: async () => null } }); + await new Promise((resolve) => setTimeout(resolve, 60)); + + blockWithCpu(800); + await waitFor(() => caused().length > 0); + + // A loaded runner can add unrelated pauses; check the one this test caused. + const [stall] = caused(); + expect(stall!.cpuUserMs + stall!.cpuSystemMs).toBeGreaterThanOrEqual(400); + expect(stall!.likelyCause).toBe("main_thread_cpu"); + expect(Date.parse(stall!.stallEndedAt) - Date.parse(stall!.stallStartedAt)).toBeGreaterThanOrEqual(700); + }); + + it("records an off-CPU block, such as sync I/O, as blocked_off_cpu", async () => { + const stalls: EventLoopStall[] = []; + const caused = () => stalls.filter((stall) => stall.stallMs >= 700); + start({ log: (stall) => stalls.push(stall), intervalMs: 20, thresholdMs: 250, probes: { readCgroupThrottledUsec: async () => null } }); + await new Promise((resolve) => setTimeout(resolve, 60)); + + blockOffCpu(800); + await waitFor(() => caused().length > 0); + + const [stall] = caused(); + expect(stall!.likelyCause).toBe("blocked_off_cpu"); + }); + + const fakeProbes = (state: { monotonic: number; throttledUsec: number | null; fsRead: number }) => ({ + monotonicNow: () => state.monotonic, + wallNow: () => 1_794_298_792_000 + state.monotonic, + cpuUsage: () => ({ user: 0, system: 0 }), + resourceUsage: () => ({ + majorPageFault: 0, minorPageFault: 0, fsRead: state.fsRead, fsWrite: 0, + voluntaryContextSwitches: 0, involuntaryContextSwitches: 0, + }), + readCgroupThrottledUsec: async () => state.throttledUsec, + }); + + it("stays silent while the loop is responsive and after stop", async () => { + vi.useFakeTimers(); + const state = { monotonic: 0, throttledUsec: null, fsRead: 0 }; + const log = vi.fn(); + const monitor = start({ log, intervalMs: 500, thresholdMs: 2_000, gcEntries: () => [], probes: fakeProbes(state) }); + for (let tick = 1; tick <= 10; tick++) { + state.monotonic = tick * 500 + 100; + await vi.advanceTimersByTimeAsync(500); + } + expect(log).not.toHaveBeenCalled(); + + monitor.stop(); + state.monotonic += 60_000; + await vi.advanceTimersByTimeAsync(5_000); + expect(log).not.toHaveBeenCalled(); + }); + + it("keeps the I/O deltas of the stall while the cgroup read is pending", async () => { + vi.useFakeTimers(); + const state = { monotonic: 0, throttledUsec: 5_000_000 as number | null, fsRead: 10 }; + const stalls: EventLoopStall[] = []; + start({ log: (stall) => stalls.push(stall), intervalMs: 500, thresholdMs: 2_000, gcEntries: () => [], probes: fakeProbes(state) }); + await vi.advanceTimersByTimeAsync(0); + + state.monotonic = 100_500; + state.fsRead = 4_010; + await vi.advanceTimersByTimeAsync(500); + + expect(stalls).toHaveLength(1); + expect(stalls[0]).toMatchObject({ fsReads: 4_000, cgroupThrottledMs: 0, likelyCause: "blocked_off_cpu" }); + }); + + it("reports cgroup throttling measured across the stall", async () => { + vi.useFakeTimers(); + let monotonic = 0; + let throttledUsec = 1_000_000; + const stalls: EventLoopStall[] = []; + start({ + log: (stall) => stalls.push(stall), + intervalMs: 500, + thresholdMs: 2_000, + gcEntries: () => [], + probes: { + monotonicNow: () => monotonic, + wallNow: () => 1_794_298_792_000 + monotonic, + cpuUsage: () => ({ user: 0, system: 0 }), + resourceUsage: () => ({ + majorPageFault: 0, minorPageFault: 0, fsRead: 0, fsWrite: 0, + voluntaryContextSwitches: 0, involuntaryContextSwitches: 0, + }), + readCgroupThrottledUsec: async () => throttledUsec, + }, + }); + await vi.advanceTimersByTimeAsync(0); + + monotonic = 100_500; + throttledUsec += 90_000_000; + await vi.advanceTimersByTimeAsync(500); + + expect(stalls).toHaveLength(1); + expect(stalls[0]).toMatchObject({ + stallMs: 100_000, + stallStartedAt: "2026-11-10T08:19:52.000Z", + stallEndedAt: "2026-11-10T08:21:32.500Z", + cgroupThrottledMs: 90_000, + likelyCause: "cpu_throttled", + }); + }); + + it("classifies each cause from the measured deltas", () => { + const base = { stallMs: 100_000, monotonicElapsedMs: 100_500, wallElapsedMs: 100_500, cpuMs: 0, gcPauseMs: 0, majorPageFaults: 0, cgroupThrottledMs: null }; + expect(classifyEventLoopStall(base)).toBe("blocked_off_cpu"); + expect(classifyEventLoopStall({ ...base, cpuMs: 99_000 })).toBe("main_thread_cpu"); + expect(classifyEventLoopStall({ ...base, cpuMs: 99_000, gcPauseMs: 95_000 })).toBe("gc"); + expect(classifyEventLoopStall({ ...base, majorPageFaults: 50_000 })).toBe("memory_paging"); + expect(classifyEventLoopStall({ ...base, cgroupThrottledMs: 80_000 })).toBe("cpu_throttled"); + expect(classifyEventLoopStall({ ...base, monotonicElapsedMs: 500 })).toBe("host_suspended"); + }); +}); diff --git a/server/src/event-loop-stall-monitor.ts b/server/src/event-loop-stall-monitor.ts new file mode 100644 index 00000000000..989bbc6b279 --- /dev/null +++ b/server/src/event-loop-stall-monitor.ts @@ -0,0 +1,288 @@ +import { readFile } from "node:fs/promises"; +import { PerformanceObserver, performance, type PerformanceEntry } from "node:perf_hooks"; + +// Records a long event-loop block as one local log line. Nothing leaves the +// process: this is neither the Telemetry nor the Observability path. +// +// A timer that should fire every `intervalMs` measures how late it ran. When it +// is late by `thresholdMs` or more, the line carries the process-level deltas +// that tell the usual causes apart: +// - main-thread CPU work (sync JSON, regex, hashing, compression): CPU ≈ stall +// - garbage collection: GC pause time ≈ stall +// - memory paging: many major page faults +// - host suspend: wall clock advanced far more than the monotonic clock +// - CPU throttling by the container: cgroup throttled time grows +// - sync file I/O or a sync child process: little CPU, none of the above +// +// The timer reads only process counters (and, every ten seconds, the cgroup's +// cpu.stat). It never queries the database or the network, so it does not keep +// an idle instance or its database awake; it is unref'd and stopped on shutdown. +export type EventLoopStallCause = + | "gc" + | "main_thread_cpu" + | "memory_paging" + | "host_suspended" + | "cpu_throttled" + | "blocked_off_cpu"; + +export type EventLoopStall = { + stallMs: number; + monotonicElapsedMs: number; + wallElapsedMs: number; + stallStartedAt: string; + stallEndedAt: string; + likelyCause: EventLoopStallCause; + cpuUserMs: number; + cpuSystemMs: number; + gcPauseMs: number; + gcCount: number; + majorPageFaults: number; + minorPageFaults: number; + fsReads: number; + fsWrites: number; + voluntaryContextSwitches: number; + involuntaryContextSwitches: number; + cgroupThrottledMs: number | null; + rssBytes: number; + heapUsedBytes: number; + heapTotalBytes: number; + externalBytes: number; + arrayBuffersBytes: number; + processUptimeSec: number; +}; + +type ResourceSample = Pick< + NodeJS.ResourceUsage, + | "majorPageFault" + | "minorPageFault" + | "fsRead" + | "fsWrite" + | "voluntaryContextSwitches" + | "involuntaryContextSwitches" +>; + +export type EventLoopStallProbes = { + monotonicNow: () => number; + wallNow: () => number; + cpuUsage: () => NodeJS.CpuUsage; + resourceUsage: () => ResourceSample; + memoryUsage: () => NodeJS.MemoryUsage; + uptimeSec: () => number; + // Total time this process's cgroup was CPU-throttled, in microseconds, or null. + readCgroupThrottledUsec: () => Promise; +}; + +export type EventLoopStallMonitorOptions = { + log: (stall: EventLoopStall) => void; + intervalMs?: number; + thresholdMs?: number; + probes?: Partial; + // GC pause entries can be supplied by a test; by default a GC observer is used. + gcEntries?: () => readonly Pick[]; +}; + +export const EVENT_LOOP_STALL_INTERVAL_MS = 1_500; +export const EVENT_LOOP_STALL_THRESHOLD_MS = 2_000; +const CGROUP_SAMPLE_INTERVAL_MS = 10_000; +const MAX_GC_ENTRIES = 512; +const MAJOR_FAULTS_FOR_PAGING = 1_000; + +async function readCgroupV2ThrottledUsec(): Promise { + if (process.platform !== "linux") return null; + try { + const stat = await readFile("/sys/fs/cgroup/cpu.stat", "utf8"); + const match = /^throttled_usec\s+(\d+)$/m.exec(stat); + return match ? Number(match[1]) : null; + } catch { + return null; + } +} + +const defaultProbes: EventLoopStallProbes = { + monotonicNow: () => performance.now(), + wallNow: () => Date.now(), + cpuUsage: () => process.cpuUsage(), + resourceUsage: () => process.resourceUsage(), + memoryUsage: () => process.memoryUsage(), + uptimeSec: () => process.uptime(), + readCgroupThrottledUsec: readCgroupV2ThrottledUsec, +}; + +export function classifyEventLoopStall(input: { + stallMs: number; + monotonicElapsedMs: number; + wallElapsedMs: number; + cpuMs: number; + gcPauseMs: number; + majorPageFaults: number; + cgroupThrottledMs: number | null; +}): EventLoopStallCause { + const half = input.stallMs / 2; + if (input.wallElapsedMs - input.monotonicElapsedMs >= half) return "host_suspended"; + if (input.gcPauseMs >= half) return "gc"; + if (input.majorPageFaults >= MAJOR_FAULTS_FOR_PAGING) return "memory_paging"; + if (input.cgroupThrottledMs !== null && input.cgroupThrottledMs >= half) return "cpu_throttled"; + if (input.cpuMs >= half) return "main_thread_cpu"; + return "blocked_off_cpu"; +} + +export function startEventLoopStallMonitor(options: EventLoopStallMonitorOptions): { stop: () => void } { + const probes = { ...defaultProbes, ...options.probes }; + const intervalMs = options.intervalMs ?? EVENT_LOOP_STALL_INTERVAL_MS; + const thresholdMs = options.thresholdMs ?? EVENT_LOOP_STALL_THRESHOLD_MS; + + let gcObserver: PerformanceObserver | null = null; + const observedGc: Pick[] = []; + let gcEntries = options.gcEntries; + if (!gcEntries) { + try { + gcObserver = new PerformanceObserver((list) => { + for (const entry of list.getEntries()) { + observedGc.push({ startTime: entry.startTime, duration: entry.duration }); + } + if (observedGc.length > MAX_GC_ENTRIES) observedGc.splice(0, observedGc.length - MAX_GC_ENTRIES); + }); + gcObserver.observe({ entryTypes: ["gc"] }); + } catch { + gcObserver = null; + } + gcEntries = () => observedGc; + } + + let lastMonotonic = probes.monotonicNow(); + let lastWall = probes.wallNow(); + let lastCpu = probes.cpuUsage(); + let lastResources = probes.resourceUsage(); + let cgroupBaseline: number | null = null; + let cgroupSampledAt = Number.NEGATIVE_INFINITY; + let cgroupReading = false; + let stopped = false; + + const sampleCgroup = () => { + if (cgroupReading || stopped) return; + cgroupReading = true; + void probes.readCgroupThrottledUsec() + .then((value) => { cgroupBaseline = value; }) + .catch(() => { cgroupBaseline = null; }) + .finally(() => { cgroupReading = false; }); + }; + + const check = () => { + const monotonic = probes.monotonicNow(); + const wall = probes.wallNow(); + const monotonicElapsedMs = monotonic - lastMonotonic; + const wallElapsedMs = wall - lastWall; + // A host suspend may stop the monotonic clock, so use the larger of the two. + const stallMs = Math.max(monotonicElapsedMs, wallElapsedMs) - intervalMs; + if (stallMs >= thresholdMs) { + const cpu = probes.cpuUsage(); + const resources = probes.resourceUsage(); + const memory = probes.memoryUsage(); + const windowStart = lastMonotonic; + let gcPauseMs = 0; + let gcCount = 0; + for (const entry of gcEntries!()) { + if (entry.startTime + entry.duration < windowStart || entry.startTime > monotonic) continue; + gcPauseMs += entry.duration; + gcCount += 1; + } + const cpuUserMs = (cpu.user - lastCpu.user) / 1000; + const cpuSystemMs = (cpu.system - lastCpu.system) / 1000; + // Compute every delta now: the cgroup read below is asynchronous, and + // later ticks replace the baselines before it settles. + const previous = lastResources; + const majorPageFaults = resources.majorPageFault - previous.majorPageFault; + const minorPageFaults = resources.minorPageFault - previous.minorPageFault; + const fsReads = resources.fsRead - previous.fsRead; + const fsWrites = resources.fsWrite - previous.fsWrite; + const voluntaryContextSwitches = resources.voluntaryContextSwitches - previous.voluntaryContextSwitches; + const involuntaryContextSwitches = resources.involuntaryContextSwitches - previous.involuntaryContextSwitches; + const uptimeSec = Math.round(probes.uptimeSec()); + const baseline = cgroupBaseline; + const stallStartedAt = new Date(lastWall).toISOString(); + const stallEndedAt = new Date(wall).toISOString(); + const report = (cgroupThrottledMs: number | null) => { + const rounded = Math.round(stallMs); + options.log({ + stallMs: rounded, + monotonicElapsedMs: Math.round(monotonicElapsedMs), + wallElapsedMs: Math.round(wallElapsedMs), + stallStartedAt, + stallEndedAt, + likelyCause: classifyEventLoopStall({ + stallMs: rounded, + monotonicElapsedMs, + wallElapsedMs, + cpuMs: cpuUserMs + cpuSystemMs, + gcPauseMs, + majorPageFaults, + cgroupThrottledMs, + }), + cpuUserMs: Math.round(cpuUserMs), + cpuSystemMs: Math.round(cpuSystemMs), + gcPauseMs: Math.round(gcPauseMs), + gcCount, + majorPageFaults, + minorPageFaults, + fsReads, + fsWrites, + voluntaryContextSwitches, + involuntaryContextSwitches, + cgroupThrottledMs, + rssBytes: memory.rss, + heapUsedBytes: memory.heapUsed, + heapTotalBytes: memory.heapTotal, + externalBytes: memory.external, + arrayBuffersBytes: memory.arrayBuffers, + processUptimeSec: uptimeSec, + }); + }; + // Throttled time is read after the stall; the baseline is at most one + // sampling interval older than the stall start, so the delta can include + // a few seconds before it. + if (baseline === null) { + report(null); + } else { + void probes.readCgroupThrottledUsec() + .then((after) => stopped ? undefined : report(after === null ? null : Math.round((after - baseline) / 1000))) + .catch(() => report(null)); + } + cgroupSampledAt = Number.NEGATIVE_INFINITY; + lastCpu = cpu; + lastResources = resources; + } else { + lastCpu = probes.cpuUsage(); + lastResources = probes.resourceUsage(); + } + lastMonotonic = monotonic; + lastWall = wall; + if (monotonic - cgroupSampledAt >= CGROUP_SAMPLE_INTERVAL_MS) { + cgroupSampledAt = monotonic; + sampleCgroup(); + } + }; + + // One pending unref'd timeout, re-armed after each check. Server startup + // creates no interval timers, and this probe is not a work scan. + let timer: NodeJS.Timeout | null = null; + const arm = () => { + if (stopped) return; + timer = setTimeout(() => { + timer = null; + check(); + arm(); + }, intervalMs); + (timer as Partial).unref?.(); + }; + arm(); + sampleCgroup(); + cgroupSampledAt = lastMonotonic; + + return { + stop: () => { + stopped = true; + if (timer) clearTimeout(timer); + gcObserver?.disconnect(); + }, + }; +} diff --git a/server/src/index.ts b/server/src/index.ts index dfa92d5a9ad..37a0c42d20e 100644 --- a/server/src/index.ts +++ b/server/src/index.ts @@ -132,6 +132,7 @@ import { drainHttpRequestWork } from "./middleware/idle-admission.js"; import { initializeCloudRuntimeConfig } from "./services/cloud-runtime-config.js"; import { loadCloudBootstrapConfig, loadConfig, type Config } from "./config.js"; import { logger } from "./middleware/logger.js"; +import { startEventLoopStallMonitor } from "./event-loop-stall-monitor.js"; import { setStartupRecoveryPhase } from "./startup-recovery-state.js"; import { StartupRefusalError, @@ -1090,6 +1091,13 @@ async function startServerWithDatabaseTeardown( }); }); startupListenerBound = true; + // A blocked event loop lapses every controller lease and freezes every + // request, so record each long block with the deltas that name its class. + const eventLoopStallMonitor = startEventLoopStallMonitor({ + log: (stall) => logger.warn({ eventLoopStall: stall }, `event loop blocked for ${stall.stallMs} ms (likely ${stall.likelyCause})`), + }); + // A failed startup closes the listener without the ordered shutdown path. + server.once("close", () => eventLoopStallMonitor.stop()); // The factory publishes the verified numeric endpoint on listening. Native // recovery must never fall back to a configured/public URL if it is absent. resolveLocalRuntimeApiUrl(); @@ -2062,6 +2070,7 @@ async function startServerWithDatabaseTeardown( ) => { const shutdownStartedAt = Date.now(); logger.info({ signal }, "shutdown signal received; starting ordered shutdown"); + eventLoopStallMonitor.stop(); setStartupRecoveryPhase("draining"); for (const client of liveEventsWebSocketServer.clients) client.close(1012, "Server restarting"); liveEventsWebSocketServer.close();