mirror of
https://github.com/paperclipai/paperclip.git
synced 2026-11-13 07:12:00 +01:00
fix(server): record a long event-loop block with the deltas that name its cause (#20709)
## Thinking Path > - Paperclip is the open source app people use to manage AI agents for work > - One server process owns the controller leases of its runs, renews them on timers, and serves every request > - On a hosted instance, the process stopped for about 103 seconds without a restart. Every lease lapsed, and two runs needed a manual Retry (the symptom is fixed in #20694) > - Nobody can say what blocked the process. The server records no event-loop delay, and it has no CPU, GC or memory record for that minute > - This pull request logs one local line for each event-loop block of 2 s or more. The line holds the deltas that tell the possible causes apart, and a likely-cause class > - The benefit is that the next stall names its class (main-thread CPU, GC, paging, CPU throttling, host suspend, or a blocking sync call) and its exact time, so we can match it to the run timeline and fix the cause ## Linked Issues or Issue Description Refs #20694 **What happened?** On a hosted instance, the merged run-event timeline of all active runs had no events from 08:19:52.04Z to 08:21:35.37Z (103.3 s). Events from streaming runs arrived about every 0.5 s before and after the gap. The process did not restart (the run diagnostic shows an observer uptime of about 24 minutes when the reaper ran). The first event after the gap was a span with a 60 s timeout that ended after 103.5 s. Thus the timer callback ran about 43 s late. This agrees with a blocked event loop, or with a frozen process. Nothing in the process recorded which one. **Expected behavior** A long event-loop block is a product failure. It lapses every lease and freezes every user. The server must record each long block with enough data to identify its cause. **Steps to reproduce** 1. Start the server. 2. Block the main thread for more than 2 s, for example with a synchronous read on a slow disk or a busy loop. 3. Before this change: the logs show nothing. After this change: the logs show `event loop blocked for <n> ms (likely <cause>)` with the measured deltas. ## What Changed - `server/src/event-loop-stall-monitor.ts` (new): one unref'd 1.5 s timeout, re-armed after each check, measures how late it runs. (Server startup creates no interval timers, so it is not a `setInterval`.) When a check is 2 s or more late, it logs once with these fields: - stall duration, start and end time (wall clock and monotonic clock) - process CPU (user and system), GC pause time and count (`perf_hooks` GC entries) - major and minor page faults, file-system reads and writes, voluntary and involuntary context switches (`process.resourceUsage()`) - cgroup v2 `throttled_usec` delta (Linux; read asynchronously, best effort) - RSS, heap and external memory - `likelyCause`: `host_suspended`, `gc`, `memory_paging`, `cpu_throttled`, `main_thread_cpu`, or `blocked_off_cpu` (sync file I/O, a sync child process, or another off-CPU wait) - `server/src/index.ts`: starts the monitor when the listener binds. It stops the monitor at the start of shutdown, and when a failed startup closes the listener. It writes the line with the existing `logger.warn`. - This is a local log line only. It is not the Telemetry path and not the Observability (OpenTelemetry) path. No data leaves the process. ## Verification - `pnpm --filter @paperclipai/server exec vitest run src/event-loop-stall-monitor.test.ts src/__tests__/server-startup-feedback-export.test.ts` (131 passed; the monitor file passed 5 runs in a row): - an 800 ms busy loop is recorded as `main_thread_cpu`, with the stall and CPU time - an 800 ms `Atomics.wait` (blocks without CPU, like a sync read on a stalled disk) is recorded as `blocked_off_cpu` - nothing is logged while the loop is responsive, or after `stop()` (injected clock) - the file-read delta of a stall is kept while the cgroup read is pending - server startup still creates no interval timer - a 100 s stall with 90 s of cgroup throttling is recorded as `cpu_throttled`, with the stall start and end times - each cause class is selected from its deltas - `pnpm --filter @paperclipai/server exec tsc --noEmit` passes. - CI supplies the broad server suites. ## Risks - Low risk. The timeout reads only process counters. Every 10 s it reads one small cgroup file asynchronously. It does not query 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. - `process.cpuUsage()` counts all threads of the process, not only the main thread. A busy libuv thread pool during a stall can make an off-CPU block look like `main_thread_cpu`. The raw deltas are in the line, so a reader can check this. - If a platform suspends and resumes the process, each resume can log one `host_suspended` line. This is expected and useful. - The monitor names the class of a block, not the call stack. If the class is not enough, the next step is a bounded CPU profile around the stall time. ## Model Used - Anthropic Claude Opus 5.5 (`claude-opus-5-5`), used through Claude Code with tool use, shell, and code execution. ## Checklist - [x] I have included a thinking path that traces from project context to this change - [x] I have specified the model used (with version and capability details) - [x] I have checked ROADMAP.md and confirmed this PR does not duplicate planned core work - [x] I have searched GitHub for duplicate or related PRs and linked them above - [x] I have either (a) linked existing issues with `Fixes: #` / `Closes #` / `Refs #` OR (b) described the issue in-PR following the relevant issue template - [x] I have not referenced internal/instance-local Paperclip issues or links (only public GitHub `#NNN` / `github.com/paperclipai/paperclip` URLs) - [x] My branch name describes the change (e.g. `docs/...`, `fix/...`) and contains no internal Paperclip ticket id or instance-derived details - [x] I have run tests locally and they pass - [x] I have added or updated tests where applicable - [x] I have updated relevant documentation to reflect my changes (the module comment carries the contract) - [x] I have considered and documented any risks above - [ ] All Paperclip CI gates are green - [ ] Greptile is 5/5 with no open P2s, recommendations, or follow-ups - [x] I will address all Greptile and reviewer comments before requesting merge 🤖 Generated with [Claude Code](https://claude.com/claude-code) --------- Co-authored-by: Claude <noreply@anthropic.com>
This commit is contained in:
DottaandClaude authored and GitHub committed
1 parent
6d1eae73c0
commit
855e241887
3 files changed
+457
No files matched your search
@@ -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<typeof startEventLoopStallMonitor>[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");
|
||||
});
|
||||
});
|
||||
@@ -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<number | null>;
|
||||
};
|
||||
|
||||
export type EventLoopStallMonitorOptions = {
|
||||
log: (stall: EventLoopStall) => void;
|
||||
intervalMs?: number;
|
||||
thresholdMs?: number;
|
||||
probes?: Partial<EventLoopStallProbes>;
|
||||
// GC pause entries can be supplied by a test; by default a GC observer is used.
|
||||
gcEntries?: () => readonly Pick<PerformanceEntry, "startTime" | "duration">[];
|
||||
};
|
||||
|
||||
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<number | null> {
|
||||
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<PerformanceEntry, "startTime" | "duration">[] = [];
|
||||
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<NodeJS.Timeout>).unref?.();
|
||||
};
|
||||
arm();
|
||||
sampleCgroup();
|
||||
cgroupSampledAt = lastMonotonic;
|
||||
|
||||
return {
|
||||
stop: () => {
|
||||
stopped = true;
|
||||
if (timer) clearTimeout(timer);
|
||||
gcObserver?.disconnect();
|
||||
},
|
||||
};
|
||||
}
|
||||
@@ -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();
|
||||
|
||||
Reference in new issue
Block a user