fix(terminal): retain only timings in typing diagnostics (#36088)

* fix(terminal): retain only timings in typing diagnostics

* Remove typed text from latency diagnostics and cover task overlap

* Preserve text metadata in diagnostic lifecycle test
This commit is contained in:
Jinjing
2026-10-29 17:11:47 -07:00
committed by GitHub
parent 12b589474c
commit 165f63a02d
10 changed files with 157 additions and 47 deletions
@@ -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] })
@@ -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
@@ -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
@@ -86,10 +86,9 @@ function recordAndDispatch(
entry: InstrumentedPane,
fake: ReturnType<typeof fakeTerminal>,
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()
@@ -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 }
@@ -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<TypingInputSource, number>
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),
@@ -10,7 +10,6 @@ describe('createInputSourceTally', () => {
tally.addObservation({
attribution: 'single-input',
source: 'direct',
text: 'a',
inputToDispatchMs: 1,
dispatchToParseMs: 3,
parseToPaintMs: 4,
@@ -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,
@@ -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<RendererLongTaskLog, 'droppedTasks' | 'incompleteBefore'> = {
droppedTasks: 0,
incompleteBefore: 0
@@ -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,