From 9847f269e96524a24a4305783c87734b5c634eb1 Mon Sep 17 00:00:00 2001 From: David Sexton Date: Tue, 11 Aug 2026 19:49:07 -0700 Subject: [PATCH 1/2] Add performance watchdog for sustained idle main-thread work MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A tab once burned ~18% of a core for three days before anyone noticed, and the condition stopped mid-investigation with no record of what had been running. This adds an always-on monitor that catches the onset, samples it while it is live, and names the culprit. Three cheap signals, no per-event instrumentation in the steady state: a longtask PerformanceObserver, a 500ms interval that measures its own scheduling delay, and a requestAnimationFrame wrapper that counts callers. The wrapper never schedules a frame of its own — installing a rAF loop to measure frame rate pins the page at 60fps and manufactures the load it claims to observe. Only trips while idle (no keydown or pointer activity for 10s) and visible, since background tabs throttle timers to ~1Hz and sustained work during active use is expected. Exactly one console warning per episode; the episode ends after the condition stays clear for 60s. On trip it records live subsystems, inbound message and output rates sampled from store entry-id deltas, rAF callers per second, and long-task totals, then ranks them so the warning names the top contributors. Records are JSON and go to a pluggable sink, defaulting to a bounded in-memory array, so the diagnostics buffer can be dropped in later. Co-Authored-By: Claude Fable 5 --- src/App.tsx | 5 + src/EditorManager.ts | 14 + src/diagnostics/perfWatchdog.test.ts | 276 +++++++++++++ src/diagnostics/perfWatchdog.ts | 568 +++++++++++++++++++++++++++ src/diagnostics/watchdogTypes.ts | 114 ++++++ 5 files changed, 977 insertions(+) create mode 100644 src/diagnostics/perfWatchdog.test.ts create mode 100644 src/diagnostics/perfWatchdog.ts create mode 100644 src/diagnostics/watchdogTypes.ts diff --git a/src/App.tsx b/src/App.tsx index 1c8db332..c75542f1 100644 --- a/src/App.tsx +++ b/src/App.tsx @@ -20,6 +20,7 @@ import WasmGuest from "./components/WasmGuest"; import type { WasmHostState } from "./components/WasmHost"; import WasmHost from "./components/WasmHost"; import { createConfiguredClient } from "./createConfiguredClient"; +import { ensurePerfWatchdog } from "./diagnostics/perfWatchdog"; import type { GMCPMessageRoomInfo } from "./gmcp/Room"; import { createHapticsRuntime, type HapticsRuntime } from "./haptics/runtime"; import { useChannelHistory } from "./hooks/useChannelHistory"; @@ -216,6 +217,10 @@ function App() { [isMobile], ); + // Watch for sustained main-thread work while idle, for the life of the app. + // Independent of the connection, so it keeps measuring across reconnects. + useEffect(() => ensurePerfWatchdog(), []); + // Default telnet mode: create client and connect via WebSocket useEffect(() => { if (!isDefaultMode) return; diff --git a/src/EditorManager.ts b/src/EditorManager.ts index 05a8ec83..6fb89347 100644 --- a/src/EditorManager.ts +++ b/src/EditorManager.ts @@ -21,6 +21,20 @@ export class EditorManager { this.setupChannelListeners(); } + /** + * Editor windows that are still open. Read by the performance watchdog when + * attributing sustained main-thread work. + */ + get openEditorCount(): number { + let count = 0; + for (const session of this.editors.values()) { + if (session.state !== EditorState.Closed && session.window && !session.window.closed) { + count += 1; + } + } + return count; + } + openEditorWindow(editorSession: EditorSession) { console.log('Opening editor window for session:', editorSession); const id = editorSession.reference; diff --git a/src/diagnostics/perfWatchdog.test.ts b/src/diagnostics/perfWatchdog.test.ts new file mode 100644 index 00000000..a431c9a3 --- /dev/null +++ b/src/diagnostics/perfWatchdog.test.ts @@ -0,0 +1,276 @@ +import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; + +import { + clearWatchdogRecords, + getWatchdogRecords, + startPerfWatchdog, +} from "./perfWatchdog"; +import type { + PerfWatchdogHandle, + PerfWatchdogOptions, + WatchdogLongTask, + WatchdogRecord, + WatchdogSubsystems, +} from "./watchdogTypes"; + +const SAMPLE_INTERVAL_MS = 500; +/** Ticks before the idle threshold (10s) is satisfied. */ +const IDLE_TICKS = 20; +/** Baseline tick plus a full 21-sample window. */ +const WINDOW_TICKS = 22; +const TICKS_TO_FIRST_TRIP = IDLE_TICKS + WINDOW_TICKS; + +interface StepOptions { + lagMs?: number; + longTaskMs?: number; + rafCalls?: number; + outputLines?: number; + inboundMessages?: number; +} + +function createHarness(overrides: PerfWatchdogOptions = {}) { + let clock = 0; + let outputEntryId = 0; + let inboundEntryId = 0; + let emitLongTasks: ((tasks: WatchdogLongTask[]) => void) | undefined; + + const sink = vi.fn<[WatchdogRecord], void>(); + const warn = vi.fn<[string, WatchdogRecord], void>(); + const subsystems: WatchdogSubsystems = { + audioContextState: "running", + connected: true, + editorsOpen: 2, + voiceChatActive: true, + }; + + const handle = startPerfWatchdog({ + now: () => clock, + sink, + warn, + probes: { + readCounters: () => ({ outputEntryId, inboundEntryId }), + readSubsystems: () => ({ ...subsystems }), + }, + observeLongTasks: (onLongTasks) => { + emitLongTasks = onLongTasks; + return () => { + emitLongTasks = undefined; + }; + }, + ...overrides, + }); + + const step = (count: number, options: StepOptions = {}) => { + for (let index = 0; index < count; index += 1) { + if (options.longTaskMs) { + emitLongTasks?.([{ duration: options.longTaskMs }]); + } + for (let call = 0; call < (options.rafCalls ?? 0); call += 1) { + window.requestAnimationFrame(() => undefined); + } + outputEntryId += options.outputLines ?? 0; + inboundEntryId += options.inboundMessages ?? 0; + clock += SAMPLE_INTERVAL_MS + (options.lagMs ?? 0); + vi.advanceTimersByTime(SAMPLE_INTERVAL_MS); + } + }; + + return { + handle, + sink, + subsystems, + step, + warn, + interact: () => { + window.dispatchEvent(new KeyboardEvent("keydown", { key: "a" })); + }, + }; +} + +function setVisibility(state: DocumentVisibilityState): void { + Object.defineProperty(document, "visibilityState", { + configurable: true, + get: () => state, + }); +} + +describe("perfWatchdog", () => { + const originalRequestAnimationFrame = window.requestAnimationFrame; + let handles: PerfWatchdogHandle[] = []; + + beforeEach(() => { + vi.useFakeTimers(); + clearWatchdogRecords(); + setVisibility("visible"); + window.requestAnimationFrame = vi.fn( + () => 1, + ) as unknown as typeof window.requestAnimationFrame; + handles = []; + }); + + afterEach(() => { + for (const handle of handles) { + handle.stop(); + } + vi.useRealTimers(); + vi.restoreAllMocks(); + setVisibility("visible"); + window.requestAnimationFrame = originalRequestAnimationFrame; + clearWatchdogRecords(); + }); + + const track = (harness: T): T => { + handles.push(harness.handle); + return harness; + }; + + it("warns exactly once per episode of sustained long-task work", () => { + const { sink, step, warn } = track(createHarness()); + + step(TICKS_TO_FIRST_TRIP + 40, { longTaskMs: 200 }); + + expect(warn).toHaveBeenCalledTimes(1); + expect(sink).toHaveBeenCalledTimes(1); + expect(sink.mock.calls[0][0].reason).toBe("long-tasks"); + }); + + it("opens a new episode only after the condition clears for the cooldown", () => { + const { step, warn } = track(createHarness()); + + step(TICKS_TO_FIRST_TRIP + 10, { longTaskMs: 200 }); + expect(warn).toHaveBeenCalledTimes(1); + + // 60s cooldown at 500ms per tick, plus slack to refill the window. + step(140); + expect(warn).toHaveBeenCalledTimes(1); + + step(WINDOW_TICKS + 2, { longTaskMs: 200 }); + expect(warn).toHaveBeenCalledTimes(2); + }); + + it("stays silent while the user is interacting", () => { + const { step, warn, interact } = track(createHarness()); + + for (let round = 0; round < 12; round += 1) { + interact(); + step(10, { longTaskMs: 400 }); + } + + expect(warn).not.toHaveBeenCalled(); + }); + + it("stays silent while the tab is hidden", () => { + const { step, warn } = track(createHarness()); + setVisibility("hidden"); + + step(TICKS_TO_FIRST_TRIP + 40, { longTaskMs: 400, lagMs: 900 }); + + expect(warn).not.toHaveBeenCalled(); + }); + + it("trips on sustained event-loop lag with no long tasks at all", () => { + const { sink, step } = track(createHarness()); + + step(TICKS_TO_FIRST_TRIP + 2, { lagMs: 40 }); + + expect(sink).toHaveBeenCalledTimes(1); + const record = sink.mock.calls[0][0]; + expect(record.reason).toBe("event-loop-lag"); + expect(record.longTaskCount).toBe(0); + expect(record.lagAverageMs).toBeCloseTo(40, 1); + }); + + it("records attribution naming the top contributors", () => { + const { sink, step, warn } = track(createHarness()); + + step(TICKS_TO_FIRST_TRIP + 2, { + longTaskMs: 200, + rafCalls: 30, + outputLines: 10, + inboundMessages: 3, + }); + + expect(sink).toHaveBeenCalledTimes(1); + const record = sink.mock.calls[0][0]; + + expect(record.kind).toBe("perf-watchdog"); + expect(record.busyPercent).toBeCloseTo(40, 0); + expect(record.idleForMs).toBeGreaterThanOrEqual(10_000); + expect(record.longTaskCount).toBeGreaterThan(0); + expect(record.subsystems).toEqual({ + audioContextState: "running", + connected: true, + editorsOpen: 2, + voiceChatActive: true, + }); + // 30 rAF calls, 10 output lines and 3 inbound messages every 500ms. + expect(record.rates.animationFrameCallsPerSecond).toBeCloseTo(60, 0); + expect(record.rates.outputLinesPerSecond).toBeCloseTo(20, 0); + expect(record.rates.inboundMessagesPerSecond).toBeCloseTo(6, 0); + + const names = record.topContributors.map((contributor) => contributor.name); + expect(names[0]).toBe("animation frames"); + expect(names).toContain("output"); + expect(record.summary).toContain("animation frames"); + expect(warn).toHaveBeenCalledWith(record.summary, record); + + // Records must survive a trip through the diagnostics buffer as JSON. + expect(JSON.parse(JSON.stringify(record))).toEqual(record); + }); + + it("falls back to the bounded array sink and console.warn", () => { + const consoleWarn = vi.spyOn(console, "warn").mockImplementation(() => undefined); + const { step } = track(createHarness({ sink: undefined, warn: undefined })); + + step(TICKS_TO_FIRST_TRIP + 2, { longTaskMs: 200 }); + + const records = getWatchdogRecords(); + expect(records).toHaveLength(1); + expect(records[0].kind).toBe("perf-watchdog"); + expect(consoleWarn).toHaveBeenCalledTimes(1); + expect(consoleWarn.mock.calls[0][0]).toContain("[perf-watchdog]"); + }); + + describe("requestAnimationFrame wrapper", () => { + it("counts callers, passes through, and never schedules a frame itself", () => { + const native = vi.fn(() => 42) as unknown as typeof window.requestAnimationFrame; + window.requestAnimationFrame = native; + + const { sink, step } = track(createHarness()); + expect(window.requestAnimationFrame).not.toBe(native); + + const callback = () => undefined; + expect(window.requestAnimationFrame(callback)).toBe(42); + expect(native).toHaveBeenCalledWith(callback); + + // 20 callers per second for the whole window; the watchdog adds none. + step(TICKS_TO_FIRST_TRIP + 2, { longTaskMs: 200, rafCalls: 10 }); + expect(native).toHaveBeenCalledTimes(1 + (TICKS_TO_FIRST_TRIP + 2) * 10); + expect(sink.mock.calls[0][0].rates.animationFrameCallsPerSecond).toBeCloseTo(20, 0); + }); + + it("restores the original scheduler on stop", () => { + const native = vi.fn(() => 7) as unknown as typeof window.requestAnimationFrame; + window.requestAnimationFrame = native; + + const { handle } = createHarness(); + expect(window.requestAnimationFrame).not.toBe(native); + + handle.stop(); + expect(window.requestAnimationFrame).toBe(native); + + // Stopping twice must not reinstall or throw. + handle.stop(); + expect(window.requestAnimationFrame).toBe(native); + }); + + it("stops sampling once torn down", () => { + const { handle, sink, step } = track(createHarness()); + handle.stop(); + + step(TICKS_TO_FIRST_TRIP + 20, { longTaskMs: 400 }); + + expect(sink).not.toHaveBeenCalled(); + }); + }); +}); diff --git a/src/diagnostics/perfWatchdog.ts b/src/diagnostics/perfWatchdog.ts new file mode 100644 index 00000000..6b331c04 --- /dev/null +++ b/src/diagnostics/perfWatchdog.ts @@ -0,0 +1,568 @@ +/** + * Performance watchdog. + * + * Detects sustained main-thread work while the client is idle and records what + * was running at the time, so a runaway loop leaves evidence instead of a + * three-day archaeology dig. + * + * Three cheap signals, no per-event instrumentation in the steady state: + * + * - a `longtask` PerformanceObserver (browser-native, free when nothing is slow), + * - a 500 ms interval that measures its own scheduling delay (event-loop lag), + * - a `requestAnimationFrame` wrapper that counts *callers*. + * + * The rAF wrapper never schedules a frame of its own. Installing a rAF loop to + * measure frame rate pins the page at 60 fps and manufactures the very load it + * claims to observe — that mistake produced a false positive during the + * investigation this module comes from. + */ + +import { useChannelHistoryStore } from "../stores/channelHistoryStore"; +import { useConnectionStore } from "../stores/connectionStore"; +import { useLiveKitStore } from "../stores/liveKitStore"; +import { useOutputStore } from "../stores/outputStore"; +import type { + LongTaskObserverFactory, + PerfWatchdogHandle, + PerfWatchdogOptions, + WatchdogContributor, + WatchdogCounters, + WatchdogRates, + WatchdogRecord, + WatchdogSink, + WatchdogSubsystems, + WatchdogTripReason, +} from "./watchdogTypes"; + +/** How often the sampler wakes up. Coarse on purpose. */ +const SAMPLE_INTERVAL_MS = 500; +/** Rolling window the trip conditions are evaluated over. */ +const WINDOW_MS = 10_000; +/** First sample is the baseline, so one extra slot covers a full window. */ +const MAX_SAMPLES = WINDOW_MS / SAMPLE_INTERVAL_MS + 1; +/** No keydown or pointer activity for this long counts as idle. */ +const IDLE_THRESHOLD_MS = 10_000; +/** Share of the window inside long tasks that counts as busy. */ +const LONG_TASK_BUSY_RATIO = 0.2; +/** Long tasks must land in this many samples, so one stall cannot trip it. */ +const LONG_TASK_SPREAD_SAMPLES = 4; +/** Average scheduling lag over the window that counts as sustained. */ +const LAG_TRIP_AVERAGE_MS = 25; +/** A single sample counts as laggy above this. */ +const LAG_ELEVATED_MS = 10; +/** Most of the window has to be laggy, not one spike. */ +const LAG_SPREAD_SAMPLES = 12; +/** An episode ends after the condition stays clear this long. */ +const EPISODE_COOLDOWN_MS = 60_000; +/** Cap on the default in-memory record array. */ +const MAX_RECORDS = 20; + +const INTERACTION_EVENTS = ["keydown", "pointerdown", "pointermove"] as const; + +interface WatchdogSample { + at: number; + lagMs: number; + longTaskMs: number; + longTaskCount: number; + longTaskMaxMs: number; + rafCalls: number; + counters: WatchdogCounters; +} + +interface WindowMetrics { + spanMs: number; + longTaskCount: number; + longTaskTotalMs: number; + longTaskMaxMs: number; + busyPercent: number; + lagAverageMs: number; + lagMaxMs: number; + rafCallsPerSecond: number; + samplesWithLongTasks: number; + samplesWithElevatedLag: number; +} + +const recentRecords: WatchdogRecord[] = []; + +/** Default sink: a small bounded array, readable via `getWatchdogRecords`. */ +export const defaultWatchdogSink: WatchdogSink = (record) => { + recentRecords.push(record); + if (recentRecords.length > MAX_RECORDS) { + recentRecords.splice(0, recentRecords.length - MAX_RECORDS); + } +}; + +/** Records held by the default sink, oldest first. */ +export function getWatchdogRecords(): WatchdogRecord[] { + return [...recentRecords]; +} + +export function clearWatchdogRecords(): void { + recentRecords.length = 0; +} + +function roundTo(value: number, places: number): number { + const factor = 10 ** places; + return Math.round(value * factor) / factor; +} + +function perSecond(delta: number, spanMs: number): number { + if (spanMs <= 0 || delta <= 0) { + return 0; + } + return roundTo((delta * 1000) / spanMs, 2); +} + +function lastEntryId(entries: ReadonlyArray<{ id: number }>): number { + return entries.length > 0 ? entries[entries.length - 1].id : 0; +} + +/** + * The bits of `window.mudClient` the watchdog reads. Structural rather than an + * import of `MudClient`, so diagnostics stay decoupled from the client graph. + */ +interface ProbeClientShape { + media?: { cacophony?: { context?: { state?: string } } }; + editors?: { openEditorCount?: number }; +} + +function getProbeClient(): ProbeClientShape | undefined { + if (typeof window === "undefined") { + return undefined; + } + return (window as unknown as { mudClient?: ProbeClientShape }).mudClient; +} + +/** O(1): the stores keep entries in insertion order with monotonic ids. */ +function defaultReadCounters(): WatchdogCounters { + return { + outputEntryId: lastEntryId(useOutputStore.getState().entries), + inboundEntryId: lastEntryId(useChannelHistoryStore.getState().entries), + }; +} + +function defaultReadSubsystems(): WatchdogSubsystems { + const client = getProbeClient(); + return { + audioContextState: client?.media?.cacophony?.context?.state ?? null, + connected: useConnectionStore.getState().connected, + editorsOpen: client?.editors?.openEditorCount ?? 0, + voiceChatActive: useLiveKitStore.getState().tokens.length > 0, + }; +} + +const defaultObserveLongTasks: LongTaskObserverFactory = (onLongTasks) => { + if (typeof PerformanceObserver === "undefined") { + return undefined; + } + try { + const observer = new PerformanceObserver((list) => { + onLongTasks(list.getEntries().map((entry) => ({ duration: entry.duration }))); + }); + observer.observe({ type: "longtask", buffered: false }); + return () => observer.disconnect(); + } catch { + // Firefox and Safari have no `longtask` entry type; lag sampling covers us. + return undefined; + } +}; + +const wrappedAnimationFrameSchedulers = new WeakSet(); + +/** + * Counts `requestAnimationFrame` callers by wrapping the scheduler. The + * callback is passed through untouched and the native id is returned, so + * `cancelAnimationFrame` keeps working. + */ +function installAnimationFrameCounter(onSchedule: () => void): (() => void) | undefined { + if (typeof window === "undefined") { + return undefined; + } + const original = window.requestAnimationFrame; + if (typeof original !== "function" || wrappedAnimationFrameSchedulers.has(original)) { + return undefined; + } + + const wrapped: typeof window.requestAnimationFrame = (callback) => { + onSchedule(); + return original.call(window, callback); + }; + wrappedAnimationFrameSchedulers.add(wrapped); + window.requestAnimationFrame = wrapped; + + return () => { + if (window.requestAnimationFrame === wrapped) { + window.requestAnimationFrame = original; + } + }; +} + +function isVisible(): boolean { + return typeof document === "undefined" || document.visibilityState === "visible"; +} + +function summarizeWindow(samples: WatchdogSample[]): WindowMetrics | undefined { + if (samples.length < 2) { + return undefined; + } + const first = samples[0]; + const last = samples[samples.length - 1]; + const spanMs = last.at - first.at; + if (spanMs <= 0) { + return undefined; + } + + let longTaskCount = 0; + let longTaskTotalMs = 0; + let longTaskMaxMs = 0; + let rafCalls = 0; + let lagTotalMs = 0; + let lagMaxMs = 0; + let samplesWithLongTasks = 0; + let samplesWithElevatedLag = 0; + + // The first sample only supplies the baseline: its accumulators belong to the + // interval before the window opened. + for (let index = 1; index < samples.length; index += 1) { + const sample = samples[index]; + longTaskCount += sample.longTaskCount; + longTaskTotalMs += sample.longTaskMs; + longTaskMaxMs = Math.max(longTaskMaxMs, sample.longTaskMaxMs); + rafCalls += sample.rafCalls; + lagTotalMs += sample.lagMs; + lagMaxMs = Math.max(lagMaxMs, sample.lagMs); + if (sample.longTaskMs > 0) { + samplesWithLongTasks += 1; + } + if (sample.lagMs >= LAG_ELEVATED_MS) { + samplesWithElevatedLag += 1; + } + } + + const measuredSamples = samples.length - 1; + return { + spanMs, + longTaskCount, + longTaskTotalMs: roundTo(longTaskTotalMs, 1), + longTaskMaxMs: roundTo(longTaskMaxMs, 1), + busyPercent: roundTo((longTaskTotalMs / spanMs) * 100, 1), + lagAverageMs: roundTo(lagTotalMs / measuredSamples, 1), + lagMaxMs: roundTo(lagMaxMs, 1), + rafCallsPerSecond: perSecond(rafCalls, spanMs), + samplesWithLongTasks, + samplesWithElevatedLag, + }; +} + +function evaluateTrip(metrics: WindowMetrics): WatchdogTripReason | undefined { + if ( + metrics.busyPercent >= LONG_TASK_BUSY_RATIO * 100 && + metrics.samplesWithLongTasks >= LONG_TASK_SPREAD_SAMPLES + ) { + return "long-tasks"; + } + if ( + metrics.lagAverageMs >= LAG_TRIP_AVERAGE_MS && + metrics.samplesWithElevatedLag >= LAG_SPREAD_SAMPLES + ) { + return "event-loop-lag"; + } + return undefined; +} + +function rankContributors( + metrics: WindowMetrics, + rates: WatchdogRates, + subsystems: WatchdogSubsystems, +): WatchdogContributor[] { + const contributors: WatchdogContributor[] = []; + + if (rates.animationFrameCallsPerSecond >= 1) { + contributors.push({ + name: "animation frames", + detail: `${rates.animationFrameCallsPerSecond} requestAnimationFrame calls/s`, + score: rates.animationFrameCallsPerSecond, + }); + } + if (rates.outputLinesPerSecond >= 0.5) { + contributors.push({ + name: "output", + detail: `${rates.outputLinesPerSecond} output lines/s`, + score: rates.outputLinesPerSecond * 2, + }); + } + if (rates.inboundMessagesPerSecond >= 0.5) { + contributors.push({ + name: "inbound messages", + detail: `${rates.inboundMessagesPerSecond} channel messages/s`, + score: rates.inboundMessagesPerSecond * 2, + }); + } + if (metrics.longTaskCount > 0) { + contributors.push({ + name: "long tasks", + detail: `${metrics.longTaskCount} tasks, ${metrics.longTaskTotalMs}ms total, longest ${metrics.longTaskMaxMs}ms`, + score: metrics.busyPercent, + }); + } + if (metrics.lagAverageMs >= LAG_ELEVATED_MS) { + contributors.push({ + name: "event loop", + detail: `${metrics.lagAverageMs}ms average scheduling lag, peak ${metrics.lagMaxMs}ms`, + score: metrics.lagAverageMs, + }); + } + if (subsystems.voiceChatActive) { + contributors.push({ name: "voice chat", detail: "LiveKit session active", score: 8 }); + } + if (subsystems.audioContextState === "running") { + contributors.push({ name: "audio", detail: "AudioContext running", score: 5 }); + } + if (subsystems.editorsOpen > 0) { + contributors.push({ + name: "editors", + detail: `${subsystems.editorsOpen} editor window(s) open`, + score: subsystems.editorsOpen * 3, + }); + } + + if (contributors.length === 0) { + return [{ name: "unattributed", detail: "no active subsystem stood out", score: 0 }]; + } + + return contributors.sort((left, right) => right.score - left.score).slice(0, 3); +} + +function buildSummary(record: WatchdogRecord): string { + const contributors = record.topContributors + .map((contributor) => `${contributor.name} (${contributor.detail})`) + .join("; "); + return ( + `[perf-watchdog] Sustained main-thread work while idle: ` + + `${record.busyPercent}% of the last ${roundTo(record.windowMs / 1000, 1)}s in long tasks, ` + + `${record.lagAverageMs}ms average event-loop lag, idle for ${Math.round(record.idleForMs / 1000)}s. ` + + `Top contributors: ${contributors}.` + ); +} + +/** + * Starts the watchdog. Cheap to stop: one interval, one observer, three passive + * listeners, and the rAF wrapper, all released by the returned handle. + */ +export function startPerfWatchdog(options: PerfWatchdogOptions = {}): PerfWatchdogHandle { + const clock = options.now ?? (() => performance.now()); + const sink = options.sink ?? defaultWatchdogSink; + const warn = + options.warn ?? + ((summary: string, record: WatchdogRecord) => { + console.warn(summary, record); + }); + const readCounters = options.probes?.readCounters ?? defaultReadCounters; + const readSubsystems = options.probes?.readSubsystems ?? defaultReadSubsystems; + const observeLongTasks = options.observeLongTasks ?? defaultObserveLongTasks; + + const samples: WatchdogSample[] = []; + let lastInteractionAt = clock(); + let lastTickAt = clock(); + let pendingLongTaskMs = 0; + let pendingLongTaskCount = 0; + let pendingLongTaskMaxMs = 0; + let pendingRafCalls = 0; + let previousTickSkipped = true; + let episodeActive = false; + let clearSince: number | null = null; + let stopped = false; + + const noteInteraction = () => { + lastInteractionAt = clock(); + }; + const noteAnimationFrameSchedule = () => { + pendingRafCalls += 1; + }; + + const noteClear = (now: number) => { + if (!episodeActive) { + return; + } + if (clearSince === null) { + clearSince = now; + return; + } + if (now - clearSince >= EPISODE_COOLDOWN_MS) { + episodeActive = false; + clearSince = null; + } + }; + + const emitRecord = ( + reason: WatchdogTripReason, + metrics: WindowMetrics, + samplesInWindow: WatchdogSample[], + idleForMs: number, + ) => { + const first = samplesInWindow[0]; + const last = samplesInWindow[samplesInWindow.length - 1]; + const subsystems = readSubsystems(); + const rates: WatchdogRates = { + inboundMessagesPerSecond: perSecond( + last.counters.inboundEntryId - first.counters.inboundEntryId, + metrics.spanMs, + ), + outputLinesPerSecond: perSecond( + last.counters.outputEntryId - first.counters.outputEntryId, + metrics.spanMs, + ), + animationFrameCallsPerSecond: metrics.rafCallsPerSecond, + }; + + const record: WatchdogRecord = { + kind: "perf-watchdog", + reason, + at: Date.now(), + windowMs: Math.round(metrics.spanMs), + idleForMs: Math.round(idleForMs), + longTaskCount: metrics.longTaskCount, + longTaskTotalMs: metrics.longTaskTotalMs, + longTaskMaxMs: metrics.longTaskMaxMs, + busyPercent: metrics.busyPercent, + lagAverageMs: metrics.lagAverageMs, + lagMaxMs: metrics.lagMaxMs, + rates, + subsystems, + topContributors: rankContributors(metrics, rates, subsystems), + summary: "", + }; + record.summary = buildSummary(record); + + sink(record); + warn(record.summary, record); + }; + + const tick = () => { + if (stopped) { + return; + } + const now = clock(); + const lagMs = Math.max(0, now - (lastTickAt + SAMPLE_INTERVAL_MS)); + lastTickAt = now; + + const longTaskMs = pendingLongTaskMs; + const longTaskCount = pendingLongTaskCount; + const longTaskMaxMs = pendingLongTaskMaxMs; + const rafCalls = pendingRafCalls; + pendingLongTaskMs = 0; + pendingLongTaskCount = 0; + pendingLongTaskMaxMs = 0; + pendingRafCalls = 0; + + const idleForMs = now - lastInteractionAt; + // Background tabs throttle timers to roughly 1 Hz, which reads as lag that + // is not there, so a hidden tab never contributes samples. + if (idleForMs < IDLE_THRESHOLD_MS || !isVisible()) { + samples.length = 0; + previousTickSkipped = true; + noteClear(now); + return; + } + if (previousTickSkipped) { + // Re-baseline after a gap: this tick's lag reflects the gap, not the page. + previousTickSkipped = false; + return; + } + + samples.push({ + at: now, + lagMs, + longTaskMs, + longTaskCount, + longTaskMaxMs, + rafCalls, + counters: readCounters(), + }); + if (samples.length > MAX_SAMPLES) { + samples.splice(0, samples.length - MAX_SAMPLES); + } + if (samples.length < MAX_SAMPLES) { + noteClear(now); + return; + } + + const metrics = summarizeWindow(samples); + const reason = metrics ? evaluateTrip(metrics) : undefined; + if (!metrics || !reason) { + noteClear(now); + return; + } + + clearSince = null; + if (episodeActive) { + // One warning per episode, not a stream. + return; + } + episodeActive = true; + emitRecord(reason, metrics, samples, idleForMs); + }; + + const disposeLongTasks = observeLongTasks((tasks) => { + for (const task of tasks) { + pendingLongTaskMs += task.duration; + pendingLongTaskCount += 1; + pendingLongTaskMaxMs = Math.max(pendingLongTaskMaxMs, task.duration); + } + }); + const disposeAnimationFrameCounter = installAnimationFrameCounter(noteAnimationFrameSchedule); + + if (typeof window !== "undefined") { + for (const eventName of INTERACTION_EVENTS) { + window.addEventListener(eventName, noteInteraction, { passive: true, capture: true }); + } + } + const interval = setInterval(tick, SAMPLE_INTERVAL_MS); + + return { + stop: () => { + if (stopped) { + return; + } + stopped = true; + clearInterval(interval); + disposeLongTasks?.(); + disposeAnimationFrameCounter?.(); + if (typeof window !== "undefined") { + for (const eventName of INTERACTION_EVENTS) { + window.removeEventListener(eventName, noteInteraction, { capture: true }); + } + } + samples.length = 0; + }, + }; +} + +let activeWatchdog: PerfWatchdogHandle | null = null; +let watchdogHolders = 0; + +/** + * Starts the watchdog once for the whole app and hands back a release + * function. Extra callers share the running instance; the last release stops + * it. Survives reconnects because it is tied to the app, not the connection. + */ +export function ensurePerfWatchdog(options?: PerfWatchdogOptions): () => void { + watchdogHolders += 1; + if (!activeWatchdog) { + activeWatchdog = startPerfWatchdog(options); + } + + let released = false; + return () => { + if (released) { + return; + } + released = true; + watchdogHolders -= 1; + if (watchdogHolders <= 0) { + watchdogHolders = 0; + activeWatchdog?.stop(); + activeWatchdog = null; + } + }; +} diff --git a/src/diagnostics/watchdogTypes.ts b/src/diagnostics/watchdogTypes.ts new file mode 100644 index 00000000..3916849f --- /dev/null +++ b/src/diagnostics/watchdogTypes.ts @@ -0,0 +1,114 @@ +/** + * Types for the performance watchdog (see `perfWatchdog.ts`). + * + * Every shape here is plain JSON so a record can be dropped straight into a + * diagnostics buffer, stringified, and pasted into an issue. + */ + +/** Which detector tripped. */ +export type WatchdogTripReason = "long-tasks" | "event-loop-lag"; + +/** Subsystems that are live at the moment of the trip. */ +export interface WatchdogSubsystems { + /** `AudioContext.state`, or null when no audio graph exists yet. */ + audioContextState: string | null; + /** Whether the MUD connection is up. */ + connected: boolean; + /** Editor windows the client believes are open. */ + editorsOpen: number; + /** Voice chat (LiveKit) has at least one live token. */ + voiceChatActive: boolean; +} + +/** Coarse traffic rates, derived from store entry-id deltas over the window. */ +export interface WatchdogRates { + /** Channel/comm messages arriving per second. */ + inboundMessagesPerSecond: number; + /** Output entries appended per second. */ + outputLinesPerSecond: number; + /** `requestAnimationFrame` scheduling calls per second, by caller count. */ + animationFrameCallsPerSecond: number; +} + +/** A named suspect, ranked so the warning can lead with the loudest one. */ +export interface WatchdogContributor { + name: string; + detail: string; + score: number; +} + +/** One episode of sustained main-thread work while the client was idle. */ +export interface WatchdogRecord { + kind: "perf-watchdog"; + reason: WatchdogTripReason; + /** Wall-clock time of the trip (`Date.now()`). */ + at: number; + /** Span the measurements cover, in milliseconds. */ + windowMs: number; + /** How long the user had been idle when the watchdog tripped. */ + idleForMs: number; + longTaskCount: number; + longTaskTotalMs: number; + longTaskMaxMs: number; + /** Share of the window spent inside long tasks, 0-100. */ + busyPercent: number; + lagAverageMs: number; + lagMaxMs: number; + rates: WatchdogRates; + subsystems: WatchdogSubsystems; + /** Highest-scoring suspects, most significant first. */ + topContributors: WatchdogContributor[]; + /** Human-readable one-liner; the same text used for the console warning. */ + summary: string; +} + +/** + * Where records go. Defaults to a small bounded in-memory array; the + * diagnostics buffer can be passed in instead. + */ +export type WatchdogSink = (record: WatchdogRecord) => void; + +/** Cheap per-tick counters. Must stay O(1) — this runs twice a second. */ +export interface WatchdogCounters { + /** Latest id in the output store, monotonic until reset. */ + outputEntryId: number; + /** Latest id in the channel history store, monotonic until reset. */ + inboundEntryId: number; +} + +/** Attribution probes, split so the expensive half only runs on a trip. */ +export interface WatchdogProbes { + readCounters: () => WatchdogCounters; + readSubsystems: () => WatchdogSubsystems; +} + +/** A long task, reduced to the two fields the watchdog needs. */ +export interface WatchdogLongTask { + duration: number; +} + +/** + * Installs a long-task source and returns a disposer, or undefined when the + * platform has no `longtask` support (Firefox and Safari, at time of writing). + */ +export type LongTaskObserverFactory = ( + onLongTasks: (tasks: WatchdogLongTask[]) => void, +) => (() => void) | undefined; + +export interface PerfWatchdogOptions { + /** Record destination. Defaults to the bounded in-memory array. */ + sink?: WatchdogSink; + /** Warning emitter. Defaults to `console.warn`. */ + warn?: (summary: string, record: WatchdogRecord) => void; + /** Monotonic clock, in milliseconds. Defaults to `performance.now()`. */ + now?: () => number; + /** Overrides for attribution probes; unspecified probes use the defaults. */ + probes?: Partial; + /** Long-task source. Defaults to a `longtask` PerformanceObserver. */ + observeLongTasks?: LongTaskObserverFactory; +} + +export interface PerfWatchdogHandle { + /** Removes every listener, timer, observer, and the rAF wrapper. */ + stop: () => void; +} From 20a209b0872966e7a76874588cf49fbf260d383b Mon Sep 17 00:00:00 2001 From: David Sexton Date: Tue, 11 Aug 2026 19:57:04 -0700 Subject: [PATCH 2/2] Neutralize openEditorCount doc comment Matches the identical hunk in the diagnostics branch (#111) so the two PRs merge cleanly in either order. Co-Authored-By: Claude Fable 5 --- src/EditorManager.ts | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/EditorManager.ts b/src/EditorManager.ts index 6fb89347..241ad1d1 100644 --- a/src/EditorManager.ts +++ b/src/EditorManager.ts @@ -22,8 +22,8 @@ export class EditorManager { } /** - * Editor windows that are still open. Read by the performance watchdog when - * attributing sustained main-thread work. + * Editor windows that are still open. Read by the diagnostics and + * performance tooling when attributing main-thread work. */ get openEditorCount(): number { let count = 0;