diff --git a/src/App.tsx b/src/App.tsx index 1c8db33..c75542f 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 05a8ec8..241ad1d 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 diagnostics and + * performance tooling when attributing 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 0000000..a431c9a --- /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 0000000..6b331c0 --- /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 0000000..3916849 --- /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; +}