feat(tui): add event-loop watchdog and phase breadcrumbs for stall diagnosis
Always-on LoopWatchdog (armed in TUI.start/stop) logs ui.loop-blocked with blockedMs and the current loop phase on the rising edge of a late probe tick. New pushLoopPhase/popLoopPhase/currentLoopPhase stack in pi-utils feeds it; breadcrumbs at in-process subagent dispatch (subagent:<id>) and the SelectList fuzzy filter (ui.select-filter) attribute residual main-thread stalls.
This commit is contained in:
@@ -1,6 +1,9 @@
|
||||
# Changelog
|
||||
|
||||
## [Unreleased]
|
||||
### Added
|
||||
|
||||
- Added `subagent:<id>` loop-phase breadcrumbs around in-process subagent event dispatch and finalization so the TUI event-loop watchdog can attribute a main-thread stall to subagent execution ([#2485](https://github.com/can1357/oh-my-pi/issues/2485))
|
||||
|
||||
## [15.12.5] - 2026-06-13
|
||||
### Changed
|
||||
|
||||
@@ -8,7 +8,7 @@ import path from "node:path";
|
||||
import type { AgentEvent, AgentIdentity, AgentTelemetryConfig, ThinkingLevel } from "@oh-my-pi/pi-agent-core";
|
||||
import { recordHandoff, resolveTelemetry } from "@oh-my-pi/pi-agent-core";
|
||||
import type { Usage } from "@oh-my-pi/pi-ai";
|
||||
import { logger, prompt, untilAborted } from "@oh-my-pi/pi-utils";
|
||||
import { logger, popLoopPhase, prompt, pushLoopPhase, untilAborted } from "@oh-my-pi/pi-utils";
|
||||
import type { Rule } from "../capability/rule";
|
||||
import { ModelRegistry } from "../config/model-registry";
|
||||
import { resolveModelOverrideWithAuthFallback } from "../config/model-resolver";
|
||||
@@ -1198,6 +1198,9 @@ function createSubagentRunMonitor(args: RunMonitorArgs): SubagentRunMonitor {
|
||||
return;
|
||||
}
|
||||
if (isAgentEvent(event)) {
|
||||
// Breadcrumb the synchronous subagent event handling so the loop
|
||||
// watchdog can attribute any block to this in-process subagent.
|
||||
pushLoopPhase(`subagent:${id}`);
|
||||
try {
|
||||
processEvent(event);
|
||||
} catch (err) {
|
||||
@@ -1205,6 +1208,8 @@ function createSubagentRunMonitor(args: RunMonitorArgs): SubagentRunMonitor {
|
||||
error: err instanceof Error ? err.message : String(err),
|
||||
});
|
||||
requestAbort("terminate");
|
||||
} finally {
|
||||
popLoopPhase();
|
||||
}
|
||||
}
|
||||
});
|
||||
@@ -1444,16 +1449,24 @@ async function finalizeRunResult(args: FinalizeRunArgs): Promise<SingleResult> {
|
||||
const yieldItems = progress.extractedToolData?.yield as YieldItem[] | undefined;
|
||||
const reportFindingDetails = progress.extractedToolData?.report_finding as ReportFindingDetails[] | undefined;
|
||||
const reportFindings: ReviewFinding[] | undefined = reportFindingDetails?.map(toReviewFinding);
|
||||
const finalized = finalizeSubprocessOutput({
|
||||
rawOutput,
|
||||
exitCode,
|
||||
stderr,
|
||||
doneAborted: Boolean(done.aborted),
|
||||
signalAborted: Boolean(signal?.aborted),
|
||||
yieldItems,
|
||||
reportFindings,
|
||||
outputSchema: args.outputSchema,
|
||||
});
|
||||
// Breadcrumb the synchronous yield-payload shaping (O(rawOutput)) so a block
|
||||
// here is attributed to this subagent rather than logged as "unknown".
|
||||
pushLoopPhase(`subagent:${id}`);
|
||||
let finalized: FinalizeSubprocessOutputResult;
|
||||
try {
|
||||
finalized = finalizeSubprocessOutput({
|
||||
rawOutput,
|
||||
exitCode,
|
||||
stderr,
|
||||
doneAborted: Boolean(done.aborted),
|
||||
signalAborted: Boolean(signal?.aborted),
|
||||
yieldItems,
|
||||
reportFindings,
|
||||
outputSchema: args.outputSchema,
|
||||
});
|
||||
} finally {
|
||||
popLoopPhase();
|
||||
}
|
||||
rawOutput = finalized.rawOutput;
|
||||
exitCode = finalized.exitCode;
|
||||
stderr = finalized.stderr;
|
||||
|
||||
@@ -1,6 +1,9 @@
|
||||
# Changelog
|
||||
|
||||
## [Unreleased]
|
||||
### Added
|
||||
|
||||
- Added an always-on `LoopWatchdog` armed in `TUI.start()`/`TUI.stop()` that logs `ui.loop-blocked` (rising-edge deduped, with `blockedMs` and the phase active during the elapsed interval) when a self-scheduled probe tick runs late, plus a `ui.select-filter` breadcrumb around the `SelectList` fuzzy filter. The phase is read via `takeRecentLoopPhase`, so a synchronous block whose breadcrumb was pushed and popped before the delayed tick runs is still attributed to its phase instead of "unknown". `stop()` cancels the armed timer (via `clearTimeout` on the default handle) so repeated start/stop cycles leave no pending probe, with the generation guard as a fallback ([#2485](https://github.com/can1357/oh-my-pi/issues/2485))
|
||||
|
||||
## [15.12.5] - 2026-06-13
|
||||
### Added
|
||||
|
||||
@@ -1,3 +1,4 @@
|
||||
import { popLoopPhase, pushLoopPhase } from "@oh-my-pi/pi-utils";
|
||||
import { fuzzyFilter } from "../fuzzy";
|
||||
import { getKeybindings } from "../keybindings";
|
||||
import { extractPrintableText } from "../keys";
|
||||
@@ -482,9 +483,18 @@ export class SelectList implements Component {
|
||||
|
||||
#setFilter(filter: string, notify: boolean): void {
|
||||
this.#filterQuery = filter;
|
||||
this.#filteredItems = filter.trim()
|
||||
? fuzzyFilter([...this.items], filter, item => this.#getFilterText(item))
|
||||
: this.items;
|
||||
if (filter.trim()) {
|
||||
// Breadcrumb the fuzzy match so the loop watchdog can attribute a
|
||||
// large-list filter stall instead of logging it as "unknown".
|
||||
pushLoopPhase("ui.select-filter");
|
||||
try {
|
||||
this.#filteredItems = fuzzyFilter([...this.items], filter, item => this.#getFilterText(item));
|
||||
} finally {
|
||||
popLoopPhase();
|
||||
}
|
||||
} else {
|
||||
this.#filteredItems = this.items;
|
||||
}
|
||||
this.#selectedIndex = 0;
|
||||
if (notify) {
|
||||
this.#notifySelectionChange();
|
||||
|
||||
@@ -0,0 +1,106 @@
|
||||
import { performance } from "node:perf_hooks";
|
||||
import { logger, takeRecentLoopPhase } from "@oh-my-pi/pi-utils";
|
||||
|
||||
export interface LoopWatchdogOptions {
|
||||
/** How far ahead each probe tick is scheduled, in ms. Default 250. */
|
||||
intervalMs?: number;
|
||||
/** A tick later than this past its deadline counts as a block. Default 250. */
|
||||
thresholdMs?: number;
|
||||
/** Monotonic clock source; injectable for tests. Default `performance.now`. */
|
||||
now?: () => number;
|
||||
/** Timer source; injectable for tests. Default `setTimeout`. */
|
||||
schedule?: (cb: () => void, ms: number) => LoopWatchdogTimer;
|
||||
}
|
||||
|
||||
/**
|
||||
* Timer handle the watchdog arms. `cancel`, when present, is invoked on stop()
|
||||
* so a stopped watchdog leaves no armed timer to wake the loop even once.
|
||||
*/
|
||||
interface LoopWatchdogTimer {
|
||||
unref?(): void;
|
||||
cancel?(): void;
|
||||
}
|
||||
|
||||
/**
|
||||
* 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
|
||||
* the loop was blocked that long. The overshoot is logged once on the rising
|
||||
* edge (one block ⇒ one line, deduped via `#wasBlocked`), tagged with the phase
|
||||
* active during the elapsed interval via {@link takeRecentLoopPhase} — which
|
||||
* survives the synchronous push/pop the instrumented hot paths do before this
|
||||
* delayed tick can run — so the stall names its cause instead of "unknown".
|
||||
*
|
||||
* 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.
|
||||
*/
|
||||
export class LoopWatchdog {
|
||||
#intervalMs: number;
|
||||
#thresholdMs: number;
|
||||
#now: () => number;
|
||||
#schedule: (cb: () => void, ms: number) => LoopWatchdogTimer;
|
||||
#expected = 0;
|
||||
#wasBlocked = false;
|
||||
#running = false;
|
||||
// Bumped by stop(); each scheduled tick captures the generation it was armed
|
||||
// under and no-ops if it no longer matches, so a start()→stop()→start() cycle
|
||||
// cannot leave the pre-stop timer chain rescheduling itself in parallel.
|
||||
#generation = 0;
|
||||
#handle: LoopWatchdogTimer | undefined;
|
||||
|
||||
constructor(options: LoopWatchdogOptions = {}) {
|
||||
this.#intervalMs = options.intervalMs ?? 250;
|
||||
this.#thresholdMs = options.thresholdMs ?? 250;
|
||||
this.#now = options.now ?? (() => performance.now());
|
||||
this.#schedule =
|
||||
options.schedule ??
|
||||
((cb, ms) => {
|
||||
const timer = setTimeout(cb, ms);
|
||||
return { unref: () => timer.unref?.(), cancel: () => clearTimeout(timer) };
|
||||
});
|
||||
}
|
||||
|
||||
start(): void {
|
||||
if (this.#running) return;
|
||||
this.#running = true;
|
||||
this.#wasBlocked = false;
|
||||
this.#armTick();
|
||||
}
|
||||
|
||||
stop(): void {
|
||||
this.#running = false;
|
||||
this.#wasBlocked = false;
|
||||
this.#generation++;
|
||||
this.#handle?.cancel?.();
|
||||
this.#handle = undefined;
|
||||
}
|
||||
|
||||
#armTick(): void {
|
||||
const generation = this.#generation;
|
||||
this.#expected = this.#now() + this.#intervalMs;
|
||||
this.#handle = this.#schedule(() => this.#tick(generation), this.#intervalMs);
|
||||
this.#handle.unref?.();
|
||||
}
|
||||
|
||||
#tick(generation: number): void {
|
||||
if (!this.#running || generation !== this.#generation) return;
|
||||
const blockedMs = this.#now() - this.#expected;
|
||||
// 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 (!this.#wasBlocked) {
|
||||
this.#wasBlocked = true;
|
||||
logger.warn("ui.loop-blocked", {
|
||||
blockedMs: Math.round(blockedMs),
|
||||
phase: phase ?? "unknown",
|
||||
});
|
||||
}
|
||||
} else {
|
||||
this.#wasBlocked = false;
|
||||
}
|
||||
this.#armTick();
|
||||
}
|
||||
}
|
||||
@@ -16,6 +16,7 @@ import { $flag, getDebugLogPath } from "@oh-my-pi/pi-utils";
|
||||
import { DEFAULT_MAX_INLINE_IMAGES, ImageBudget } from "./components/image";
|
||||
import { planDeccaraFills } from "./deccara";
|
||||
import { isKeyRelease, matchesKey } from "./keys";
|
||||
import { LoopWatchdog } from "./loop-watchdog";
|
||||
import { isConPTYHosted, setAltScreenActive, type Terminal } from "./terminal";
|
||||
import {
|
||||
encodeKittyDeleteImage,
|
||||
@@ -771,6 +772,10 @@ export class TUI extends Container {
|
||||
// the lifetime of the drag. Exposed for tests/diagnostics.
|
||||
#resizeViewportPaintCount = 0;
|
||||
#stopped = false;
|
||||
// Always-on event-loop lag probe. The high default threshold keeps it quiet;
|
||||
// it only logs `ui.loop-blocked` (with the current loop phase) when a frame
|
||||
// budget is genuinely starved. Armed in start(), disarmed in stop().
|
||||
#watchdog: LoopWatchdog;
|
||||
|
||||
// Transient alternate-screen state for a fullscreen overlay. While active, the
|
||||
// engine paints only the modal on the alt buffer and leaves every
|
||||
@@ -835,6 +840,7 @@ export class TUI extends Container {
|
||||
this.terminal = terminal;
|
||||
this.#renderScheduler = options?.renderScheduler ?? DEFAULT_RENDER_SCHEDULER;
|
||||
this.#showHardwareCursor = showHardwareCursor === undefined ? this.#showHardwareCursor : showHardwareCursor;
|
||||
this.#watchdog = new LoopWatchdog();
|
||||
}
|
||||
|
||||
override render(width: number): readonly string[] {
|
||||
@@ -1181,6 +1187,7 @@ export class TUI extends Container {
|
||||
|
||||
start(options?: TUIStartOptions): void {
|
||||
this.#stopped = false;
|
||||
this.#watchdog.start();
|
||||
this.#ghosttyInitialImageDelayDone = false;
|
||||
this.#ghosttyImageReadyAtMs = this.#renderScheduler.now() + TUI.#GHOSTTY_INITIAL_IMAGE_DELAY_MS;
|
||||
// A DECRQM report for mode 2026 is authoritative: enable synchronized
|
||||
@@ -1423,6 +1430,7 @@ export class TUI extends Container {
|
||||
}
|
||||
this.#clearSixelProbeState();
|
||||
this.#stopped = true;
|
||||
this.#watchdog.stop();
|
||||
if (this.#renderTimer) {
|
||||
this.#renderTimer.cancel();
|
||||
this.#renderTimer = undefined;
|
||||
|
||||
@@ -0,0 +1,36 @@
|
||||
import { afterEach, describe, expect, it, vi } from "bun:test";
|
||||
import { TUI } from "@oh-my-pi/pi-tui";
|
||||
import { LoopWatchdog } from "@oh-my-pi/pi-tui/loop-watchdog";
|
||||
import { VirtualTerminal } from "./virtual-terminal";
|
||||
|
||||
/**
|
||||
* Contract: the user-visible loop-blocked diagnostic depends on `TUI.start()`
|
||||
* arming the watchdog and `TUI.stop()` disarming it. The unit tests exercise
|
||||
* `LoopWatchdog` in isolation, so this guards the wiring itself — dropping
|
||||
* either TUI call would leave a live session with no loop-block logging while
|
||||
* every `LoopWatchdog` unit test still passed.
|
||||
*
|
||||
* Spies the prototype (never `mock.module`, which leaks across files) so the
|
||||
* real watchdog still runs; its timer handle is `unref`'d and disarmed on stop.
|
||||
*/
|
||||
describe("TUI loop-watchdog wiring", () => {
|
||||
afterEach(() => {
|
||||
vi.restoreAllMocks();
|
||||
});
|
||||
|
||||
it("arms the watchdog on start() and disarms it on stop()", () => {
|
||||
const startSpy = vi.spyOn(LoopWatchdog.prototype, "start");
|
||||
const stopSpy = vi.spyOn(LoopWatchdog.prototype, "stop");
|
||||
const tui = new TUI(new VirtualTerminal(80, 24));
|
||||
|
||||
try {
|
||||
tui.start();
|
||||
expect(startSpy).toHaveBeenCalledTimes(1);
|
||||
|
||||
tui.stop();
|
||||
expect(stopSpy).toHaveBeenCalledTimes(1);
|
||||
} finally {
|
||||
tui.stop();
|
||||
}
|
||||
});
|
||||
});
|
||||
@@ -0,0 +1,209 @@
|
||||
import { afterEach, describe, expect, test, vi } from "bun:test";
|
||||
import { LoopWatchdog } from "@oh-my-pi/pi-tui/loop-watchdog";
|
||||
import { currentLoopPhase, logger, popLoopPhase, pushLoopPhase, takeRecentLoopPhase } from "@oh-my-pi/pi-utils";
|
||||
|
||||
/**
|
||||
* Contract: LoopWatchdog turns event-loop lag into exactly one
|
||||
* `logger.warn("ui.loop-blocked", { blockedMs, phase })` line per block. A tick
|
||||
* that fires more than `thresholdMs` past its `intervalMs` deadline is a block; it
|
||||
* is logged once on the rising edge (deduped while the loop stays blocked), tagged
|
||||
* with the current loop phase and the rounded overshoot, and a stopped watchdog
|
||||
* emits nothing even for a tick already armed before stop().
|
||||
*
|
||||
* Time and the timer are injected so the test drives elapsed time deterministically
|
||||
* instead of sleeping. `schedule` captures the armed callback so the test fires
|
||||
* ticks by hand; firing re-arms via schedule, so the captured callback always
|
||||
* advances to the next pending tick.
|
||||
*/
|
||||
function harness(options: Partial<{ intervalMs: number; thresholdMs: number }> = {}) {
|
||||
let nowValue = 0;
|
||||
let scheduled: (() => void) | undefined;
|
||||
const now = () => nowValue;
|
||||
const schedule = (cb: () => void) => {
|
||||
scheduled = cb;
|
||||
return {};
|
||||
};
|
||||
const wd = new LoopWatchdog({ now, schedule, ...options });
|
||||
return {
|
||||
wd,
|
||||
setNow(value: number): void {
|
||||
nowValue = value;
|
||||
},
|
||||
fireTick(): void {
|
||||
const cb = scheduled;
|
||||
if (!cb) throw new Error("no tick was scheduled");
|
||||
cb();
|
||||
},
|
||||
};
|
||||
}
|
||||
|
||||
afterEach(() => {
|
||||
vi.restoreAllMocks();
|
||||
// The phase stack is a process-global; drain anything these cases pushed.
|
||||
while (currentLoopPhase() !== undefined) popLoopPhase();
|
||||
// Drain the consume-on-read recent slot too, so a phase one case set cannot
|
||||
// leak into another's attribution assertion.
|
||||
takeRecentLoopPhase();
|
||||
});
|
||||
|
||||
describe("LoopWatchdog", () => {
|
||||
test("logs ui.loop-blocked once with the current phase and overshoot when a tick runs late", () => {
|
||||
const warnSpy = vi.spyOn(logger, "warn").mockImplementation(() => {});
|
||||
const { wd, setNow, fireTick } = harness(); // intervalMs=250, thresholdMs=250
|
||||
|
||||
pushLoopPhase("render");
|
||||
wd.start(); // deadline armed at now(0)+250 = 250
|
||||
setNow(560); // tick fires at 560 → blockedMs = 560 - 250 = 310 (> threshold)
|
||||
fireTick();
|
||||
|
||||
expect(warnSpy).toHaveBeenCalledTimes(1);
|
||||
const [event, ctx] = warnSpy.mock.calls[0] as [string, { blockedMs: number; phase: string }];
|
||||
expect(event).toBe("ui.loop-blocked");
|
||||
expect(ctx.phase).toBe("render");
|
||||
expect(ctx.blockedMs).toBeGreaterThanOrEqual(250);
|
||||
});
|
||||
|
||||
test("stays silent when a tick fires on its deadline", () => {
|
||||
const warnSpy = vi.spyOn(logger, "warn").mockImplementation(() => {});
|
||||
const { wd, setNow, fireTick } = harness();
|
||||
|
||||
pushLoopPhase("render");
|
||||
wd.start(); // deadline at 250
|
||||
setNow(250); // blockedMs = 0, not a block
|
||||
fireTick();
|
||||
|
||||
expect(warnSpy).not.toHaveBeenCalled();
|
||||
});
|
||||
|
||||
test("dedupes a sustained block: two consecutive late ticks log only once", () => {
|
||||
const warnSpy = vi.spyOn(logger, "warn").mockImplementation(() => {});
|
||||
const { wd, setNow, fireTick } = harness();
|
||||
|
||||
pushLoopPhase("render");
|
||||
wd.start(); // deadline at 250
|
||||
setNow(600); // blockedMs = 350 → rising edge, logs once; re-armed deadline = 850
|
||||
fireTick();
|
||||
setNow(1200); // blockedMs = 350 again, but still blocked → no second log
|
||||
fireTick();
|
||||
|
||||
expect(warnSpy).toHaveBeenCalledTimes(1);
|
||||
});
|
||||
|
||||
test("emits nothing for a tick that fires after stop()", () => {
|
||||
const warnSpy = vi.spyOn(logger, "warn").mockImplementation(() => {});
|
||||
const { wd, setNow, fireTick } = harness();
|
||||
|
||||
pushLoopPhase("render");
|
||||
wd.start(); // deadline at 250
|
||||
setNow(600); // first block logs once and re-arms a follow-up tick
|
||||
fireTick();
|
||||
expect(warnSpy).toHaveBeenCalledTimes(1);
|
||||
|
||||
wd.stop();
|
||||
setNow(5000); // the already-armed follow-up tick would otherwise be a huge block
|
||||
fireTick();
|
||||
|
||||
expect(warnSpy).toHaveBeenCalledTimes(1); // stop() short-circuits the stale tick
|
||||
});
|
||||
|
||||
test("attributes a synchronous block whose phase was already popped before the tick", () => {
|
||||
const warnSpy = vi.spyOn(logger, "warn").mockImplementation(() => {});
|
||||
const { wd, setNow, fireTick } = harness();
|
||||
|
||||
wd.start(); // deadline 250
|
||||
// A hot sync path pushes and pops its phase within one macrotask, so the
|
||||
// stack is empty by the time the delayed tick runs — the recent slot must
|
||||
// still surface the culprit instead of "unknown".
|
||||
pushLoopPhase("ui.select-filter");
|
||||
popLoopPhase();
|
||||
setNow(600); // blockedMs = 350
|
||||
fireTick();
|
||||
|
||||
expect(warnSpy).toHaveBeenCalledTimes(1);
|
||||
expect((warnSpy.mock.calls[0]![1] as { phase: string }).phase).toBe("ui.select-filter");
|
||||
});
|
||||
|
||||
test("does not misattribute a finished phase to a later phase-less block", () => {
|
||||
const warnSpy = vi.spyOn(logger, "warn").mockImplementation(() => {});
|
||||
const { wd, setNow, fireTick } = harness();
|
||||
|
||||
wd.start(); // deadline 250
|
||||
pushLoopPhase("ui.select-filter");
|
||||
popLoopPhase();
|
||||
setNow(250); // on-time tick consumes the recent phase, logs nothing; re-arm 500
|
||||
fireTick();
|
||||
setNow(900); // block in the next interval with no phase active
|
||||
fireTick();
|
||||
|
||||
expect(warnSpy).toHaveBeenCalledTimes(1);
|
||||
expect((warnSpy.mock.calls[0]![1] as { phase: string }).phase).toBe("unknown");
|
||||
});
|
||||
|
||||
test("re-arms after recovery: late then on-time then late logs twice", () => {
|
||||
const warnSpy = vi.spyOn(logger, "warn").mockImplementation(() => {});
|
||||
const { wd, setNow, fireTick } = harness();
|
||||
|
||||
pushLoopPhase("render");
|
||||
wd.start(); // deadline 250
|
||||
setNow(600); // block #1 (350) → logs; re-arm 850
|
||||
fireTick();
|
||||
setNow(850); // on-time → falling edge resets #wasBlocked; re-arm 1100
|
||||
fireTick();
|
||||
setNow(1450); // block #2 (350) → logs again
|
||||
fireTick();
|
||||
|
||||
expect(warnSpy).toHaveBeenCalledTimes(2);
|
||||
});
|
||||
|
||||
test("a pre-stop tick no-ops after start() -> stop() -> start() and arms no parallel chain", () => {
|
||||
const warnSpy = vi.spyOn(logger, "warn").mockImplementation(() => {});
|
||||
let nowValue = 0;
|
||||
const callbacks: Array<() => void> = [];
|
||||
const schedule = (cb: () => void) => {
|
||||
callbacks.push(cb);
|
||||
return {};
|
||||
};
|
||||
const wd = new LoopWatchdog({ now: () => nowValue, schedule });
|
||||
|
||||
wd.start(); // arms callbacks[0] under generation 0
|
||||
const stale = callbacks[callbacks.length - 1]!;
|
||||
wd.stop(); // generation bumped
|
||||
wd.start(); // arms callbacks[1] under generation 1
|
||||
expect(callbacks).toHaveLength(2);
|
||||
|
||||
nowValue = 5000; // the stale callback would otherwise be a huge block
|
||||
stale();
|
||||
|
||||
expect(warnSpy).not.toHaveBeenCalled(); // generation mismatch short-circuits
|
||||
expect(callbacks).toHaveLength(2); // and it did NOT re-arm a parallel timer chain
|
||||
});
|
||||
|
||||
test("unrefs every scheduled timer handle so the always-on probe never holds the process open", () => {
|
||||
vi.spyOn(logger, "warn").mockImplementation(() => {});
|
||||
const unref = vi.fn();
|
||||
let nowValue = 0;
|
||||
let cb: (() => void) | undefined;
|
||||
const schedule = (c: () => void) => {
|
||||
cb = c;
|
||||
return { unref };
|
||||
};
|
||||
const wd = new LoopWatchdog({ now: () => nowValue, schedule });
|
||||
|
||||
wd.start();
|
||||
expect(unref).toHaveBeenCalledTimes(1); // armed on start
|
||||
nowValue = 600;
|
||||
cb?.(); // late tick logs and re-arms
|
||||
expect(unref).toHaveBeenCalledTimes(2); // the re-armed handle is unref'd too
|
||||
});
|
||||
|
||||
test("stop() cancels the armed timer handle so no stale tick is left pending", () => {
|
||||
const cancel = vi.fn();
|
||||
const schedule = (_cb: () => void) => ({ cancel });
|
||||
const wd = new LoopWatchdog({ now: () => 0, schedule });
|
||||
|
||||
wd.start(); // arms a handle exposing cancel()
|
||||
wd.stop();
|
||||
|
||||
expect(cancel).toHaveBeenCalledTimes(1);
|
||||
});
|
||||
});
|
||||
@@ -0,0 +1,50 @@
|
||||
import { afterEach, describe, expect, it } from "bun:test";
|
||||
import { type SelectItem, SelectList, type SelectListTheme } from "@oh-my-pi/pi-tui";
|
||||
import { currentLoopPhase, popLoopPhase, takeRecentLoopPhase } from "@oh-my-pi/pi-utils";
|
||||
|
||||
/**
|
||||
* Contract: the SelectList fuzzy filter — a synchronous, potentially expensive
|
||||
* pass over a large list — is wrapped in a `ui.select-filter` loop-phase
|
||||
* breadcrumb so the event-loop watchdog can attribute a filter stall to it.
|
||||
*
|
||||
* The LoopWatchdog unit tests cover the watchdog/recent-slot mechanism in
|
||||
* isolation; this guards the actual call site. Removing the
|
||||
* `pushLoopPhase("ui.select-filter")` around the filter would leave a real stall
|
||||
* logged as "unknown" while every watchdog unit test still passed — and this
|
||||
* case would fail.
|
||||
*
|
||||
* The phase stack is a process-global; drain it (and the consume-on-read recent
|
||||
* slot) after each case so nothing leaks across tests.
|
||||
*/
|
||||
afterEach(() => {
|
||||
while (currentLoopPhase() !== undefined) popLoopPhase();
|
||||
takeRecentLoopPhase();
|
||||
});
|
||||
|
||||
describe("SelectList fuzzy-filter loop-phase breadcrumb", () => {
|
||||
it("wraps the fuzzy filter in a ui.select-filter breadcrumb the watchdog can read", () => {
|
||||
const items: SelectItem[] = [
|
||||
{ value: "alpha", label: "Alpha" },
|
||||
{ value: "beta", label: "Beta" },
|
||||
{ value: "gamma", label: "Gamma" },
|
||||
];
|
||||
const list = new SelectList(items, 2, {} as unknown as SelectListTheme);
|
||||
|
||||
list.setFilter("al");
|
||||
|
||||
// The breadcrumb is pushed and popped synchronously around the filter, so by
|
||||
// the time setFilter returns the stack is balanced — but the consume-on-read
|
||||
// recent slot still surfaces the phase, which is exactly what lets a
|
||||
// synchronous filter stall be attributed instead of logged as "unknown".
|
||||
expect(currentLoopPhase()).toBeUndefined();
|
||||
expect(takeRecentLoopPhase()).toBe("ui.select-filter");
|
||||
});
|
||||
|
||||
it("does not breadcrumb an empty/whitespace filter (no fuzzy work to attribute)", () => {
|
||||
const list = new SelectList([{ value: "x", label: "X" }], 2, {} as unknown as SelectListTheme);
|
||||
|
||||
list.setFilter(" ");
|
||||
|
||||
expect(takeRecentLoopPhase()).toBeUndefined();
|
||||
});
|
||||
});
|
||||
@@ -1,6 +1,9 @@
|
||||
# Changelog
|
||||
|
||||
## [Unreleased]
|
||||
### Added
|
||||
|
||||
- Added a lightweight loop-phase breadcrumb stack (`pushLoopPhase`/`popLoopPhase`/`currentLoopPhase`, plus `takeRecentLoopPhase` which returns the live phase or the most recently popped one and clears it) so the TUI event-loop watchdog can attribute a main-thread block to the phase that caused it — including a synchronous phase already popped before the watchdog's delayed tick runs ([#2485](https://github.com/can1357/oh-my-pi/issues/2485))
|
||||
|
||||
## [15.12.4] - 2026-06-13
|
||||
|
||||
|
||||
@@ -10,6 +10,7 @@ export * from "./fs-error";
|
||||
export * from "./glob";
|
||||
export * from "./json";
|
||||
export * as logger from "./logger";
|
||||
export * from "./loop-phase";
|
||||
export * from "./mermaid-ascii";
|
||||
export * from "./mime";
|
||||
export * from "./path-tree";
|
||||
|
||||
@@ -0,0 +1,49 @@
|
||||
/**
|
||||
* Live event-loop phase breadcrumb. Hot synchronous paths push a short label
|
||||
* before running and pop it after (via `try`/`finally`); the loop watchdog
|
||||
* reads {@link takeRecentLoopPhase} when it detects a block, so a stall is
|
||||
* logged with the work that caused it instead of an opaque "unknown".
|
||||
*
|
||||
* This is deliberately a process-global stack and not part of the logger span
|
||||
* machinery: `main.ts` ends timing spans before the interactive TUI starts, so
|
||||
* `logger.openSpanPath()` is empty in a live session.
|
||||
*
|
||||
* Correctness constraint: each `pushLoopPhase` must be balanced by a
|
||||
* `popLoopPhase` within the SAME synchronous execution (always via `try`/
|
||||
* `finally`). The stack is global and shared, so a label held across an
|
||||
* `await`/async boundary — or interleaved between concurrent tasks — would
|
||||
* misattribute or leak phases. Instrument only synchronous spans; for async
|
||||
* work, push/pop around each synchronous chunk, not across the await.
|
||||
*/
|
||||
const stack: string[] = [];
|
||||
// The most recent label pushed, retained after it is popped. A hot path pushes
|
||||
// and pops a phase entirely within one synchronous macrotask, so by the time
|
||||
// the watchdog's delayed tick runs the stack is already empty; this slot keeps
|
||||
// the culprit available for that one tick. Consumed (cleared) on read so it
|
||||
// only attributes the just-elapsed interval.
|
||||
let recentPhase: string | undefined;
|
||||
|
||||
export function pushLoopPhase(label: string): void {
|
||||
stack.push(label);
|
||||
recentPhase = label;
|
||||
}
|
||||
|
||||
export function popLoopPhase(): void {
|
||||
stack.pop();
|
||||
}
|
||||
|
||||
export function currentLoopPhase(): string | undefined {
|
||||
return stack[stack.length - 1];
|
||||
}
|
||||
|
||||
/**
|
||||
* Phase to blame for a just-detected loop block: the live top phase if one is
|
||||
* still held, else the most recent phase pushed since the last call. Clears the
|
||||
* recent slot so a block in a later, phase-less interval is not misattributed
|
||||
* to a phase that already finished.
|
||||
*/
|
||||
export function takeRecentLoopPhase(): string | undefined {
|
||||
const phase = stack[stack.length - 1] ?? recentPhase;
|
||||
recentPhase = undefined;
|
||||
return phase;
|
||||
}
|
||||
@@ -0,0 +1,81 @@
|
||||
import { afterEach, beforeEach, describe, expect, test } from "bun:test";
|
||||
import { currentLoopPhase, popLoopPhase, pushLoopPhase, takeRecentLoopPhase } from "@oh-my-pi/pi-utils";
|
||||
|
||||
/**
|
||||
* Contract: the loop-phase breadcrumb is a LIFO string stack. `currentLoopPhase()`
|
||||
* reports the most recently pushed, still-unpopped label and `undefined` once the
|
||||
* stack drains. The watchdog reads this to name the work that blocked the loop, so
|
||||
* the ordering and empty-state behavior are the externally observable guarantee.
|
||||
*
|
||||
* The stack is a process-global; drain it around each case so a leaked phase from
|
||||
* this or any other suite cannot poison an assertion or leak outward.
|
||||
*/
|
||||
function drain(): void {
|
||||
while (currentLoopPhase() !== undefined) popLoopPhase();
|
||||
takeRecentLoopPhase(); // clear the consume-on-read recent slot between cases
|
||||
}
|
||||
|
||||
beforeEach(drain);
|
||||
afterEach(drain);
|
||||
|
||||
describe("loop phase stack", () => {
|
||||
test("currentLoopPhase() is undefined on an empty stack", () => {
|
||||
expect(currentLoopPhase()).toBeUndefined();
|
||||
});
|
||||
|
||||
test("push/pop expose the top label in strict LIFO order through nested phases", () => {
|
||||
pushLoopPhase("render");
|
||||
expect(currentLoopPhase()).toBe("render");
|
||||
|
||||
pushLoopPhase("layout");
|
||||
expect(currentLoopPhase()).toBe("layout");
|
||||
|
||||
pushLoopPhase("paint");
|
||||
expect(currentLoopPhase()).toBe("paint");
|
||||
|
||||
// Unwinding reveals each enclosing phase in reverse insertion order.
|
||||
popLoopPhase();
|
||||
expect(currentLoopPhase()).toBe("layout");
|
||||
|
||||
popLoopPhase();
|
||||
expect(currentLoopPhase()).toBe("render");
|
||||
|
||||
popLoopPhase();
|
||||
expect(currentLoopPhase()).toBeUndefined();
|
||||
});
|
||||
|
||||
test("popping an already-empty stack stays undefined without underflow", () => {
|
||||
// Unbalanced pops (error paths popping more than they pushed) must not throw
|
||||
// or wrap around to a stale label.
|
||||
popLoopPhase();
|
||||
popLoopPhase();
|
||||
expect(currentLoopPhase()).toBeUndefined();
|
||||
|
||||
// And the stack is still usable afterward.
|
||||
pushLoopPhase("after-underflow");
|
||||
expect(currentLoopPhase()).toBe("after-underflow");
|
||||
});
|
||||
|
||||
test("takeRecentLoopPhase surfaces a popped phase once, then clears it", () => {
|
||||
// A synchronous hot path pushes then pops its phase entirely before the
|
||||
// watchdog's delayed tick runs, so the live stack is empty by then.
|
||||
pushLoopPhase("ui.select-filter");
|
||||
popLoopPhase();
|
||||
expect(currentLoopPhase()).toBeUndefined();
|
||||
|
||||
// The recent slot still names the just-finished phase for that one read,
|
||||
// then is consumed so a later phase-less block is not blamed on it.
|
||||
expect(takeRecentLoopPhase()).toBe("ui.select-filter");
|
||||
expect(takeRecentLoopPhase()).toBeUndefined();
|
||||
});
|
||||
|
||||
test("takeRecentLoopPhase prefers a still-held live phase over the recent slot", () => {
|
||||
pushLoopPhase("outer"); // stays held across the inner phase
|
||||
pushLoopPhase("inner");
|
||||
popLoopPhase(); // inner done; recent slot last saw "inner", outer still live
|
||||
|
||||
// A live phase wins over the recent slot — the block is still inside it.
|
||||
expect(takeRecentLoopPhase()).toBe("outer");
|
||||
popLoopPhase();
|
||||
});
|
||||
});
|
||||
Reference in New Issue
Block a user