From 51f03eb525c5b2ae66d633c05fe72ba2d06568fa Mon Sep 17 00:00:00 2001 From: Neil <4138956+nwparker@users.noreply.github.com> Date: Sat, 29 Aug 2026 03:55:45 -0700 Subject: [PATCH 1/4] fix(diagnostics): measure terminal IME input --- .../terminal-ime-composition-route.ts | 20 +- ...me-xterm-linux-native-trace-replay.test.ts | 63 ++- .../src/lib/typing-latency-diagnostic.ts | 203 -------- ...yping-latency-echo-instrumentation.test.ts | 138 ----- .../typing-latency-echo-instrumentation.ts | 176 ------- .../census-probe.ts} | 10 +- .../diagnostic-lifecycle.test.ts | 107 ++++ .../diagnostic-summary.test.ts} | 13 +- .../diagnostic-summary.ts} | 10 +- .../src/lib/typing-latency/diagnostic.ts | 307 ++++++++++++ .../echo-instrumentation.test.ts | 472 ++++++++++++++++++ .../typing-latency/echo-instrumentation.ts | 310 ++++++++++++ .../lib/typing-latency/echo-observation.ts | 92 ++++ .../lib/typing-latency/input-events.test.ts | 97 ++++ .../src/lib/typing-latency/input-events.ts | 69 +++ .../lib/typing-latency/input-source.test.ts | 76 +++ .../src/lib/typing-latency/input-source.ts | 94 ++++ .../src/lib/typing-latency/pane-target.ts | 54 ++ .../lib/typing-latency/sample-window.test.ts | 28 ++ .../src/lib/typing-latency/sample-window.ts | 42 ++ src/renderer/src/main.tsx | 2 +- 21 files changed, 1831 insertions(+), 552 deletions(-) delete mode 100644 src/renderer/src/lib/typing-latency-diagnostic.ts delete mode 100644 src/renderer/src/lib/typing-latency-echo-instrumentation.test.ts delete mode 100644 src/renderer/src/lib/typing-latency-echo-instrumentation.ts rename src/renderer/src/lib/{typing-latency-census-probe.ts => typing-latency/census-probe.ts} (90%) create mode 100644 src/renderer/src/lib/typing-latency/diagnostic-lifecycle.test.ts rename src/renderer/src/lib/{typing-latency-diagnostic-summary.test.ts => typing-latency/diagnostic-summary.test.ts} (94%) rename src/renderer/src/lib/{typing-latency-diagnostic-summary.ts => typing-latency/diagnostic-summary.ts} (96%) create mode 100644 src/renderer/src/lib/typing-latency/diagnostic.ts create mode 100644 src/renderer/src/lib/typing-latency/echo-instrumentation.test.ts create mode 100644 src/renderer/src/lib/typing-latency/echo-instrumentation.ts create mode 100644 src/renderer/src/lib/typing-latency/echo-observation.ts create mode 100644 src/renderer/src/lib/typing-latency/input-events.test.ts create mode 100644 src/renderer/src/lib/typing-latency/input-events.ts create mode 100644 src/renderer/src/lib/typing-latency/input-source.test.ts create mode 100644 src/renderer/src/lib/typing-latency/input-source.ts create mode 100644 src/renderer/src/lib/typing-latency/pane-target.ts create mode 100644 src/renderer/src/lib/typing-latency/sample-window.test.ts create mode 100644 src/renderer/src/lib/typing-latency/sample-window.ts diff --git a/src/renderer/src/components/terminal-pane/terminal-ime-composition-route.ts b/src/renderer/src/components/terminal-pane/terminal-ime-composition-route.ts index 8287b4854cc0..7b7ed78989fb 100644 --- a/src/renderer/src/components/terminal-pane/terminal-ime-composition-route.ts +++ b/src/renderer/src/components/terminal-pane/terminal-ime-composition-route.ts @@ -4,7 +4,7 @@ import type { PtyTransport } from './pty-transport' export const XTERM_COMPOSITION_SESSION_START_EVENT = 'xterm-composition-session-start' export const XTERM_COMPOSITION_SESSION_END_EVENT = 'xterm-composition-session-end' -type CompositionSessionDetail = { +export type TerminalImeCompositionSessionDetail = { id: number data?: string dataPendingReconciliation?: boolean @@ -75,16 +75,22 @@ export function hasPendingTerminalImeComposition( return false } -function getCompositionDetail(event: Event): CompositionSessionDetail | null { +export function readTerminalImeCompositionSessionDetail( + event: Event +): TerminalImeCompositionSessionDetail | null { if (!(event instanceof CustomEvent)) { return null } - const detail = event.detail as Partial | null - if (!detail || !Number.isSafeInteger(detail.id) || detail.id! <= 0) { + const detail = event.detail as Partial | null + if (!detail) { + return null + } + const id = detail.id + if (typeof id !== 'number' || !Number.isSafeInteger(id) || id <= 0) { return null } return { - id: detail.id!, + id, data: typeof detail.data === 'string' ? detail.data : undefined, dataPendingReconciliation: detail.dataPendingReconciliation === true } @@ -109,7 +115,7 @@ export function installTerminalImeCompositionRoute(args: { } const onSessionStart = (event: Event): void => { - const detail = getCompositionDetail(event) + const detail = readTerminalImeCompositionSessionDetail(event) if (!detail || disposed) { return } @@ -122,7 +128,7 @@ export function installTerminalImeCompositionRoute(args: { } const onSessionEnd = (event: Event): void => { - const detail = getCompositionDetail(event) + const detail = readTerminalImeCompositionSessionDetail(event) if (!detail) { return } diff --git a/src/renderer/src/components/terminal-pane/terminal-ime-xterm-linux-native-trace-replay.test.ts b/src/renderer/src/components/terminal-pane/terminal-ime-xterm-linux-native-trace-replay.test.ts index e8a7767f3546..3be79ea7b9cb 100644 --- a/src/renderer/src/components/terminal-pane/terminal-ime-xterm-linux-native-trace-replay.test.ts +++ b/src/renderer/src/components/terminal-pane/terminal-ime-xterm-linux-native-trace-replay.test.ts @@ -16,6 +16,10 @@ import { Terminal } from '@xterm/xterm' import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest' import fcitx5Trace from './__fixtures__/fcitx5-hangul-mixed-ascii-terminal-trace.json' import ibusTrace from './__fixtures__/ibus-hangul-mixed-ascii-terminal-trace.json' +import { + installTypingLatencyInputEvents, + type TypingInputSignal +} from '@/lib/typing-latency/input-events' type RecordedEvent = { type: string @@ -102,27 +106,35 @@ type PreeditSample = { data: string; shown: boolean } async function replayTrace( trace: RecordedTrace -): Promise<{ stream: string; preedits: PreeditSample[] }> { +): Promise<{ stream: string; preedits: PreeditSample[]; inputSignals: TypingInputSignal[] }> { const { emitted, terminal, textarea } = openTerminal() const preedits: PreeditSample[] = [] - for (const recorded of trace.dom) { - // Keys were driven 20 ms apart, so every physical key event began its own task; the composition - // and input events the IME derived from one key stay in that key's task, which is what lets - // xterm's deferred commit see them. - if (recorded.type === 'keydown' || recorded.type === 'keyup') { - await nextEventLoop() - } - replayEvent(textarea, recorded) - if (recorded.type === 'compositionupdate' && recorded.data) { - const view = terminal.element?.querySelector('.composition-view') - preedits.push({ data: recorded.data, shown: view?.classList.contains('active') === true }) + const inputSignals: TypingInputSignal[] = [] + const detachInputEvents = installTypingLatencyInputEvents(window, (signal) => { + inputSignals.push(signal) + }) + try { + for (const recorded of trace.dom) { + // Keys were driven 20 ms apart, so every physical key event began its own task; the composition + // and input events the IME derived from one key stay in that key's task, which is what lets + // xterm's deferred commit see them. + if (recorded.type === 'keydown' || recorded.type === 'keyup') { + await nextEventLoop() + } + replayEvent(textarea, recorded) + if (recorded.type === 'compositionupdate' && recorded.data) { + const view = terminal.element?.querySelector('.composition-view') + preedits.push({ data: recorded.data, shown: view?.classList.contains('active') === true }) + } } + // Two turns: the commit's deferred send, then the late-native-commit window it opens. + await nextEventLoop() + await nextEventLoop() + return { stream: emitted.join(''), preedits, inputSignals } + } finally { + detachInputEvents() + terminal.dispose() } - // Two turns: the commit's deferred send, then the late-native-commit window it opens. - await nextEventLoop() - await nextEventLoop() - terminal.dispose() - return { stream: emitted.join(''), preedits } } describe.each([ @@ -152,6 +164,23 @@ describe.each([ expect(stream.match(/abc/g)).toHaveLength(trace.repetitions) }) + it('reports each reconciled commit to the typing diagnostic', async () => { + const { inputSignals } = await replayTrace(trace) + const expectedCommits = trace.expectedLines.flatMap((line) => [line.at(0), line.at(-1)]) + const commitSignals = inputSignals + .filter((signal) => signal.source === 'ime') + .map((signal) => signal.text) + + if (trace.inputFramework === 'ibus') { + const rawEndData = trace.dom + .filter((recorded) => recorded.type === 'compositionend') + .map((recorded) => recorded.data ?? '') + expect(rawEndData.length).toBeGreaterThan(0) + expect(rawEndData.every((data) => data === '')).toBe(true) + } + expect(commitSignals).toEqual(expectedCommits) + }) + it('matches the bytes the PTY received on the recorded run', async () => { const { stream } = await replayTrace(trace) // The tty turned each CR into LF, so compare against the recorded lines plus that conversion. diff --git a/src/renderer/src/lib/typing-latency-diagnostic.ts b/src/renderer/src/lib/typing-latency-diagnostic.ts deleted file mode 100644 index 28630cd49eb8..000000000000 --- a/src/renderer/src/lib/typing-latency-diagnostic.ts +++ /dev/null @@ -1,203 +0,0 @@ -/** - * One-paste typing-latency self-diagnostic: - * - * window.__orcaTypingDiagnostic.start() // then type normally for ~20s - * window.__orcaTypingDiagnostic.report() // logs + returns a JSON-safe object - * window.__orcaTypingDiagnostic.stop() - * - * Why: keystroke-echo lag reproduces on one user's machine only, so the - * measurement has to run THERE. The census answers what a user cannot: agent-row - * scale, store listener count, suspect settings, and which agent/screen mode the - * focused pane is in. - * - * Nothing attaches to the keystroke path until start(); stop() detaches all of it. - */ -import { - countMountedAgentRows, - readFocusedPaneCensus, - readProbeStoreState, - readStoreListenerCount -} from './typing-latency-census-probe' -import { - detachPaneEcho, - findPaneOwningFocus, - instrumentPaneEcho, - listProbePanes, - recordKeystroke, - type InstrumentedPane -} from './typing-latency-echo-instrumentation' -import { - summarizeLatencySamples, - summarizeTypingScaleCensus, - type LatencyPercentiles, - type TypingScaleCensus -} from './typing-latency-diagnostic-summary' - -/** Bounds memory during sustained typing: percentiles only need a rolling window. */ -const MAX_SAMPLES = 2000 - -type ProbeState = { - startedAt: number - startedAtIso: string - parseLatencies: number[] - paintLatencies: number[] - keystrokeBytes: number[] - keystrokeWrites: number[] - unmatchedKeystrokes: number - keystrokesWithoutTerminalFocus: number - panes: InstrumentedPane[] - detachKeydown: () => void -} - -let active: ProbeState | null = null -let lastState: ProbeState | null = null -let cachedAppVersion: string | null = null - -function push(values: number[], value: number): void { - values.push(value) - if (values.length > MAX_SAMPLES) { - values.shift() - } -} - -export type TypingLatencyReport = { - capturedAt: string - sampling: { - running: boolean - startedAt: string | null - durationMs: number | null - keystrokesWithoutTerminalFocus: number - unmatchedKeystrokes: number - instrumentedPanes: number - } - echoParseMs: LatencyPercentiles - echoPaintMs: LatencyPercentiles - bytesPerKeystroke: LatencyPercentiles - writesPerKeystroke: LatencyPercentiles - census: TypingScaleCensus -} - -function buildReport(state: ProbeState | null, running: boolean): TypingLatencyReport { - return { - capturedAt: new Date().toISOString(), - sampling: { - running, - startedAt: state?.startedAtIso ?? null, - durationMs: state ? Math.round(performance.now() - state.startedAt) : null, - keystrokesWithoutTerminalFocus: state?.keystrokesWithoutTerminalFocus ?? 0, - unmatchedKeystrokes: state?.unmatchedKeystrokes ?? 0, - instrumentedPanes: state?.panes.length ?? 0 - }, - echoParseMs: summarizeLatencySamples(state?.parseLatencies ?? []), - echoPaintMs: summarizeLatencySamples(state?.paintLatencies ?? []), - bytesPerKeystroke: summarizeLatencySamples(state?.keystrokeBytes ?? []), - writesPerKeystroke: summarizeLatencySamples(state?.keystrokeWrites ?? []), - census: summarizeTypingScaleCensus({ - state: readProbeStoreState(), - appVersion: cachedAppVersion, - livePaneCount: listProbePanes().length, - instrumentedPaneCount: state?.panes.length ?? 0, - mountedAgentRowCount: countMountedAgentRows(), - storeListenerCount: readStoreListenerCount(), - focusedPane: readFocusedPaneCensus() - }) - } -} - -function cacheAppVersion(): void { - void window.api?.updater - ?.getVersion?.() - .then((version) => { - cachedAppVersion = version - }) - .catch(() => undefined) -} - -/** Modifier-only presses produce no echo and would poison the pending queue. */ -function isEchoingKey(event: KeyboardEvent): boolean { - return event.key.length === 1 || event.key === 'Enter' || event.key === 'Backspace' -} - -function startProbe(): string { - if (active) { - return 'Typing diagnostic already running. Type for ~20s, then run __orcaTypingDiagnostic.report().' - } - cacheAppVersion() - - const state: ProbeState = { - startedAt: performance.now(), - startedAtIso: new Date().toISOString(), - parseLatencies: [], - paintLatencies: [], - keystrokeBytes: [], - keystrokeWrites: [], - unmatchedKeystrokes: 0, - keystrokesWithoutTerminalFocus: 0, - panes: [], - detachKeydown: () => undefined - } - state.panes = listProbePanes().map((pane) => - instrumentPaneEcho(pane, (sample) => { - push(state.parseLatencies, sample.parseMs) - push(state.paintLatencies, sample.paintMs) - push(state.keystrokeBytes, sample.bytes) - push(state.keystrokeWrites, sample.writes) - }) - ) - - const onKeydown = (event: KeyboardEvent): void => { - if (!isEchoingKey(event)) { - return - } - const target = findPaneOwningFocus(state.panes) - if (!target) { - state.keystrokesWithoutTerminalFocus += 1 - return - } - state.unmatchedKeystrokes += recordKeystroke(target, performance.now()) - } - window.addEventListener('keydown', onKeydown, { capture: true }) - state.detachKeydown = () => window.removeEventListener('keydown', onKeydown, { capture: true }) - - active = state - lastState = state - return `Typing diagnostic started on ${state.panes.length} pane(s). Click into the agent terminal, type normally for ~20 seconds, then run __orcaTypingDiagnostic.report().` -} - -function stopProbe(): string { - const state = active - if (!state) { - return 'Typing diagnostic was not running.' - } - active = null - state.detachKeydown() - for (const entry of state.panes) { - detachPaneEcho(entry) - } - return 'Typing diagnostic stopped. Run __orcaTypingDiagnostic.report() to read the last samples.' -} - -function reportProbe(): TypingLatencyReport { - const report = buildReport(active ?? lastState, active !== null) - console.log('[orca] typing latency diagnostic', report) - return report -} - -export type TypingDiagnosticBridge = { - start: () => string - stop: () => string - report: () => TypingLatencyReport -} - -type TypingDiagnosticWindow = Window & { __orcaTypingDiagnostic?: TypingDiagnosticBridge } - -export function installTypingLatencyDiagnostic(): void { - if (typeof window === 'undefined') { - return - } - const target = window as TypingDiagnosticWindow - if (target.__orcaTypingDiagnostic) { - return - } - target.__orcaTypingDiagnostic = { start: startProbe, stop: stopProbe, report: reportProbe } -} diff --git a/src/renderer/src/lib/typing-latency-echo-instrumentation.test.ts b/src/renderer/src/lib/typing-latency-echo-instrumentation.test.ts deleted file mode 100644 index 7e220eaa9dd5..000000000000 --- a/src/renderer/src/lib/typing-latency-echo-instrumentation.test.ts +++ /dev/null @@ -1,138 +0,0 @@ -import { describe, expect, it } from 'vitest' -import { - detachPaneEcho, - instrumentPaneEcho, - recordKeystroke, - type EchoSample, - type InstrumentedPane -} from './typing-latency-echo-instrumentation' - -function emptyEntry(): InstrumentedPane { - return { pane: {}, pending: [], disposables: [], restoreWrite: null } -} - -type FakeTerminal = { - write: (data: string | Uint8Array, callback?: () => void) => void - onWriteParsed: (listener: () => void) => { dispose: () => void } - onRender: (listener: () => void) => { dispose: () => void } -} - -function fakeTerminal(): { - terminal: FakeTerminal - emitParsed: () => void - emitRender: () => void - writtenPayloads: (string | Uint8Array)[] - disposeCount: () => number -} { - const parsedListeners: (() => void)[] = [] - const renderListeners: (() => void)[] = [] - const writtenPayloads: (string | Uint8Array)[] = [] - let disposed = 0 - return { - terminal: { - write: (data) => { - writtenPayloads.push(data) - }, - onWriteParsed: (listener) => { - parsedListeners.push(listener) - return { - dispose: () => { - disposed += 1 - } - } - }, - onRender: (listener) => { - renderListeners.push(listener) - return { - dispose: () => { - disposed += 1 - } - } - } - }, - emitParsed: () => parsedListeners.forEach((listener) => listener()), - emitRender: () => renderListeners.forEach((listener) => listener()), - writtenPayloads, - disposeCount: () => disposed - } -} - -describe('recordKeystroke', () => { - it('queues keystrokes rather than overwriting a single slot', () => { - const entry = emptyEntry() - expect(recordKeystroke(entry, 0)).toBe(0) - expect(recordKeystroke(entry, 5)).toBe(0) - expect(entry.pending.map((pending) => pending.t0)).toEqual([0, 5]) - }) - - it('counts keystrokes whose echo never parsed as dropped', () => { - const entry = emptyEntry() - recordKeystroke(entry, 0) - recordKeystroke(entry, 1) - expect(recordKeystroke(entry, 5000)).toBe(2) - expect(entry.pending).toHaveLength(1) - }) - - it('bounds the queue so sustained typing cannot grow memory', () => { - const entry = emptyEntry() - for (let index = 0; index < 200; index += 1) { - recordKeystroke(entry, index) - } - expect(entry.pending.length).toBeLessThanOrEqual(64) - }) -}) - -describe('instrumentPaneEcho', () => { - it('reports parse/paint latency and per-keystroke byte and write volume', () => { - const fake = fakeTerminal() - const samples: EchoSample[] = [] - const entry = instrumentPaneEcho({ terminal: fake.terminal }, (sample) => samples.push(sample)) - - recordKeystroke(entry, performance.now()) - fake.terminal.write('a'.repeat(230)) - fake.terminal.write(new Uint8Array(6)) - fake.emitParsed() - fake.emitRender() - - expect(samples).toHaveLength(1) - expect(samples[0]?.bytes).toBe(236) - expect(samples[0]?.writes).toBe(2) - expect(samples[0]?.parseMs).toBeGreaterThanOrEqual(0) - expect(samples[0]?.paintMs).toBeGreaterThanOrEqual(samples[0]?.parseMs ?? 0) - // Wrapping write() must not swallow terminal output. - expect(fake.writtenPayloads).toHaveLength(2) - }) - - it('holds an unparsed keystroke across a render instead of discarding it', () => { - const fake = fakeTerminal() - const samples: EchoSample[] = [] - const entry = instrumentPaneEcho({ terminal: fake.terminal }, (sample) => samples.push(sample)) - - recordKeystroke(entry, performance.now()) - fake.emitRender() - expect(samples).toHaveLength(0) - - fake.emitParsed() - fake.emitRender() - expect(samples).toHaveLength(1) - }) - - it('restores the original write and disposes listeners on detach', () => { - const fake = fakeTerminal() - const originalWrite = fake.terminal.write - const entry = instrumentPaneEcho({ terminal: fake.terminal }, () => undefined) - expect(fake.terminal.write).not.toBe(originalWrite) - - detachPaneEcho(entry) - - expect(fake.terminal.write).toBe(originalWrite) - expect(fake.disposeCount()).toBe(2) - expect(entry.pending).toEqual([]) - }) - - it('degrades to a no-op instead of throwing when the pane has no terminal', () => { - const entry = instrumentPaneEcho({}, () => undefined) - expect(entry.disposables).toEqual([]) - expect(() => detachPaneEcho(entry)).not.toThrow() - }) -}) diff --git a/src/renderer/src/lib/typing-latency-echo-instrumentation.ts b/src/renderer/src/lib/typing-latency-echo-instrumentation.ts deleted file mode 100644 index 3c7b3b50f12d..000000000000 --- a/src/renderer/src/lib/typing-latency-echo-instrumentation.ts +++ /dev/null @@ -1,176 +0,0 @@ -/** - * Per-pane echo instrumentation for the devtools typing-latency probe. - * - * Mechanics mirror the E2E echo probe: keydown stamps t0, xterm's - * onWriteParsed marks the echo parse, onRender marks the paint, and a bounded - * pending QUEUE (never a single slot) keeps a slow echo from being silently - * discarded. Attached only while the probe runs; detachPaneEcho restores - * everything it wrapped. - */ -import { forEachLivePaneForDesyncSentinel } from '@/lib/pane-manager/pane-manager-registry' - -type Disposable = { dispose: () => void } - -type TerminalLike = { - cols?: number - rows?: number - element?: HTMLElement | null - buffer?: { active?: { type?: string; length?: number } } - write?: (data: string | Uint8Array, callback?: () => void) => void - onWriteParsed?: (listener: () => void) => Disposable - onRender?: (listener: () => void) => Disposable -} - -export type ProbePane = { - id?: number - terminal?: TerminalLike - container?: HTMLElement - leafId?: string -} - -type PendingKeystroke = { - t0: number - bytes: number - writes: number - parsedAt: number | null -} - -export type EchoSample = { - parseMs: number - paintMs: number - bytes: number - writes: number -} - -export type InstrumentedPane = { - pane: ProbePane - pending: PendingKeystroke[] - disposables: Disposable[] - restoreWrite: (() => void) | null -} - -/** An echo that has not parsed within this window is counted as unmatched, never as a sample. */ -const ECHO_TIMEOUT_MS = 2000 -const MAX_PENDING = 64 - -export function listProbePanes(): ProbePane[] { - const panes: ProbePane[] = [] - try { - forEachLivePaneForDesyncSentinel((_key, pane) => { - panes.push(pane as ProbePane) - }) - } catch { - // Why: a mid-teardown manager must not prevent the probe from starting. - } - return panes -} - -export function paneRootElement(pane: ProbePane): HTMLElement | null { - return pane.container ?? pane.terminal?.element ?? null -} - -export function findPaneOwningFocus( - entries: readonly T[] -): T | null { - const focused = typeof document === 'undefined' ? null : document.activeElement - if (!focused) { - return null - } - return entries.find((entry) => paneRootElement(entry.pane)?.contains(focused) === true) ?? null -} - -function oldestUnparsed(entry: InstrumentedPane): PendingKeystroke | null { - return entry.pending.find((pending) => pending.parsedAt === null) ?? null -} - -/** Returns how many pending keystrokes were dropped without an echo. */ -export function recordKeystroke(entry: InstrumentedPane, now: number): number { - let dropped = 0 - while (entry.pending.length > 0 && now - (entry.pending[0]?.t0 ?? now) > ECHO_TIMEOUT_MS) { - entry.pending.shift() - dropped += 1 - } - while (entry.pending.length >= MAX_PENDING) { - entry.pending.shift() - dropped += 1 - } - entry.pending.push({ t0: now, bytes: 0, writes: 0, parsedAt: null }) - return dropped -} - -export function instrumentPaneEcho( - pane: ProbePane, - onSample: (sample: EchoSample) => void -): InstrumentedPane { - const entry: InstrumentedPane = { pane, pending: [], disposables: [], restoreWrite: null } - const terminal = pane.terminal - if (!terminal) { - return entry - } - - // Why: xterm exposes no per-write byte counter, so the probe wraps write() for - // the duration of sampling — this is how per-keystroke output volume (Codex - // ~230-306 bytes vs grok ~66) becomes visible without a build change. - const originalWrite = terminal.write - if (typeof originalWrite === 'function') { - const wrapped = (data: string | Uint8Array, callback?: () => void): void => { - const pending = oldestUnparsed(entry) - if (pending) { - pending.writes += 1 - pending.bytes += typeof data === 'string' ? data.length : data.byteLength - } - originalWrite.call(terminal, data, callback) - } - terminal.write = wrapped - entry.restoreWrite = () => { - if (terminal.write === wrapped) { - terminal.write = originalWrite - } - } - } - - if (typeof terminal.onWriteParsed === 'function') { - entry.disposables.push( - terminal.onWriteParsed(() => { - const pending = oldestUnparsed(entry) - if (pending) { - pending.parsedAt = performance.now() - } - }) - ) - } - if (typeof terminal.onRender === 'function') { - entry.disposables.push( - terminal.onRender(() => { - const now = performance.now() - while (entry.pending.length > 0 && entry.pending[0]?.parsedAt != null) { - const pending = entry.pending.shift() - if (!pending || pending.parsedAt == null) { - continue - } - onSample({ - parseMs: pending.parsedAt - pending.t0, - paintMs: now - pending.t0, - bytes: pending.bytes, - writes: pending.writes - }) - } - }) - ) - } - return entry -} - -export function detachPaneEcho(entry: InstrumentedPane): void { - for (const disposable of entry.disposables) { - try { - disposable.dispose() - } catch { - // Why: a pane disposed mid-run already dropped its listeners. - } - } - entry.disposables = [] - entry.restoreWrite?.() - entry.restoreWrite = null - entry.pending = [] -} diff --git a/src/renderer/src/lib/typing-latency-census-probe.ts b/src/renderer/src/lib/typing-latency/census-probe.ts similarity index 90% rename from src/renderer/src/lib/typing-latency-census-probe.ts rename to src/renderer/src/lib/typing-latency/census-probe.ts index 6ba950abdac7..e8b85fc8139e 100644 --- a/src/renderer/src/lib/typing-latency-census-probe.ts +++ b/src/renderer/src/lib/typing-latency/census-probe.ts @@ -1,15 +1,11 @@ /** - * Live-state reads for the typing-latency census: focused-pane identity/screen + * Live-state reads for the typing latency census: focused-pane identity/screen * mode, mounted agent-row count, and the zustand listener count. Split from the * probe so the sampling loop stays free of store/DOM lookups. */ import { useAppStore } from '@/store' -import { - listProbePanes, - paneRootElement, - type ProbePane -} from './typing-latency-echo-instrumentation' -import type { FocusedPaneCensus } from './typing-latency-diagnostic-summary' +import { listProbePanes, paneRootElement, type ProbePane } from './echo-instrumentation' +import type { FocusedPaneCensus } from './diagnostic-summary' type ProbeStoreState = { activeTabId?: string | null diff --git a/src/renderer/src/lib/typing-latency/diagnostic-lifecycle.test.ts b/src/renderer/src/lib/typing-latency/diagnostic-lifecycle.test.ts new file mode 100644 index 000000000000..cfb04bc0509b --- /dev/null +++ b/src/renderer/src/lib/typing-latency/diagnostic-lifecycle.test.ts @@ -0,0 +1,107 @@ +// @vitest-environment happy-dom +import { afterEach, describe, expect, it, vi } from 'vitest' +import { installTypingLatencyDiagnostic, type TypingDiagnosticBridge } from './diagnostic' +import type { PreventedKeystrokeDiscard } from './echo-instrumentation' +import type { TypingInputRegistration, TypingInputSignal } from './input-events' + +const mocks = vi.hoisted(() => { + const panes = [{ id: 1 }, { id: 2 }] + return { + discardUndispatchedKeystroke: vi.fn<() => PreventedKeystrokeDiscard>(() => null), + detachInputEvents: vi.fn(), + detachPaneEcho: vi.fn(() => 1), + findPaneOwningFocus: vi.fn<() => object | null>(() => null), + findPaneOwningNode: vi.fn<() => object | null>(() => null), + inputListener: null as ((signal: TypingInputSignal) => TypingInputRegistration | void) | null, + panes, + recordKeystroke: vi.fn(() => 0) + } +}) + +vi.mock('./census-probe', () => ({ + countMountedAgentRows: () => 0, + readFocusedPaneCensus: () => null, + readProbeStoreState: () => null, + readStoreListenerCount: () => 0 +})) + +vi.mock('./echo-instrumentation', () => ({ + detachPaneEcho: mocks.detachPaneEcho, + discardUndispatchedKeystroke: mocks.discardUndispatchedKeystroke, + findPaneOwningFocus: mocks.findPaneOwningFocus, + findPaneOwningNode: mocks.findPaneOwningNode, + instrumentPaneEcho: vi.fn((pane) => ({ pane })), + listProbePanes: vi.fn(() => mocks.panes), + recordKeystroke: mocks.recordKeystroke +})) + +vi.mock('./input-events', () => ({ + installTypingLatencyInputEvents: vi.fn((_target, listener) => { + mocks.inputListener = listener + return mocks.detachInputEvents + }) +})) + +type DiagnosticWindow = Window & { __orcaTypingDiagnostic?: TypingDiagnosticBridge } + +describe('typing latency diagnostic lifecycle', () => { + afterEach(() => { + delete (window as DiagnosticWindow).__orcaTypingDiagnostic + vi.restoreAllMocks() + }) + + it('releases stopped pane state while preserving the instrumented count', () => { + vi.spyOn(console, 'log').mockImplementation(() => undefined) + installTypingLatencyDiagnostic() + const bridge = (window as DiagnosticWindow).__orcaTypingDiagnostic + if (!bridge) { + throw new Error('Typing latency diagnostic bridge was not installed') + } + + bridge.start() + expect(bridge.report().sampling.instrumentedPanes).toBe(2) + bridge.stop() + + expect(mocks.detachInputEvents).toHaveBeenCalledOnce() + expect(mocks.detachPaneEcho).toHaveBeenCalledTimes(2) + expect(bridge.report()).toMatchObject({ + sampling: { instrumentedPanes: 2, unmatchedKeystrokes: 2 }, + census: { panes: { instrumented: 2 } } + }) + + const inputListener = mocks.inputListener + if (!inputListener) { + throw new Error('Typing latency input listener was not installed') + } + const event = new KeyboardEvent('keydown', { key: 'a' }) + Object.defineProperty(event, 'target', { value: document.body }) + inputListener({ event, source: 'direct', text: 'a' }) + + expect(mocks.findPaneOwningNode).toHaveBeenLastCalledWith([], document.body) + expect(mocks.findPaneOwningFocus).toHaveBeenLastCalledWith([]) + }) + + it('removes the queue-cap unmatched count when an IME commit is prevented', () => { + vi.spyOn(console, 'log').mockImplementation(() => undefined) + mocks.findPaneOwningNode.mockReturnValueOnce({ pane: mocks.panes[0] }) + mocks.recordKeystroke.mockReturnValueOnce(1) + mocks.discardUndispatchedKeystroke.mockReturnValueOnce('counted-unmatched') + installTypingLatencyDiagnostic() + const bridge = (window as DiagnosticWindow).__orcaTypingDiagnostic + if (!bridge || !mocks.inputListener) { + throw new Error('Typing latency diagnostic did not start') + } + bridge.start() + + const registration = mocks.inputListener({ + event: new CustomEvent('xterm-composition-session-end'), + source: 'ime', + text: '한' + }) + expect(bridge.report().sampling.unmatchedKeystrokes).toBe(1) + registration?.discardIfPrevented() + + expect(bridge.report().sampling.unmatchedKeystrokes).toBe(0) + bridge.stop() + }) +}) diff --git a/src/renderer/src/lib/typing-latency-diagnostic-summary.test.ts b/src/renderer/src/lib/typing-latency/diagnostic-summary.test.ts similarity index 94% rename from src/renderer/src/lib/typing-latency-diagnostic-summary.test.ts rename to src/renderer/src/lib/typing-latency/diagnostic-summary.test.ts index 46facf743632..ae91edf3037c 100644 --- a/src/renderer/src/lib/typing-latency-diagnostic-summary.test.ts +++ b/src/renderer/src/lib/typing-latency/diagnostic-summary.test.ts @@ -2,8 +2,9 @@ import { describe, expect, it } from 'vitest' import { summarizeLatencySamples, summarizeTypingScaleCensus, - summarizeWorktreeNesting -} from './typing-latency-diagnostic-summary' + summarizeWorktreeNesting, + typingSampleDurationMs +} from './diagnostic-summary' describe('summarizeLatencySamples', () => { it('reports null percentiles with no samples', () => { @@ -30,6 +31,14 @@ describe('summarizeLatencySamples', () => { }) }) +describe('typingSampleDurationMs', () => { + it('keeps a stopped sampling window fixed as wall time advances', () => { + expect(typingSampleDurationMs(100, null, 350)).toBe(250) + expect(typingSampleDurationMs(100, 300, 10_000)).toBe(200) + expect(typingSampleDurationMs(null, null, 350)).toBeNull() + }) +}) + describe('summarizeWorktreeNesting', () => { it('returns zero depth for flat sibling worktrees', () => { expect(summarizeWorktreeNesting(['/a/one', '/a/two'])).toEqual({ diff --git a/src/renderer/src/lib/typing-latency-diagnostic-summary.ts b/src/renderer/src/lib/typing-latency/diagnostic-summary.ts similarity index 96% rename from src/renderer/src/lib/typing-latency-diagnostic-summary.ts rename to src/renderer/src/lib/typing-latency/diagnostic-summary.ts index 0808f30e2a58..00934c591c4c 100644 --- a/src/renderer/src/lib/typing-latency-diagnostic-summary.ts +++ b/src/renderer/src/lib/typing-latency/diagnostic-summary.ts @@ -3,7 +3,7 @@ * per-keystroke samples, plus the scale census (agent rows, tabs, panes, * worktree nesting, suspect settings) that explains WHY a renderer is slow. * - * Kept separate from the DOM/store wiring in typing-latency-diagnostic.ts so + * Kept separate from the DOM/store wiring in diagnostic.ts so * the arithmetic is unit-testable without an xterm or a live store. */ @@ -39,6 +39,14 @@ export function summarizeLatencySamples(values: readonly number[]): LatencyPerce } } +export function typingSampleDurationMs( + startedAt: number | null, + stoppedAt: number | null, + now: number +): number | null { + return startedAt === null ? null : Math.max(0, Math.round((stoppedAt ?? now) - startedAt)) +} + export type WorktreeNestingCensus = { maxDepth: number nestedWorktrees: number diff --git a/src/renderer/src/lib/typing-latency/diagnostic.ts b/src/renderer/src/lib/typing-latency/diagnostic.ts new file mode 100644 index 000000000000..d4668ffac3ca --- /dev/null +++ b/src/renderer/src/lib/typing-latency/diagnostic.ts @@ -0,0 +1,307 @@ +/** + * One-paste typing-latency self-diagnostic: + * + * window.__orcaTypingDiagnostic.start() // then type normally for ~20s + * window.__orcaTypingDiagnostic.report() // logs + returns a JSON-safe object + * window.__orcaTypingDiagnostic.stop() + * + * Why: keystroke-echo lag reproduces on one user's machine only, so the + * measurement has to run THERE. The census answers what a user cannot: agent-row + * scale, store listener count, suspect settings, and which agent/screen mode the + * focused pane is in. + * + * Nothing attaches to the keystroke path until start(); stop() detaches all of it. + */ +import { + countMountedAgentRows, + readFocusedPaneCensus, + readProbeStoreState, + readStoreListenerCount +} from './census-probe' +import { + detachPaneEcho, + discardUndispatchedKeystroke, + findPaneOwningFocus, + findPaneOwningNode, + instrumentPaneEcho, + listProbePanes, + recordKeystroke, + type EchoObservation, + type InstrumentedPane +} from './echo-instrumentation' +import { + summarizeLatencySamples, + summarizeTypingScaleCensus, + typingSampleDurationMs, + type LatencyPercentiles, + type TypingScaleCensus +} from './diagnostic-summary' +import { installTypingLatencyInputEvents } from './input-events' +import { + createInputSourceTally, + emptyInputSourceBreakdown, + type InputSourceBreakdown, + type InputSourceTally +} from './input-source' +import { + appendExactLatencySample, + appendTypingLatencySample, + createExactLatencySampleWindow, + type ExactLatencySampleWindow +} from './sample-window' + +type AmbiguousBurstState = { + inputCounts: number[] + firstOutputParseFromFirstDispatchMs: number[] + firstOutputParseFromLastDispatchMs: number[] + parseToPaintMs: number[] + outputBytes: number[] + outputWrites: number[] +} + +type ProbeState = { + startedAt: number + stoppedAt: number | null + startedAtIso: string + exact: ExactLatencySampleWindow + ambiguous: AmbiguousBurstState + exactInputs: number + ambiguousInputs: number + ambiguousBurstCount: number + attributionGapBursts: number + unmatchedKeystrokes: number + keystrokesWithoutTerminalFocus: number + instrumentedPaneCount: number + panes: InstrumentedPane[] + detachInputEvents: () => void + byInputSource: InputSourceTally +} + +let active: ProbeState | null = null +let lastState: ProbeState | null = null +let cachedAppVersion: string | null = null + +export type TypingLatencyReport = { + capturedAt: string + sampling: { + running: boolean + startedAt: string | null + durationMs: number | null + keystrokesWithoutTerminalFocus: number + unmatchedKeystrokes: number + exactInputs: number + ambiguousInputs: number + ambiguousBursts: number + attributionGapBursts: number + instrumentedPanes: number + } + exact: { + inputToDispatchMs: LatencyPercentiles + dispatchToParseMs: LatencyPercentiles + parseToPaintMs: LatencyPercentiles + inputToPaintMs: LatencyPercentiles + outputBytesPerInput: LatencyPercentiles + outputWritesPerInput: LatencyPercentiles + } + ambiguousBursts: { + inputCount: LatencyPercentiles + firstOutputParseFromFirstDispatchMs: LatencyPercentiles + firstOutputParseFromLastDispatchMs: LatencyPercentiles + parseToPaintMs: LatencyPercentiles + outputBatchBytes: LatencyPercentiles + outputBatchWrites: LatencyPercentiles + } + byInputSource: InputSourceBreakdown + census: TypingScaleCensus +} + +function buildReport(state: ProbeState | null, running: boolean): TypingLatencyReport { + return { + capturedAt: new Date().toISOString(), + sampling: { + running, + startedAt: state?.startedAtIso ?? null, + durationMs: typingSampleDurationMs( + state?.startedAt ?? null, + state?.stoppedAt ?? null, + performance.now() + ), + keystrokesWithoutTerminalFocus: state?.keystrokesWithoutTerminalFocus ?? 0, + unmatchedKeystrokes: state?.unmatchedKeystrokes ?? 0, + exactInputs: state?.exactInputs ?? 0, + ambiguousInputs: state?.ambiguousInputs ?? 0, + ambiguousBursts: state?.ambiguousBurstCount ?? 0, + attributionGapBursts: state?.attributionGapBursts ?? 0, + instrumentedPanes: state?.instrumentedPaneCount ?? 0 + }, + exact: { + inputToDispatchMs: summarizeLatencySamples(state?.exact.inputToDispatchMs ?? []), + dispatchToParseMs: summarizeLatencySamples(state?.exact.dispatchToParseMs ?? []), + parseToPaintMs: summarizeLatencySamples(state?.exact.parseToPaintMs ?? []), + inputToPaintMs: summarizeLatencySamples(state?.exact.inputToPaintMs ?? []), + outputBytesPerInput: summarizeLatencySamples(state?.exact.outputBytes ?? []), + outputWritesPerInput: summarizeLatencySamples(state?.exact.outputWrites ?? []) + }, + ambiguousBursts: { + inputCount: summarizeLatencySamples(state?.ambiguous.inputCounts ?? []), + firstOutputParseFromFirstDispatchMs: summarizeLatencySamples( + state?.ambiguous.firstOutputParseFromFirstDispatchMs ?? [] + ), + firstOutputParseFromLastDispatchMs: summarizeLatencySamples( + state?.ambiguous.firstOutputParseFromLastDispatchMs ?? [] + ), + parseToPaintMs: summarizeLatencySamples(state?.ambiguous.parseToPaintMs ?? []), + outputBatchBytes: summarizeLatencySamples(state?.ambiguous.outputBytes ?? []), + outputBatchWrites: summarizeLatencySamples(state?.ambiguous.outputWrites ?? []) + }, + byInputSource: state?.byInputSource.breakdown() ?? emptyInputSourceBreakdown(), + census: summarizeTypingScaleCensus({ + state: readProbeStoreState(), + appVersion: cachedAppVersion, + livePaneCount: listProbePanes().length, + instrumentedPaneCount: state?.instrumentedPaneCount ?? 0, + mountedAgentRowCount: countMountedAgentRows(), + storeListenerCount: readStoreListenerCount(), + focusedPane: readFocusedPaneCensus() + }) + } +} + +function recordObservation(state: ProbeState, observation: EchoObservation): void { + if (observation.attribution === 'single-input') { + state.exactInputs += 1 + appendExactLatencySample(state.exact, observation) + } else { + state.ambiguousInputs += observation.inputCount + state.ambiguousBurstCount += 1 + state.attributionGapBursts += observation.reason === 'attribution-gap' ? 1 : 0 + appendTypingLatencySample(state.ambiguous.inputCounts, observation.inputCount) + appendTypingLatencySample( + state.ambiguous.firstOutputParseFromFirstDispatchMs, + observation.firstOutputParseFromFirstDispatchMs + ) + appendTypingLatencySample( + state.ambiguous.firstOutputParseFromLastDispatchMs, + observation.firstOutputParseFromLastDispatchMs + ) + appendTypingLatencySample(state.ambiguous.parseToPaintMs, observation.parseToPaintMs) + appendTypingLatencySample(state.ambiguous.outputBytes, observation.outputBatchBytes) + appendTypingLatencySample(state.ambiguous.outputWrites, observation.outputBatchWrites) + } + state.byInputSource.addObservation(observation) +} + +function cacheAppVersion(): void { + void window.api?.updater + ?.getVersion?.() + .then((version) => { + cachedAppVersion = version + }) + .catch(() => undefined) +} + +function startProbe(): string { + if (active) { + return 'Typing diagnostic already running. Type for ~20s, then run __orcaTypingDiagnostic.report().' + } + cacheAppVersion() + + const state: ProbeState = { + startedAt: performance.now(), + stoppedAt: null, + startedAtIso: new Date().toISOString(), + exact: createExactLatencySampleWindow(), + ambiguous: { + inputCounts: [], + firstOutputParseFromFirstDispatchMs: [], + firstOutputParseFromLastDispatchMs: [], + parseToPaintMs: [], + outputBytes: [], + outputWrites: [] + }, + exactInputs: 0, + ambiguousInputs: 0, + ambiguousBurstCount: 0, + attributionGapBursts: 0, + unmatchedKeystrokes: 0, + keystrokesWithoutTerminalFocus: 0, + instrumentedPaneCount: 0, + panes: [], + detachInputEvents: () => undefined, + byInputSource: createInputSourceTally() + } + state.panes = listProbePanes().map((pane) => + instrumentPaneEcho(pane, (observation) => recordObservation(state, observation)) + ) + state.instrumentedPaneCount = state.panes.length + + state.detachInputEvents = installTypingLatencyInputEvents(window, (signal) => { + const eventTarget = signal.event.target instanceof Node ? signal.event.target : null + const target = findPaneOwningNode(state.panes, eventTarget) ?? findPaneOwningFocus(state.panes) + if (!target) { + state.keystrokesWithoutTerminalFocus += 1 + return undefined + } + state.byInputSource.recordInput(signal.source, signal.text) + const recordedAt = performance.now() + state.unmatchedKeystrokes += recordKeystroke(target, recordedAt, signal.source, signal.text) + if (signal.source === 'ime') { + return { + discardIfPrevented: () => { + if ( + discardUndispatchedKeystroke(target, recordedAt, signal.source) === 'counted-unmatched' + ) { + state.unmatchedKeystrokes = Math.max(0, state.unmatchedKeystrokes - 1) + } + } + } + } + return undefined + }) + + active = state + lastState = state + return `Typing diagnostic started on ${state.panes.length} pane(s). Click into the agent terminal, type normally for ~20 seconds, then run __orcaTypingDiagnostic.report().` +} + +function stopProbe(): string { + const state = active + if (!state) { + return 'Typing diagnostic was not running.' + } + active = null + state.stoppedAt = performance.now() + state.instrumentedPaneCount = state.panes.length + state.detachInputEvents() + state.detachInputEvents = () => undefined + for (const entry of state.panes) { + state.unmatchedKeystrokes += detachPaneEcho(entry) + } + state.panes = [] + return 'Typing diagnostic stopped. Run __orcaTypingDiagnostic.report() to read the last samples.' +} + +function reportProbe(): TypingLatencyReport { + const report = buildReport(active ?? lastState, active !== null) + console.log('[orca] typing latency diagnostic', report) + return report +} + +export type TypingDiagnosticBridge = { + start: () => string + stop: () => string + report: () => TypingLatencyReport +} + +type TypingDiagnosticWindow = Window & { __orcaTypingDiagnostic?: TypingDiagnosticBridge } + +export function installTypingLatencyDiagnostic(): void { + if (typeof window === 'undefined') { + return + } + const target = window as TypingDiagnosticWindow + if (target.__orcaTypingDiagnostic) { + return + } + target.__orcaTypingDiagnostic = { start: startProbe, stop: stopProbe, report: reportProbe } +} diff --git a/src/renderer/src/lib/typing-latency/echo-instrumentation.test.ts b/src/renderer/src/lib/typing-latency/echo-instrumentation.test.ts new file mode 100644 index 000000000000..16ea26497e7e --- /dev/null +++ b/src/renderer/src/lib/typing-latency/echo-instrumentation.test.ts @@ -0,0 +1,472 @@ +import { afterEach, describe, expect, it, vi } from 'vitest' +import { + detachPaneEcho, + discardUndispatchedKeystroke, + instrumentPaneEcho, + recordKeystroke, + type EchoObservation, + type InstrumentedPane +} from './echo-instrumentation' + +function emptyEntry(): InstrumentedPane { + return { + pane: {}, + undispatched: [], + nextDispatch: null, + deferredNextDispatch: null, + ignoredDispatches: 0, + lastIgnoredDispatch: null, + awaitingEcho: [], + attributionGap: false, + parsingBatch: null, + parsedBatches: [], + pendingCount: 0, + disposables: [], + restoreWrite: null + } +} + +type FakeTerminal = { + write: (data: string | Uint8Array, callback?: () => void) => void + onData: (listener: (data: string) => void) => { dispose: () => void } + onWriteParsed: (listener: () => void) => { dispose: () => void } + onRender: (listener: () => void) => { dispose: () => void } +} + +function fakeTerminal(): { + terminal: FakeTerminal + emitData: (data?: string) => void + emitParsed: () => void + emitRender: () => void + writtenPayloads: (string | Uint8Array)[] + disposeCount: () => number +} { + const dataListeners = new Set<(data: string) => void>() + const parsedListeners = new Set<() => void>() + const renderListeners = new Set<() => void>() + const writtenPayloads: (string | Uint8Array)[] = [] + let disposed = 0 + const listen = (listeners: Set, listener: T): { dispose: () => void } => { + listeners.add(listener) + return { + dispose: () => { + if (listeners.delete(listener)) { + disposed += 1 + } + } + } + } + return { + terminal: { + write: (data) => writtenPayloads.push(data), + onData: (listener) => listen(dataListeners, listener), + onWriteParsed: (listener) => listen(parsedListeners, listener), + onRender: (listener) => listen(renderListeners, listener) + }, + emitData: (data = 'x') => dataListeners.forEach((listener) => listener(data)), + emitParsed: () => parsedListeners.forEach((listener) => listener()), + emitRender: () => renderListeners.forEach((listener) => listener()), + writtenPayloads, + disposeCount: () => disposed + } +} + +function recordAndDispatch( + entry: InstrumentedPane, + fake: ReturnType, + source: 'direct' | 'ime' = 'direct', + recordedAt: number = performance.now(), + text: string = '' +): void { + recordKeystroke(entry, recordedAt, source, text) + fake.emitData() +} + +afterEach(() => { + vi.restoreAllMocks() +}) + +describe('recordKeystroke', () => { + it('queues inputs rather than overwriting a single slot', () => { + const entry = emptyEntry() + expect(recordKeystroke(entry, 0, 'direct')).toBe(0) + expect(recordKeystroke(entry, 5, 'ime')).toBe(0) + expect(entry.undispatched.map((pending) => pending.t0)).toEqual([0, 5]) + expect(entry.pendingCount).toBe(2) + }) + + it('counts timed-out undispatched inputs without creating an output attribution gap', () => { + const entry = emptyEntry() + recordKeystroke(entry, 0, 'direct') + recordKeystroke(entry, 1, 'direct') + expect(recordKeystroke(entry, 5000, 'direct')).toBe(2) + expect(entry.pendingCount).toBe(1) + expect(entry.attributionGap).toBe(false) + }) + + it('bounds pending input state during sustained typing', () => { + const entry = emptyEntry() + let dropped = 0 + for (let index = 0; index < 200; index += 1) { + dropped += recordKeystroke(entry, index, 'direct') + } + expect(entry.pendingCount).toBe(64) + expect(entry.undispatched).toHaveLength(64) + expect(dropped).toBe(136) + }) + + it('drops a prevented commit only when it never dispatched', () => { + const fake = fakeTerminal() + const entry = instrumentPaneEcho({ terminal: fake.terminal }, () => undefined) + recordKeystroke(entry, 10, 'ime', '한') + expect(discardUndispatchedKeystroke(entry, 10, 'ime')).toBe('pending') + + recordKeystroke(entry, 20, 'ime', '글') + fake.emitData('글') + expect(discardUndispatchedKeystroke(entry, 20, 'ime')).toBeNull() + expect(entry.awaitingEcho).toHaveLength(1) + }) + + it('dispatches a nested IME finalizer before its outer direct key', () => { + const fake = fakeTerminal() + const entry = instrumentPaneEcho({ terminal: fake.terminal }, () => undefined) + recordKeystroke(entry, 10, 'direct', 'Enter') + recordKeystroke(entry, 11, 'ime', '한') + + fake.emitData('한') + fake.emitData('\r') + + expect(entry.awaitingEcho.map((pending) => pending.source)).toEqual(['ime', 'direct']) + }) + + it('uses a cap-rejection sentinel instead of consuming a retained input', () => { + const fake = fakeTerminal() + const entry = instrumentPaneEcho({ terminal: fake.terminal }, () => undefined) + for (let index = 0; index < 64; index += 1) { + recordKeystroke(entry, index, 'direct') + } + + expect(recordKeystroke(entry, 64, 'direct')).toBe(1) + fake.emitData('rejected') + + expect(entry.undispatched).toHaveLength(64) + expect(entry.awaitingEcho).toEqual([]) + expect(entry.pendingCount).toBe(64) + expect(entry.attributionGap).toBe(true) + }) + + it('settles a prevented cap-rejected commit without touching retained inputs', () => { + const entry = emptyEntry() + for (let index = 0; index < 64; index += 1) { + recordKeystroke(entry, index, 'direct') + } + + expect(recordKeystroke(entry, 64, 'ime', '한')).toBe(1) + expect(discardUndispatchedKeystroke(entry, 64, 'ime')).toBe('counted-unmatched') + expect(entry.undispatched).toHaveLength(64) + expect(entry.ignoredDispatches).toBe(0) + expect(entry.attributionGap).toBe(false) + }) +}) + +describe('instrumentPaneEcho', () => { + it('measures input, dispatch, parse, and paint stages separately', () => { + const fake = fakeTerminal() + const observations: EchoObservation[] = [] + const entry = instrumentPaneEcho({ terminal: fake.terminal }, (value) => + observations.push(value) + ) + const now = vi.spyOn(performance, 'now') + + recordKeystroke(entry, 10, 'direct', 'a') + now.mockReturnValueOnce(25) + fake.emitData('a') + fake.terminal.write('echo') + now.mockReturnValueOnce(40) + fake.emitParsed() + now.mockReturnValueOnce(50) + fake.emitRender() + + expect(observations).toEqual([ + { + attribution: 'single-input', + source: 'direct', + text: 'a', + inputToDispatchMs: 15, + dispatchToParseMs: 15, + parseToPaintMs: 10, + inputToPaintMs: 40, + outputBytes: 4, + outputWrites: 1 + } + ]) + }) + + it('counts UTF-8 bytes consistently for string and binary writes', () => { + const fake = fakeTerminal() + const observations: EchoObservation[] = [] + const entry = instrumentPaneEcho({ terminal: fake.terminal }, (value) => + observations.push(value) + ) + + recordAndDispatch(entry, fake, 'ime', performance.now(), '한𠀀') + fake.terminal.write('한𠀀') + fake.terminal.write(new Uint8Array(6)) + fake.emitParsed() + fake.emitRender() + + expect(observations).toHaveLength(1) + expect(observations[0]).toMatchObject({ + attribution: 'single-input', + outputBytes: 13, + outputWrites: 2 + }) + expect(fake.writtenPayloads).toHaveLength(2) + }) + + it('does not credit output that arrived before the input dispatched', () => { + const fake = fakeTerminal() + const observations: EchoObservation[] = [] + const entry = instrumentPaneEcho({ terminal: fake.terminal }, (value) => + observations.push(value) + ) + + recordKeystroke(entry, performance.now(), 'direct') + fake.terminal.write('unrelated') + fake.emitParsed() + fake.emitRender() + expect(observations).toEqual([]) + + fake.emitData() + fake.terminal.write('echo') + fake.emitParsed() + fake.emitRender() + expect(observations).toHaveLength(1) + }) + + it('emits one ambiguous burst when overlapping inputs receive separate outputs', () => { + const fake = fakeTerminal() + const observations: EchoObservation[] = [] + const entry = instrumentPaneEcho({ terminal: fake.terminal }, (value) => + observations.push(value) + ) + + recordAndDispatch(entry, fake, 'direct') + recordAndDispatch(entry, fake, 'direct') + fake.terminal.write('A') + fake.emitParsed() + fake.emitRender() + fake.terminal.write('B') + fake.emitParsed() + fake.emitRender() + + expect(observations).toHaveLength(1) + expect(observations[0]).toMatchObject({ + attribution: 'ambiguous-burst', + reason: 'overlapping-inputs', + inputCount: 2, + sourceCounts: { direct: 2, ime: 0 }, + outputBatchBytes: 1, + outputBatchWrites: 1 + }) + }) + + it('emits one aggregate observation for genuinely coalesced mixed-source output', () => { + const fake = fakeTerminal() + const observations: EchoObservation[] = [] + const entry = instrumentPaneEcho({ terminal: fake.terminal }, (value) => + observations.push(value) + ) + + recordAndDispatch(entry, fake, 'direct') + recordAndDispatch(entry, fake, 'ime') + fake.terminal.write('x'.repeat(90)) + fake.emitParsed() + fake.emitRender() + + expect(observations).toHaveLength(1) + expect(observations[0]).toMatchObject({ + attribution: 'ambiguous-burst', + inputCount: 2, + sourceCounts: { direct: 1, ime: 1 }, + outputBatchBytes: 90, + outputBatchWrites: 1 + }) + }) + + it('keeps a batch ambiguous when another input arrives before parsing finishes', () => { + const fake = fakeTerminal() + const observations: EchoObservation[] = [] + const entry = instrumentPaneEcho({ terminal: fake.terminal }, (value) => + observations.push(value) + ) + + recordAndDispatch(entry, fake) + fake.terminal.write('x'.repeat(90)) + recordAndDispatch(entry, fake) + fake.terminal.write('x'.repeat(30)) + fake.emitParsed() + fake.emitRender() + + expect(observations).toHaveLength(1) + expect(observations[0]).toMatchObject({ + attribution: 'ambiguous-burst', + inputCount: 2, + outputBatchBytes: 120, + outputBatchWrites: 2 + }) + }) + + it('aggregates thousands of writes in constant-size batch accounting', () => { + const fake = fakeTerminal() + const observations: EchoObservation[] = [] + const entry = instrumentPaneEcho({ terminal: fake.terminal }, (value) => + observations.push(value) + ) + + recordAndDispatch(entry, fake) + for (let index = 0; index < 1_000; index += 1) { + fake.terminal.write('x') + } + + expect(entry.parsingBatch).toMatchObject({ outputBytes: 1_000, outputWrites: 1_000 }) + expect(entry.parsingBatch?.candidates).toHaveLength(1) + fake.emitParsed() + fake.emitRender() + expect(observations[0]).toMatchObject({ outputBytes: 1_000, outputWrites: 1_000 }) + }) + + it('keeps parsed batches separate when two parses precede one render', () => { + const fake = fakeTerminal() + const observations: EchoObservation[] = [] + const entry = instrumentPaneEcho({ terminal: fake.terminal }, (value) => + observations.push(value) + ) + + recordAndDispatch(entry, fake) + fake.terminal.write('a') + fake.emitParsed() + recordAndDispatch(entry, fake) + fake.terminal.write('b') + fake.emitParsed() + fake.emitRender() + + expect(observations.map((value) => value.attribution)).toEqual(['single-input', 'single-input']) + }) + + it('marks the first late output after a timeout as ambiguous, then restores confidence', () => { + const fake = fakeTerminal() + const observations: EchoObservation[] = [] + const entry = instrumentPaneEcho({ terminal: fake.terminal }, (value) => + observations.push(value) + ) + const now = vi.spyOn(performance, 'now') + + recordKeystroke(entry, 0, 'direct', 'A') + now.mockReturnValueOnce(1) + fake.emitData('A') + expect(recordKeystroke(entry, 5_000, 'direct', 'B')).toBe(1) + now.mockReturnValueOnce(5_001) + fake.emitData('B') + fake.terminal.write('late A') + now.mockReturnValueOnce(5_010) + fake.emitParsed() + now.mockReturnValueOnce(5_015) + fake.emitRender() + + recordKeystroke(entry, 5_020, 'ime', '한') + now.mockReturnValueOnce(5_021) + fake.emitData('한') + fake.terminal.write('한') + now.mockReturnValueOnce(5_030) + fake.emitParsed() + now.mockReturnValueOnce(5_035) + fake.emitRender() + + expect(observations[0]).toMatchObject({ + attribution: 'ambiguous-burst', + reason: 'attribution-gap', + inputCount: 1 + }) + expect(observations[1]).toMatchObject({ + attribution: 'single-input', + source: 'ime', + text: '한' + }) + }) + + it('clears a gap-only output boundary without retaining an empty parsed batch', () => { + const fake = fakeTerminal() + const observations: EchoObservation[] = [] + const entry = instrumentPaneEcho({ terminal: fake.terminal }, (value) => + observations.push(value) + ) + const now = vi.spyOn(performance, 'now') + + recordKeystroke(entry, 0, 'direct', 'A') + now.mockReturnValueOnce(1) + fake.emitData('A') + expect(recordKeystroke(entry, 5_000, 'direct', 'B')).toBe(1) + fake.terminal.write('late A') + now.mockReturnValueOnce(5_001) + fake.emitParsed() + + expect(entry.parsedBatches).toEqual([]) + now.mockReturnValueOnce(5_002) + fake.emitData('B') + fake.terminal.write('B') + now.mockReturnValueOnce(5_010) + fake.emitParsed() + now.mockReturnValueOnce(5_015) + fake.emitRender() + + expect(observations).toHaveLength(1) + expect(observations[0]).toMatchObject({ attribution: 'single-input', text: 'B' }) + }) + + it('holds an unparsed input across a render instead of discarding it', () => { + const fake = fakeTerminal() + const observations: EchoObservation[] = [] + const entry = instrumentPaneEcho({ terminal: fake.terminal }, (value) => + observations.push(value) + ) + + recordAndDispatch(entry, fake) + fake.terminal.write('echo') + fake.emitRender() + expect(observations).toHaveLength(0) + + fake.emitParsed() + fake.emitRender() + expect(observations).toHaveLength(1) + }) + + it('returns trailing unmatched inputs and releases pane and listener closures', () => { + const fake = fakeTerminal() + const originalWrite = fake.terminal.write + const observations: EchoObservation[] = [] + const entry = instrumentPaneEcho({ terminal: fake.terminal }, (value) => + observations.push(value) + ) + recordAndDispatch(entry, fake) + fake.terminal.write('parsed but not painted') + fake.emitParsed() + recordKeystroke(entry, performance.now(), 'direct') + + expect(detachPaneEcho(entry)).toBe(2) + expect(fake.terminal.write).toBe(originalWrite) + expect(fake.disposeCount()).toBe(3) + expect(entry).toMatchObject({ pane: null, pendingCount: 0, restoreWrite: null }) + + fake.emitRender() + fake.emitData() + expect(observations).toEqual([]) + }) + + it('degrades to a no-op when the pane has no terminal', () => { + const entry = instrumentPaneEcho({}, () => undefined) + expect(entry.disposables).toEqual([]) + expect(detachPaneEcho(entry)).toBe(0) + expect(entry.pane).toBeNull() + }) +}) diff --git a/src/renderer/src/lib/typing-latency/echo-instrumentation.ts b/src/renderer/src/lib/typing-latency/echo-instrumentation.ts new file mode 100644 index 000000000000..b7c720dd97a2 --- /dev/null +++ b/src/renderer/src/lib/typing-latency/echo-instrumentation.ts @@ -0,0 +1,310 @@ +/** + * Per-pane output instrumentation for the devtools typing-latency probe. + * + * An input signal stamps t0, xterm's onData marks PTY dispatch, + * onWriteParsed marks the first subsequent output parse, and onRender marks + * paint. Overlapping inputs are one ambiguous burst because terminal output is + * opaque; the probe never apportions one output batch across those inputs. + */ +import { getUtf8ByteLength } from '../../../../shared/utf8-byte-limits' +import { + createEchoObservation, + type EchoBatch, + type EchoCandidate, + type EchoObservation as EchoObservationValue +} from './echo-observation' +import type { TypingInputSource } from './input-events' +import type { ProbePane } from './pane-target' + +export type { + AmbiguousEchoBurst, + EchoObservation, + EchoSourceCounts, + ExactEchoSample +} from './echo-observation' +export { + findPaneOwningFocus, + findPaneOwningNode, + listProbePanes, + paneRootElement +} from './pane-target' +export type { ProbePane } from './pane-target' + +type Disposable = { dispose: () => void } + +export type KeystrokeSource = TypingInputSource + +export type PreventedKeystrokeDiscard = 'pending' | 'counted-unmatched' | null + +type PendingKeystroke = EchoCandidate + +type IgnoredDispatch = { + t0: number + source: KeystrokeSource +} + +export type InstrumentedPane = { + pane: ProbePane | null + undispatched: PendingKeystroke[] + nextDispatch: PendingKeystroke | null + deferredNextDispatch: PendingKeystroke | null + ignoredDispatches: number + lastIgnoredDispatch: IgnoredDispatch | null + awaitingEcho: PendingKeystroke[] + attributionGap: boolean + parsingBatch: EchoBatch | null + parsedBatches: EchoBatch[] + pendingCount: number + disposables: Disposable[] + restoreWrite: (() => void) | null +} + +/** An input with no output write in this window is unmatched, never an exact sample. */ +const ECHO_TIMEOUT_MS = 2000 +const MAX_PENDING = 64 + +function clearDispatchSelection(entry: InstrumentedPane, pending: PendingKeystroke): void { + if (entry.nextDispatch === pending) { + entry.nextDispatch = null + } + if (entry.deferredNextDispatch === pending) { + entry.deferredNextDispatch = null + } +} + +function restoreDeferredDispatch(entry: InstrumentedPane): void { + const deferred = entry.deferredNextDispatch + entry.deferredNextDispatch = null + if (deferred && entry.undispatched.includes(deferred)) { + entry.nextDispatch = deferred + } +} + +function removeOldestTimedOut(entry: InstrumentedPane, now: number): boolean { + const undispatched = entry.undispatched[0] + const awaitingEcho = entry.awaitingEcho[0] + const oldest = + !undispatched || (awaitingEcho && awaitingEcho.t0 < undispatched.t0) + ? awaitingEcho + : undispatched + if (!oldest || now - oldest.t0 <= ECHO_TIMEOUT_MS) { + return false + } + if (oldest === awaitingEcho) { + entry.awaitingEcho.shift() + entry.attributionGap = true + } else { + entry.undispatched.shift() + clearDispatchSelection(entry, oldest) + } + entry.pendingCount -= 1 + return true +} + +/** Returns how many inputs were dropped without a painted output observation. */ +export function recordKeystroke( + entry: InstrumentedPane, + now: number, + source: KeystrokeSource, + text: string = '' +): number { + let dropped = 0 + while (removeOldestTimedOut(entry, now)) { + dropped += 1 + } + if (entry.pendingCount >= MAX_PENDING) { + if (entry.ignoredDispatches === 0) { + entry.deferredNextDispatch = entry.nextDispatch + } + entry.nextDispatch = null + entry.ignoredDispatches += 1 + entry.lastIgnoredDispatch = { t0: now, source } + return dropped + 1 + } + const pending = { t0: now, source, text, dispatchedAt: null } + entry.undispatched.push(pending) + entry.nextDispatch = pending + entry.pendingCount += 1 + return dropped +} + +/** Removes a prevented routed commit only if it never reached terminal.onData. */ +export function discardUndispatchedKeystroke( + entry: InstrumentedPane, + recordedAt: number, + source: KeystrokeSource +): PreventedKeystrokeDiscard { + const ignored = entry.lastIgnoredDispatch + if (ignored?.t0 === recordedAt && ignored.source === source) { + entry.ignoredDispatches = Math.max(0, entry.ignoredDispatches - 1) + entry.lastIgnoredDispatch = null + if (entry.ignoredDispatches === 0) { + restoreDeferredDispatch(entry) + } + return 'counted-unmatched' + } + for (let index = entry.undispatched.length - 1; index >= 0; index -= 1) { + const pending = entry.undispatched[index] + if (!pending || pending.t0 !== recordedAt || pending.source !== source) { + continue + } + entry.undispatched.splice(index, 1) + clearDispatchSelection(entry, pending) + entry.nextDispatch ??= entry.undispatched.at(-1) ?? null + entry.pendingCount -= 1 + return 'pending' + } + return null +} + +function updateEchoBatch(entry: InstrumentedPane): EchoBatch | null { + if (!entry.parsingBatch && entry.awaitingEcho.length === 0 && !entry.attributionGap) { + return null + } + const batch = entry.parsingBatch ?? { + candidates: [], + hasAttributionGap: false, + outputBytes: 0, + outputWrites: 0, + parsedAt: null + } + if (entry.awaitingEcho.length > 0) { + batch.candidates.push(...entry.awaitingEcho) + entry.awaitingEcho = [] + } + if (entry.attributionGap) { + batch.hasAttributionGap = true + entry.attributionGap = false + } + entry.parsingBatch = batch + return batch +} + +export function instrumentPaneEcho( + pane: ProbePane, + onObservation: (observation: EchoObservationValue) => void +): InstrumentedPane { + const entry: InstrumentedPane = { + pane, + undispatched: [], + nextDispatch: null, + deferredNextDispatch: null, + ignoredDispatches: 0, + lastIgnoredDispatch: null, + awaitingEcho: [], + attributionGap: false, + parsingBatch: null, + parsedBatches: [], + pendingCount: 0, + disposables: [], + restoreWrite: null + } + const terminal = pane.terminal + if (!terminal) { + return entry + } + + const originalWrite = terminal.write + if (typeof originalWrite === 'function') { + const wrapped = (data: string | Uint8Array, callback?: () => void): void => { + const batch = updateEchoBatch(entry) + if (batch) { + batch.outputBytes += typeof data === 'string' ? getUtf8ByteLength(data) : data.byteLength + batch.outputWrites += 1 + } + originalWrite.call(terminal, data, callback) + } + terminal.write = wrapped + entry.restoreWrite = () => { + if (terminal.write === wrapped) { + terminal.write = originalWrite + } + } + } + + if (typeof terminal.onData === 'function') { + entry.disposables.push( + terminal.onData(() => { + let pending = entry.nextDispatch + if (pending && entry.undispatched.at(-1) === pending) { + entry.undispatched.pop() + entry.nextDispatch = null + } else if (!pending && entry.ignoredDispatches > 0) { + entry.ignoredDispatches -= 1 + entry.lastIgnoredDispatch = null + entry.attributionGap = true + if (entry.ignoredDispatches === 0) { + restoreDeferredDispatch(entry) + } + return + } else { + pending = entry.undispatched.shift() ?? null + entry.nextDispatch = null + } + if (!pending) { + return + } + pending.dispatchedAt = performance.now() + entry.awaitingEcho.push(pending) + }) + ) + } + if (typeof terminal.onWriteParsed === 'function') { + entry.disposables.push( + terminal.onWriteParsed(() => { + const batch = entry.parsingBatch + if (batch) { + batch.parsedAt = performance.now() + if (batch.candidates.length > 0) { + entry.parsedBatches.push(batch) + } + entry.parsingBatch = null + } + }) + ) + } + if (typeof terminal.onRender === 'function') { + entry.disposables.push( + terminal.onRender(() => { + const paintedAt = performance.now() + const batches = entry.parsedBatches + entry.parsedBatches = [] + for (const batch of batches) { + entry.pendingCount -= batch.candidates.length + const observation = createEchoObservation(batch, paintedAt) + if (observation) { + onObservation(observation) + } + } + }) + ) + } + return entry +} + +/** Returns trailing inputs that never reached a painted output observation. */ +export function detachPaneEcho(entry: InstrumentedPane): number { + const unmatched = entry.pendingCount + for (const disposable of entry.disposables) { + try { + disposable.dispose() + } catch { + // Why: a pane disposed mid-run already dropped its listeners. + } + } + entry.disposables = [] + entry.restoreWrite?.() + entry.restoreWrite = null + entry.pane = null + entry.undispatched = [] + entry.nextDispatch = null + entry.deferredNextDispatch = null + entry.ignoredDispatches = 0 + entry.lastIgnoredDispatch = null + entry.awaitingEcho = [] + entry.attributionGap = false + entry.parsingBatch = null + entry.parsedBatches = [] + entry.pendingCount = 0 + return unmatched +} diff --git a/src/renderer/src/lib/typing-latency/echo-observation.ts b/src/renderer/src/lib/typing-latency/echo-observation.ts new file mode 100644 index 000000000000..e9b620ad926d --- /dev/null +++ b/src/renderer/src/lib/typing-latency/echo-observation.ts @@ -0,0 +1,92 @@ +import type { TypingInputSource } from './input-events' + +export type EchoCandidate = { + t0: number + source: TypingInputSource + text: string + dispatchedAt: number | null +} + +export type EchoBatch = { + candidates: EchoCandidate[] + hasAttributionGap: boolean + outputBytes: number + outputWrites: number + parsedAt: number | null +} + +export type EchoSourceCounts = Record + +export type ExactEchoSample = { + attribution: 'single-input' + source: TypingInputSource + text: string + inputToDispatchMs: number + dispatchToParseMs: number + parseToPaintMs: number + inputToPaintMs: number + outputBytes: number + outputWrites: number +} + +export type AmbiguousEchoBurst = { + attribution: 'ambiguous-burst' + reason: 'overlapping-inputs' | 'attribution-gap' + inputCount: number + sourceCounts: EchoSourceCounts + /** Bounds from the earliest and latest candidate dispatch to the first parsed output batch. */ + firstOutputParseFromFirstDispatchMs: number + firstOutputParseFromLastDispatchMs: number + parseToPaintMs: number + outputBatchBytes: number + outputBatchWrites: number +} + +export type EchoObservation = ExactEchoSample | AmbiguousEchoBurst + +function countSources(candidates: readonly EchoCandidate[]): EchoSourceCounts { + const counts: EchoSourceCounts = { direct: 0, ime: 0 } + for (const candidate of candidates) { + counts[candidate.source] += 1 + } + return counts +} + +export function createEchoObservation(batch: EchoBatch, paintedAt: number): EchoObservation | null { + const parsedAt = batch.parsedAt + if (parsedAt === null || batch.candidates.length === 0) { + return null + } + if (batch.candidates.length === 1 && !batch.hasAttributionGap) { + const candidate = batch.candidates[0] + if (!candidate) { + return null + } + const dispatchedAt = candidate.dispatchedAt ?? candidate.t0 + return { + attribution: 'single-input', + source: candidate.source, + text: candidate.text, + inputToDispatchMs: Math.max(0, dispatchedAt - candidate.t0), + dispatchToParseMs: Math.max(0, parsedAt - dispatchedAt), + parseToPaintMs: Math.max(0, paintedAt - parsedAt), + inputToPaintMs: Math.max(0, paintedAt - candidate.t0), + outputBytes: batch.outputBytes, + outputWrites: batch.outputWrites + } + } + const dispatchTimes = batch.candidates.map((candidate) => candidate.dispatchedAt ?? candidate.t0) + const firstDispatch = Math.min(...dispatchTimes) + const lastDispatch = Math.max(...dispatchTimes) + return { + attribution: 'ambiguous-burst', + reason: batch.hasAttributionGap ? 'attribution-gap' : 'overlapping-inputs', + inputCount: batch.candidates.length, + sourceCounts: countSources(batch.candidates), + firstOutputParseFromFirstDispatchMs: Math.max(0, parsedAt - firstDispatch), + firstOutputParseFromLastDispatchMs: Math.max(0, parsedAt - lastDispatch), + parseToPaintMs: Math.max(0, paintedAt - parsedAt), + outputBatchBytes: batch.outputBytes, + outputBatchWrites: batch.outputWrites + } +} diff --git a/src/renderer/src/lib/typing-latency/input-events.test.ts b/src/renderer/src/lib/typing-latency/input-events.test.ts new file mode 100644 index 000000000000..3c5bf3fb56ac --- /dev/null +++ b/src/renderer/src/lib/typing-latency/input-events.test.ts @@ -0,0 +1,97 @@ +// @vitest-environment happy-dom +import { XTERM_COMPOSITION_SESSION_END_EVENT } from '@/components/terminal-pane/terminal-ime-composition-route' +import { afterEach, describe, expect, it } from 'vitest' +import { installTypingLatencyInputEvents, type TypingInputSignal } from './input-events' + +function keydown(init: KeyboardEventInit): void { + window.dispatchEvent(new KeyboardEvent('keydown', init)) +} + +function sessionEnd(data: string, dataPendingReconciliation = false): void { + window.dispatchEvent( + new CustomEvent(XTERM_COMPOSITION_SESSION_END_EVENT, { + detail: { id: 1, data, dataPendingReconciliation } + }) + ) +} + +describe('installTypingLatencyInputEvents', () => { + let detach: (() => void) | null = null + + afterEach(() => { + detach?.() + detach = null + document.body.replaceChildren() + }) + + it('classifies direct keys and ignores IME-owned preedit keydowns', () => { + const signals: TypingInputSignal[] = [] + detach = installTypingLatencyInputEvents(window, (signal) => { + signals.push(signal) + }) + + keydown({ key: 'Process', code: 'KeyG', isComposing: true }) + keydown({ key: 'a', code: 'KeyA', isComposing: true }) + keydown({ key: '@', code: 'Digit2', keyCode: 229 }) + keydown({ key: 'Shift', code: 'ShiftLeft' }) + keydown({ key: 'a', code: 'KeyA' }) + keydown({ key: 'Enter', code: 'Enter' }) + + expect(signals.map(({ source, text }) => ({ source, text }))).toEqual([ + { source: 'direct', text: 'a' }, + { source: 'direct', text: 'Enter' } + ]) + }) + + it('uses reconciled xterm session data instead of raw compositionend data', () => { + const signals: TypingInputSignal[] = [] + detach = installTypingLatencyInputEvents(window, (signal) => { + signals.push(signal) + }) + + window.dispatchEvent(new CompositionEvent('compositionend', { data: '', bubbles: true })) + sessionEnd('') + sessionEnd('stale', true) + sessionEnd('한') + + expect(signals.map(({ source, text }) => ({ source, text }))).toEqual([ + { source: 'ime', text: '한' } + ]) + }) + + it('detaches every listener', () => { + const signals: TypingInputSignal[] = [] + detach = installTypingLatencyInputEvents(window, (signal) => { + signals.push(signal) + }) + detach() + detach = null + + keydown({ key: 'a' }) + sessionEnd('한') + + expect(signals).toEqual([]) + }) + + it('settles a prevented routed commit before the outer input resumes', () => { + const terminalElement = document.createElement('div') + document.body.appendChild(terminalElement) + let discarded = 0 + detach = installTypingLatencyInputEvents(window, (signal) => + signal.source === 'ime' ? { discardIfPrevented: () => (discarded += 1) } : undefined + ) + terminalElement.addEventListener(XTERM_COMPOSITION_SESSION_END_EVENT, (event) => + event.preventDefault() + ) + + terminalElement.dispatchEvent( + new CustomEvent(XTERM_COMPOSITION_SESSION_END_EVENT, { + bubbles: true, + cancelable: true, + detail: { id: 1, data: '한' } + }) + ) + + expect(discarded).toBe(1) + }) +}) diff --git a/src/renderer/src/lib/typing-latency/input-events.ts b/src/renderer/src/lib/typing-latency/input-events.ts new file mode 100644 index 000000000000..f8644efd47e9 --- /dev/null +++ b/src/renderer/src/lib/typing-latency/input-events.ts @@ -0,0 +1,69 @@ +import { + readTerminalImeCompositionSessionDetail, + XTERM_COMPOSITION_SESSION_END_EVENT +} from '@/components/terminal-pane/terminal-ime-composition-route' +import { isImeOwnedKeyboardEvent } from '@/lib/ime-composition-keyboard-event' + +export type TypingInputSource = 'direct' | 'ime' + +export type TypingInputSignal = { + source: TypingInputSource + text: string + event: Event +} + +type InputEventTarget = Pick + +export type TypingInputRegistration = { + discardIfPrevented: () => void +} + +function isDirectEchoInput(event: KeyboardEvent): boolean { + if (isImeOwnedKeyboardEvent(event) || event.key === 'Process') { + return false + } + return event.key.length === 1 || event.key === 'Enter' || event.key === 'Backspace' +} + +/** Watches inputs that actually dispatch terminal data, not the IME's preedit keystrokes. */ +export function installTypingLatencyInputEvents( + target: InputEventTarget, + onInput: (signal: TypingInputSignal) => TypingInputRegistration | void +): () => void { + const pendingPreventedCommits = new WeakMap() + const onKeydown = (event: Event): void => { + if (event instanceof KeyboardEvent && isDirectEchoInput(event)) { + onInput({ source: 'direct', text: event.key, event }) + } + } + const onCompositionSessionEnd = (event: Event): void => { + const detail = readTerminalImeCompositionSessionDetail(event) + if (!detail?.data || detail.dataPendingReconciliation) { + return + } + const registration = onInput({ source: 'ime', text: detail.data, event }) + if (registration) { + pendingPreventedCommits.set(event, registration) + } + } + const settleCompositionSessionEnd = (event: Event): void => { + const registration = pendingPreventedCommits.get(event) + pendingPreventedCommits.delete(event) + if (event.defaultPrevented) { + registration?.discardIfPrevented() + } + } + + target.addEventListener('keydown', onKeydown, { capture: true }) + target.addEventListener(XTERM_COMPOSITION_SESSION_END_EVENT, onCompositionSessionEnd, { + capture: true + }) + target.addEventListener(XTERM_COMPOSITION_SESSION_END_EVENT, settleCompositionSessionEnd) + return () => { + target.removeEventListener('keydown', onKeydown, { capture: true }) + target.removeEventListener(XTERM_COMPOSITION_SESSION_END_EVENT, onCompositionSessionEnd, { + capture: true + }) + target.removeEventListener(XTERM_COMPOSITION_SESSION_END_EVENT, settleCompositionSessionEnd) + } +} diff --git a/src/renderer/src/lib/typing-latency/input-source.test.ts b/src/renderer/src/lib/typing-latency/input-source.test.ts new file mode 100644 index 000000000000..a6ac694da8f6 --- /dev/null +++ b/src/renderer/src/lib/typing-latency/input-source.test.ts @@ -0,0 +1,76 @@ +import { describe, expect, it } from 'vitest' +import { createInputSourceTally } from './input-source' + +describe('createInputSourceTally', () => { + it('keeps exact source percentiles free of ambiguous bursts', () => { + const tally = createInputSourceTally() + tally.recordInput('direct', 'a') + tally.recordInput('direct', 'b') + tally.recordInput('ime', '한𠀀') + tally.addObservation({ + attribution: 'single-input', + source: 'direct', + text: 'a', + inputToDispatchMs: 1, + dispatchToParseMs: 3, + parseToPaintMs: 4, + inputToPaintMs: 8, + outputBytes: 20, + outputWrites: 1 + }) + tally.addObservation({ + attribution: 'ambiguous-burst', + reason: 'overlapping-inputs', + inputCount: 2, + sourceCounts: { direct: 1, ime: 1 }, + firstOutputParseFromFirstDispatchMs: 10, + firstOutputParseFromLastDispatchMs: 6, + parseToPaintMs: 2, + outputBatchBytes: 40, + outputBatchWrites: 1 + }) + + const breakdown = tally.breakdown() + expect(breakdown.direct).toMatchObject({ + observedInputs: 2, + exactInputs: 1, + ambiguousInputs: 1 + }) + expect(breakdown.direct.inputToPaintMs).toEqual({ count: 1, p50: 8, p95: 8, max: 8 }) + expect(breakdown.ime).toMatchObject({ + observedInputs: 1, + exactInputs: 0, + ambiguousInputs: 1 + }) + expect(breakdown.ime.inputToPaintMs).toEqual({ + count: 0, + p50: null, + p95: null, + max: null + }) + expect(breakdown.imeCommitChars).toEqual({ count: 1, p50: 2, p95: 2, max: 2 }) + }) + + it('records an isolated IME commit as one exact source sample', () => { + const tally = createInputSourceTally() + tally.recordInput('ime', '한') + tally.addObservation({ + attribution: 'single-input', + source: 'ime', + text: '한', + inputToDispatchMs: 2, + dispatchToParseMs: 7, + parseToPaintMs: 3, + inputToPaintMs: 12, + outputBytes: 3, + outputWrites: 1 + }) + + expect(tally.breakdown().ime).toMatchObject({ + observedInputs: 1, + exactInputs: 1, + ambiguousInputs: 0, + outputBytesPerInput: { count: 1, p50: 3, p95: 3, max: 3 } + }) + }) +}) diff --git a/src/renderer/src/lib/typing-latency/input-source.ts b/src/renderer/src/lib/typing-latency/input-source.ts new file mode 100644 index 000000000000..2f6720c7d25c --- /dev/null +++ b/src/renderer/src/lib/typing-latency/input-source.ts @@ -0,0 +1,94 @@ +import { summarizeLatencySamples, type LatencyPercentiles } from './diagnostic-summary' +import type { EchoObservation, KeystrokeSource } from './echo-instrumentation' +import { + appendExactLatencySample, + appendTypingLatencySample, + createExactLatencySampleWindow, + type ExactLatencySampleWindow +} from './sample-window' + +type SourceTally = { + observedInputs: number + exactInputs: number + ambiguousInputs: number + exact: ExactLatencySampleWindow +} + +export type InputSourceLatency = { + observedInputs: number + exactInputs: number + ambiguousInputs: number + inputToDispatchMs: LatencyPercentiles + dispatchToParseMs: LatencyPercentiles + parseToPaintMs: LatencyPercentiles + inputToPaintMs: LatencyPercentiles + outputBytesPerInput: LatencyPercentiles + outputWritesPerInput: LatencyPercentiles +} + +export type InputSourceBreakdown = Record & { + imeCommitChars: LatencyPercentiles +} + +export type InputSourceTally = { + recordInput: (source: KeystrokeSource, text: string) => void + addObservation: (observation: EchoObservation) => void + breakdown: () => InputSourceBreakdown +} + +function emptySourceTally(): SourceTally { + return { + observedInputs: 0, + exactInputs: 0, + ambiguousInputs: 0, + exact: createExactLatencySampleWindow() + } +} + +function summarizeSource(tally: SourceTally): InputSourceLatency { + return { + observedInputs: tally.observedInputs, + exactInputs: tally.exactInputs, + ambiguousInputs: tally.ambiguousInputs, + inputToDispatchMs: summarizeLatencySamples(tally.exact.inputToDispatchMs), + dispatchToParseMs: summarizeLatencySamples(tally.exact.dispatchToParseMs), + parseToPaintMs: summarizeLatencySamples(tally.exact.parseToPaintMs), + inputToPaintMs: summarizeLatencySamples(tally.exact.inputToPaintMs), + outputBytesPerInput: summarizeLatencySamples(tally.exact.outputBytes), + outputWritesPerInput: summarizeLatencySamples(tally.exact.outputWrites) + } +} + +export function createInputSourceTally(): InputSourceTally { + const bySource: Record = { + direct: emptySourceTally(), + ime: emptySourceTally() + } + const imeCommitChars: number[] = [] + return { + recordInput: (source, text) => { + bySource[source].observedInputs += 1 + if (source === 'ime' && text.length > 0) { + appendTypingLatencySample(imeCommitChars, Array.from(text).length) + } + }, + addObservation: (observation) => { + if (observation.attribution === 'single-input') { + bySource[observation.source].exactInputs += 1 + appendExactLatencySample(bySource[observation.source].exact, observation) + return + } + bySource.direct.ambiguousInputs += observation.sourceCounts.direct + bySource.ime.ambiguousInputs += observation.sourceCounts.ime + }, + breakdown: () => ({ + direct: summarizeSource(bySource.direct), + ime: summarizeSource(bySource.ime), + imeCommitChars: summarizeLatencySamples(imeCommitChars) + }) + } +} + +export function emptyInputSourceBreakdown(): InputSourceBreakdown { + return createInputSourceTally().breakdown() +} diff --git a/src/renderer/src/lib/typing-latency/pane-target.ts b/src/renderer/src/lib/typing-latency/pane-target.ts new file mode 100644 index 000000000000..45026281ce55 --- /dev/null +++ b/src/renderer/src/lib/typing-latency/pane-target.ts @@ -0,0 +1,54 @@ +import { forEachLivePaneForDesyncSentinel } from '@/lib/pane-manager/pane-manager-registry' + +type ProbeDisposable = { dispose: () => void } + +type TerminalLike = { + cols?: number + rows?: number + element?: HTMLElement | null + buffer?: { active?: { type?: string; length?: number } } + write?: (data: string | Uint8Array, callback?: () => void) => void + onData?: (listener: (data: string) => void) => ProbeDisposable + onWriteParsed?: (listener: () => void) => ProbeDisposable + onRender?: (listener: () => void) => ProbeDisposable +} + +export type ProbePane = { + id?: number + terminal?: TerminalLike + container?: HTMLElement + leafId?: string +} + +export function listProbePanes(): ProbePane[] { + const panes: ProbePane[] = [] + try { + forEachLivePaneForDesyncSentinel((_key, pane) => { + panes.push(pane as ProbePane) + }) + } catch { + // Why: a mid-teardown manager must not prevent the probe from starting. + } + return panes +} + +export function paneRootElement(pane: ProbePane | null): HTMLElement | null { + return pane?.container ?? pane?.terminal?.element ?? null +} + +export function findPaneOwningNode( + entries: readonly T[], + node: Node | null +): T | null { + if (!node) { + return null + } + return entries.find((entry) => paneRootElement(entry.pane)?.contains(node) === true) ?? null +} + +export function findPaneOwningFocus( + entries: readonly T[] +): T | null { + const focused = typeof document === 'undefined' ? null : document.activeElement + return findPaneOwningNode(entries, focused) +} diff --git a/src/renderer/src/lib/typing-latency/sample-window.test.ts b/src/renderer/src/lib/typing-latency/sample-window.test.ts new file mode 100644 index 000000000000..909e1bd430bd --- /dev/null +++ b/src/renderer/src/lib/typing-latency/sample-window.test.ts @@ -0,0 +1,28 @@ +import { describe, expect, it } from 'vitest' +import { appendExactLatencySample, createExactLatencySampleWindow } from './sample-window' + +describe('typing latency sample window', () => { + it('retains the newest 2000 exact samples in every percentile series', () => { + const samples = createExactLatencySampleWindow() + + for (let value = 0; value <= 2000; value += 1) { + appendExactLatencySample(samples, { + attribution: 'single-input', + source: 'direct', + text: 'a', + inputToDispatchMs: value, + dispatchToParseMs: value, + parseToPaintMs: value, + inputToPaintMs: value, + outputBytes: value, + outputWrites: value + }) + } + + for (const values of Object.values(samples)) { + expect(values).toHaveLength(2000) + expect(values[0]).toBe(1) + expect(values.at(-1)).toBe(2000) + } + }) +}) diff --git a/src/renderer/src/lib/typing-latency/sample-window.ts b/src/renderer/src/lib/typing-latency/sample-window.ts new file mode 100644 index 000000000000..143bb43026a7 --- /dev/null +++ b/src/renderer/src/lib/typing-latency/sample-window.ts @@ -0,0 +1,42 @@ +import type { ExactEchoSample } from './echo-observation' + +const TYPING_LATENCY_SAMPLE_LIMIT = 2000 + +export type ExactLatencySampleWindow = { + inputToDispatchMs: number[] + dispatchToParseMs: number[] + parseToPaintMs: number[] + inputToPaintMs: number[] + outputBytes: number[] + outputWrites: number[] +} + +export function createExactLatencySampleWindow(): ExactLatencySampleWindow { + return { + inputToDispatchMs: [], + dispatchToParseMs: [], + parseToPaintMs: [], + inputToPaintMs: [], + outputBytes: [], + outputWrites: [] + } +} + +export function appendTypingLatencySample(values: number[], value: number): void { + values.push(value) + if (values.length > TYPING_LATENCY_SAMPLE_LIMIT) { + values.shift() + } +} + +export function appendExactLatencySample( + samples: ExactLatencySampleWindow, + sample: ExactEchoSample +): void { + appendTypingLatencySample(samples.inputToDispatchMs, sample.inputToDispatchMs) + appendTypingLatencySample(samples.dispatchToParseMs, sample.dispatchToParseMs) + appendTypingLatencySample(samples.parseToPaintMs, sample.parseToPaintMs) + appendTypingLatencySample(samples.inputToPaintMs, sample.inputToPaintMs) + appendTypingLatencySample(samples.outputBytes, sample.outputBytes) + appendTypingLatencySample(samples.outputWrites, sample.outputWrites) +} diff --git a/src/renderer/src/main.tsx b/src/renderer/src/main.tsx index 825ff536b6f7..6a4e24cff2e0 100644 --- a/src/renderer/src/main.tsx +++ b/src/renderer/src/main.tsx @@ -16,7 +16,7 @@ import { } from './lib/crash-diagnostics' import { installAutomationHostDiagnostic } from './components/automations/automation-host-diagnostics' import { applyDocumentTheme } from './lib/document-theme' -import { installTypingLatencyDiagnostic } from './lib/typing-latency-diagnostic' +import { installTypingLatencyDiagnostic } from './lib/typing-latency/diagnostic' import { shouldEnableReactGrab } from './lib/react-grab-dev-gate' import { I18nProvider } from './i18n/I18nProvider' import { translate } from './i18n/i18n' From 7836b6820909eb0979eb8bd4bdb1de32bc3b9546 Mon Sep 17 00:00:00 2001 From: Neil <4138956+nwparker@users.noreply.github.com> Date: Sat, 29 Aug 2026 04:26:20 -0700 Subject: [PATCH 2/4] fix(diagnostics): settle prevented IME inputs --- .../diagnostic-lifecycle.test.ts | 65 ++++++++++++++++++- .../src/lib/typing-latency/diagnostic.ts | 13 ++-- .../lib/typing-latency/input-events.test.ts | 31 +++++---- .../src/lib/typing-latency/input-events.ts | 14 ++-- 4 files changed, 95 insertions(+), 28 deletions(-) diff --git a/src/renderer/src/lib/typing-latency/diagnostic-lifecycle.test.ts b/src/renderer/src/lib/typing-latency/diagnostic-lifecycle.test.ts index cfb04bc0509b..9e625d142865 100644 --- a/src/renderer/src/lib/typing-latency/diagnostic-lifecycle.test.ts +++ b/src/renderer/src/lib/typing-latency/diagnostic-lifecycle.test.ts @@ -81,7 +81,60 @@ describe('typing latency diagnostic lifecycle', () => { expect(mocks.findPaneOwningFocus).toHaveBeenLastCalledWith([]) }) - it('removes the queue-cap unmatched count when an IME commit is prevented', () => { + it('does not count a stale prevented IME commit', () => { + vi.spyOn(console, 'log').mockImplementation(() => undefined) + mocks.findPaneOwningNode.mockReturnValueOnce({ pane: mocks.panes[0] }) + mocks.discardUndispatchedKeystroke.mockReturnValueOnce('pending') + installTypingLatencyDiagnostic() + const bridge = (window as DiagnosticWindow).__orcaTypingDiagnostic + if (!bridge || !mocks.inputListener) { + throw new Error('Typing latency diagnostic did not start') + } + bridge.start() + + const registration = mocks.inputListener({ + event: new CustomEvent('xterm-composition-session-end'), + source: 'ime', + text: '한' + }) + registration?.settleAfterPropagation(true) + + expect(bridge.report()).toMatchObject({ + sampling: { unmatchedKeystrokes: 0 }, + byInputSource: { + ime: { observedInputs: 0 }, + imeCommitChars: { count: 0 } + } + }) + bridge.stop() + }) + + it('counts a prevented IME commit that reached terminal input', () => { + vi.spyOn(console, 'log').mockImplementation(() => undefined) + mocks.findPaneOwningNode.mockReturnValueOnce({ pane: mocks.panes[0] }) + mocks.discardUndispatchedKeystroke.mockReturnValueOnce(null) + installTypingLatencyDiagnostic() + const bridge = (window as DiagnosticWindow).__orcaTypingDiagnostic + if (!bridge || !mocks.inputListener) { + throw new Error('Typing latency diagnostic did not start') + } + bridge.start() + + const registration = mocks.inputListener({ + event: new CustomEvent('xterm-composition-session-end'), + source: 'ime', + text: '한' + }) + registration?.settleAfterPropagation(true) + + expect(bridge.report().byInputSource).toMatchObject({ + ime: { observedInputs: 1 }, + imeCommitChars: { count: 1, p50: 1 } + }) + bridge.stop() + }) + + it('removes queue-cap accounting when a prevented IME commit was not retained', () => { vi.spyOn(console, 'log').mockImplementation(() => undefined) mocks.findPaneOwningNode.mockReturnValueOnce({ pane: mocks.panes[0] }) mocks.recordKeystroke.mockReturnValueOnce(1) @@ -99,9 +152,15 @@ describe('typing latency diagnostic lifecycle', () => { text: '한' }) expect(bridge.report().sampling.unmatchedKeystrokes).toBe(1) - registration?.discardIfPrevented() + registration?.settleAfterPropagation(true) - expect(bridge.report().sampling.unmatchedKeystrokes).toBe(0) + expect(bridge.report()).toMatchObject({ + sampling: { unmatchedKeystrokes: 0 }, + byInputSource: { + ime: { observedInputs: 0 }, + imeCommitChars: { count: 0 } + } + }) bridge.stop() }) }) diff --git a/src/renderer/src/lib/typing-latency/diagnostic.ts b/src/renderer/src/lib/typing-latency/diagnostic.ts index d4668ffac3ca..3183cfb2debd 100644 --- a/src/renderer/src/lib/typing-latency/diagnostic.ts +++ b/src/renderer/src/lib/typing-latency/diagnostic.ts @@ -242,20 +242,23 @@ function startProbe(): string { state.keystrokesWithoutTerminalFocus += 1 return undefined } - state.byInputSource.recordInput(signal.source, signal.text) const recordedAt = performance.now() state.unmatchedKeystrokes += recordKeystroke(target, recordedAt, signal.source, signal.text) if (signal.source === 'ime') { return { - discardIfPrevented: () => { - if ( - discardUndispatchedKeystroke(target, recordedAt, signal.source) === 'counted-unmatched' - ) { + settleAfterPropagation: (defaultPrevented) => { + const discardResult = defaultPrevented + ? discardUndispatchedKeystroke(target, recordedAt, signal.source) + : null + if (discardResult === null) { + state.byInputSource.recordInput(signal.source, signal.text) + } else if (discardResult === 'counted-unmatched') { state.unmatchedKeystrokes = Math.max(0, state.unmatchedKeystrokes - 1) } } } } + state.byInputSource.recordInput(signal.source, signal.text) return undefined }) diff --git a/src/renderer/src/lib/typing-latency/input-events.test.ts b/src/renderer/src/lib/typing-latency/input-events.test.ts index 3c5bf3fb56ac..63866fe721ae 100644 --- a/src/renderer/src/lib/typing-latency/input-events.test.ts +++ b/src/renderer/src/lib/typing-latency/input-events.test.ts @@ -73,25 +73,32 @@ describe('installTypingLatencyInputEvents', () => { expect(signals).toEqual([]) }) - it('settles a prevented routed commit before the outer input resumes', () => { + it('settles prevented and unprevented commits once after propagation', () => { const terminalElement = document.createElement('div') document.body.appendChild(terminalElement) - let discarded = 0 + const settlements: boolean[] = [] detach = installTypingLatencyInputEvents(window, (signal) => - signal.source === 'ime' ? { discardIfPrevented: () => (discarded += 1) } : undefined + signal.source === 'ime' + ? { settleAfterPropagation: (defaultPrevented) => settlements.push(defaultPrevented) } + : undefined ) + + const dispatchSessionEnd = (): void => { + terminalElement.dispatchEvent( + new CustomEvent(XTERM_COMPOSITION_SESSION_END_EVENT, { + bubbles: true, + cancelable: true, + detail: { id: 1, data: '한' } + }) + ) + } + dispatchSessionEnd() + terminalElement.addEventListener(XTERM_COMPOSITION_SESSION_END_EVENT, (event) => event.preventDefault() ) + dispatchSessionEnd() - terminalElement.dispatchEvent( - new CustomEvent(XTERM_COMPOSITION_SESSION_END_EVENT, { - bubbles: true, - cancelable: true, - detail: { id: 1, data: '한' } - }) - ) - - expect(discarded).toBe(1) + expect(settlements).toEqual([false, true]) }) }) diff --git a/src/renderer/src/lib/typing-latency/input-events.ts b/src/renderer/src/lib/typing-latency/input-events.ts index f8644efd47e9..5368432ef34b 100644 --- a/src/renderer/src/lib/typing-latency/input-events.ts +++ b/src/renderer/src/lib/typing-latency/input-events.ts @@ -15,7 +15,7 @@ export type TypingInputSignal = { type InputEventTarget = Pick export type TypingInputRegistration = { - discardIfPrevented: () => void + settleAfterPropagation: (defaultPrevented: boolean) => void } function isDirectEchoInput(event: KeyboardEvent): boolean { @@ -30,7 +30,7 @@ export function installTypingLatencyInputEvents( target: InputEventTarget, onInput: (signal: TypingInputSignal) => TypingInputRegistration | void ): () => void { - const pendingPreventedCommits = new WeakMap() + const pendingCompositionInputs = new WeakMap() const onKeydown = (event: Event): void => { if (event instanceof KeyboardEvent && isDirectEchoInput(event)) { onInput({ source: 'direct', text: event.key, event }) @@ -43,15 +43,13 @@ export function installTypingLatencyInputEvents( } const registration = onInput({ source: 'ime', text: detail.data, event }) if (registration) { - pendingPreventedCommits.set(event, registration) + pendingCompositionInputs.set(event, registration) } } const settleCompositionSessionEnd = (event: Event): void => { - const registration = pendingPreventedCommits.get(event) - pendingPreventedCommits.delete(event) - if (event.defaultPrevented) { - registration?.discardIfPrevented() - } + const registration = pendingCompositionInputs.get(event) + pendingCompositionInputs.delete(event) + registration?.settleAfterPropagation(event.defaultPrevented) } target.addEventListener('keydown', onKeydown, { capture: true }) From 11fa0c311c93ef5b5c02f9751d3563bb3c259fa9 Mon Sep 17 00:00:00 2001 From: Neil <4138956+nwparker@users.noreply.github.com> Date: Sat, 29 Aug 2026 19:31:17 -0700 Subject: [PATCH 3/4] fix(typing-diagnostic): preserve sample attribution invariants --- .../diagnostic-lifecycle.test.ts | 17 +++ .../typing-latency/diagnostic-summary.test.ts | 49 +++++++- .../lib/typing-latency/diagnostic-summary.ts | 64 +++++----- .../src/lib/typing-latency/diagnostic.ts | 7 ++ .../typing-latency/echo-candidate-timeout.ts | 67 ++++++++++ .../echo-instrumentation.test.ts | 118 +++++++++++++++++- .../typing-latency/echo-instrumentation.ts | 81 ++++++------ 7 files changed, 323 insertions(+), 80 deletions(-) create mode 100644 src/renderer/src/lib/typing-latency/echo-candidate-timeout.ts diff --git a/src/renderer/src/lib/typing-latency/diagnostic-lifecycle.test.ts b/src/renderer/src/lib/typing-latency/diagnostic-lifecycle.test.ts index 9e625d142865..e9d49cfe7e08 100644 --- a/src/renderer/src/lib/typing-latency/diagnostic-lifecycle.test.ts +++ b/src/renderer/src/lib/typing-latency/diagnostic-lifecycle.test.ts @@ -10,6 +10,7 @@ const mocks = vi.hoisted(() => { discardUndispatchedKeystroke: vi.fn<() => PreventedKeystrokeDiscard>(() => null), detachInputEvents: vi.fn(), detachPaneEcho: vi.fn(() => 1), + drainTimedOutEchoCandidates: vi.fn(() => 0), findPaneOwningFocus: vi.fn<() => object | null>(() => null), findPaneOwningNode: vi.fn<() => object | null>(() => null), inputListener: null as ((signal: TypingInputSignal) => TypingInputRegistration | void) | null, @@ -28,6 +29,7 @@ vi.mock('./census-probe', () => ({ vi.mock('./echo-instrumentation', () => ({ detachPaneEcho: mocks.detachPaneEcho, discardUndispatchedKeystroke: mocks.discardUndispatchedKeystroke, + drainTimedOutEchoCandidates: mocks.drainTimedOutEchoCandidates, findPaneOwningFocus: mocks.findPaneOwningFocus, findPaneOwningNode: mocks.findPaneOwningNode, instrumentPaneEcho: vi.fn((pane) => ({ pane })), @@ -81,6 +83,21 @@ describe('typing latency diagnostic lifecycle', () => { expect(mocks.findPaneOwningFocus).toHaveBeenLastCalledWith([]) }) + it('counts timed-out trailing inputs in a live report exactly once', () => { + vi.spyOn(console, 'log').mockImplementation(() => undefined) + mocks.drainTimedOutEchoCandidates.mockReturnValueOnce(1) + installTypingLatencyDiagnostic() + const bridge = (window as DiagnosticWindow).__orcaTypingDiagnostic + if (!bridge) { + throw new Error('Typing latency diagnostic bridge was not installed') + } + + bridge.start() + expect(bridge.report().sampling.unmatchedKeystrokes).toBe(1) + expect(bridge.report().sampling.unmatchedKeystrokes).toBe(1) + bridge.stop() + }) + it('does not count a stale prevented IME commit', () => { vi.spyOn(console, 'log').mockImplementation(() => undefined) mocks.findPaneOwningNode.mockReturnValueOnce({ pane: mocks.panes[0] }) diff --git a/src/renderer/src/lib/typing-latency/diagnostic-summary.test.ts b/src/renderer/src/lib/typing-latency/diagnostic-summary.test.ts index ae91edf3037c..abd5b0240051 100644 --- a/src/renderer/src/lib/typing-latency/diagnostic-summary.test.ts +++ b/src/renderer/src/lib/typing-latency/diagnostic-summary.test.ts @@ -40,8 +40,11 @@ describe('typingSampleDurationMs', () => { }) describe('summarizeWorktreeNesting', () => { + const worktreesAtPaths = (...paths: string[]): { path: string }[] => + paths.map((path) => ({ path })) + it('returns zero depth for flat sibling worktrees', () => { - expect(summarizeWorktreeNesting(['/a/one', '/a/two'])).toEqual({ + expect(summarizeWorktreeNesting(worktreesAtPaths('/a/one', '/a/two'))).toEqual({ maxDepth: 0, nestedWorktrees: 0 }) @@ -49,26 +52,62 @@ describe('summarizeWorktreeNesting', () => { it('counts nesting depth for worktrees inside worktrees', () => { expect( - summarizeWorktreeNesting(['/repo', '/repo/wt-a', '/repo/wt-a/wt-b', '/repo/wt-a/wt-b/wt-c']) + summarizeWorktreeNesting( + worktreesAtPaths('/repo', '/repo/wt-a', '/repo/wt-a/wt-b', '/repo/wt-a/wt-b/wt-c') + ) ).toEqual({ maxDepth: 3, nestedWorktrees: 3 }) }) it('normalizes windows separators, case, and trailing slashes', () => { - expect(summarizeWorktreeNesting(['C:\\Repo\\', 'c:/repo/Nested'])).toEqual({ + expect(summarizeWorktreeNesting(worktreesAtPaths('C:\\Repo\\', 'c:/repo/Nested'))).toEqual({ maxDepth: 1, nestedWorktrees: 1 }) }) + it('preserves case-distinct POSIX and SSH worktree paths', () => { + expect( + summarizeWorktreeNesting( + worktreesAtPaths('/srv/Repo', '/srv/repo/nested').map((worktree) => ({ + ...worktree, + hostId: 'ssh:openclaw' + })) + ) + ).toEqual({ maxDepth: 0, nestedWorktrees: 0 }) + }) + + it('does not infer nesting across execution hosts', () => { + expect( + summarizeWorktreeNesting([ + { path: '/srv/repo', hostId: 'local' }, + { path: '/srv/repo/nested', hostId: 'ssh:openclaw' } + ]) + ).toEqual({ maxDepth: 0, nestedWorktrees: 0 }) + }) + + it('recognizes worktrees nested under filesystem roots', () => { + expect( + summarizeWorktreeNesting([ + { path: '/', hostId: 'ssh:openclaw' }, + { path: '/repo', hostId: 'ssh:openclaw' }, + { path: 'C:\\', hostId: 'windows' }, + { path: 'C:\\repo', hostId: 'windows' } + ]) + ).toEqual({ maxDepth: 1, nestedWorktrees: 2 }) + }) + it('ignores prefix matches that are not path boundaries', () => { - expect(summarizeWorktreeNesting(['/repo', '/repo-two'])).toEqual({ + expect(summarizeWorktreeNesting(worktreesAtPaths('/repo', '/repo-two'))).toEqual({ maxDepth: 0, nestedWorktrees: 0 }) }) it('tolerates empty and duplicate entries', () => { - expect(summarizeWorktreeNesting(['', '/a', '/a'])).toEqual({ maxDepth: 0, nestedWorktrees: 0 }) + expect(summarizeWorktreeNesting(worktreesAtPaths('', '/a', '/a'))).toEqual({ + maxDepth: 0, + nestedWorktrees: 0 + }) }) }) diff --git a/src/renderer/src/lib/typing-latency/diagnostic-summary.ts b/src/renderer/src/lib/typing-latency/diagnostic-summary.ts index 00934c591c4c..3f60e5a7e029 100644 --- a/src/renderer/src/lib/typing-latency/diagnostic-summary.ts +++ b/src/renderer/src/lib/typing-latency/diagnostic-summary.ts @@ -6,6 +6,7 @@ * Kept separate from the DOM/store wiring in diagnostic.ts so * the arithmetic is unit-testable without an xterm or a live store. */ +import { normalizeRuntimePathForComparison } from '../../../../shared/cross-platform-path' export type LatencyPercentiles = { count: number @@ -52,29 +53,36 @@ export type WorktreeNestingCensus = { nestedWorktrees: number } -/** Windows and default macOS filesystems are case-insensitive, so compare case-folded. */ -function normalizePathForNesting(rawPath: string): string { - const unified = rawPath.replaceAll('\\', '/').toLowerCase() - return unified.length > 1 && unified.endsWith('/') ? unified.slice(0, -1) : unified -} +type WorktreeLike = { path?: string | null; hostId?: string | null } -export function summarizeWorktreeNesting(paths: readonly string[]): WorktreeNestingCensus { - const normalized = paths - .filter((path) => typeof path === 'string' && path.length > 0) - .map((path) => normalizePathForNesting(path)) - const unique = [...new Set(normalized)] +export function summarizeWorktreeNesting( + worktrees: readonly WorktreeLike[] +): WorktreeNestingCensus { + const pathsByHost = new Map>() + for (const worktree of worktrees) { + if (typeof worktree.path !== 'string' || worktree.path.length === 0) { + continue + } + const hostId = worktree.hostId ?? null + const paths = pathsByHost.get(hostId) ?? new Set() + paths.add(normalizeRuntimePathForComparison(worktree.path)) + pathsByHost.set(hostId, paths) + } let maxDepth = 0 let nestedWorktrees = 0 - for (const candidate of unique) { - let depth = 0 - for (const ancestor of unique) { - if (ancestor !== candidate && candidate.startsWith(`${ancestor}/`)) { - depth += 1 + for (const paths of pathsByHost.values()) { + for (const candidate of paths) { + let depth = 0 + for (const ancestor of paths) { + const ancestorPrefix = ancestor.endsWith('/') ? ancestor : `${ancestor}/` + if (ancestor !== candidate && candidate.startsWith(ancestorPrefix)) { + depth += 1 + } + } + maxDepth = Math.max(maxDepth, depth) + if (depth > 0) { + nestedWorktrees += 1 } - } - maxDepth = Math.max(maxDepth, depth) - if (depth > 0) { - nestedWorktrees += 1 } } return { maxDepth, nestedWorktrees } @@ -96,8 +104,6 @@ export type FocusedPaneCensus = { type CountableRecord = Record | null | undefined -type WorktreeLike = { path?: string | null } - export type TypingCensusStoreShape = { worktreesByRepo?: Record | null tabsByWorktree?: Record | null @@ -177,22 +183,24 @@ function readNumber( return typeof value === 'number' && Number.isFinite(value) ? value : null } -function collectWorktreePaths(byRepo: Record | null | undefined): string[] { +function collectWorktrees( + byRepo: Record | null | undefined +): WorktreeLike[] { if (!byRepo) { return [] } - const paths: string[] = [] + const collected: WorktreeLike[] = [] for (const worktrees of Object.values(byRepo)) { if (!Array.isArray(worktrees)) { continue } for (const worktree of worktrees) { if (typeof worktree?.path === 'string') { - paths.push(worktree.path) + collected.push(worktree) } } } - return paths + return collected } export function summarizeTypingScaleCensus(input: { @@ -206,14 +214,14 @@ export function summarizeTypingScaleCensus(input: { }): TypingScaleCensus { const state = input.state const settings = state?.settings ?? null - const worktreePaths = collectWorktreePaths(state?.worktreesByRepo) + const worktrees = collectWorktrees(state?.worktreesByRepo) const storeLive = countRecord(state?.agentStatusByPaneKey) const storeRetained = countRecord(state?.retainedAgentsByPaneKey) return { appVersion: input.appVersion, repos: state?.worktreesByRepo ? Object.keys(state.worktreesByRepo).length : 0, - worktrees: worktreePaths.length, - worktreeNesting: summarizeWorktreeNesting(worktreePaths), + worktrees: worktrees.length, + worktreeNesting: summarizeWorktreeNesting(worktrees), tabs: { terminal: sumArrayLengths(state?.tabsByWorktree), unified: sumArrayLengths(state?.unifiedTabsByWorktree) diff --git a/src/renderer/src/lib/typing-latency/diagnostic.ts b/src/renderer/src/lib/typing-latency/diagnostic.ts index 3183cfb2debd..d6d06887d2c2 100644 --- a/src/renderer/src/lib/typing-latency/diagnostic.ts +++ b/src/renderer/src/lib/typing-latency/diagnostic.ts @@ -21,6 +21,7 @@ import { import { detachPaneEcho, discardUndispatchedKeystroke, + drainTimedOutEchoCandidates, findPaneOwningFocus, findPaneOwningNode, instrumentPaneEcho, @@ -285,6 +286,12 @@ function stopProbe(): string { } function reportProbe(): TypingLatencyReport { + if (active) { + const now = performance.now() + for (const entry of active.panes) { + active.unmatchedKeystrokes += drainTimedOutEchoCandidates(entry, now) + } + } const report = buildReport(active ?? lastState, active !== null) console.log('[orca] typing latency diagnostic', report) return report diff --git a/src/renderer/src/lib/typing-latency/echo-candidate-timeout.ts b/src/renderer/src/lib/typing-latency/echo-candidate-timeout.ts new file mode 100644 index 000000000000..e4e016c30b67 --- /dev/null +++ b/src/renderer/src/lib/typing-latency/echo-candidate-timeout.ts @@ -0,0 +1,67 @@ +import type { InstrumentedPane } from './echo-instrumentation' +import type { EchoCandidate } from './echo-observation' + +const ECHO_TIMEOUT_MS = 2000 + +export function clearEchoDispatchSelection( + entry: InstrumentedPane, + candidate: EchoCandidate +): void { + if (entry.nextDispatch === candidate) { + entry.nextDispatch = null + } + if (entry.deferredNextDispatch === candidate) { + entry.deferredNextDispatch = null + } +} + +function drainTimedOutCandidates( + candidates: EchoCandidate[], + now: number, + onDrop?: (candidate: EchoCandidate) => void +): number { + let retained = 0 + let dropped = 0 + for (const candidate of candidates) { + if (now - candidate.t0 > ECHO_TIMEOUT_MS) { + dropped += 1 + onDrop?.(candidate) + } else { + candidates[retained] = candidate + retained += 1 + } + } + candidates.length = retained + return dropped +} + +/** Removes inputs whose echo window elapsed and returns the unmatched count. */ +export function drainTimedOutEchoCandidates(entry: InstrumentedPane, now: number): number { + let dropped = drainTimedOutCandidates(entry.undispatched, now, (candidate) => + clearEchoDispatchSelection(entry, candidate) + ) + const awaitingEchoDropped = drainTimedOutCandidates(entry.awaitingEcho, now) + if (awaitingEchoDropped > 0) { + entry.attributionGap = true + dropped += awaitingEchoDropped + } + if (entry.parsingBatch) { + const parsingDropped = drainTimedOutCandidates(entry.parsingBatch.candidates, now) + if (parsingDropped > 0) { + entry.parsingBatch.hasAttributionGap = true + dropped += parsingDropped + } + } + for (const batch of entry.parsedBatches) { + const parsedDropped = drainTimedOutCandidates(batch.candidates, now) + if (parsedDropped > 0) { + batch.hasAttributionGap = true + dropped += parsedDropped + } + } + if (dropped > 0) { + entry.pendingCount -= dropped + entry.parsedBatches = entry.parsedBatches.filter((batch) => batch.candidates.length > 0) + } + return dropped +} diff --git a/src/renderer/src/lib/typing-latency/echo-instrumentation.test.ts b/src/renderer/src/lib/typing-latency/echo-instrumentation.test.ts index 16ea26497e7e..95dc479e9523 100644 --- a/src/renderer/src/lib/typing-latency/echo-instrumentation.test.ts +++ b/src/renderer/src/lib/typing-latency/echo-instrumentation.test.ts @@ -1,7 +1,9 @@ import { afterEach, describe, expect, it, vi } from 'vitest' +import { Terminal } from '@xterm/xterm' import { detachPaneEcho, discardUndispatchedKeystroke, + drainTimedOutEchoCandidates, instrumentPaneEcho, recordKeystroke, type EchoObservation, @@ -15,7 +17,7 @@ function emptyEntry(): InstrumentedPane { nextDispatch: null, deferredNextDispatch: null, ignoredDispatches: 0, - lastIgnoredDispatch: null, + ignoredDispatchIdentities: [], awaitingEcho: [], attributionGap: false, parsingBatch: null, @@ -33,6 +35,14 @@ type FakeTerminal = { onRender: (listener: () => void) => { dispose: () => void } } +type CoreServiceAccess = { + _core: { + coreService: { + triggerDataEvent: (data: string, wasUserInput?: boolean) => void + } + } +} + function fakeTerminal(): { terminal: FakeTerminal emitData: (data?: string) => void @@ -104,6 +114,15 @@ describe('recordKeystroke', () => { expect(entry.attributionGap).toBe(false) }) + it('drains a final timed-out input without waiting for another keystroke', () => { + const entry = emptyEntry() + recordKeystroke(entry, 0, 'direct') + + expect(drainTimedOutEchoCandidates(entry, 2_001)).toBe(1) + expect(drainTimedOutEchoCandidates(entry, 2_002)).toBe(0) + expect(entry.pendingCount).toBe(0) + }) + it('bounds pending input state during sustained typing', () => { const entry = emptyEntry() let dropped = 0 @@ -167,9 +186,56 @@ describe('recordKeystroke', () => { expect(entry.ignoredDispatches).toBe(0) expect(entry.attributionGap).toBe(false) }) + + it('settles overlapping cap-rejected commits by identity', () => { + const entry = emptyEntry() + for (let index = 0; index < 64; index += 1) { + recordKeystroke(entry, index, 'direct') + } + + expect(recordKeystroke(entry, 64, 'ime', '한')).toBe(1) + expect(recordKeystroke(entry, 65, 'ime', '글')).toBe(1) + expect(discardUndispatchedKeystroke(entry, 64, 'ime')).toBe('counted-unmatched') + expect(discardUndispatchedKeystroke(entry, 65, 'ime')).toBe('counted-unmatched') + expect(entry.undispatched).toHaveLength(64) + expect(entry.ignoredDispatches).toBe(0) + expect(entry.attributionGap).toBe(false) + }) + + it('settles same-timestamp cap rejections independently', () => { + const entry = emptyEntry() + for (let index = 0; index < 64; index += 1) { + recordKeystroke(entry, index, 'direct') + } + + recordKeystroke(entry, 64, 'ime', '한') + recordKeystroke(entry, 64, 'ime', '글') + + expect(discardUndispatchedKeystroke(entry, 64, 'ime')).toBe('counted-unmatched') + expect(discardUndispatchedKeystroke(entry, 64, 'ime')).toBe('counted-unmatched') + expect(entry.ignoredDispatches).toBe(0) + }) }) describe('instrumentPaneEcho', () => { + it('does not attribute parser replies as user dispatches', () => { + const terminal = new Terminal({ allowProposedApi: true }) + const entry = instrumentPaneEcho({ terminal }, () => undefined) + const coreService = (terminal as unknown as CoreServiceAccess)._core.coreService + + recordKeystroke(entry, 10, 'direct', 'a') + coreService.triggerDataEvent('\x1b[?1;2c', false) + expect(entry.undispatched).toHaveLength(1) + expect(entry.awaitingEcho).toEqual([]) + + coreService.triggerDataEvent('a', true) + expect(entry.undispatched).toEqual([]) + expect(entry.awaitingEcho).toHaveLength(1) + + detachPaneEcho(entry) + terminal.dispose() + }) + it('measures input, dispatch, parse, and paint stages separately', () => { const fake = fakeTerminal() const observations: EchoObservation[] = [] @@ -441,6 +507,56 @@ describe('instrumentPaneEcho', () => { expect(observations).toHaveLength(1) }) + it('drains parsed output that never paints exactly once', () => { + const fake = fakeTerminal() + const observations: EchoObservation[] = [] + const entry = instrumentPaneEcho({ terminal: fake.terminal }, (value) => + observations.push(value) + ) + + recordAndDispatch(entry, fake, 'direct', 0, 'A') + fake.terminal.write('A') + fake.emitParsed() + + expect(drainTimedOutEchoCandidates(entry, 2_001)).toBe(1) + expect(drainTimedOutEchoCandidates(entry, 2_002)).toBe(0) + expect(entry).toMatchObject({ parsedBatches: [], pendingCount: 0 }) + + recordAndDispatch(entry, fake, 'direct', 2_003, 'B') + fake.terminal.write('B') + fake.emitParsed() + fake.emitRender() + + expect(observations).toHaveLength(1) + expect(observations[0]).toMatchObject({ attribution: 'single-input', text: 'B' }) + expect(entry.pendingCount).toBe(0) + }) + + it('keeps a shared unparsed batch ambiguous after draining its stale input', () => { + const fake = fakeTerminal() + const observations: EchoObservation[] = [] + const entry = instrumentPaneEcho({ terminal: fake.terminal }, (value) => + observations.push(value) + ) + + recordAndDispatch(entry, fake, 'direct', 0, 'A') + fake.terminal.write('late A') + expect(drainTimedOutEchoCandidates(entry, 2_001)).toBe(1) + + recordAndDispatch(entry, fake, 'direct', 2_002, 'B') + fake.terminal.write('B') + fake.emitParsed() + fake.emitRender() + + expect(observations).toHaveLength(1) + expect(observations[0]).toMatchObject({ + attribution: 'ambiguous-burst', + reason: 'attribution-gap', + inputCount: 1 + }) + expect(entry.pendingCount).toBe(0) + }) + it('returns trailing unmatched inputs and releases pane and listener closures', () => { const fake = fakeTerminal() const originalWrite = fake.terminal.write diff --git a/src/renderer/src/lib/typing-latency/echo-instrumentation.ts b/src/renderer/src/lib/typing-latency/echo-instrumentation.ts index b7c720dd97a2..03fe933dde0e 100644 --- a/src/renderer/src/lib/typing-latency/echo-instrumentation.ts +++ b/src/renderer/src/lib/typing-latency/echo-instrumentation.ts @@ -7,6 +7,9 @@ * opaque; the probe never apportions one output batch across those inputs. */ import { getUtf8ByteLength } from '../../../../shared/utf8-byte-limits' +import { subscribeToTerminalUserInput } from '@/components/terminal-pane/terminal-user-input-signal' +import type { Terminal } from '@xterm/xterm' +import { clearEchoDispatchSelection, drainTimedOutEchoCandidates } from './echo-candidate-timeout' import { createEchoObservation, type EchoBatch, @@ -29,6 +32,7 @@ export { paneRootElement } from './pane-target' export type { ProbePane } from './pane-target' +export { drainTimedOutEchoCandidates } type Disposable = { dispose: () => void } @@ -49,7 +53,7 @@ export type InstrumentedPane = { nextDispatch: PendingKeystroke | null deferredNextDispatch: PendingKeystroke | null ignoredDispatches: number - lastIgnoredDispatch: IgnoredDispatch | null + ignoredDispatchIdentities: IgnoredDispatch[] awaitingEcho: PendingKeystroke[] attributionGap: boolean parsingBatch: EchoBatch | null @@ -59,19 +63,8 @@ export type InstrumentedPane = { restoreWrite: (() => void) | null } -/** An input with no output write in this window is unmatched, never an exact sample. */ -const ECHO_TIMEOUT_MS = 2000 const MAX_PENDING = 64 -function clearDispatchSelection(entry: InstrumentedPane, pending: PendingKeystroke): void { - if (entry.nextDispatch === pending) { - entry.nextDispatch = null - } - if (entry.deferredNextDispatch === pending) { - entry.deferredNextDispatch = null - } -} - function restoreDeferredDispatch(entry: InstrumentedPane): void { const deferred = entry.deferredNextDispatch entry.deferredNextDispatch = null @@ -80,27 +73,6 @@ function restoreDeferredDispatch(entry: InstrumentedPane): void { } } -function removeOldestTimedOut(entry: InstrumentedPane, now: number): boolean { - const undispatched = entry.undispatched[0] - const awaitingEcho = entry.awaitingEcho[0] - const oldest = - !undispatched || (awaitingEcho && awaitingEcho.t0 < undispatched.t0) - ? awaitingEcho - : undispatched - if (!oldest || now - oldest.t0 <= ECHO_TIMEOUT_MS) { - return false - } - if (oldest === awaitingEcho) { - entry.awaitingEcho.shift() - entry.attributionGap = true - } else { - entry.undispatched.shift() - clearDispatchSelection(entry, oldest) - } - entry.pendingCount -= 1 - return true -} - /** Returns how many inputs were dropped without a painted output observation. */ export function recordKeystroke( entry: InstrumentedPane, @@ -108,17 +80,17 @@ export function recordKeystroke( source: KeystrokeSource, text: string = '' ): number { - let dropped = 0 - while (removeOldestTimedOut(entry, now)) { - dropped += 1 - } + const dropped = drainTimedOutEchoCandidates(entry, now) if (entry.pendingCount >= MAX_PENDING) { if (entry.ignoredDispatches === 0) { entry.deferredNextDispatch = entry.nextDispatch } entry.nextDispatch = null entry.ignoredDispatches += 1 - entry.lastIgnoredDispatch = { t0: now, source } + entry.ignoredDispatchIdentities.push({ t0: now, source }) + if (entry.ignoredDispatchIdentities.length > MAX_PENDING) { + entry.ignoredDispatchIdentities.shift() + } return dropped + 1 } const pending = { t0: now, source, text, dispatchedAt: null } @@ -134,10 +106,13 @@ export function discardUndispatchedKeystroke( recordedAt: number, source: KeystrokeSource ): PreventedKeystrokeDiscard { - const ignored = entry.lastIgnoredDispatch - if (ignored?.t0 === recordedAt && ignored.source === source) { - entry.ignoredDispatches = Math.max(0, entry.ignoredDispatches - 1) - entry.lastIgnoredDispatch = null + for (let index = entry.ignoredDispatchIdentities.length - 1; index >= 0; index -= 1) { + const ignored = entry.ignoredDispatchIdentities[index] + if (!ignored || ignored.t0 !== recordedAt || ignored.source !== source) { + continue + } + entry.ignoredDispatchIdentities.splice(index, 1) + entry.ignoredDispatches -= 1 if (entry.ignoredDispatches === 0) { restoreDeferredDispatch(entry) } @@ -149,7 +124,7 @@ export function discardUndispatchedKeystroke( continue } entry.undispatched.splice(index, 1) - clearDispatchSelection(entry, pending) + clearEchoDispatchSelection(entry, pending) entry.nextDispatch ??= entry.undispatched.at(-1) ?? null entry.pendingCount -= 1 return 'pending' @@ -190,7 +165,7 @@ export function instrumentPaneEcho( nextDispatch: null, deferredNextDispatch: null, ignoredDispatches: 0, - lastIgnoredDispatch: null, + ignoredDispatchIdentities: [], awaitingEcho: [], attributionGap: false, parsingBatch: null, @@ -222,16 +197,30 @@ export function instrumentPaneEcho( } } + let pendingUserInputSignals = 0 + const userInputDisposable = subscribeToTerminalUserInput(terminal as Terminal, () => { + pendingUserInputSignals = Math.min(MAX_PENDING, pendingUserInputSignals + 1) + }) + if (userInputDisposable) { + entry.disposables.push(userInputDisposable) + } + if (typeof terminal.onData === 'function') { entry.disposables.push( terminal.onData(() => { + if (userInputDisposable) { + if (pendingUserInputSignals === 0) { + return + } + pendingUserInputSignals -= 1 + } let pending = entry.nextDispatch if (pending && entry.undispatched.at(-1) === pending) { entry.undispatched.pop() entry.nextDispatch = null } else if (!pending && entry.ignoredDispatches > 0) { entry.ignoredDispatches -= 1 - entry.lastIgnoredDispatch = null + entry.ignoredDispatchIdentities.pop() entry.attributionGap = true if (entry.ignoredDispatches === 0) { restoreDeferredDispatch(entry) @@ -300,7 +289,7 @@ export function detachPaneEcho(entry: InstrumentedPane): number { entry.nextDispatch = null entry.deferredNextDispatch = null entry.ignoredDispatches = 0 - entry.lastIgnoredDispatch = null + entry.ignoredDispatchIdentities = [] entry.awaitingEcho = [] entry.attributionGap = false entry.parsingBatch = null From d1f14c8a0a721b5a8aa28aea094f6224e22b7777 Mon Sep 17 00:00:00 2001 From: Neil <4138956+nwparker@users.noreply.github.com> Date: Sat, 29 Aug 2026 19:54:56 -0700 Subject: [PATCH 4/4] fix(typing-diagnostic): bound echo settlement state --- .../diagnostic-lifecycle.test.ts | 31 ++++- .../src/lib/typing-latency/diagnostic.ts | 5 +- .../typing-latency/echo-candidate-timeout.ts | 62 ++++++++- .../echo-instrumentation.test.ts | 120 ++++++++++++---- .../typing-latency/echo-instrumentation.ts | 130 +++++++++--------- .../lib/typing-latency/echo-observation.ts | 19 +++ 6 files changed, 264 insertions(+), 103 deletions(-) diff --git a/src/renderer/src/lib/typing-latency/diagnostic-lifecycle.test.ts b/src/renderer/src/lib/typing-latency/diagnostic-lifecycle.test.ts index e9d49cfe7e08..0720586ca8aa 100644 --- a/src/renderer/src/lib/typing-latency/diagnostic-lifecycle.test.ts +++ b/src/renderer/src/lib/typing-latency/diagnostic-lifecycle.test.ts @@ -15,7 +15,7 @@ const mocks = vi.hoisted(() => { findPaneOwningNode: vi.fn<() => object | null>(() => null), inputListener: null as ((signal: TypingInputSignal) => TypingInputRegistration | void) | null, panes, - recordKeystroke: vi.fn(() => 0) + recordKeystroke: vi.fn(() => ({ candidate: {}, unmatched: 0 })) } }) @@ -98,6 +98,33 @@ describe('typing latency diagnostic lifecycle', () => { bridge.stop() }) + it('reverses a timeout count when the IME commit later settles prevented', () => { + vi.spyOn(console, 'log').mockImplementation(() => undefined) + mocks.findPaneOwningNode.mockReturnValueOnce({ pane: mocks.panes[0] }) + mocks.drainTimedOutEchoCandidates.mockReturnValueOnce(1) + mocks.discardUndispatchedKeystroke.mockReturnValueOnce('counted-unmatched') + installTypingLatencyDiagnostic() + const bridge = (window as DiagnosticWindow).__orcaTypingDiagnostic + if (!bridge || !mocks.inputListener) { + throw new Error('Typing latency diagnostic did not start') + } + bridge.start() + + const registration = mocks.inputListener({ + event: new CustomEvent('xterm-composition-session-end'), + source: 'ime', + text: '한' + }) + expect(bridge.report().sampling.unmatchedKeystrokes).toBe(1) + registration?.settleAfterPropagation(true) + + expect(bridge.report()).toMatchObject({ + sampling: { unmatchedKeystrokes: 0 }, + byInputSource: { ime: { observedInputs: 0 } } + }) + bridge.stop() + }) + it('does not count a stale prevented IME commit', () => { vi.spyOn(console, 'log').mockImplementation(() => undefined) mocks.findPaneOwningNode.mockReturnValueOnce({ pane: mocks.panes[0] }) @@ -154,7 +181,7 @@ describe('typing latency diagnostic lifecycle', () => { it('removes queue-cap accounting when a prevented IME commit was not retained', () => { vi.spyOn(console, 'log').mockImplementation(() => undefined) mocks.findPaneOwningNode.mockReturnValueOnce({ pane: mocks.panes[0] }) - mocks.recordKeystroke.mockReturnValueOnce(1) + mocks.recordKeystroke.mockReturnValueOnce({ candidate: {}, unmatched: 1 }) mocks.discardUndispatchedKeystroke.mockReturnValueOnce('counted-unmatched') installTypingLatencyDiagnostic() const bridge = (window as DiagnosticWindow).__orcaTypingDiagnostic diff --git a/src/renderer/src/lib/typing-latency/diagnostic.ts b/src/renderer/src/lib/typing-latency/diagnostic.ts index d6d06887d2c2..9c68c7a689d6 100644 --- a/src/renderer/src/lib/typing-latency/diagnostic.ts +++ b/src/renderer/src/lib/typing-latency/diagnostic.ts @@ -244,12 +244,13 @@ function startProbe(): string { return undefined } const recordedAt = performance.now() - state.unmatchedKeystrokes += recordKeystroke(target, recordedAt, signal.source, signal.text) + const recorded = recordKeystroke(target, recordedAt, signal.source, signal.text) + state.unmatchedKeystrokes += recorded.unmatched if (signal.source === 'ime') { return { settleAfterPropagation: (defaultPrevented) => { const discardResult = defaultPrevented - ? discardUndispatchedKeystroke(target, recordedAt, signal.source) + ? discardUndispatchedKeystroke(target, recorded.candidate) : null if (discardResult === null) { state.byInputSource.recordInput(signal.source, signal.text) diff --git a/src/renderer/src/lib/typing-latency/echo-candidate-timeout.ts b/src/renderer/src/lib/typing-latency/echo-candidate-timeout.ts index e4e016c30b67..e6d66b420cf6 100644 --- a/src/renderer/src/lib/typing-latency/echo-candidate-timeout.ts +++ b/src/renderer/src/lib/typing-latency/echo-candidate-timeout.ts @@ -2,6 +2,24 @@ import type { InstrumentedPane } from './echo-instrumentation' import type { EchoCandidate } from './echo-observation' const ECHO_TIMEOUT_MS = 2000 +export const MAX_PENDING_ECHO_CANDIDATES = 64 + +export function trackIgnoredEchoDispatch( + entry: InstrumentedPane, + candidate: EchoCandidate, + now: number +): void { + if (entry.ignoredDispatches.length === 0) { + entry.deferredNextDispatch = entry.nextDispatch + } + entry.nextDispatch = null + candidate.status = 'unmatched-undispatched' + entry.ignoredDispatches.push(candidate) + if (entry.ignoredDispatches.length > MAX_PENDING_ECHO_CANDIDATES) { + entry.ignoredDispatches.shift() + entry.ignoredDispatchOverflowedAt = now + } +} export function clearEchoDispatchSelection( entry: InstrumentedPane, @@ -15,6 +33,14 @@ export function clearEchoDispatchSelection( } } +export function restoreDeferredEchoDispatch(entry: InstrumentedPane): void { + const deferred = entry.deferredNextDispatch + entry.deferredNextDispatch = null + if (deferred && entry.undispatched.includes(deferred)) { + entry.nextDispatch = deferred + } +} + function drainTimedOutCandidates( candidates: EchoCandidate[], now: number, @@ -37,23 +63,49 @@ function drainTimedOutCandidates( /** Removes inputs whose echo window elapsed and returns the unmatched count. */ export function drainTimedOutEchoCandidates(entry: InstrumentedPane, now: number): number { - let dropped = drainTimedOutCandidates(entry.undispatched, now, (candidate) => + const hadIgnoredDispatches = entry.ignoredDispatches.length > 0 + drainTimedOutCandidates(entry.ignoredDispatches, now) + const overflowExpired = + entry.ignoredDispatchOverflowedAt !== null && + now - entry.ignoredDispatchOverflowedAt > ECHO_TIMEOUT_MS + if (overflowExpired) { + entry.ignoredDispatchOverflowedAt = null + } + if ( + (hadIgnoredDispatches || overflowExpired) && + entry.ignoredDispatches.length === 0 && + entry.ignoredDispatchOverflowedAt === null + ) { + restoreDeferredEchoDispatch(entry) + } + let dropped = drainTimedOutCandidates(entry.undispatched, now, (candidate) => { + candidate.status = 'unmatched-undispatched' clearEchoDispatchSelection(entry, candidate) - ) - const awaitingEchoDropped = drainTimedOutCandidates(entry.awaitingEcho, now) + }) + const awaitingEchoDropped = drainTimedOutCandidates(entry.awaitingEcho, now, (candidate) => { + candidate.status = 'unmatched-dispatched' + }) if (awaitingEchoDropped > 0) { entry.attributionGap = true dropped += awaitingEchoDropped } if (entry.parsingBatch) { - const parsingDropped = drainTimedOutCandidates(entry.parsingBatch.candidates, now) + const parsingDropped = drainTimedOutCandidates( + entry.parsingBatch.candidates, + now, + (candidate) => { + candidate.status = 'unmatched-dispatched' + } + ) if (parsingDropped > 0) { entry.parsingBatch.hasAttributionGap = true dropped += parsingDropped } } for (const batch of entry.parsedBatches) { - const parsedDropped = drainTimedOutCandidates(batch.candidates, now) + const parsedDropped = drainTimedOutCandidates(batch.candidates, now, (candidate) => { + candidate.status = 'unmatched-dispatched' + }) if (parsedDropped > 0) { batch.hasAttributionGap = true dropped += parsedDropped diff --git a/src/renderer/src/lib/typing-latency/echo-instrumentation.test.ts b/src/renderer/src/lib/typing-latency/echo-instrumentation.test.ts index 95dc479e9523..2be3f8cbb8e6 100644 --- a/src/renderer/src/lib/typing-latency/echo-instrumentation.test.ts +++ b/src/renderer/src/lib/typing-latency/echo-instrumentation.test.ts @@ -16,8 +16,8 @@ function emptyEntry(): InstrumentedPane { undispatched: [], nextDispatch: null, deferredNextDispatch: null, - ignoredDispatches: 0, - ignoredDispatchIdentities: [], + ignoredDispatches: [], + ignoredDispatchOverflowedAt: null, awaitingEcho: [], attributionGap: false, parsingBatch: null, @@ -99,8 +99,8 @@ afterEach(() => { describe('recordKeystroke', () => { it('queues inputs rather than overwriting a single slot', () => { const entry = emptyEntry() - expect(recordKeystroke(entry, 0, 'direct')).toBe(0) - expect(recordKeystroke(entry, 5, 'ime')).toBe(0) + expect(recordKeystroke(entry, 0, 'direct').unmatched).toBe(0) + expect(recordKeystroke(entry, 5, 'ime').unmatched).toBe(0) expect(entry.undispatched.map((pending) => pending.t0)).toEqual([0, 5]) expect(entry.pendingCount).toBe(2) }) @@ -109,40 +109,69 @@ describe('recordKeystroke', () => { const entry = emptyEntry() recordKeystroke(entry, 0, 'direct') recordKeystroke(entry, 1, 'direct') - expect(recordKeystroke(entry, 5000, 'direct')).toBe(2) + expect(recordKeystroke(entry, 5000, 'direct').unmatched).toBe(2) expect(entry.pendingCount).toBe(1) expect(entry.attributionGap).toBe(false) }) it('drains a final timed-out input without waiting for another keystroke', () => { const entry = emptyEntry() - recordKeystroke(entry, 0, 'direct') + const recorded = recordKeystroke(entry, 0, 'direct') expect(drainTimedOutEchoCandidates(entry, 2_001)).toBe(1) expect(drainTimedOutEchoCandidates(entry, 2_002)).toBe(0) + expect(recorded.candidate.status).toBe('unmatched-undispatched') + expect(entry.pendingCount).toBe(0) + }) + + it('reverses timeout accounting when an undispatched IME commit settles prevented', () => { + const entry = emptyEntry() + const recorded = recordKeystroke(entry, 0, 'ime', '한') + + expect(drainTimedOutEchoCandidates(entry, 2_001)).toBe(1) + expect(discardUndispatchedKeystroke(entry, recorded.candidate)).toBe('counted-unmatched') + expect(discardUndispatchedKeystroke(entry, recorded.candidate)).toBeNull() + expect(entry).toMatchObject({ pendingCount: 0, ignoredDispatches: [] }) + }) + + it('keeps timeout accounting when the IME commit reached terminal input', () => { + const fake = fakeTerminal() + const entry = instrumentPaneEcho({ terminal: fake.terminal }, () => undefined) + const recorded = recordKeystroke(entry, 0, 'ime', '한') + fake.emitData('한') + + expect(drainTimedOutEchoCandidates(entry, 2_001)).toBe(1) + expect(recorded.candidate.status).toBe('unmatched-dispatched') + expect(discardUndispatchedKeystroke(entry, recorded.candidate)).toBeNull() expect(entry.pendingCount).toBe(0) }) it('bounds pending input state during sustained typing', () => { const entry = emptyEntry() let dropped = 0 + const records: ReturnType[] = [] for (let index = 0; index < 200; index += 1) { - dropped += recordKeystroke(entry, index, 'direct') + const recorded = recordKeystroke(entry, index, 'direct') + dropped += recorded.unmatched + records.push(recorded) } expect(entry.pendingCount).toBe(64) expect(entry.undispatched).toHaveLength(64) + expect(entry.ignoredDispatches).toHaveLength(64) expect(dropped).toBe(136) + expect(discardUndispatchedKeystroke(entry, records[64]!.candidate)).toBe('counted-unmatched') + expect(entry.ignoredDispatches).toHaveLength(64) }) it('drops a prevented commit only when it never dispatched', () => { const fake = fakeTerminal() const entry = instrumentPaneEcho({ terminal: fake.terminal }, () => undefined) - recordKeystroke(entry, 10, 'ime', '한') - expect(discardUndispatchedKeystroke(entry, 10, 'ime')).toBe('pending') + const prevented = recordKeystroke(entry, 10, 'ime', '한') + expect(discardUndispatchedKeystroke(entry, prevented.candidate)).toBe('pending') - recordKeystroke(entry, 20, 'ime', '글') + const dispatched = recordKeystroke(entry, 20, 'ime', '글') fake.emitData('글') - expect(discardUndispatchedKeystroke(entry, 20, 'ime')).toBeNull() + expect(discardUndispatchedKeystroke(entry, dispatched.candidate)).toBeNull() expect(entry.awaitingEcho).toHaveLength(1) }) @@ -165,7 +194,7 @@ describe('recordKeystroke', () => { recordKeystroke(entry, index, 'direct') } - expect(recordKeystroke(entry, 64, 'direct')).toBe(1) + expect(recordKeystroke(entry, 64, 'direct').unmatched).toBe(1) fake.emitData('rejected') expect(entry.undispatched).toHaveLength(64) @@ -174,16 +203,51 @@ describe('recordKeystroke', () => { expect(entry.attributionGap).toBe(true) }) + it('fences overflow dispatches without consuming retained inputs', () => { + const fake = fakeTerminal() + const entry = instrumentPaneEcho({ terminal: fake.terminal }, () => undefined) + for (let index = 0; index < 64; index += 1) { + recordKeystroke(entry, index, 'direct') + } + for (let index = 64; index < 129; index += 1) { + recordKeystroke(entry, index, 'direct') + } + + expect(entry.ignoredDispatches).toHaveLength(64) + expect(entry.ignoredDispatchOverflowedAt).toBe(128) + for (let index = 0; index < 65; index += 1) { + fake.emitData('rejected') + } + + expect(entry.undispatched).toHaveLength(64) + expect(entry).toMatchObject({ + awaitingEcho: [], + pendingCount: 64, + ignoredDispatches: [], + ignoredDispatchOverflowedAt: 128 + }) + expect(drainTimedOutEchoCandidates(entry, 2_129)).toBe(64) + expect(entry).toMatchObject({ + undispatched: [], + pendingCount: 0, + ignoredDispatchOverflowedAt: null + }) + const recovered = recordKeystroke(entry, 2_130, 'direct') + fake.emitData('recovered') + expect(entry.awaitingEcho).toEqual([recovered.candidate]) + }) + it('settles a prevented cap-rejected commit without touching retained inputs', () => { const entry = emptyEntry() for (let index = 0; index < 64; index += 1) { recordKeystroke(entry, index, 'direct') } - expect(recordKeystroke(entry, 64, 'ime', '한')).toBe(1) - expect(discardUndispatchedKeystroke(entry, 64, 'ime')).toBe('counted-unmatched') + const rejected = recordKeystroke(entry, 64, 'ime', '한') + expect(rejected.unmatched).toBe(1) + expect(discardUndispatchedKeystroke(entry, rejected.candidate)).toBe('counted-unmatched') expect(entry.undispatched).toHaveLength(64) - expect(entry.ignoredDispatches).toBe(0) + expect(entry.ignoredDispatches).toEqual([]) expect(entry.attributionGap).toBe(false) }) @@ -193,12 +257,14 @@ describe('recordKeystroke', () => { recordKeystroke(entry, index, 'direct') } - expect(recordKeystroke(entry, 64, 'ime', '한')).toBe(1) - expect(recordKeystroke(entry, 65, 'ime', '글')).toBe(1) - expect(discardUndispatchedKeystroke(entry, 64, 'ime')).toBe('counted-unmatched') - expect(discardUndispatchedKeystroke(entry, 65, 'ime')).toBe('counted-unmatched') + const first = recordKeystroke(entry, 64, 'ime', '한') + const second = recordKeystroke(entry, 65, 'ime', '글') + expect(first.unmatched).toBe(1) + expect(second.unmatched).toBe(1) + expect(discardUndispatchedKeystroke(entry, first.candidate)).toBe('counted-unmatched') + expect(discardUndispatchedKeystroke(entry, second.candidate)).toBe('counted-unmatched') expect(entry.undispatched).toHaveLength(64) - expect(entry.ignoredDispatches).toBe(0) + expect(entry.ignoredDispatches).toEqual([]) expect(entry.attributionGap).toBe(false) }) @@ -208,12 +274,12 @@ describe('recordKeystroke', () => { recordKeystroke(entry, index, 'direct') } - recordKeystroke(entry, 64, 'ime', '한') - recordKeystroke(entry, 64, 'ime', '글') + const first = recordKeystroke(entry, 64, 'ime', '한') + const second = recordKeystroke(entry, 64, 'ime', '글') - expect(discardUndispatchedKeystroke(entry, 64, 'ime')).toBe('counted-unmatched') - expect(discardUndispatchedKeystroke(entry, 64, 'ime')).toBe('counted-unmatched') - expect(entry.ignoredDispatches).toBe(0) + expect(discardUndispatchedKeystroke(entry, first.candidate)).toBe('counted-unmatched') + expect(discardUndispatchedKeystroke(entry, second.candidate)).toBe('counted-unmatched') + expect(entry.ignoredDispatches).toEqual([]) }) }) @@ -431,7 +497,7 @@ describe('instrumentPaneEcho', () => { recordKeystroke(entry, 0, 'direct', 'A') now.mockReturnValueOnce(1) fake.emitData('A') - expect(recordKeystroke(entry, 5_000, 'direct', 'B')).toBe(1) + expect(recordKeystroke(entry, 5_000, 'direct', 'B').unmatched).toBe(1) now.mockReturnValueOnce(5_001) fake.emitData('B') fake.terminal.write('late A') @@ -472,7 +538,7 @@ describe('instrumentPaneEcho', () => { recordKeystroke(entry, 0, 'direct', 'A') now.mockReturnValueOnce(1) fake.emitData('A') - expect(recordKeystroke(entry, 5_000, 'direct', 'B')).toBe(1) + expect(recordKeystroke(entry, 5_000, 'direct', 'B').unmatched).toBe(1) fake.terminal.write('late A') now.mockReturnValueOnce(5_001) fake.emitParsed() diff --git a/src/renderer/src/lib/typing-latency/echo-instrumentation.ts b/src/renderer/src/lib/typing-latency/echo-instrumentation.ts index 03fe933dde0e..bc9268d03836 100644 --- a/src/renderer/src/lib/typing-latency/echo-instrumentation.ts +++ b/src/renderer/src/lib/typing-latency/echo-instrumentation.ts @@ -9,12 +9,20 @@ import { getUtf8ByteLength } from '../../../../shared/utf8-byte-limits' import { subscribeToTerminalUserInput } from '@/components/terminal-pane/terminal-user-input-signal' import type { Terminal } from '@xterm/xterm' -import { clearEchoDispatchSelection, drainTimedOutEchoCandidates } from './echo-candidate-timeout' import { + clearEchoDispatchSelection, + drainTimedOutEchoCandidates, + MAX_PENDING_ECHO_CANDIDATES, + restoreDeferredEchoDispatch, + trackIgnoredEchoDispatch +} from './echo-candidate-timeout' +import { + createEchoCandidate, createEchoObservation, type EchoBatch, type EchoCandidate, - type EchoObservation as EchoObservationValue + type EchoObservation as EchoObservationValue, + type RecordedKeystroke } from './echo-observation' import type { TypingInputSource } from './input-events' import type { ProbePane } from './pane-target' @@ -23,7 +31,8 @@ export type { AmbiguousEchoBurst, EchoObservation, EchoSourceCounts, - ExactEchoSample + ExactEchoSample, + RecordedKeystroke } from './echo-observation' export { findPaneOwningFocus, @@ -42,18 +51,13 @@ export type PreventedKeystrokeDiscard = 'pending' | 'counted-unmatched' | null type PendingKeystroke = EchoCandidate -type IgnoredDispatch = { - t0: number - source: KeystrokeSource -} - export type InstrumentedPane = { pane: ProbePane | null undispatched: PendingKeystroke[] nextDispatch: PendingKeystroke | null deferredNextDispatch: PendingKeystroke | null - ignoredDispatches: number - ignoredDispatchIdentities: IgnoredDispatch[] + ignoredDispatches: PendingKeystroke[] + ignoredDispatchOverflowedAt: number | null awaitingEcho: PendingKeystroke[] attributionGap: boolean parsingBatch: EchoBatch | null @@ -63,73 +67,54 @@ export type InstrumentedPane = { restoreWrite: (() => void) | null } -const MAX_PENDING = 64 - -function restoreDeferredDispatch(entry: InstrumentedPane): void { - const deferred = entry.deferredNextDispatch - entry.deferredNextDispatch = null - if (deferred && entry.undispatched.includes(deferred)) { - entry.nextDispatch = deferred - } -} - /** Returns how many inputs were dropped without a painted output observation. */ export function recordKeystroke( entry: InstrumentedPane, now: number, source: KeystrokeSource, text: string = '' -): number { +): RecordedKeystroke { const dropped = drainTimedOutEchoCandidates(entry, now) - if (entry.pendingCount >= MAX_PENDING) { - if (entry.ignoredDispatches === 0) { - entry.deferredNextDispatch = entry.nextDispatch - } - entry.nextDispatch = null - entry.ignoredDispatches += 1 - entry.ignoredDispatchIdentities.push({ t0: now, source }) - if (entry.ignoredDispatchIdentities.length > MAX_PENDING) { - entry.ignoredDispatchIdentities.shift() - } - return dropped + 1 + const candidate = createEchoCandidate(now, source, text) + if (entry.pendingCount >= MAX_PENDING_ECHO_CANDIDATES) { + trackIgnoredEchoDispatch(entry, candidate, now) + return { candidate, unmatched: dropped + 1 } } - const pending = { t0: now, source, text, dispatchedAt: null } - entry.undispatched.push(pending) - entry.nextDispatch = pending + entry.undispatched.push(candidate) + entry.nextDispatch = candidate entry.pendingCount += 1 - return dropped + return { candidate, unmatched: dropped } } /** Removes a prevented routed commit only if it never reached terminal.onData. */ export function discardUndispatchedKeystroke( entry: InstrumentedPane, - recordedAt: number, - source: KeystrokeSource + candidate: PendingKeystroke ): PreventedKeystrokeDiscard { - for (let index = entry.ignoredDispatchIdentities.length - 1; index >= 0; index -= 1) { - const ignored = entry.ignoredDispatchIdentities[index] - if (!ignored || ignored.t0 !== recordedAt || ignored.source !== source) { - continue + if (candidate.status === 'unmatched-undispatched') { + const index = entry.ignoredDispatches.lastIndexOf(candidate) + if (index !== -1) { + entry.ignoredDispatches.splice(index, 1) } - entry.ignoredDispatchIdentities.splice(index, 1) - entry.ignoredDispatches -= 1 - if (entry.ignoredDispatches === 0) { - restoreDeferredDispatch(entry) + candidate.status = 'prevented' + if (entry.ignoredDispatches.length === 0 && entry.ignoredDispatchOverflowedAt === null) { + restoreDeferredEchoDispatch(entry) } return 'counted-unmatched' } - for (let index = entry.undispatched.length - 1; index >= 0; index -= 1) { - const pending = entry.undispatched[index] - if (!pending || pending.t0 !== recordedAt || pending.source !== source) { - continue - } - entry.undispatched.splice(index, 1) - clearEchoDispatchSelection(entry, pending) - entry.nextDispatch ??= entry.undispatched.at(-1) ?? null - entry.pendingCount -= 1 - return 'pending' + if (candidate.status !== 'undispatched') { + return null } - return null + const index = entry.undispatched.lastIndexOf(candidate) + if (index === -1) { + return null + } + entry.undispatched.splice(index, 1) + clearEchoDispatchSelection(entry, candidate) + entry.nextDispatch ??= entry.undispatched.at(-1) ?? null + entry.pendingCount -= 1 + candidate.status = 'prevented' + return 'pending' } function updateEchoBatch(entry: InstrumentedPane): EchoBatch | null { @@ -164,8 +149,8 @@ export function instrumentPaneEcho( undispatched: [], nextDispatch: null, deferredNextDispatch: null, - ignoredDispatches: 0, - ignoredDispatchIdentities: [], + ignoredDispatches: [], + ignoredDispatchOverflowedAt: null, awaitingEcho: [], attributionGap: false, parsingBatch: null, @@ -199,7 +184,7 @@ export function instrumentPaneEcho( let pendingUserInputSignals = 0 const userInputDisposable = subscribeToTerminalUserInput(terminal as Terminal, () => { - pendingUserInputSignals = Math.min(MAX_PENDING, pendingUserInputSignals + 1) + pendingUserInputSignals = Math.min(MAX_PENDING_ECHO_CANDIDATES, pendingUserInputSignals + 1) }) if (userInputDisposable) { entry.disposables.push(userInputDisposable) @@ -214,16 +199,26 @@ export function instrumentPaneEcho( } pendingUserInputSignals -= 1 } + if (entry.ignoredDispatchOverflowedAt !== null) { + const ignored = entry.ignoredDispatches.pop() + if (ignored) { + ignored.status = 'unmatched-dispatched' + } + entry.attributionGap = true + return + } let pending = entry.nextDispatch if (pending && entry.undispatched.at(-1) === pending) { entry.undispatched.pop() entry.nextDispatch = null - } else if (!pending && entry.ignoredDispatches > 0) { - entry.ignoredDispatches -= 1 - entry.ignoredDispatchIdentities.pop() + } else if (!pending && entry.ignoredDispatches.length > 0) { + const ignored = entry.ignoredDispatches.pop() + if (ignored) { + ignored.status = 'unmatched-dispatched' + } entry.attributionGap = true - if (entry.ignoredDispatches === 0) { - restoreDeferredDispatch(entry) + if (entry.ignoredDispatches.length === 0) { + restoreDeferredEchoDispatch(entry) } return } else { @@ -233,6 +228,7 @@ export function instrumentPaneEcho( if (!pending) { return } + pending.status = 'dispatched' pending.dispatchedAt = performance.now() entry.awaitingEcho.push(pending) }) @@ -288,8 +284,8 @@ export function detachPaneEcho(entry: InstrumentedPane): number { entry.undispatched = [] entry.nextDispatch = null entry.deferredNextDispatch = null - entry.ignoredDispatches = 0 - entry.ignoredDispatchIdentities = [] + entry.ignoredDispatches = [] + entry.ignoredDispatchOverflowedAt = null entry.awaitingEcho = [] entry.attributionGap = false entry.parsingBatch = null diff --git a/src/renderer/src/lib/typing-latency/echo-observation.ts b/src/renderer/src/lib/typing-latency/echo-observation.ts index e9b620ad926d..1a331755d45f 100644 --- a/src/renderer/src/lib/typing-latency/echo-observation.ts +++ b/src/renderer/src/lib/typing-latency/echo-observation.ts @@ -5,6 +5,25 @@ export type EchoCandidate = { source: TypingInputSource text: string dispatchedAt: number | null + status: + | 'undispatched' + | 'dispatched' + | 'unmatched-undispatched' + | 'unmatched-dispatched' + | 'prevented' +} + +export type RecordedKeystroke = { + candidate: EchoCandidate + unmatched: number +} + +export function createEchoCandidate( + t0: number, + source: TypingInputSource, + text: string +): EchoCandidate { + return { t0, source, text, dispatchedAt: null, status: 'undispatched' } } export type EchoBatch = {