Merge PR #8442: fix(tui): classify a long loop block by CPU time instead of duration (@Mustaqeem66)

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",
 				});
 			}

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);
+	});
+});