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 51829579f75..3f8e6c10618 100644 --- a/src/renderer/src/lib/typing-latency/diagnostic-lifecycle.test.ts +++ b/src/renderer/src/lib/typing-latency/diagnostic-lifecycle.test.ts @@ -1,7 +1,9 @@ // @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 * as diagnosticReport from './diagnostic-report' +import { instrumentPaneEcho, type PreventedKeystrokeDiscard } from './echo-instrumentation' +import { createEchoCandidate, createEchoObservation } from './echo-observation' import type { TypingInputRegistration, TypingInputSignal } from './input-events' const mocks = vi.hoisted(() => { @@ -99,6 +101,101 @@ describe('typing latency diagnostic lifecycle', () => { bridge.stop() }) + it('retains echo timings without typed text during and after a diagnostic', () => { + vi.spyOn(console, 'log').mockImplementation(() => undefined) + const buildReport = vi.spyOn(diagnosticReport, 'buildTypingLatencyReport') + const pending = [{ startTime: 90, duration: 100 }] + vi.stubGlobal( + 'PerformanceObserver', + class { + static supportedEntryTypes = ['long-animation-frame'] + observe(): void {} + disconnect(): void {} + takeRecords(): typeof pending { + return pending.splice(0) + } + } + ) + installTypingLatencyDiagnostic() + const bridge = (window as DiagnosticWindow).__orcaTypingDiagnostic + if (!bridge) { + throw new Error('Typing latency diagnostic bridge was not installed') + } + + bridge.start() + const onObservation = vi.mocked(instrumentPaneEcho).mock.lastCall?.[1] + if (!onObservation) { + throw new Error('Pane echo instrumentation was not installed') + } + for (const source of ['direct', 'ime'] as const) { + const observation = createEchoObservation( + { + candidates: [ + { + ...createEchoCandidate(110, source, source === 'direct' ? 100 : null), + dispatchedAt: 120, + arrivedAt: 130 + } + ], + hasAttributionGap: false, + outputBytes: 1, + outputWrites: 1, + firstWriteAt: 140, + parsedAt: 150 + }, + 160 + ) + if (!observation) { + throw new Error('Echo observation was not created') + } + const observationWithText = { ...observation, text: source === 'direct' ? 'a' : '한' } + onObservation(observationWithText) + } + + const runningReport = bridge.report() + expect(runningReport).toMatchObject({ + sampling: { exactInputs: 2 }, + exact: { + inputToPaintMs: { count: 2, p50: 50 }, + eventToPaintMs: { count: 1, p50: 60 } + }, + byInputSource: { direct: { exactInputs: 1 }, ime: { exactInputs: 1 } }, + longTaskOverlap: { + exactSamples: 2, + exactSamplesOverlapped: 2, + overlapMs: { count: 2, p50: 50, p95: 60, max: 60 }, + slowestExactSamples: [ + { + echoMs: 60, + longTaskOverlapMs: 60, + eventToHandlerMs: 10, + inputToDispatchMs: 10, + dispatchToArrivalMs: 10, + arrivalToWriteMs: 10, + writeToParseMs: 10, + parseToPaintMs: 10 + }, + { echoMs: 50, eventToHandlerMs: null, longTaskOverlapMs: 50 } + ] + } + }) + const runningSamples = buildReport.mock.lastCall?.[0]?.exactSamples + expect(runningSamples).toHaveLength(2) + for (const sample of runningSamples ?? []) { + expect(sample).not.toHaveProperty('text') + } + + bridge.stop() + const stoppedReport = bridge.report() + expect(stoppedReport.exact).toEqual(runningReport.exact) + expect(stoppedReport.longTaskOverlap).toEqual(runningReport.longTaskOverlap) + const stoppedSamples = buildReport.mock.lastCall?.[0]?.exactSamples + expect(stoppedSamples).toHaveLength(2) + for (const sample of stoppedSamples ?? []) { + expect(sample).not.toHaveProperty('text') + } + }) + 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] }) diff --git a/src/renderer/src/lib/typing-latency/diagnostic-report.ts b/src/renderer/src/lib/typing-latency/diagnostic-report.ts index 687ea333121..b09624b7c6b 100644 --- a/src/renderer/src/lib/typing-latency/diagnostic-report.ts +++ b/src/renderer/src/lib/typing-latency/diagnostic-report.ts @@ -11,7 +11,7 @@ import { type LatencyPercentiles, type TypingScaleCensus } from './diagnostic-summary' -import { listProbePanes, type ExactEchoSample, type InstrumentedPane } from './echo-instrumentation' +import { listProbePanes, type InstrumentedPane } from './echo-instrumentation' import { emptyInputSourceBreakdown, type InputSourceBreakdown, @@ -19,6 +19,7 @@ import { } from './input-source' import { summarizeLongTaskOverlap, + type LongTaskEchoSample, type LongTaskOverlapReport, type RendererLongTaskLog } from './renderer-long-tasks' @@ -38,7 +39,7 @@ export type ProbeState = { stoppedAt: number | null startedAtIso: string exact: ExactLatencySampleWindow - exactSamples: ExactEchoSample[] + exactSamples: LongTaskEchoSample[] longTasks: RendererLongTaskLog ambiguous: AmbiguousBurstState exactInputs: number diff --git a/src/renderer/src/lib/typing-latency/diagnostic.ts b/src/renderer/src/lib/typing-latency/diagnostic.ts index 57cf2afc7ae..799085db612 100644 --- a/src/renderer/src/lib/typing-latency/diagnostic.ts +++ b/src/renderer/src/lib/typing-latency/diagnostic.ts @@ -38,7 +38,18 @@ function recordObservation(state: ProbeState, observation: EchoObservation): voi if (observation.attribution === 'single-input') { state.exactInputs += 1 appendExactLatencySample(state.exact, observation) - state.exactSamples.push(observation) + state.exactSamples.push({ + startedAt: observation.startedAt, + paintedAt: observation.paintedAt, + inputToPaintMs: observation.inputToPaintMs, + eventToPaintMs: observation.eventToPaintMs, + eventToHandlerMs: observation.eventToHandlerMs, + inputToDispatchMs: observation.inputToDispatchMs, + dispatchToArrivalMs: observation.dispatchToArrivalMs, + arrivalToWriteMs: observation.arrivalToWriteMs, + writeToParseMs: observation.writeToParseMs, + parseToPaintMs: observation.parseToPaintMs + }) if (state.exactSamples.length > TYPING_LATENCY_SAMPLE_LIMIT) { state.exactSamples.shift() } @@ -138,7 +149,6 @@ function startProbe(): string { target, recordedAt, signal.source, - signal.text, readTrustedEventTime(signal.event, recordedAt) ) state.unmatchedKeystrokes += recorded.unmatched 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 39c9e4bff26..3df9b6788c9 100644 --- a/src/renderer/src/lib/typing-latency/echo-instrumentation.test.ts +++ b/src/renderer/src/lib/typing-latency/echo-instrumentation.test.ts @@ -86,10 +86,9 @@ function recordAndDispatch( entry: InstrumentedPane, fake: ReturnType, source: 'direct' | 'ime' = 'direct', - recordedAt: number = performance.now(), - text: string = '' + recordedAt: number = performance.now() ): void { - recordKeystroke(entry, recordedAt, source, text) + recordKeystroke(entry, recordedAt, source) fake.emitData() } @@ -127,7 +126,7 @@ describe('recordKeystroke', () => { it('reverses timeout accounting when an undispatched IME commit settles prevented', () => { const entry = emptyEntry() - const recorded = recordKeystroke(entry, 0, 'ime', '한') + const recorded = recordKeystroke(entry, 0, 'ime') expect(drainTimedOutEchoCandidates(entry, 2_001)).toBe(1) expect(discardUndispatchedKeystroke(entry, recorded.candidate)).toBe('counted-unmatched') @@ -138,7 +137,7 @@ describe('recordKeystroke', () => { 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', '한') + const recorded = recordKeystroke(entry, 0, 'ime') fake.emitData('한') expect(drainTimedOutEchoCandidates(entry, 2_001)).toBe(1) @@ -167,10 +166,10 @@ describe('recordKeystroke', () => { it('drops a prevented commit only when it never dispatched', () => { const fake = fakeTerminal() const entry = instrumentPaneEcho({ terminal: fake.terminal }, () => undefined) - const prevented = recordKeystroke(entry, 10, 'ime', '한') + const prevented = recordKeystroke(entry, 10, 'ime') expect(discardUndispatchedKeystroke(entry, prevented.candidate)).toBe('pending') - const dispatched = recordKeystroke(entry, 20, 'ime', '글') + const dispatched = recordKeystroke(entry, 20, 'ime') fake.emitData('글') expect(discardUndispatchedKeystroke(entry, dispatched.candidate)).toBeNull() expect(entry.awaitingEcho).toHaveLength(1) @@ -179,8 +178,8 @@ describe('recordKeystroke', () => { 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', '한') + recordKeystroke(entry, 10, 'direct') + recordKeystroke(entry, 11, 'ime') fake.emitData('한') fake.emitData('\r') @@ -244,7 +243,7 @@ describe('recordKeystroke', () => { recordKeystroke(entry, index, 'direct') } - const rejected = recordKeystroke(entry, 64, 'ime', '한') + const rejected = recordKeystroke(entry, 64, 'ime') expect(rejected.unmatched).toBe(1) expect(discardUndispatchedKeystroke(entry, rejected.candidate)).toBe('counted-unmatched') expect(entry.undispatched).toHaveLength(64) @@ -258,8 +257,8 @@ describe('recordKeystroke', () => { recordKeystroke(entry, index, 'direct') } - const first = recordKeystroke(entry, 64, 'ime', '한') - const second = recordKeystroke(entry, 65, 'ime', '글') + 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') @@ -275,8 +274,8 @@ describe('recordKeystroke', () => { recordKeystroke(entry, index, 'direct') } - const first = recordKeystroke(entry, 64, 'ime', '한') - const second = recordKeystroke(entry, 64, 'ime', '글') + const first = recordKeystroke(entry, 64, 'ime') + const second = recordKeystroke(entry, 64, 'ime') expect(discardUndispatchedKeystroke(entry, first.candidate)).toBe('counted-unmatched') expect(discardUndispatchedKeystroke(entry, second.candidate)).toBe('counted-unmatched') @@ -290,7 +289,7 @@ describe('instrumentPaneEcho', () => { const entry = instrumentPaneEcho({ terminal }, () => undefined) const coreService = (terminal as unknown as CoreServiceAccess)._core.coreService - recordKeystroke(entry, 10, 'direct', 'a') + recordKeystroke(entry, 10, 'direct') coreService.triggerDataEvent('\x1b[?1;2c', false) expect(entry.undispatched).toHaveLength(1) expect(entry.awaitingEcho).toEqual([]) @@ -311,7 +310,7 @@ describe('instrumentPaneEcho', () => { ) const now = vi.spyOn(performance, 'now') - recordKeystroke(entry, 10, 'direct', 'a', 4) + recordKeystroke(entry, 10, 'direct', 4) now.mockReturnValueOnce(25) fake.emitData('a') noteEchoOutputArrival(entry, 30) @@ -326,7 +325,6 @@ describe('instrumentPaneEcho', () => { { attribution: 'single-input', source: 'direct', - text: 'a', inputToDispatchMs: 15, dispatchToParseMs: 15, parseToPaintMs: 10, @@ -351,7 +349,7 @@ describe('instrumentPaneEcho', () => { observations.push(value) ) - recordAndDispatch(entry, fake, 'ime', performance.now(), '한𠀀') + recordAndDispatch(entry, fake, 'ime') fake.terminal.write('한𠀀') fake.terminal.write(new Uint8Array(6)) fake.emitParsed() @@ -504,10 +502,10 @@ describe('instrumentPaneEcho', () => { ) const now = vi.spyOn(performance, 'now') - recordKeystroke(entry, 0, 'direct', 'A') + recordKeystroke(entry, 0, 'direct') now.mockReturnValueOnce(1) fake.emitData('A') - expect(recordKeystroke(entry, 5_000, 'direct', 'B').unmatched).toBe(1) + expect(recordKeystroke(entry, 5_000, 'direct').unmatched).toBe(1) now.mockReturnValueOnce(5_001) fake.emitData('B') fake.terminal.write('late A') @@ -516,7 +514,7 @@ describe('instrumentPaneEcho', () => { now.mockReturnValueOnce(5_015) fake.emitRender() - recordKeystroke(entry, 5_020, 'ime', '한') + recordKeystroke(entry, 5_020, 'ime') now.mockReturnValueOnce(5_021) fake.emitData('한') fake.terminal.write('한') @@ -532,8 +530,7 @@ describe('instrumentPaneEcho', () => { }) expect(observations[1]).toMatchObject({ attribution: 'single-input', - source: 'ime', - text: '한' + source: 'ime' }) }) @@ -545,10 +542,10 @@ describe('instrumentPaneEcho', () => { ) const now = vi.spyOn(performance, 'now') - recordKeystroke(entry, 0, 'direct', 'A') + recordKeystroke(entry, 0, 'direct') now.mockReturnValueOnce(1) fake.emitData('A') - expect(recordKeystroke(entry, 5_000, 'direct', 'B').unmatched).toBe(1) + expect(recordKeystroke(entry, 5_000, 'direct').unmatched).toBe(1) fake.terminal.write('late A') now.mockReturnValueOnce(5_001) fake.emitParsed() @@ -563,7 +560,7 @@ describe('instrumentPaneEcho', () => { fake.emitRender() expect(observations).toHaveLength(1) - expect(observations[0]).toMatchObject({ attribution: 'single-input', text: 'B' }) + expect(observations[0]).toMatchObject({ attribution: 'single-input', startedAt: 5_000 }) }) it('holds an unparsed input across a render instead of discarding it', () => { @@ -590,7 +587,7 @@ describe('instrumentPaneEcho', () => { observations.push(value) ) - recordAndDispatch(entry, fake, 'direct', 0, 'A') + recordAndDispatch(entry, fake, 'direct', 0) fake.terminal.write('A') fake.emitParsed() @@ -598,13 +595,13 @@ describe('instrumentPaneEcho', () => { expect(drainTimedOutEchoCandidates(entry, 2_002)).toBe(0) expect(entry).toMatchObject({ parsedBatches: [], pendingCount: 0 }) - recordAndDispatch(entry, fake, 'direct', 2_003, 'B') + recordAndDispatch(entry, fake, 'direct', 2_003) fake.terminal.write('B') fake.emitParsed() fake.emitRender() expect(observations).toHaveLength(1) - expect(observations[0]).toMatchObject({ attribution: 'single-input', text: 'B' }) + expect(observations[0]).toMatchObject({ attribution: 'single-input', startedAt: 2_003 }) expect(entry.pendingCount).toBe(0) }) @@ -615,11 +612,11 @@ describe('instrumentPaneEcho', () => { observations.push(value) ) - recordAndDispatch(entry, fake, 'direct', 0, 'A') + recordAndDispatch(entry, fake, 'direct', 0) fake.terminal.write('late A') expect(drainTimedOutEchoCandidates(entry, 2_001)).toBe(1) - recordAndDispatch(entry, fake, 'direct', 2_002, 'B') + recordAndDispatch(entry, fake, 'direct', 2_002) fake.terminal.write('B') fake.emitParsed() fake.emitRender() diff --git a/src/renderer/src/lib/typing-latency/echo-instrumentation.ts b/src/renderer/src/lib/typing-latency/echo-instrumentation.ts index c7a61bccb2b..e32540e15a2 100644 --- a/src/renderer/src/lib/typing-latency/echo-instrumentation.ts +++ b/src/renderer/src/lib/typing-latency/echo-instrumentation.ts @@ -65,11 +65,10 @@ export function recordKeystroke( entry: InstrumentedPane, now: number, source: KeystrokeSource, - text: string = '', eventAt: number | null = null ): RecordedKeystroke { const dropped = drainTimedOutEchoCandidates(entry, now) - const candidate = createEchoCandidate(now, source, text, eventAt) + const candidate = createEchoCandidate(now, source, eventAt) if (entry.pendingCount >= MAX_PENDING_ECHO_CANDIDATES) { trackIgnoredEchoDispatch(entry, candidate, now) return { candidate, unmatched: dropped + 1 } diff --git a/src/renderer/src/lib/typing-latency/echo-observation.ts b/src/renderer/src/lib/typing-latency/echo-observation.ts index d64e4a3c588..0d734e5fc7c 100644 --- a/src/renderer/src/lib/typing-latency/echo-observation.ts +++ b/src/renderer/src/lib/typing-latency/echo-observation.ts @@ -5,7 +5,6 @@ export type EchoCandidate = { /** Trusted DOM event timestamp; the gap to t0 is time the input waited behind other renderer work. */ eventAt: number | null source: TypingInputSource - text: string dispatchedAt: number | null /** First PTY output handed to the renderer's output scheduler after dispatch. */ arrivedAt: number | null @@ -25,14 +24,12 @@ export type RecordedKeystroke = { export function createEchoCandidate( t0: number, source: TypingInputSource, - text: string, eventAt: number | null = null ): EchoCandidate { return { t0, eventAt, source, - text, dispatchedAt: null, arrivedAt: null, status: 'undispatched' @@ -53,7 +50,6 @@ export type EchoSourceCounts = Record export type ExactEchoSample = { attribution: 'single-input' source: TypingInputSource - text: string inputToDispatchMs: number dispatchToParseMs: number parseToPaintMs: number @@ -111,7 +107,6 @@ export function createEchoObservation(batch: EchoBatch, paintedAt: number): Echo 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), diff --git a/src/renderer/src/lib/typing-latency/input-source.test.ts b/src/renderer/src/lib/typing-latency/input-source.test.ts index 8bad5a121ae..b315b44c978 100644 --- a/src/renderer/src/lib/typing-latency/input-source.test.ts +++ b/src/renderer/src/lib/typing-latency/input-source.test.ts @@ -10,7 +10,6 @@ describe('createInputSourceTally', () => { tally.addObservation({ attribution: 'single-input', source: 'direct', - text: 'a', inputToDispatchMs: 1, dispatchToParseMs: 3, parseToPaintMs: 4, diff --git a/src/renderer/src/lib/typing-latency/renderer-long-tasks.test.ts b/src/renderer/src/lib/typing-latency/renderer-long-tasks.test.ts index 48eeee420b6..c62079ba61f 100644 --- a/src/renderer/src/lib/typing-latency/renderer-long-tasks.test.ts +++ b/src/renderer/src/lib/typing-latency/renderer-long-tasks.test.ts @@ -10,7 +10,6 @@ function sample(startedAt: number, paintedAt: number): ExactEchoSample { return { attribution: 'single-input', source: 'direct', - text: 'a', inputToDispatchMs: 0, dispatchToParseMs: 0, parseToPaintMs: 0, diff --git a/src/renderer/src/lib/typing-latency/renderer-long-tasks.ts b/src/renderer/src/lib/typing-latency/renderer-long-tasks.ts index c05e52e28f7..916c10b3d3d 100644 --- a/src/renderer/src/lib/typing-latency/renderer-long-tasks.ts +++ b/src/renderer/src/lib/typing-latency/renderer-long-tasks.ts @@ -6,6 +6,20 @@ const LONG_TASK_LIMIT = 500 const SLOWEST_SAMPLE_LIMIT = 10 const SCRIPTS_PER_TASK = 3 +export type LongTaskEchoSample = Pick< + ExactEchoSample, + | 'startedAt' + | 'paintedAt' + | 'inputToPaintMs' + | 'eventToPaintMs' + | 'eventToHandlerMs' + | 'inputToDispatchMs' + | 'dispatchToArrivalMs' + | 'arrivalToWriteMs' + | 'writeToParseMs' + | 'parseToPaintMs' +> + export type RendererLongTaskSource = 'long-animation-frame' | 'longtask' | 'unavailable' export type RendererLongTaskScript = { @@ -152,7 +166,7 @@ export type LongTaskOverlapReport = { export function summarizeLongTaskOverlap( source: RendererLongTaskSource, tasks: readonly RendererLongTask[], - samples: readonly ExactEchoSample[], + samples: readonly LongTaskEchoSample[], history: Pick = { droppedTasks: 0, incompleteBefore: 0 diff --git a/src/renderer/src/lib/typing-latency/sample-window.test.ts b/src/renderer/src/lib/typing-latency/sample-window.test.ts index e83f2864d1b..93674d5233a 100644 --- a/src/renderer/src/lib/typing-latency/sample-window.test.ts +++ b/src/renderer/src/lib/typing-latency/sample-window.test.ts @@ -7,7 +7,6 @@ function exactSample(value: number): ExactEchoSample { return { attribution: 'single-input', source: 'direct', - text: 'a', inputToDispatchMs: value, dispatchToParseMs: value + 10000, parseToPaintMs: value + 20000,