diff --git a/packages/tui/src/loop-watchdog.ts b/packages/tui/src/loop-watchdog.ts index b02bc4b9e..10f39f00b 100644 --- a/packages/tui/src/loop-watchdog.ts +++ b/packages/tui/src/loop-watchdog.ts @@ -6,10 +6,12 @@ export interface LoopWatchdogOptions { intervalMs?: number; /** A tick later than this past its deadline counts as a block. Default 250. */ thresholdMs?: number; - /** Overshoot beyond this likely includes system sleep, so it is suppressed. Default 60_000. */ + /** Overshoot beyond this is suppressed only when the process also burned no CPU. Default 60_000. */ sleepMs?: number; /** Monotonic clock source; injectable for tests. Default `performance.now`. */ now?: () => number; + /** Process CPU time in ms; injectable for tests. Default `process.cpuUsage`. */ + cpuNow?: () => number; /** Timer source; injectable for tests. Default `setTimeout`. */ schedule?: (cb: () => void, ms: number) => LoopWatchdogTimer; } @@ -23,6 +25,15 @@ interface LoopWatchdogTimer { cancel?(): void; } +/** + * Fraction of a missed interval that must show up as CPU time for the overshoot + * to count as a synchronous stall rather than system sleep. A suspended process + * resumes having burned essentially nothing; a wedged one burned the interval on + * a core. Half leaves room for a gap that is partly sleep and partly work, which + * is still worth reporting. + */ +const CPU_BUSY_RATIO = 0.5; + /** * Always-on event-loop lag probe. Each tick is scheduled `intervalMs` ahead of * a recorded deadline; a tick that fires `thresholdMs` past its deadline means @@ -35,18 +46,22 @@ interface LoopWatchdogTimer { * The handle is `unref`'d so the probe never keeps the process alive, and stop() * cancels the armed timer when the handle exposes `cancel` (the default * `setTimeout` handle does, via `clearTimeout`). The `#generation` guard remains - * as a fallback for injected handles that cannot cancel. An overshoot beyond - * `sleepMs` is treated as system sleep rather than a synchronous stall: the - * process could not have run JS during the missed interval, and one resume - * should not produce a multi-minute `ui.loop-blocked` record. + * as a fallback for injected handles that cannot cancel. + * + * A long overshoot is classified by CPU time rather than by duration. System + * sleep and a CPU-bound wedge both produce an arbitrarily large gap, so duration + * alone cannot tell them apart, and suppressing on duration discards exactly the + * worst stalls. Only a gap the process did not spend CPU on is treated as sleep. */ export class LoopWatchdog { #intervalMs: number; #thresholdMs: number; #sleepMs: number; #now: () => number; + #cpuNow: () => number; #schedule: (cb: () => void, ms: number) => LoopWatchdogTimer; #expected = 0; + #expectedCpu = 0; #wasBlocked = false; #running = false; // Bumped by stop(); each scheduled tick captures the generation it was armed @@ -60,6 +75,12 @@ export class LoopWatchdog { this.#thresholdMs = options.thresholdMs ?? 250; this.#sleepMs = options.sleepMs ?? 60_000; this.#now = options.now ?? (() => performance.now()); + this.#cpuNow = + options.cpuNow ?? + (() => { + const usage = process.cpuUsage(); + return (usage.user + usage.system) / 1000; + }); this.#schedule = options.schedule ?? ((cb, ms) => { @@ -86,6 +107,7 @@ export class LoopWatchdog { #armTick(): void { const generation = this.#generation; this.#expected = this.#now() + this.#intervalMs; + this.#expectedCpu = this.#cpuNow(); this.#handle = this.#schedule(() => this.#tick(generation), this.#intervalMs); this.#handle.unref?.(); } @@ -93,17 +115,20 @@ export class LoopWatchdog { #tick(generation: number): void { if (!this.#running || generation !== this.#generation) return; const blockedMs = this.#now() - this.#expected; + const cpuMs = this.#cpuNow() - this.#expectedCpu; // Consume the recent phase every tick (block or not) so attribution is // scoped to the just-elapsed interval and never carries a stale phase // forward to a later, phase-less block. const phase = takeRecentLoopPhase(); if (blockedMs > this.#thresholdMs) { - if (blockedMs > this.#sleepMs) { + if (blockedMs > this.#sleepMs && cpuMs < blockedMs * CPU_BUSY_RATIO) { + // A long gap the process did not spend CPU on: it was suspended. this.#wasBlocked = false; } else if (!this.#wasBlocked) { this.#wasBlocked = true; logger.warn("ui.loop-blocked", { blockedMs: Math.round(blockedMs), + cpuMs: Math.round(cpuMs), phase: phase ?? "unknown", }); } diff --git a/packages/tui/test/loop-watchdog.test.ts b/packages/tui/test/loop-watchdog.test.ts index fad11641e..db3333ce7 100644 --- a/packages/tui/test/loop-watchdog.test.ts +++ b/packages/tui/test/loop-watchdog.test.ts @@ -94,7 +94,7 @@ describe("LoopWatchdog", () => { const { wd, setNow, fireTick } = harness({ sleepMs: 5_000 }); wd.start(); // deadline at 250 - setNow(10_250); // blockedMs = 10_000 exceeds the sleep cutoff + setNow(10_250); // blockedMs = 10_000 exceeds the sleep cutoff, and no CPU was burned fireTick(); expect(warnSpy).not.toHaveBeenCalled(); @@ -225,3 +225,77 @@ describe("LoopWatchdog", () => { expect(cancel).toHaveBeenCalledTimes(1); }); }); + +/** + * A long overshoot is classified by CPU time, not by duration. System sleep and + * a CPU-bound wedge both produce an arbitrarily large gap, so duration alone + * cannot separate them — and suppressing on duration discards exactly the worst + * stalls. Issue #5372 reported an 82,391ms block that older builds logged and + * current builds drop silently. + */ +describe("LoopWatchdog long-block classification", () => { + function cpuHarness(options: Partial<{ intervalMs: number; thresholdMs: number; sleepMs: number }> = {}) { + let nowValue = 0; + let cpuValue = 0; + let scheduled: (() => void) | undefined; + const wd = new LoopWatchdog({ + now: () => nowValue, + cpuNow: () => cpuValue, + schedule: (cb: () => void) => { + scheduled = cb; + return {}; + }, + ...options, + }); + return { + wd, + set(now: number, cpu: number): void { + nowValue = now; + cpuValue = cpu; + }, + fireTick(): void { + const cb = scheduled; + if (!cb) throw new Error("no tick was scheduled"); + cb(); + }, + }; + } + + test("reports a CPU-bound wedge longer than sleepMs instead of discarding it", () => { + const warnSpy = vi.spyOn(logger, "warn").mockImplementation(() => {}); + const h = cpuHarness(); + + h.wd.start(); // deadline 250, cpu baseline 0 + // 82,391ms of wall clock, essentially all of it burned on a core. + h.set(82_641, 82_000); + h.fireTick(); + + expect(warnSpy).toHaveBeenCalledTimes(1); + const ctx = warnSpy.mock.calls[0]![1] as { blockedMs: number; cpuMs: number }; + expect(ctx.blockedMs).toBe(82_391); + expect(ctx.cpuMs).toBeGreaterThan(80_000); + }); + + test("still suppresses a suspend/resume gap of the same duration", () => { + const warnSpy = vi.spyOn(logger, "warn").mockImplementation(() => {}); + const h = cpuHarness(); + + h.wd.start(); + // Same wall gap, but the process was suspended: no CPU consumed. + h.set(82_641, 3); + h.fireTick(); + + expect(warnSpy).not.toHaveBeenCalled(); + }); + + test("reports a long block that spent most, but not all, of the gap on CPU", () => { + const warnSpy = vi.spyOn(logger, "warn").mockImplementation(() => {}); + const h = cpuHarness(); + + h.wd.start(); + h.set(120_250, 90_000); + h.fireTick(); + + expect(warnSpy).toHaveBeenCalledTimes(1); + }); +});