From 2b126ffb80160e292267f43a4c962b3a8093e328 Mon Sep 17 00:00:00 2001 From: metaphorics <152830360+metaphorics@users.noreply.github.com> Date: Sun, 14 Jun 2026 05:14:00 +0900 Subject: [PATCH] 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:) and the SelectList fuzzy filter (ui.select-filter) attribute residual main-thread stalls. --- packages/coding-agent/CHANGELOG.md | 3 + packages/coding-agent/src/task/executor.ts | 35 ++- packages/tui/CHANGELOG.md | 3 + packages/tui/src/components/select-list.ts | 16 +- packages/tui/src/loop-watchdog.ts | 106 +++++++++ packages/tui/src/tui.ts | 8 + .../tui/test/loop-watchdog-wiring.test.ts | 36 +++ packages/tui/test/loop-watchdog.test.ts | 209 ++++++++++++++++++ .../tui/test/select-filter-breadcrumb.test.ts | 50 +++++ packages/utils/CHANGELOG.md | 3 + packages/utils/src/index.ts | 1 + packages/utils/src/loop-phase.ts | 49 ++++ packages/utils/test/loop-phase.test.ts | 81 +++++++ 13 files changed, 586 insertions(+), 14 deletions(-) create mode 100644 packages/tui/src/loop-watchdog.ts create mode 100644 packages/tui/test/loop-watchdog-wiring.test.ts create mode 100644 packages/tui/test/loop-watchdog.test.ts create mode 100644 packages/tui/test/select-filter-breadcrumb.test.ts create mode 100644 packages/utils/src/loop-phase.ts create mode 100644 packages/utils/test/loop-phase.test.ts diff --git a/packages/coding-agent/CHANGELOG.md b/packages/coding-agent/CHANGELOG.md index 7fc96cb5e..0f6d6d8bb 100644 --- a/packages/coding-agent/CHANGELOG.md +++ b/packages/coding-agent/CHANGELOG.md @@ -1,6 +1,9 @@ # Changelog ## [Unreleased] +### Added + +- Added `subagent:` 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 diff --git a/packages/coding-agent/src/task/executor.ts b/packages/coding-agent/src/task/executor.ts index 771c81833..dcb843c4c 100644 --- a/packages/coding-agent/src/task/executor.ts +++ b/packages/coding-agent/src/task/executor.ts @@ -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 { 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; diff --git a/packages/tui/CHANGELOG.md b/packages/tui/CHANGELOG.md index 4e7c142cb..005e6006a 100644 --- a/packages/tui/CHANGELOG.md +++ b/packages/tui/CHANGELOG.md @@ -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 diff --git a/packages/tui/src/components/select-list.ts b/packages/tui/src/components/select-list.ts index 04180c137..10aff5309 100644 --- a/packages/tui/src/components/select-list.ts +++ b/packages/tui/src/components/select-list.ts @@ -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(); diff --git a/packages/tui/src/loop-watchdog.ts b/packages/tui/src/loop-watchdog.ts new file mode 100644 index 000000000..af668558b --- /dev/null +++ b/packages/tui/src/loop-watchdog.ts @@ -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(); + } +} diff --git a/packages/tui/src/tui.ts b/packages/tui/src/tui.ts index 8bc218193..bc0f41ac5 100644 --- a/packages/tui/src/tui.ts +++ b/packages/tui/src/tui.ts @@ -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; diff --git a/packages/tui/test/loop-watchdog-wiring.test.ts b/packages/tui/test/loop-watchdog-wiring.test.ts new file mode 100644 index 000000000..bce85ebde --- /dev/null +++ b/packages/tui/test/loop-watchdog-wiring.test.ts @@ -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(); + } + }); +}); diff --git a/packages/tui/test/loop-watchdog.test.ts b/packages/tui/test/loop-watchdog.test.ts new file mode 100644 index 000000000..0561472d8 --- /dev/null +++ b/packages/tui/test/loop-watchdog.test.ts @@ -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); + }); +}); diff --git a/packages/tui/test/select-filter-breadcrumb.test.ts b/packages/tui/test/select-filter-breadcrumb.test.ts new file mode 100644 index 000000000..49e065470 --- /dev/null +++ b/packages/tui/test/select-filter-breadcrumb.test.ts @@ -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(); + }); +}); diff --git a/packages/utils/CHANGELOG.md b/packages/utils/CHANGELOG.md index aaeab035b..09b3c3850 100644 --- a/packages/utils/CHANGELOG.md +++ b/packages/utils/CHANGELOG.md @@ -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 diff --git a/packages/utils/src/index.ts b/packages/utils/src/index.ts index 1bb5b844b..8f554f3d0 100644 --- a/packages/utils/src/index.ts +++ b/packages/utils/src/index.ts @@ -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"; diff --git a/packages/utils/src/loop-phase.ts b/packages/utils/src/loop-phase.ts new file mode 100644 index 000000000..f86ac9ee0 --- /dev/null +++ b/packages/utils/src/loop-phase.ts @@ -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; +} diff --git a/packages/utils/test/loop-phase.test.ts b/packages/utils/test/loop-phase.test.ts new file mode 100644 index 000000000..a638a3b33 --- /dev/null +++ b/packages/utils/test/loop-phase.test.ts @@ -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(); + }); +});