From 1e87c292dcc0af1b434a1d07bd24fd5275ca0037 Mon Sep 17 00:00:00 2001 From: Dmytro Harastovych Date: Mon, 20 Jul 2026 21:33:50 +0300 Subject: [PATCH 01/15] docs: design input latency profiling --- ...26-07-20-input-latency-profiling-design.md | 308 ++++++++++++++++++ 1 file changed, 308 insertions(+) create mode 100644 docs/superpowers/specs/2026-07-20-input-latency-profiling-design.md diff --git a/docs/superpowers/specs/2026-07-20-input-latency-profiling-design.md b/docs/superpowers/specs/2026-07-20-input-latency-profiling-design.md new file mode 100644 index 0000000000..6fe1683aec --- /dev/null +++ b/docs/superpowers/specs/2026-07-20-input-latency-profiling-design.md @@ -0,0 +1,308 @@ +# Input Latency Profiling Design + +## Context + +Typing in the paginated presentation editor is measurably slower than the +underlying input dispatch. On the 7-page `large-typing-test.docx` fixture, a +main-branch browser run completed each typing action in 35–40 ms while the +painted document reflected the character after 128–152 ms. Earlier Event +Timing profiling reported a 76 ms median and 120 ms p95. The measurements use +different clocks, but both show that a substantial part of user-visible delay +occurs after the input transaction starts. + +The current pipeline exposes only partial evidence: + +- `Editor` reports total transaction duration. +- `PresentationEditor` can print several independent `SD_DEBUG_LAYOUT` logs. +- `layoutUpdated.metrics.durationMs` reports the total rerender duration. +- `PerformanceMetricsCollector` exists in `layout-bridge`, but is not connected + to the real presentation-editor typing path. + +None of these signals correlates one visible `beforeinput` with the transaction, +coalesced render, DOM paint, and following browser frame. As a result, the +repository cannot produce a reproducible baseline, explain where the latency is +spent, or demonstrate that a later optimization improved the user-visible +result. + +## Goals + +1. Correlate supported typing inputs with the complete path from the visible + editing surface to the next browser frame after DOM paint. +2. Break the path into actionable phases: input dispatch, transaction, + render scheduling, projection, layout, paint, and post-paint work. +3. Emit standard User Timing entries that are visible in Chrome Performance + traces and readable through `PerformanceObserver`. +4. Provide a repeatable profiling harness that records raw samples and summary + statistics in a versioned JSON artifact. +5. Make baseline and after-result reports directly comparable and reject + mismatched fixture, environment, or scenario configurations. +6. Avoid collecting samples, allocating trace records, or changing behavior + unless profiling is explicitly enabled. + +## Non-goals + +- This work does not optimize layout, projection, painting, or input behavior. +- It does not add production analytics or transmit performance data. +- It does not establish a CI latency gate; host contention makes wall-clock + browser latency unsuitable for an initial mandatory gate. +- It does not profile remote collaboration updates, programmatic document + mutations, or IME composition in the first version. +- It does not add the local `large-typing-test.docx` fixture to the repository. + +## Selected Approach + +Use an internal, opt-in profiler in `@superdoc/super-editor` that emits +`performance.mark()` and `performance.measure()` entries. A separate Chromium +profiling harness drives the SuperDoc Labs page, collects those entries, and +writes a versioned JSON report. + +Standard User Timing was selected over a new public SuperDoc metrics API because +it integrates with browser tooling, carries no new supported public contract, +and can be consumed both manually and automatically. A browser-only benchmark +was rejected because it could report the symptom but not attribute the time to +pipeline phases. The disconnected `layout-bridge` collector will not be reused: +input ownership and render orchestration belong to `super-editor`, and moving +typing state into `layout-bridge` would violate that boundary. + +## Architecture + +### 1. Opt-in profiler + +Add a focused internal profiler under the presentation-editor performance +folder. `PresentationEditor` creates it only when +`SD_DEBUG_INPUT_LATENCY` is enabled. When the flag is disabled, no trace object, +sample array, mark, or measure is created. Call sites may perform only a cheap +null check. + +The profiler owns: + +- monotonically increasing input and render IDs; +- pending input traces waiting for a document transaction; +- active render traces, including all inputs coalesced into that render; +- stage start/end timestamps; +- User Timing entry creation and mark cleanup; +- bounded cleanup for abandoned or incomplete traces. + +The profiler is diagnostic infrastructure. It must never throw into the editor +pipeline. Unsupported or incomplete measurements are skipped, with at most one +debug warning when profiling is explicitly enabled. + +### 2. Input and transaction correlation + +`PresentationInputBridge` records the original visible-surface `beforeinput` +before its existing microtask deferral. The first version records non-composing +`insertText` inputs used by the controlled benchmark. The profiler assigns an +input ID and queues the trace. + +The next document-changing `Editor` transaction consumes the oldest unmatched +input trace. The existing transaction-event duration is recorded without +re-measuring transaction internals. Transactions with no pending supported +input are ignored by the typing profiler. + +If multiple inputs arrive before the scheduled render begins, they are attached +to the same render ID. The render phase durations are shared, while each input +retains its own input-to-render and end-to-end duration. This preserves the +actual coalescing behavior rather than pretending that every keypress caused an +independent layout. + +### 3. Render phase instrumentation + +The profiler records these boundaries in `PresentationEditor`: + +1. visible `beforeinput`; +2. transaction completion and transaction duration; +3. render scheduled; +4. scheduled render callback started; +5. `getJSON`; +6. position-map construction; +7. `toFlowBlocks` projection; +8. font readiness/planning; +9. `incrementalLayout`; +10. `resolveLayout` and header/footer resolution; +11. `DomPainter.paint`; +12. post-paint DOM augmentation; +13. `layoutUpdated` emission; +14. the next animation-frame callback after DOM paint. + +The final animation-frame timestamp is a stable next-frame proxy, not a claim +that JavaScript can observe the physical display scanout. Baseline and after +runs use the same proxy, so relative comparisons remain valid. The report keeps +both `inputToDomPaintMs` and `inputToNextFrameMs` so optimization work can +distinguish DOM completion from frame scheduling. + +### 4. User Timing records + +Unique marks use input/render IDs internally and are cleared when a trace +finishes. Measures use stable names so DevTools and `PerformanceObserver` can +aggregate them, for example: + +- `superdoc.input-latency.total`; +- `superdoc.input-latency.input-to-transaction`; +- `superdoc.input-latency.raf-wait`; +- `superdoc.input-latency.get-json`; +- `superdoc.input-latency.position-map`; +- `superdoc.input-latency.to-flow-blocks`; +- `superdoc.input-latency.font-readiness`; +- `superdoc.input-latency.incremental-layout`; +- `superdoc.input-latency.resolve-layout`; +- `superdoc.input-latency.paint`; +- `superdoc.input-latency.post-paint`; +- `superdoc.input-latency.input-to-dom-paint`; +- `superdoc.input-latency.input-to-next-frame`. + +Each completed entry carries structured detail containing the schema version, +input ID, render ID, input type, coalesced-input count, document size, block +count, and page count. Raw text and document content are never included. + +## Profiling Harness + +Add a developer-only Chromium harness under `devtools/input-latency/`. It is not +part of the normal test suite. The harness accepts: + +- SuperDoc Labs URL; +- absolute fixture path; +- output label and output directory; +- CPU throttling rates; +- warm-up and measured-run counts; +- keystroke sequence and cadence. + +The harness uploads the fixture, waits for the expected stable document state, +focuses a deterministic body position, performs controlled real keyboard input, +collects User Timing entries, validates the sample set, and writes JSON. CPU +throttling uses a Chromium DevTools Protocol session; unsupported browsers fail +with an actionable error rather than silently running an incomparable scenario. + +Generated profiling artifacts are gitignored. The harness has separate record +and compare operations. Compare reads two reports, validates their fingerprints, +and produces machine-readable deltas plus a compact Markdown table suitable for +a pull-request description. The default output directory is +`devtools/input-latency/results/`. + +## Result Schema + +Every report includes: + +- schema version and label; +- timestamp; +- git SHA and clean/dirty status; +- operating system, architecture, browser version, logical CPU count, and + available browser memory metadata when exposed; +- fixture SHA-256 and byte size; +- URL, layout mode, zoom, document mode, page count, and block count; +- exact warm-up, run, keystroke, cadence, and CPU-throttle configuration; +- raw trace samples for every phase; +- count, minimum, average, p50, p95, p99, and maximum for every metric; +- discarded/incomplete trace counts and reasons. + +The immediate local fixture fingerprint is: + +```text +sha256=f73a0f320aa78c00d13fbadecfd2906a7f12dc95a00b306c4f0a6a18afaad277 +size=280245 +``` + +The path is intentionally absent from the comparison fingerprint so reports +remain comparable if the identical file is stored elsewhere. + +## Baseline and After Protocol + +The instrumentation-only commit is the baseline code revision. No optimization +is included in that commit. Baseline artifacts are captured before optimization +work starts; later optimization commits run the identical harness. + +Three scenarios are recorded: + +1. layout enabled at normal CPU speed; +2. layout enabled with 4x CPU slowdown; +3. layout disabled at normal CPU speed as the ProseMirror control group. + +Each scenario uses one excluded warm-up run followed by five measured runs. All +runs reload the fixture and place the caret at the end of the first non-empty +body paragraph. A run types 40 lowercase ASCII characters with a 100 ms +inter-key cadence, producing 200 measured input samples per scenario. The exact +sequence is stored in the scenario fingerprint. The JSON retains raw +measurements so summaries can be recomputed without rerunning the browser. + +The primary metric is p95 `inputToNextFrameMs` in the 4x CPU scenario. Secondary +metrics are normal-CPU p50/p95 and all phase p50/p95 values. An optimization is +not described as faster unless: + +- baseline and after fingerprints match; +- all expected samples completed without profiler errors; +- the p95 improvement exceeds observed run-to-run variation; +- 4x CPU p95 improves; +- normal-CPU p50 and p95 do not regress beyond observed variation. + +For this initial investigation, observed variation is the median absolute +deviation of the five run-level p95 values. A p95 change is material only when +its absolute value exceeds both 5 ms and twice the larger baseline/after median +absolute deviation. The same rule detects a normal-CPU regression. No fixed +percentage target is imposed before root-cause data exists. The comparison +report presents absolute milliseconds, percentage delta, the run-level values, +and their median absolute deviation so the reviewer can distinguish a material +improvement from measurement noise. + +## Error Handling and Data Integrity + +- Profiling failures cannot interrupt editing or layout. +- Abandoned traces are finalized as discarded with a reason and removed from + pending state. +- Destroying the editor clears marks, scheduled frame callbacks, and trace + state. +- The harness fails if the fixture hash changes, expected page/block counts are + unstable, samples are missing, the page emits an unhandled error, or CPU + throttling cannot be applied. +- Comparison fails on schema, fixture, scenario, cadence, layout-mode, browser, + or CPU-throttle mismatch. It does not silently compare partial scenarios. +- Raw document content, typed surrounding text, and user data are excluded from + reports. + +## Testing Strategy + +### Profiler unit tests + +- disabled mode creates no marks or traces; +- a supported input correlates with the next document transaction; +- multiple inputs correctly share one coalesced render; +- stage measures use the correct start/end boundaries; +- incomplete and destroyed traces are cleaned up; +- User Timing failure remains non-fatal; +- composing and unsupported input types are ignored in the first version. + +Tests inject fake performance and animation-frame clocks. They assert exact +durations and do not use wall-clock thresholds. + +### PresentationEditor integration tests + +- the input bridge records the timestamp before microtask forwarding; +- transaction duration is forwarded to the profiler; +- one scheduled rerender receives all pending supported inputs; +- paint and next-frame completion finalize all attached inputs; +- profiler hooks are absent when the debug flag is disabled. + +### Harness and comparison tests + +- percentile calculation and result serialization are deterministic; +- fixture and scenario fingerprint mismatches fail comparison; +- equivalent reports compare successfully; +- Markdown output reports baseline, after, absolute delta, and percentage delta; +- incomplete scenarios cannot be presented as an improvement. + +### Manual verification + +Run the harness against `large-typing-test.docx`, inspect the User Timing lanes +in Chrome Performance, save the baseline JSON, and confirm that rerunning the +same baseline produces variation small enough to support later comparison. + +## Delivery Sequence + +1. Implement and test the internal profiler and User Timing records. +2. Implement and test the record/compare harness. +3. Commit instrumentation without an optimization. +4. Capture and preserve normal, 4x CPU, and layout-off baseline artifacts. +5. Use phase evidence to state one root-cause hypothesis. +6. Test one minimal optimization in a separate commit. +7. Capture after artifacts and generate the PR comparison table. + +This sequence keeps measurement infrastructure, baseline evidence, and the +eventual optimization reviewable as separate decisions. From 25c8ac6d9a953d8f68f05bbd6c3df17c31716517 Mon Sep 17 00:00:00 2001 From: Dmytro Harastovych Date: Mon, 20 Jul 2026 21:54:07 +0300 Subject: [PATCH 02/15] docs: plan input latency profiling --- .../2026-07-20-input-latency-profiling.md | 1143 +++++++++++++++++ ...26-07-20-input-latency-profiling-design.md | 9 +- 2 files changed, 1149 insertions(+), 3 deletions(-) create mode 100644 docs/superpowers/plans/2026-07-20-input-latency-profiling.md diff --git a/docs/superpowers/plans/2026-07-20-input-latency-profiling.md b/docs/superpowers/plans/2026-07-20-input-latency-profiling.md new file mode 100644 index 0000000000..1a161964c2 --- /dev/null +++ b/docs/superpowers/plans/2026-07-20-input-latency-profiling.md @@ -0,0 +1,1143 @@ +# Input Latency Profiling Implementation Plan + +> **For agentic workers:** REQUIRED SUB-SKILL: Use superpowers:subagent-driven-development (recommended) or superpowers:executing-plans to implement this plan task-by-task. Steps use checkbox (`- [ ]`) syntax for tracking. + +**Goal:** Build opt-in, phase-level typing instrumentation plus a reproducible Chromium recorder/comparator, then capture a trustworthy baseline before attempting any latency optimization. + +**Architecture:** An internal `InputLatencyProfiler` in `@superdoc/super-editor` correlates visible `beforeinput`, Editor transactions, coalesced presentation renders, phase timings, DOM paint, and the following animation frame through standard User Timing entries. A developer-only Playwright harness records raw entries and environment metadata, validates scenario fingerprints, writes gitignored JSON, and compares baseline/after reports. + +**Tech Stack:** TypeScript, Vitest, User Timing API, Node.js test runner, Playwright/Chromium, Chrome DevTools Protocol, pnpm. + +## Global Constraints + +- Keep all work on `codex/input-latency-profiling`; do not commit to or push `main`. +- Do not implement a latency optimization in this plan. Instrument, record, and identify one evidence-backed root-cause hypothesis first. +- Do not add a public SuperDoc API or import a concrete layout adapter into `layout-engine`. +- Keep input ownership and render orchestration in `@superdoc/super-editor`. +- Enable profiling only when `process.env.SD_DEBUG_INPUT_LATENCY` is `1`/`true` or `globalThis.__SD_DEBUG_INPUT_LATENCY__ === true` before editor construction. +- When disabled, create no profiler, trace records, marks, measures, timers, or sample arrays; call sites may perform one null check. +- Never transmit profiling data or include document text in User Timing details or JSON reports. +- Initial supported input is non-composing `beforeinput` with `inputType === "insertText"`. +- Generated reports live in `devtools/input-latency/results/` and remain gitignored. +- Use the local fixture only by path; do not copy it into the repository. Expected SHA-256 is `f73a0f320aa78c00d13fbadecfd2906a7f12dc95a00b306c4f0a6a18afaad277` and size is `280245` bytes. +- Baseline protocol is one excluded warm-up run plus five measured runs of 40 lowercase ASCII characters at 100 ms cadence for normal CPU, 4x CPU slowdown, and layout-off control. +- Primary metric is 4x-CPU p95 `inputToNextFrameMs`; raw samples, run-level p95 values, and median absolute deviation must be retained. + +--- + +## File Map + +- Create `packages/super-editor/src/editors/v1/core/presentation-editor/performance/InputLatencyProfiler.ts`: opt-in trace lifecycle, User Timing emission, coalescing, cleanup. +- Create `packages/super-editor/src/editors/v1/core/presentation-editor/performance/InputLatencyProfiler.test.ts`: deterministic fake-clock unit tests. +- Modify `packages/super-editor/src/editors/v1/core/presentation-editor/input/PresentationInputBridge.ts`: call an optional pre-forward `onBeforeInput` hook. +- Modify `packages/super-editor/src/editors/v1/core/presentation-editor/tests/PresentationInputBridge.test.ts`: prove the hook runs once before microtask forwarding. +- Modify `packages/super-editor/src/editors/v1/core/presentation-editor/PresentationEditor.ts`: create the profiler, correlate transaction/update/render events, record phases, and clean up. +- Modify `packages/super-editor/src/editors/v1/core/presentation-editor/tests/PresentationEditor.test.ts`: integration coverage for disabled mode, correlation, coalescing, and completion. +- Create `devtools/input-latency/report.mjs`: result schema, statistics, fingerprint validation, comparison, Markdown rendering. +- Create `devtools/input-latency/report.test.mjs`: deterministic report/comparison tests. +- Create `devtools/input-latency/profile.mjs`: Playwright recorder CLI and layout-off control probe. +- Create `devtools/input-latency/compare.mjs`: JSON comparison CLI. +- Create `devtools/input-latency/README.md`: exact record/compare workflow. +- Modify `package.json`: add profiling scripts and an explicit `playwright` development dependency. +- Modify `pnpm-lock.yaml`: record the root Playwright importer. +- Modify `.gitignore`: ignore `devtools/input-latency/results/`. + +--- + +### Task 1: Internal Input Latency Profiler + +**Files:** +- Create: `packages/super-editor/src/editors/v1/core/presentation-editor/performance/InputLatencyProfiler.ts` +- Create: `packages/super-editor/src/editors/v1/core/presentation-editor/performance/InputLatencyProfiler.test.ts` + +**Interfaces:** +- Consumes: browser `Performance`, `requestAnimationFrame`, and `cancelAnimationFrame` supplied through `InputLatencyRuntime`. +- Produces: `createInputLatencyProfiler(windowLike): InputLatencyProfiler | null` and methods `recordBeforeInput`, `recordTransaction`, `recordRenderScheduled`, `beginRender`, `recordStage`, `recordDomPaint`, `completeAfterNextFrame`, `abortRender`, and `destroy`. +- Produces stable measures prefixed by `superdoc.input-latency.` with `InputLatencyMeasureDetail` in `PerformanceMeasure.detail`. + +- [ ] **Step 1: Write failing fake-clock tests** + +Create tests covering disabled creation, one input, two coalesced inputs, exact stage durations, ignored composing/unsupported input, aborted traces, User Timing exceptions, and destroy cleanup. Use this test fixture: + +```ts +import { describe, expect, it, vi } from 'vitest'; +import { + createInputLatencyProfiler, + InputLatencyProfiler, + type InputLatencyRuntime, +} from './InputLatencyProfiler.js'; + +function makeRuntime() { + let now = 0; + let nextFrameId = 1; + const frameCallbacks = new Map(); + const performance = { + now: vi.fn(() => now), + mark: vi.fn(), + measure: vi.fn(), + clearMarks: vi.fn(), + } as unknown as Performance; + const runtime: InputLatencyRuntime = { + performance, + requestAnimationFrame: vi.fn((callback) => { + const id = nextFrameId++; + frameCallbacks.set(id, callback); + return id; + }), + cancelAnimationFrame: vi.fn((id) => frameCallbacks.delete(id)), + }; + return { + runtime, + performance, + advance(ms: number) { + now += ms; + }, + flushFrame() { + const callbacks = [...frameCallbacks.entries()]; + frameCallbacks.clear(); + callbacks.forEach(([, callback]) => callback(now)); + }, + }; +} + +describe('InputLatencyProfiler', () => { + it('emits one total measure per input and shares a coalesced render', () => { + const clock = makeRuntime(); + const profiler = new InputLatencyProfiler(clock.runtime); + + profiler.recordBeforeInput({ inputType: 'insertText', isComposing: false }); + clock.advance(4); + profiler.recordTransaction(3); + profiler.recordRenderScheduled(); + + profiler.recordBeforeInput({ inputType: 'insertText', isComposing: false }); + clock.advance(5); + profiler.recordTransaction(2); + profiler.recordRenderScheduled(); + + clock.advance(7); + const renderId = profiler.beginRender(); + expect(renderId).not.toBeNull(); + profiler.recordStage(renderId!, 'get-json', 16, 19); + profiler.recordDomPaint(renderId!, 35); + profiler.completeAfterNextFrame(renderId!, { + documentSize: 24000, + blockCount: 680, + pageCount: 7, + }); + clock.advance(16); + clock.flushFrame(); + + const totalCalls = vi.mocked(clock.performance.measure).mock.calls.filter( + ([name]) => name === 'superdoc.input-latency.total', + ); + expect(totalCalls).toHaveLength(2); + expect(totalCalls[0]?.[1]).toMatchObject({ detail: { renderId, coalescedInputCount: 2 } }); + }); +}); +``` + +- [ ] **Step 2: Run the focused test and confirm RED** + +Run: + +```bash +pnpm --filter @superdoc/super-editor test --run src/editors/v1/core/presentation-editor/performance/InputLatencyProfiler.test.ts +``` + +Expected: FAIL because `InputLatencyProfiler.js` does not exist. + +- [ ] **Step 3: Implement the profiler contract** + +Implement these exact public types and methods: + +```ts +export const INPUT_LATENCY_PREFIX = 'superdoc.input-latency'; +export const INPUT_LATENCY_SCHEMA_VERSION = 1; + +export type InputLatencyStage = + | 'get-json' + | 'position-map' + | 'to-flow-blocks' + | 'font-readiness' + | 'incremental-layout' + | 'resolve-layout' + | 'header-footer' + | 'paint' + | 'post-paint'; + +export type InputLatencyRuntime = { + performance: Pick; + requestAnimationFrame: (callback: FrameRequestCallback) => number; + cancelAnimationFrame: (handle: number) => void; + warn?: (message: string) => void; +}; + +export type InputLatencyContext = { + documentSize: number; + blockCount: number; + pageCount: number; +}; + +export type InputLatencyMeasureDetail = InputLatencyContext & { + schemaVersion: 1; + inputId: number; + renderId: number; + inputType: 'insertText'; + coalescedInputCount: number; +}; + +type InputTrace = { + id: number; + inputType: 'insertText'; + startedAt: number; + transactionEndedAt?: number; + transactionDurationMs?: number; +}; + +type RenderTrace = { + id: number; + scheduledAt: number; + startedAt?: number; + domPaintedAt?: number; + inputTraces: InputTrace[]; + stages: Map; +}; + +export class InputLatencyProfiler { + constructor(runtime: InputLatencyRuntime); + recordBeforeInput(input: { inputType: string; isComposing: boolean }): number | null; + recordTransaction(durationMs: number): void; + recordRenderScheduled(): number | null; + beginRender(): number | null; + recordStage(renderId: number, stage: InputLatencyStage, start: number, end: number): void; + recordDomPaint(renderId: number, at: number): void; + completeAfterNextFrame(renderId: number, context: InputLatencyContext): void; + abortRender(renderId: number, reason: string): void; + destroy(): void; +} + +export function createInputLatencyProfiler(windowLike: Window): InputLatencyProfiler | null; +``` + +Implementation rules: + +```ts +const MAX_TRACE_AGE_MS = 10_000; +const MAX_PENDING_INPUTS = 200; + +function isEnabled(windowLike: Window): boolean { + const debugGlobal = windowLike as Window & { __SD_DEBUG_INPUT_LATENCY__?: boolean }; + const envValue = + typeof process !== 'undefined' && typeof process.env !== 'undefined' + ? process.env.SD_DEBUG_INPUT_LATENCY + : undefined; + return debugGlobal.__SD_DEBUG_INPUT_LATENCY__ === true || envValue === '1' || envValue === 'true'; +} + +export function createInputLatencyProfiler(windowLike: Window): InputLatencyProfiler | null { + if (!isEnabled(windowLike)) return null; + return new InputLatencyProfiler({ + performance: windowLike.performance, + requestAnimationFrame: windowLike.requestAnimationFrame.bind(windowLike), + cancelAnimationFrame: windowLike.cancelAnimationFrame.bind(windowLike), + warn: (message) => console.warn(message), + }); +} +``` + +Use FIFO matching for `recordTransaction`. `recordRenderScheduled` moves all transaction-complete inputs into the existing scheduled render or creates a new one. `beginRender` moves the scheduled render into an active map. `completeAfterNextFrame` requests one frame, emits one set of measures per input, then clears unique marks and active state. Emit `superdoc.input-latency.discarded` with `{ reason }` when pruning, aborting, or destroying incomplete traces. Wrap every `mark`, `measure`, and warning call in a non-throwing helper. + +- [ ] **Step 4: Run the profiler tests and confirm GREEN** + +Run the focused test command from Step 2. + +Expected: all profiler tests PASS with exact fake-clock durations and no wall-clock assertions. + +- [ ] **Step 5: Commit the profiler core** + +```bash +git add packages/super-editor/src/editors/v1/core/presentation-editor/performance/InputLatencyProfiler.ts packages/super-editor/src/editors/v1/core/presentation-editor/performance/InputLatencyProfiler.test.ts +git commit -m "feat(super-editor): add input latency profiler" +``` + +--- + +### Task 2: Capture Visible `beforeinput` Before Microtask Forwarding + +**Files:** +- Modify: `packages/super-editor/src/editors/v1/core/presentation-editor/input/PresentationInputBridge.ts:18-70,401-449` +- Modify: `packages/super-editor/src/editors/v1/core/presentation-editor/tests/PresentationInputBridge.test.ts` + +**Interfaces:** +- Consumes: optional constructor option `onBeforeInput`. +- Produces: exactly one synchronous callback for eligible visible-surface `beforeinput`, before the existing `queueMicrotask(dispatchSyntheticEvent)`. + +- [ ] **Step 1: Add failing ordering and filtering tests** + +Add tests that instantiate the bridge with this option: + +```ts +const calls: string[] = []; +bridge.destroy(); +bridge = new PresentationInputBridge(windowRoot, layoutSurface, getTargetDom, isEditable, undefined, { + onBeforeInput: ({ inputType, isComposing }) => { + calls.push(`hook:${inputType}:${isComposing}`); + }, +}); +targetDom.addEventListener('beforeinput', () => calls.push('forwarded')); +bridge.bind(); + +layoutSurface.dispatchEvent( + new InputEvent('beforeinput', { + data: 'a', + inputType: 'insertText', + bubbles: true, + cancelable: true, + }), +); + +expect(calls).toEqual(['hook:insertText:false']); +await Promise.resolve(); +expect(calls).toEqual(['hook:insertText:false', 'forwarded']); +``` + +Add these filtering cases beside the ordering test: + +```ts +it.each(['input', 'textInput'])('does not profile %s events', async (eventType) => { + layoutSurface.dispatchEvent(new InputEvent(eventType, { data: 'a', bubbles: true })); + await Promise.resolve(); + expect(calls.some((entry) => entry.startsWith('hook:'))).toBe(false); +}); + +it('does not profile the same forwarded beforeinput twice', async () => { + const event = new InputEvent('beforeinput', { + data: 'a', + inputType: 'insertText', + bubbles: true, + cancelable: true, + }); + layoutSurface.dispatchEvent(event); + await Promise.resolve(); + targetDom.dispatchEvent(event); + expect(calls.filter((entry) => entry.startsWith('hook:'))).toHaveLength(1); +}); +``` + +- [ ] **Step 2: Run the bridge tests and confirm RED** + +```bash +pnpm --filter @superdoc/super-editor test --run src/editors/v1/core/presentation-editor/tests/PresentationInputBridge.test.ts +``` + +Expected: FAIL because `onBeforeInput` is not part of the options contract and no hook fires. + +- [ ] **Step 3: Add the optional hook and invoke it at the correct boundary** + +Extend the options type: + +```ts +options?: { + useWindowFallback?: boolean; + getTargetEditor?: () => BridgeTargetEditor | null; + onBeforeInput?: (input: { inputType: string; isComposing: boolean }) => void; +}, +``` + +Store it in a private field: + +```ts +#onBeforeInput?: (input: { inputType: string; isComposing: boolean }) => void; +``` + +Assign it in the constructor and add this immediately after all eligibility guards in `#forwardTextEvent`, before `#markForwardedByBridge(event)`: + +```ts +if (event.type === 'beforeinput') { + this.#onBeforeInput?.({ + inputType: (event as InputEvent).inputType ?? 'insertText', + isComposing: (event as InputEvent).isComposing ?? false, + }); +} +``` + +Do not call the hook from `#captureStaleTextEvent`; the first profiler version measures the visible presentation surface only. + +- [ ] **Step 4: Run bridge and profiler tests** + +```bash +pnpm --filter @superdoc/super-editor test --run src/editors/v1/core/presentation-editor/tests/PresentationInputBridge.test.ts src/editors/v1/core/presentation-editor/performance/InputLatencyProfiler.test.ts +``` + +Expected: both files PASS. + +- [ ] **Step 5: Commit the input boundary** + +```bash +git add packages/super-editor/src/editors/v1/core/presentation-editor/input/PresentationInputBridge.ts packages/super-editor/src/editors/v1/core/presentation-editor/tests/PresentationInputBridge.test.ts +git commit -m "feat(super-editor): trace visible text input" +``` + +--- + +### Task 3: Correlate Transactions, Renders, Layout Phases, and Paint + +**Files:** +- Modify: `packages/super-editor/src/editors/v1/core/presentation-editor/PresentationEditor.ts:1-180,548-684,5012-5114,5414-5529,6066-6084,7200-7790` +- Modify: `packages/super-editor/src/editors/v1/core/presentation-editor/tests/PresentationEditor.test.ts` + +**Interfaces:** +- Consumes: `InputLatencyProfiler` from Task 1 and `onBeforeInput` from Task 2. +- Produces: phase measures for every supported input that reaches a completed presentation render. + +- [ ] **Step 1: Write failing integration tests** + +Add a `describe('input latency profiling')` block. Set the runtime flag before construction, spy on `performance.mark`/`performance.measure`, use a controllable `requestAnimationFrame`, dispatch one visible `beforeinput`, and invoke the mocked Editor's registered transaction/update listeners: + +```ts +const debugGlobal = window as Window & { __SD_DEBUG_INPUT_LATENCY__?: boolean }; +debugGlobal.__SD_DEBUG_INPUT_LATENCY__ = true; +const measureSpy = vi.spyOn(performance, 'measure'); +const frameCallbacks: FrameRequestCallback[] = []; +const rafSpy = vi.spyOn(window, 'requestAnimationFrame').mockImplementation((callback) => { + frameCallbacks.push(callback); + return frameCallbacks.length; +}); + +editor = new PresentationEditor({ element: container, documentId: 'latency-profile-doc' }); +await vi.waitFor(() => expect(mockIncrementalLayout).toHaveBeenCalled()); +measureSpy.mockClear(); + +container.dispatchEvent( + new InputEvent('beforeinput', { + data: 'a', + inputType: 'insertText', + bubbles: true, + cancelable: true, + }), +); +await Promise.resolve(); + +const editorInstance = getLastEditorInstance(); +const onMock = editorInstance.on as unknown as Mock; +const transactionHandler = onMock.mock.calls.find(([event]) => event === 'transaction')![1]; +const updateHandler = onMock.mock.calls.find(([event]) => event === 'update')![1]; +const transaction = { + docChanged: true, + mapping: { slice: vi.fn(), appendMapping: vi.fn() }, + getMeta: vi.fn(), +}; +transactionHandler({ transaction, duration: 6 }); +updateHandler({ transaction }); + +while (frameCallbacks.length > 0) { + frameCallbacks.shift()!(performance.now()); + await Promise.resolve(); +} + +await vi.waitFor(() => + expect(measureSpy).toHaveBeenCalledWith( + 'superdoc.input-latency.total', + expect.objectContaining({ detail: expect.objectContaining({ inputType: 'insertText' }) }), + ), +); +``` + +Add four named tests with these exact assertions: + +```ts +it('correlates two inputs with one coalesced presentation render', async () => { + // Repeat the beforeinput -> transaction -> update sequence twice before flushing RAF. + const totals = measureSpy.mock.calls.filter(([name]) => name === 'superdoc.input-latency.total'); + expect(totals).toHaveLength(2); + expect(totals[0]?.[1]).toMatchObject({ detail: { coalescedInputCount: 2 } }); + expect(totals[1]?.[1]).toMatchObject({ + detail: { renderId: totals[0]?.[1].detail.renderId, coalescedInputCount: 2 }, + }); +}); + +it('emits no measures when profiling is disabled', async () => { + delete debugGlobal.__SD_DEBUG_INPUT_LATENCY__; + // Construct, type, and flush using the same helpers as the enabled test. + expect(measureSpy.mock.calls.some(([name]) => String(name).startsWith('superdoc.input-latency.'))).toBe(false); +}); + +it('discards the trace when layout fails', async () => { + mockIncrementalLayout.mockRejectedValueOnce(new Error('layout failed')); + // Type once, dispatch the matching transaction/update, and flush RAF. + expect(measureSpy).toHaveBeenCalledWith( + 'superdoc.input-latency.discarded', + expect.objectContaining({ detail: expect.objectContaining({ reason: 'render-aborted' }) }), + ); +}); + +it('cancels profiler frame completion during destroy', async () => { + // Reach completeAfterNextFrame without flushing the profiler-owned RAF. + editor.destroy(); + expect(window.cancelAnimationFrame).toHaveBeenCalled(); + expect(measureSpy.mock.calls.some(([name]) => name === 'superdoc.input-latency.total')).toBe(false); +}); +``` + +- [ ] **Step 2: Run the focused PresentationEditor tests and confirm RED** + +```bash +pnpm --filter @superdoc/super-editor test --run src/editors/v1/core/presentation-editor/tests/PresentationEditor.test.ts -t "input latency profiling" +``` + +Expected: FAIL because `PresentationEditor` does not create or call the profiler. + +- [ ] **Step 3: Create and wire the profiler** + +Import the factory and stage type: + +```ts +import { + createInputLatencyProfiler, + type InputLatencyProfiler, + type InputLatencyStage, +} from './performance/InputLatencyProfiler.js'; +``` + +Add the field: + +```ts +#inputLatencyProfiler: InputLatencyProfiler | null = null; +``` + +After `viewForPosition` is resolved in the constructor: + +```ts +this.#inputLatencyProfiler = createInputLatencyProfiler(viewForPosition); +``` + +Pass the bridge hook: + +```ts +onBeforeInput: (input) => this.#inputLatencyProfiler?.recordBeforeInput(input), +``` + +Change the transaction listener payload and record document-changing transaction duration: + +```ts +const handleTransaction = (event?: { transaction?: Transaction; duration?: number }) => { + const tr = event?.transaction; + if (tr?.docChanged && typeof event?.duration === 'number') { + this.#inputLatencyProfiler?.recordTransaction(event.duration); + } +``` + +Immediately before the document-change call to `#scheduleRerender()` in `handleUpdate`: + +```ts +if (transaction?.docChanged) { + this.#inputLatencyProfiler?.recordRenderScheduled(); +} +``` + +- [ ] **Step 4: Carry a render ID through `#flushRerenderQueue` and `#rerender`** + +Change the invocation to: + +```ts +const latencyRenderId = this.#inputLatencyProfiler?.beginRender() ?? null; +await this.#rerender(latencyRenderId); +``` + +Change the method signature: + +```ts +async #rerender(latencyRenderId: number | null = null) { +``` + +In `#rerender`, add one local helper after `perfNow` is declared: + +```ts +const recordLatencyStage = (stage: InputLatencyStage, start: number, end: number) => { + if (latencyRenderId != null) { + this.#inputLatencyProfiler?.recordStage(latencyRenderId, stage, start, end); + } +}; +``` + +Call it with existing start/end values for `get-json`, `position-map`, `to-flow-blocks`, `incremental-layout`, `paint`, and `post-paint`. Add explicit start/end timestamps around font planning/readiness, `resolveLayout`, and `#layoutPerRIdHeaderFooters` for `font-readiness`, `resolve-layout`, and `header-footer`. + +- [ ] **Step 5: Complete or abort the trace without changing layout behavior** + +Immediately after `painter.paint` returns: + +```ts +if (latencyRenderId != null) { + this.#inputLatencyProfiler?.recordDomPaint(latencyRenderId, painterPaintEnd); +} +``` + +After `layoutUpdated` and `paginationUpdate` emit: + +```ts +if (latencyRenderId != null) { + this.#inputLatencyProfiler?.completeAfterNextFrame(latencyRenderId, { + documentSize: this.#editor.state.doc.content.size, + blockCount: blocksForLayout.length, + pageCount: layout.pages?.length ?? 0, + }); +} +``` + +In the existing `finally`, before selection abort handling: + +```ts +if (!layoutCompleted && latencyRenderId != null) { + this.#inputLatencyProfiler?.abortRender(latencyRenderId, 'render-aborted'); +} +``` + +In `destroy()`: + +```ts +this.#inputLatencyProfiler?.destroy(); +this.#inputLatencyProfiler = null; +``` + +- [ ] **Step 6: Run focused tests, typecheck, and formatting** + +```bash +pnpm --filter @superdoc/super-editor test --run src/editors/v1/core/presentation-editor/performance/InputLatencyProfiler.test.ts src/editors/v1/core/presentation-editor/tests/PresentationInputBridge.test.ts src/editors/v1/core/presentation-editor/tests/PresentationEditor.test.ts +pnpm --filter @superdoc/super-editor types:check +pnpm exec prettier --check packages/super-editor/src/editors/v1/core/presentation-editor/performance/InputLatencyProfiler.ts packages/super-editor/src/editors/v1/core/presentation-editor/performance/InputLatencyProfiler.test.ts packages/super-editor/src/editors/v1/core/presentation-editor/input/PresentationInputBridge.ts packages/super-editor/src/editors/v1/core/presentation-editor/tests/PresentationInputBridge.test.ts packages/super-editor/src/editors/v1/core/presentation-editor/PresentationEditor.ts packages/super-editor/src/editors/v1/core/presentation-editor/tests/PresentationEditor.test.ts +``` + +Expected: all selected tests PASS, TypeScript exits 0, and Prettier reports all files matched. + +- [ ] **Step 7: Commit the presentation pipeline instrumentation** + +```bash +git add packages/super-editor/src/editors/v1/core/presentation-editor/PresentationEditor.ts packages/super-editor/src/editors/v1/core/presentation-editor/tests/PresentationEditor.test.ts +git commit -m "feat(super-editor): trace input through presentation paint" +``` + +--- + +### Task 4: Deterministic Report Schema and Comparator + +**Files:** +- Create: `devtools/input-latency/report.mjs` +- Create: `devtools/input-latency/report.test.mjs` +- Create: `devtools/input-latency/compare.mjs` + +**Interfaces:** +- Consumes: raw per-run samples from the recorder. +- Produces: `summarize`, `medianAbsoluteDeviation`, `buildScenarioFingerprint`, `validateComparableReports`, `compareReports`, and `renderMarkdownComparison`. + +- [ ] **Step 1: Write failing Node tests for statistics and mismatch rejection** + +```js +import assert from 'node:assert/strict'; +import test from 'node:test'; +import { + summarize, + medianAbsoluteDeviation, + validateComparableReports, + compareReports, + renderMarkdownComparison, +} from './report.mjs'; + +test('summarize returns interpolated percentiles and raw count', () => { + assert.deepEqual(summarize([10, 20, 30, 40, 50]), { + count: 5, + min: 10, + average: 30, + p50: 30, + p95: 48, + p99: 49.6, + max: 50, + }); + assert.equal(medianAbsoluteDeviation([100, 105, 110, 95, 100]), 5); +}); + +test('comparison rejects a fixture mismatch', () => { + const baseline = makeReport({ fixtureSha256: 'aaa' }); + const after = makeReport({ fixtureSha256: 'bbb' }); + assert.throws(() => validateComparableReports(baseline, after), /fixtureSha256/); +}); + +test('comparison emits absolute and percentage delta', () => { + const baseline = makeReport({ fixtureSha256: 'same', p95: 120 }); + const after = makeReport({ fixtureSha256: 'same', p95: 90 }); + const comparison = compareReports(baseline, after); + assert.equal(comparison.scenarios[0].metrics.inputToNextFrameMs.p95.deltaMs, -30); + assert.equal(comparison.scenarios[0].metrics.inputToNextFrameMs.p95.deltaPercent, -25); + assert.match(renderMarkdownComparison(comparison), /\| inputToNextFrameMs p95 \| 120\.00 \| 90\.00 \| -30\.00 \| -25\.00% \|/); +}); +``` + +Define the fixture before the tests so every comparison field is explicit: + +```js +function makeReport({ fixtureSha256, p95 = 120 }) { + return { + schemaVersion: 1, + environment: { + os: 'darwin', + arch: 'arm64', + browserName: 'chromium', + browserVersion: 'test-version', + }, + fixture: { sha256: fixtureSha256, size: 280245 }, + protocol: { + zoom: 1, + documentMode: 'editing', + warmupRuns: 1, + measuredRuns: 5, + sequence: 'abcdefghijklmnopqrstuvwxyzabcdefghijklmn', + cadenceMs: 100, + }, + scenarios: [ + { + name: 'layout-on-cpu-4x', + layoutEnabled: true, + cpuThrottle: 4, + pageCount: 7, + blockCount: 680, + runs: Array.from({ length: 5 }, (_, runIndex) => ({ + runIndex, + samples: [{ inputId: runIndex + 1, inputToNextFrameMs: p95 }], + metrics: { inputToNextFrameMs: { ...summarize([p95]), p95 } }, + })), + metrics: { + inputToNextFrameMs: { + ...summarize([p95, p95, p95, p95, p95]), + p95, + runP95Values: [p95, p95, p95, p95, p95], + runP95Mad: 0, + }, + }, + }, + ], + }; +} +``` + +- [ ] **Step 2: Run the report tests and confirm RED** + +```bash +node --test devtools/input-latency/report.test.mjs +``` + +Expected: FAIL because `report.mjs` does not exist. + +- [ ] **Step 3: Implement exact statistics and fingerprint behavior** + +Use linear interpolation: + +```js +export function percentile(values, ratio) { + if (values.length === 0) return 0; + const sorted = [...values].sort((a, b) => a - b); + if (sorted.length === 1) return sorted[0]; + const index = (sorted.length - 1) * ratio; + const lower = Math.floor(index); + const upper = Math.ceil(index); + const weight = index - lower; + return sorted[lower] * (1 - weight) + sorted[upper] * weight; +} + +export function summarize(values) { + if (values.length === 0) { + return { count: 0, min: 0, average: 0, p50: 0, p95: 0, p99: 0, max: 0 }; + } + const total = values.reduce((sum, value) => sum + value, 0); + return { + count: values.length, + min: Math.min(...values), + average: total / values.length, + p50: percentile(values, 0.5), + p95: percentile(values, 0.95), + p99: percentile(values, 0.99), + max: Math.max(...values), + }; +} + +export function medianAbsoluteDeviation(values) { + if (values.length === 0) return 0; + const median = percentile(values, 0.5); + return percentile(values.map((value) => Math.abs(value - median)), 0.5); +} +``` + +The comparison fingerprint must include schema version, OS/architecture, browser name/version, fixture SHA/size, layout mode, zoom, document mode, page/block count, CPU throttle, warm-up runs, measured runs, sequence, and cadence. It must exclude label, timestamp, git SHA, dirty status, absolute fixture path, and output path. + +Materiality for p95 is: + +```js +const thresholdMs = Math.max(5, 2 * Math.max(baselineMadMs, afterMadMs)); +const material = Math.abs(afterP95 - baselineP95) > thresholdMs; +``` + +- [ ] **Step 4: Implement `compare.mjs` as a strict CLI** + +The CLI accepts exactly two JSON paths plus optional `--markdown `, calls `validateComparableReports`, prints JSON comparison to stdout, writes Markdown when requested, and exits non-zero for parse/schema/fingerprint errors. + +```js +import fs from 'node:fs/promises'; +import { compareReports, renderMarkdownComparison } from './report.mjs'; + +const [baselinePath, afterPath, ...rest] = process.argv.slice(2); +if (!baselinePath || !afterPath) { + throw new Error('Usage: node compare.mjs [--markdown ]'); +} +const baseline = JSON.parse(await fs.readFile(baselinePath, 'utf8')); +const after = JSON.parse(await fs.readFile(afterPath, 'utf8')); +const comparison = compareReports(baseline, after); +const markdownIndex = rest.indexOf('--markdown'); +if (markdownIndex >= 0) { + const outputPath = rest[markdownIndex + 1]; + if (!outputPath) throw new Error('--markdown requires an output path'); + await fs.writeFile(outputPath, renderMarkdownComparison(comparison)); +} +process.stdout.write(`${JSON.stringify(comparison, null, 2)}\n`); +``` + +- [ ] **Step 5: Run report tests and commit** + +```bash +node --test devtools/input-latency/report.test.mjs +git add devtools/input-latency/report.mjs devtools/input-latency/report.test.mjs devtools/input-latency/compare.mjs +git commit -m "feat(devtools): compare input latency profiles" +``` + +Expected: all Node tests PASS before commit. + +--- + +### Task 5: Chromium Recorder and Layout-off Control Probe + +**Files:** +- Create: `devtools/input-latency/profile.mjs` +- Modify: `package.json` +- Modify: `pnpm-lock.yaml` + +**Interfaces:** +- Consumes: running SuperDoc Labs URL, local DOCX path, and profiler User Timing entries. +- Produces: a schema-version-1 JSON report containing three scenarios and raw samples. + +- [ ] **Step 1: Add an explicit Playwright dependency and failing CLI smoke check** + +Add to root `devDependencies`: + +```json +"playwright": "catalog:" +``` + +Add scripts: + +```json +"profile:input-latency": "node devtools/input-latency/profile.mjs", +"profile:input-latency:compare": "node devtools/input-latency/compare.mjs" +``` + +Refresh the lockfile: + +```bash +pnpm install --lockfile-only +pnpm profile:input-latency -- --help +``` + +Expected before `profile.mjs` exists: the help command FAILS with module-not-found. + +- [ ] **Step 2: Implement argument parsing and metadata collection** + +Support this exact command: + +```bash +pnpm profile:input-latency -- --url http://localhost:9094 --fixture /absolute/file.docx --label baseline --output devtools/input-latency/results/baseline.json +``` + +Defaults: + +```js +const DEFAULT_SEQUENCE = 'abcdefghijklmnopqrstuvwxyzabcdefghijklmn'; +const DEFAULT_CADENCE_MS = 100; +const DEFAULT_WARMUP_RUNS = 1; +const DEFAULT_MEASURED_RUNS = 5; +const DEFAULT_SCENARIOS = [ + { name: 'layout-on-cpu-1x', layoutEnabled: true, cpuThrottle: 1 }, + { name: 'layout-on-cpu-4x', layoutEnabled: true, cpuThrottle: 4 }, + { name: 'layout-off-cpu-1x', layoutEnabled: false, cpuThrottle: 1 }, +]; +``` + +Collect git SHA/dirty status with `git rev-parse HEAD` and `git status --porcelain`, fixture SHA-256 with `node:crypto`, host metadata with `node:os`, browser version with `browser.version()`, and browser CPU/memory metadata through `page.evaluate`. + +- [ ] **Step 3: Install profiling before application startup** + +Before every navigation: + +```js +await page.addInitScript(() => { + globalThis.__SD_DEBUG_INPUT_LATENCY__ = true; +}); +``` + +For layout-off runs, also install this capture-phase probe. It deliberately measures only the native ProseMirror control path and uses the same two terminal measure names as the layout-on profiler: + +```js +await page.addInitScript(() => { + let nextInputId = 1; + document.addEventListener( + 'beforeinput', + (event) => { + if (!(event instanceof InputEvent) || event.isComposing || event.inputType !== 'insertText') return; + const editor = event.target instanceof Element ? event.target.closest('.ProseMirror') : null; + if (!editor) return; + + const inputId = nextInputId++; + const startedAt = performance.now(); + const detail = { + schemaVersion: 1, + inputId, + renderId: inputId, + inputType: 'insertText', + coalescedInputCount: 1, + documentSize: editor.textContent?.length ?? 0, + blockCount: editor.querySelectorAll('p, li, table').length, + pageCount: 1, + }; + const observer = new MutationObserver(() => { + observer.disconnect(); + performance.measure('superdoc.input-latency.input-to-dom-paint', { + start: startedAt, + end: performance.now(), + detail, + }); + requestAnimationFrame((frameTime) => { + performance.measure('superdoc.input-latency.input-to-next-frame', { + start: startedAt, + end: frameTime, + detail, + }); + }); + }); + observer.observe(editor, { childList: true, characterData: true, subtree: true }); + }, + { capture: true }, + ); +}); +``` + +- [ ] **Step 4: Implement one deterministic run** + +For each run: + +```js +const targetUrl = layoutEnabled ? url : `${url.replace(/\/$/, '')}/?layout=0`; +await page.goto(targetUrl, { waitUntil: 'domcontentloaded' }); +await page.locator('input[type="file"]').setInputFiles(fixturePath); + +if (layoutEnabled) { + await page.waitForFunction(() => document.querySelectorAll('.superdoc-text-run[data-pm-start]').length > 0); + const target = page.locator('.superdoc-text-run[data-pm-start]').filter({ hasText: /\S/ }).first(); + await target.click(); + await page.keyboard.press('End'); +} else { + await page.waitForSelector('.ProseMirror[contenteditable="true"]'); + const target = page.locator('.ProseMirror[contenteditable="true"] p').filter({ hasText: /\S/ }).first(); + await target.click(); + await page.keyboard.press('End'); +} + +await page.evaluate(() => { + performance.clearMarks('superdoc.input-latency'); + performance.clearMeasures(); +}); +await page.keyboard.type(sequence, { delay: cadenceMs }); +await page.waitForFunction( + (expected) => + performance.getEntriesByName('superdoc.input-latency.total').length >= expected || + performance.getEntriesByName('superdoc.input-latency.input-to-next-frame').length >= expected, + sequence.length, +); +``` + +Use `context.newCDPSession(page)` and `Emulation.setCPUThrottlingRate` before the run. Capture `pageerror` and console errors; fail the run if either occurs. Collect entries with name, startTime, duration, and cloned `detail`, then group them by input ID. Validate exactly 40 completed inputs and stable fixture/page/block metadata. + +- [ ] **Step 5: Aggregate warm-up and measured runs** + +Discard all warm-up samples. For each measured run, store raw inputs and a per-metric summary. At scenario level, concatenate the five measured runs, compute the aggregate summary, store the five run-level p95 values, and calculate their median absolute deviation with Task 4 helpers. + +Write the report atomically by writing `.tmp` then renaming it to the requested output path. Ensure `browser.close()` runs in `finally` and restore CPU throttling to 1 before closing. + +- [ ] **Step 6: Exercise recorder validation without claiming a baseline** + +```bash +pnpm profile:input-latency -- --help +pnpm exec prettier --check devtools/input-latency/profile.mjs devtools/input-latency/report.mjs devtools/input-latency/report.test.mjs devtools/input-latency/compare.mjs package.json +node --test devtools/input-latency/report.test.mjs +``` + +Expected: help exits 0 and documents all required flags; Prettier passes; Node tests pass. Do not record baseline until Task 6 verification is complete and the instrumentation tree is clean. + +- [ ] **Step 7: Commit the recorder** + +```bash +git add package.json pnpm-lock.yaml devtools/input-latency/profile.mjs +git commit -m "feat(devtools): record browser input latency" +``` + +--- + +### Task 6: Documentation, Ignore Rules, and Full Instrumentation Verification + +**Files:** +- Create: `devtools/input-latency/README.md` +- Modify: `.gitignore` + +**Interfaces:** +- Consumes: record and compare CLIs from Tasks 4–5. +- Produces: reproducible operator instructions and a clean instrumentation-only revision. + +- [ ] **Step 1: Add the result ignore rule** + +Append: + +```gitignore +# Local input-latency profiling artifacts +devtools/input-latency/results/ +``` + +- [ ] **Step 2: Write the operator README** + +Document these commands exactly: + +```bash +pnpm dev + +pnpm profile:input-latency -- \ + --url http://localhost:9094 \ + --fixture /absolute/path/to/large-typing-test.docx \ + --label baseline \ + --output devtools/input-latency/results/baseline.json + +pnpm profile:input-latency:compare -- \ + devtools/input-latency/results/baseline.json \ + devtools/input-latency/results/after.json \ + --markdown devtools/input-latency/results/comparison.md +``` + +Explain the three scenarios, expected fixture hash, 40-character/100-ms cadence, five measured runs, materiality threshold, headed Chromium requirement, and why raw reports are not committed. + +- [ ] **Step 3: Run all instrumentation-focused verification** + +```bash +node --test devtools/input-latency/report.test.mjs +pnpm --filter @superdoc/super-editor test --run src/editors/v1/core/presentation-editor/performance/InputLatencyProfiler.test.ts src/editors/v1/core/presentation-editor/tests/PresentationInputBridge.test.ts src/editors/v1/core/presentation-editor/tests/PresentationEditor.test.ts +pnpm --filter @superdoc/super-editor types:check +pnpm exec prettier --check packages/super-editor/src/editors/v1/core/presentation-editor/performance/InputLatencyProfiler.ts packages/super-editor/src/editors/v1/core/presentation-editor/performance/InputLatencyProfiler.test.ts packages/super-editor/src/editors/v1/core/presentation-editor/input/PresentationInputBridge.ts packages/super-editor/src/editors/v1/core/presentation-editor/tests/PresentationInputBridge.test.ts packages/super-editor/src/editors/v1/core/presentation-editor/PresentationEditor.ts packages/super-editor/src/editors/v1/core/presentation-editor/tests/PresentationEditor.test.ts devtools/input-latency/profile.mjs devtools/input-latency/report.mjs devtools/input-latency/report.test.mjs devtools/input-latency/compare.mjs package.json +pnpm lint +``` + +Expected: zero test failures, type errors, formatting differences, or lint errors. + +- [ ] **Step 4: Run the full package suite once** + +```bash +pnpm --filter @superdoc/super-editor test --run +``` + +Expected: all tests pass. If the known encrypted-document tests time out only under full parallel load, rerun those exact tests separately and report both the full-suite failure and isolated result; do not describe the full suite as green. + +- [ ] **Step 5: Commit docs and ignore rule** + +```bash +git add .gitignore devtools/input-latency/README.md +git commit -m "docs: document input latency profiling" +``` + +- [ ] **Step 6: Verify the instrumentation-only revision is clean** + +```bash +git status --short --branch +git log -6 --oneline --decorate +``` + +Expected: branch `codex/input-latency-profiling`, no worktree changes, and no optimization commit. + +--- + +### Task 7: Capture Baseline and State One Root-cause Hypothesis + +**Files:** +- Generate, do not commit: `devtools/input-latency/results/baseline-a.json` +- Generate, do not commit: `devtools/input-latency/results/baseline-b.json` +- Generate, do not commit: `devtools/input-latency/results/baseline-repeatability.md` + +**Interfaces:** +- Consumes: clean instrumentation-only git SHA and local fixture. +- Produces: two complete baseline reports, repeatability comparison, and one evidence-backed hypothesis for a separate optimization plan. + +- [ ] **Step 1: Verify the fixture before launching the browser** + +```bash +shasum -a 256 /Users/dmytroharastovych/Desktop/large-typing-test.docx +stat -f '%z' /Users/dmytroharastovych/Desktop/large-typing-test.docx +git status --short --branch +``` + +Expected: SHA-256 `f73a0f320aa78c00d13fbadecfd2906a7f12dc95a00b306c4f0a6a18afaad277`, size `280245`, and clean feature branch. + +- [ ] **Step 2: Ensure SuperDoc Labs is running at the fixed URL** + +```bash +curl --fail --silent --show-error http://localhost:9094/ >/dev/null +``` + +If unavailable, start `pnpm dev` and wait until the URL responds. Use the same dev-server process for both baseline recordings. + +- [ ] **Step 3: Record baseline A** + +```bash +pnpm profile:input-latency -- \ + --url http://localhost:9094 \ + --fixture /Users/dmytroharastovych/Desktop/large-typing-test.docx \ + --label baseline-a \ + --output devtools/input-latency/results/baseline-a.json +``` + +Expected: three complete scenarios, 200 measured input samples per scenario, no discarded/incomplete samples, and fixture fingerprint match. + +- [ ] **Step 4: Record baseline B without changing code or environment** + +Run the same command with label/output `baseline-b`. + +Expected: the same scenario/sample counts and fingerprint as baseline A. + +- [ ] **Step 5: Compare baseline A and B to quantify noise** + +```bash +pnpm profile:input-latency:compare -- \ + devtools/input-latency/results/baseline-a.json \ + devtools/input-latency/results/baseline-b.json \ + --markdown devtools/input-latency/results/baseline-repeatability.md +``` + +Expected: comparison succeeds with identical fingerprints. If the normal or 4x p95 delta is material under the `max(5 ms, 2 × MAD)` rule, stop and reduce environmental noise before optimizing. + +- [ ] **Step 6: Attribute the current p95 and form one hypothesis** + +For the 4x scenario, rank phase p95 values and calculate their share of `inputToDomPaintMs`. State one hypothesis in this exact form: + +```text +Hypothesis: is the primary root cause because it contributes and of 4x input-to-DOM-paint latency across both repeatable baselines. The first optimization experiment will change only . +``` + +Do not implement the experiment in this plan. Write a new design/implementation plan whose success criterion compares its after report against `baseline-a.json` using the existing comparator. + +- [ ] **Step 7: Confirm profiling artifacts remain untracked** + +```bash +git status --short --branch +git check-ignore -v devtools/input-latency/results/baseline-a.json devtools/input-latency/results/baseline-b.json devtools/input-latency/results/baseline-repeatability.md +``` + +Expected: clean worktree and all three result files matched by `.gitignore`. diff --git a/docs/superpowers/specs/2026-07-20-input-latency-profiling-design.md b/docs/superpowers/specs/2026-07-20-input-latency-profiling-design.md index 6fe1683aec..1005c2abfe 100644 --- a/docs/superpowers/specs/2026-07-20-input-latency-profiling-design.md +++ b/docs/superpowers/specs/2026-07-20-input-latency-profiling-design.md @@ -70,9 +70,12 @@ typing state into `layout-bridge` would violate that boundary. Add a focused internal profiler under the presentation-editor performance folder. `PresentationEditor` creates it only when -`SD_DEBUG_INPUT_LATENCY` is enabled. When the flag is disabled, no trace object, -sample array, mark, or measure is created. Call sites may perform only a cheap -null check. +`SD_DEBUG_INPUT_LATENCY` is enabled at build time or +`globalThis.__SD_DEBUG_INPUT_LATENCY__ === true` is installed before editor +construction. The runtime form lets the Chromium harness enable profiling on +an already-running development server through an init script. When neither +flag is enabled, no trace object, sample array, mark, or measure is created. +Call sites may perform only a cheap null check. The profiler owns: From b8303e3347b88050623409f7d71681e63424121d Mon Sep 17 00:00:00 2001 From: Dmytro Harastovych Date: Mon, 20 Jul 2026 22:13:10 +0300 Subject: [PATCH 03/15] feat(super-editor): add input latency profiler --- .../performance/InputLatencyProfiler.test.ts | 232 ++++++++++++ .../performance/InputLatencyProfiler.ts | 332 ++++++++++++++++++ 2 files changed, 564 insertions(+) create mode 100644 packages/super-editor/src/editors/v1/core/presentation-editor/performance/InputLatencyProfiler.test.ts create mode 100644 packages/super-editor/src/editors/v1/core/presentation-editor/performance/InputLatencyProfiler.ts diff --git a/packages/super-editor/src/editors/v1/core/presentation-editor/performance/InputLatencyProfiler.test.ts b/packages/super-editor/src/editors/v1/core/presentation-editor/performance/InputLatencyProfiler.test.ts new file mode 100644 index 0000000000..f9dd842c27 --- /dev/null +++ b/packages/super-editor/src/editors/v1/core/presentation-editor/performance/InputLatencyProfiler.test.ts @@ -0,0 +1,232 @@ +import { describe, expect, it, vi } from 'vitest'; +import { createInputLatencyProfiler, InputLatencyProfiler, type InputLatencyRuntime } from './InputLatencyProfiler.js'; + +function makeRuntime() { + let now = 0; + let nextFrameId = 1; + const frameCallbacks = new Map(); + const warn = vi.fn(); + const performance = { + now: vi.fn(() => now), + mark: vi.fn(), + measure: vi.fn(), + clearMarks: vi.fn(), + } as unknown as Performance; + const runtime: InputLatencyRuntime = { + performance, + requestAnimationFrame: vi.fn((callback) => { + const id = nextFrameId++; + frameCallbacks.set(id, callback); + return id; + }), + cancelAnimationFrame: vi.fn((id) => frameCallbacks.delete(id)), + warn, + }; + return { + runtime, + performance, + warn, + advance(ms: number) { + now += ms; + }, + get pendingFrames() { + return frameCallbacks.size; + }, + flushFrame() { + const callbacks = [...frameCallbacks.entries()]; + frameCallbacks.clear(); + callbacks.forEach(([, callback]) => callback(now)); + }, + }; +} + +function totalCalls(performance: Performance) { + return vi.mocked(performance.measure).mock.calls.filter(([name]) => name === 'superdoc.input-latency.total'); +} + +function measureCalls(performance: Performance, name: string) { + return vi.mocked(performance.measure).mock.calls.filter(([callName]) => callName === name); +} + +describe('InputLatencyProfiler', () => { + it('creates no profiler when the debug flag is disabled', () => { + const windowLike = { + performance: { now: () => 0, mark: () => {}, measure: () => {}, clearMarks: () => {} }, + requestAnimationFrame: () => 1, + cancelAnimationFrame: () => {}, + } as unknown as Window; + expect(createInputLatencyProfiler(windowLike)).toBeNull(); + }); + + it('creates a profiler when the debug global is enabled', () => { + const windowLike = { + __SD_DEBUG_INPUT_LATENCY__: true, + performance: { now: () => 0, mark: () => {}, measure: () => {}, clearMarks: () => {} }, + requestAnimationFrame: (cb: FrameRequestCallback) => { + void cb; + return 1; + }, + cancelAnimationFrame: () => {}, + } as unknown as Window; + expect(createInputLatencyProfiler(windowLike)).toBeInstanceOf(InputLatencyProfiler); + }); + + it('emits a total measure for a single input', () => { + const clock = makeRuntime(); + const profiler = new InputLatencyProfiler(clock.runtime); + + const inputId = profiler.recordBeforeInput({ inputType: 'insertText', isComposing: false }); + expect(inputId).not.toBeNull(); + clock.advance(4); + profiler.recordTransaction(3); + profiler.recordRenderScheduled(); + + clock.advance(6); + const renderId = profiler.beginRender(); + expect(renderId).not.toBeNull(); + profiler.recordDomPaint(renderId!, 12); + profiler.completeAfterNextFrame(renderId!, { documentSize: 100, blockCount: 4, pageCount: 1 }); + clock.advance(16); + clock.flushFrame(); + + const totals = totalCalls(clock.performance); + expect(totals).toHaveLength(1); + expect(totals[0]?.[1]).toMatchObject({ + detail: { renderId, inputId, coalescedInputCount: 1, inputType: 'insertText' }, + }); + }); + + it('emits one total measure per input and shares a coalesced render', () => { + const clock = makeRuntime(); + const profiler = new InputLatencyProfiler(clock.runtime); + + profiler.recordBeforeInput({ inputType: 'insertText', isComposing: false }); + clock.advance(4); + profiler.recordTransaction(3); + profiler.recordRenderScheduled(); + + profiler.recordBeforeInput({ inputType: 'insertText', isComposing: false }); + clock.advance(5); + profiler.recordTransaction(2); + profiler.recordRenderScheduled(); + + clock.advance(7); + const renderId = profiler.beginRender(); + expect(renderId).not.toBeNull(); + profiler.recordStage(renderId!, 'get-json', 16, 19); + profiler.recordDomPaint(renderId!, 35); + profiler.completeAfterNextFrame(renderId!, { + documentSize: 24000, + blockCount: 680, + pageCount: 7, + }); + clock.advance(16); + clock.flushFrame(); + + const totals = totalCalls(clock.performance); + expect(totals).toHaveLength(2); + expect(totals[0]?.[1]).toMatchObject({ detail: { renderId, coalescedInputCount: 2 } }); + expect(totals[1]?.[1]).toMatchObject({ detail: { renderId, coalescedInputCount: 2 } }); + }); + + it('emits stage measures with the exact recorded start and end', () => { + const clock = makeRuntime(); + const profiler = new InputLatencyProfiler(clock.runtime); + + profiler.recordBeforeInput({ inputType: 'insertText', isComposing: false }); + clock.advance(2); + profiler.recordTransaction(1); + profiler.recordRenderScheduled(); + const renderId = profiler.beginRender(); + profiler.recordStage(renderId!, 'get-json', 16, 19); + profiler.recordStage(renderId!, 'paint', 40, 52); + profiler.recordDomPaint(renderId!, 52); + profiler.completeAfterNextFrame(renderId!, { documentSize: 10, blockCount: 1, pageCount: 1 }); + clock.flushFrame(); + + const getJson = measureCalls(clock.performance, 'superdoc.input-latency.stage.get-json'); + expect(getJson).toHaveLength(1); + expect(getJson[0]?.[1]).toMatchObject({ start: 16, end: 19 }); + const paint = measureCalls(clock.performance, 'superdoc.input-latency.stage.paint'); + expect(paint[0]?.[1]).toMatchObject({ start: 40, end: 52 }); + const domPaint = measureCalls(clock.performance, 'superdoc.input-latency.input-to-dom-paint'); + expect(domPaint).toHaveLength(1); + expect(domPaint[0]?.[1]).toMatchObject({ end: 52 }); + }); + + it('ignores composing and unsupported input types', () => { + const clock = makeRuntime(); + const profiler = new InputLatencyProfiler(clock.runtime); + + expect(profiler.recordBeforeInput({ inputType: 'insertText', isComposing: true })).toBeNull(); + expect(profiler.recordBeforeInput({ inputType: 'deleteContentBackward', isComposing: false })).toBeNull(); + expect(profiler.recordBeforeInput({ inputType: 'insertParagraph', isComposing: false })).toBeNull(); + + profiler.recordTransaction(1); + profiler.recordRenderScheduled(); + expect(profiler.beginRender()).toBeNull(); + }); + + it('emits a discarded measure when a render is aborted', () => { + const clock = makeRuntime(); + const profiler = new InputLatencyProfiler(clock.runtime); + + profiler.recordBeforeInput({ inputType: 'insertText', isComposing: false }); + clock.advance(3); + profiler.recordTransaction(2); + profiler.recordRenderScheduled(); + const renderId = profiler.beginRender(); + profiler.abortRender(renderId!, 'render-aborted'); + + const discarded = measureCalls(clock.performance, 'superdoc.input-latency.discarded'); + expect(discarded).toHaveLength(1); + expect(discarded[0]?.[1]).toMatchObject({ detail: { reason: 'render-aborted' } }); + // Aborted render no longer completes. + profiler.completeAfterNextFrame(renderId!, { documentSize: 1, blockCount: 1, pageCount: 1 }); + clock.flushFrame(); + expect(totalCalls(clock.performance)).toHaveLength(0); + }); + + it('never throws when User Timing calls fail and warns instead', () => { + const clock = makeRuntime(); + vi.mocked(clock.performance.measure).mockImplementation(() => { + throw new Error('measure failed'); + }); + const profiler = new InputLatencyProfiler(clock.runtime); + + profiler.recordBeforeInput({ inputType: 'insertText', isComposing: false }); + clock.advance(2); + profiler.recordTransaction(1); + profiler.recordRenderScheduled(); + const renderId = profiler.beginRender(); + profiler.recordDomPaint(renderId!, 5); + expect(() => { + profiler.completeAfterNextFrame(renderId!, { documentSize: 1, blockCount: 1, pageCount: 1 }); + clock.flushFrame(); + }).not.toThrow(); + expect(clock.warn).toHaveBeenCalled(); + }); + + it('cancels a pending frame and discards active traces on destroy', () => { + const clock = makeRuntime(); + const profiler = new InputLatencyProfiler(clock.runtime); + + profiler.recordBeforeInput({ inputType: 'insertText', isComposing: false }); + clock.advance(2); + profiler.recordTransaction(1); + profiler.recordRenderScheduled(); + const renderId = profiler.beginRender(); + profiler.recordDomPaint(renderId!, 5); + profiler.completeAfterNextFrame(renderId!, { documentSize: 1, blockCount: 1, pageCount: 1 }); + expect(clock.pendingFrames).toBe(1); + + profiler.destroy(); + expect(clock.runtime.cancelAnimationFrame).toHaveBeenCalled(); + expect(clock.pendingFrames).toBe(0); + const discarded = measureCalls(clock.performance, 'superdoc.input-latency.discarded'); + expect( + discarded.some(([, options]) => (options as { detail?: { reason?: string } })?.detail?.reason === 'destroyed'), + ).toBe(true); + expect(totalCalls(clock.performance)).toHaveLength(0); + }); +}); diff --git a/packages/super-editor/src/editors/v1/core/presentation-editor/performance/InputLatencyProfiler.ts b/packages/super-editor/src/editors/v1/core/presentation-editor/performance/InputLatencyProfiler.ts new file mode 100644 index 0000000000..8d5c3de975 --- /dev/null +++ b/packages/super-editor/src/editors/v1/core/presentation-editor/performance/InputLatencyProfiler.ts @@ -0,0 +1,332 @@ +/** + * Internal, opt-in input-latency profiler for the presentation editor. + * + * The profiler correlates a visible `beforeinput`, the ProseMirror transaction it + * produces, the coalesced presentation render that flushes it, per-phase layout + * timings, DOM paint, and the following animation frame. It emits standard User + * Timing measures prefixed with `superdoc.input-latency.` so a developer-only + * recorder can read them back through `performance.getEntriesByName`. + * + * It is created only when profiling is explicitly enabled (see + * {@link createInputLatencyProfiler}). When disabled, no profiler, marks, + * measures, timers, or sample arrays are created; call sites do a single null + * check. No profiling data is ever transmitted and no document text is included + * in measure details. + */ + +export const INPUT_LATENCY_PREFIX = 'superdoc.input-latency'; +export const INPUT_LATENCY_SCHEMA_VERSION = 1; + +const NAME_TOTAL = `${INPUT_LATENCY_PREFIX}.total`; +const NAME_DOM_PAINT = `${INPUT_LATENCY_PREFIX}.input-to-dom-paint`; +const NAME_TRANSACTION = `${INPUT_LATENCY_PREFIX}.transaction`; +const NAME_DISCARDED = `${INPUT_LATENCY_PREFIX}.discarded`; +const stageMeasureName = (stage: InputLatencyStage) => `${INPUT_LATENCY_PREFIX}.stage.${stage}`; + +const MAX_TRACE_AGE_MS = 10_000; +const MAX_PENDING_INPUTS = 200; + +export type InputLatencyStage = + | 'get-json' + | 'position-map' + | 'to-flow-blocks' + | 'font-readiness' + | 'incremental-layout' + | 'resolve-layout' + | 'header-footer' + | 'paint' + | 'post-paint'; + +export type InputLatencyRuntime = { + performance: Pick; + requestAnimationFrame: (callback: FrameRequestCallback) => number; + cancelAnimationFrame: (handle: number) => void; + warn?: (message: string) => void; +}; + +export type InputLatencyContext = { + documentSize: number; + blockCount: number; + pageCount: number; +}; + +export type InputLatencyMeasureDetail = InputLatencyContext & { + schemaVersion: 1; + inputId: number; + renderId: number; + inputType: 'insertText'; + coalescedInputCount: number; +}; + +type InputTrace = { + id: number; + inputType: 'insertText'; + startedAt: number; + transactionEndedAt?: number; + transactionDurationMs?: number; +}; + +type RenderTrace = { + id: number; + scheduledAt: number; + startedAt?: number; + domPaintedAt?: number; + frameHandle?: number; + inputTraces: InputTrace[]; + stages: Map; +}; + +function isSupportedInput(input: { inputType: string; isComposing: boolean }): boolean { + return input.isComposing === false && input.inputType === 'insertText'; +} + +function isEnabled(windowLike: Window): boolean { + const debugGlobal = windowLike as Window & { __SD_DEBUG_INPUT_LATENCY__?: boolean }; + const envValue = + typeof process !== 'undefined' && typeof process.env !== 'undefined' + ? process.env.SD_DEBUG_INPUT_LATENCY + : undefined; + return debugGlobal.__SD_DEBUG_INPUT_LATENCY__ === true || envValue === '1' || envValue === 'true'; +} + +export class InputLatencyProfiler { + #runtime: InputLatencyRuntime; + #nextInputId = 1; + #nextRenderId = 1; + + /** Inputs seen via `recordBeforeInput`, awaiting a matching transaction (FIFO). */ + #pendingInputs: InputTrace[] = []; + /** Inputs whose transaction has completed, awaiting a scheduled render. */ + #transactionCompleteInputs: InputTrace[] = []; + /** The render scheduled but not yet begun; coalesces inputs until `beginRender`. */ + #scheduledRender: RenderTrace | null = null; + /** Renders that have begun and not yet completed/aborted. */ + #activeRenders = new Map(); + + constructor(runtime: InputLatencyRuntime) { + this.#runtime = runtime; + } + + recordBeforeInput(input: { inputType: string; isComposing: boolean }): number | null { + if (!isSupportedInput(input)) return null; + this.#pruneStaleInputs(); + if (this.#pendingInputs.length >= MAX_PENDING_INPUTS) { + const dropped = this.#pendingInputs.shift(); + if (dropped) this.#emitDiscarded('pending-overflow'); + } + const trace: InputTrace = { + id: this.#nextInputId++, + inputType: 'insertText', + startedAt: this.#now(), + }; + this.#pendingInputs.push(trace); + return trace.id; + } + + recordTransaction(durationMs: number): void { + const trace = this.#pendingInputs.shift(); + if (!trace) return; + trace.transactionEndedAt = this.#now(); + trace.transactionDurationMs = durationMs; + this.#transactionCompleteInputs.push(trace); + } + + recordRenderScheduled(): number | null { + if (this.#transactionCompleteInputs.length === 0 && !this.#scheduledRender) { + return null; + } + if (!this.#scheduledRender) { + this.#scheduledRender = { + id: this.#nextRenderId++, + scheduledAt: this.#now(), + inputTraces: [], + stages: new Map(), + }; + } + this.#scheduledRender.inputTraces.push(...this.#transactionCompleteInputs); + this.#transactionCompleteInputs = []; + return this.#scheduledRender.id; + } + + beginRender(): number | null { + const render = this.#scheduledRender; + if (!render) return null; + this.#scheduledRender = null; + render.startedAt = this.#now(); + this.#activeRenders.set(render.id, render); + return render.id; + } + + recordStage(renderId: number, stage: InputLatencyStage, start: number, end: number): void { + const render = this.#activeRenders.get(renderId); + if (!render) return; + render.stages.set(stage, { start, end }); + } + + recordDomPaint(renderId: number, at: number): void { + const render = this.#activeRenders.get(renderId); + if (!render) return; + render.domPaintedAt = at; + } + + completeAfterNextFrame(renderId: number, context: InputLatencyContext): void { + const render = this.#activeRenders.get(renderId); + if (!render) return; + render.frameHandle = this.#runtime.requestAnimationFrame((frameTime) => { + render.frameHandle = undefined; + // The active render may have been removed by destroy(); guard against it. + if (!this.#activeRenders.has(renderId)) return; + this.#emitRenderMeasures(render, context, frameTime); + this.#finishRender(render); + }); + } + + abortRender(renderId: number, reason: string): void { + const render = this.#activeRenders.get(renderId); + if (!render) return; + if (render.frameHandle != null) { + this.#safe(() => this.#runtime.cancelAnimationFrame(render.frameHandle as number)); + render.frameHandle = undefined; + } + this.#emitDiscarded(reason, render); + this.#finishRender(render); + } + + destroy(): void { + for (const render of this.#activeRenders.values()) { + if (render.frameHandle != null) { + this.#safe(() => this.#runtime.cancelAnimationFrame(render.frameHandle as number)); + render.frameHandle = undefined; + } + this.#emitDiscarded('destroyed', render); + this.#clearRenderMarks(render); + } + this.#activeRenders.clear(); + if (this.#scheduledRender) { + this.#emitDiscarded('destroyed', this.#scheduledRender); + this.#scheduledRender = null; + } + if (this.#pendingInputs.length > 0 || this.#transactionCompleteInputs.length > 0) { + this.#emitDiscarded('destroyed'); + } + this.#pendingInputs = []; + this.#transactionCompleteInputs = []; + } + + #now(): number { + return this.#safeValue(() => this.#runtime.performance.now(), 0); + } + + #emitRenderMeasures(render: RenderTrace, context: InputLatencyContext, frameTime: number): void { + const coalescedInputCount = render.inputTraces.length; + for (const input of render.inputTraces) { + const detail: InputLatencyMeasureDetail = { + schemaVersion: INPUT_LATENCY_SCHEMA_VERSION, + inputId: input.id, + renderId: render.id, + inputType: 'insertText', + coalescedInputCount, + documentSize: context.documentSize, + blockCount: context.blockCount, + pageCount: context.pageCount, + }; + this.#measure(NAME_TOTAL, input.startedAt, frameTime, detail); + if (render.domPaintedAt != null) { + this.#measure(NAME_DOM_PAINT, input.startedAt, render.domPaintedAt, detail); + } + if (input.transactionEndedAt != null && input.transactionDurationMs != null) { + const start = input.transactionEndedAt - input.transactionDurationMs; + this.#measure(NAME_TRANSACTION, start, input.transactionEndedAt, detail); + } + for (const [stage, span] of render.stages) { + this.#measure(stageMeasureName(stage), span.start, span.end, detail); + } + } + this.#clearRenderMarks(render); + } + + #emitDiscarded(reason: string, render?: RenderTrace): void { + const now = this.#now(); + this.#safe(() => + this.#runtime.performance.measure(NAME_DISCARDED, { + start: now, + end: now, + detail: { + schemaVersion: INPUT_LATENCY_SCHEMA_VERSION, + reason, + renderId: render?.id, + inputCount: render?.inputTraces.length, + }, + } as PerformanceMeasureOptions), + ); + } + + #finishRender(render: RenderTrace): void { + this.#clearRenderMarks(render); + this.#activeRenders.delete(render.id); + } + + #clearRenderMarks(render: RenderTrace): void { + for (const input of render.inputTraces) { + this.#safe(() => this.#runtime.performance.clearMarks(`${INPUT_LATENCY_PREFIX}.input-${input.id}`)); + } + } + + #pruneStaleInputs(): void { + const now = this.#now(); + const cutoff = now - MAX_TRACE_AGE_MS; + const staleCount = this.#pendingInputs.filter((input) => input.startedAt < cutoff).length; + if (staleCount > 0) { + this.#pendingInputs = this.#pendingInputs.filter((input) => input.startedAt >= cutoff); + this.#emitDiscarded('stale-pending'); + } + } + + #measure(name: string, start: number, end: number, detail: InputLatencyMeasureDetail): void { + this.#safe(() => + this.#runtime.performance.measure(name, { + start, + end, + detail, + } as PerformanceMeasureOptions), + ); + } + + #safe(fn: () => void): void { + try { + fn(); + } catch (error) { + this.#warn(error); + } + } + + #safeValue(fn: () => T, fallback: T): T { + try { + return fn(); + } catch (error) { + this.#warn(error); + return fallback; + } + } + + #warn(error: unknown): void { + const message = error instanceof Error ? error.message : String(error); + if (this.#runtime.warn) { + try { + this.#runtime.warn(`[input-latency] ${message}`); + } catch { + // Swallow: profiling must never affect editor behavior. + } + } + } +} + +export function createInputLatencyProfiler(windowLike: Window): InputLatencyProfiler | null { + if (!isEnabled(windowLike)) return null; + return new InputLatencyProfiler({ + performance: windowLike.performance, + requestAnimationFrame: windowLike.requestAnimationFrame.bind(windowLike), + cancelAnimationFrame: windowLike.cancelAnimationFrame.bind(windowLike), + warn: (message) => console.warn(message), + }); +} From e999bc98f1512a0152ad8208fc0285ac0ab3392b Mon Sep 17 00:00:00 2001 From: Dmytro Harastovych Date: Mon, 20 Jul 2026 22:15:32 +0300 Subject: [PATCH 04/15] feat(super-editor): trace visible text input --- .../input/PresentationInputBridge.ts | 15 +++++ .../tests/PresentationInputBridge.test.ts | 64 +++++++++++++++++++ 2 files changed, 79 insertions(+) diff --git a/packages/super-editor/src/editors/v1/core/presentation-editor/input/PresentationInputBridge.ts b/packages/super-editor/src/editors/v1/core/presentation-editor/input/PresentationInputBridge.ts index 41f54261d0..8203b4ef56 100644 --- a/packages/super-editor/src/editors/v1/core/presentation-editor/input/PresentationInputBridge.ts +++ b/packages/super-editor/src/editors/v1/core/presentation-editor/input/PresentationInputBridge.ts @@ -26,6 +26,7 @@ export class PresentationInputBridge { /** Callback that returns whether the editor is in an editable mode (editing/suggesting vs viewing) */ #isEditable: () => boolean; #onTargetChanged?: (target: HTMLElement | null) => void; + #onBeforeInput?: (input: { inputType: string; isComposing: boolean }) => void; #listeners: Array<{ type: string; handler: EventListener; target: EventTarget; useCapture: boolean }>; #currentTarget: HTMLElement | null = null; #destroyed = false; @@ -47,6 +48,8 @@ export class PresentationInputBridge { * - useWindowFallback: Whether to attach window-level event listeners as fallback * - getTargetEditor: Returns the active editor so focus restoration can * use editor-aware focus logic instead of raw DOM focus + * - onBeforeInput: Optional profiling hook invoked exactly once, synchronously, + * for each eligible visible-surface `beforeinput` before it is forwarded */ constructor( windowRoot: Window, @@ -57,6 +60,7 @@ export class PresentationInputBridge { options?: { useWindowFallback?: boolean; getTargetEditor?: () => BridgeTargetEditor | null; + onBeforeInput?: (input: { inputType: string; isComposing: boolean }) => void; }, ) { this.#windowRoot = windowRoot; @@ -65,6 +69,7 @@ export class PresentationInputBridge { this.#getTargetEditor = options?.getTargetEditor; this.#isEditable = isEditable; this.#onTargetChanged = onTargetChanged; + this.#onBeforeInput = options?.onBeforeInput; this.#listeners = []; this.#useWindowFallback = options?.useWindowFallback ?? false; } @@ -416,6 +421,16 @@ export class PresentationInputBridge { if (event.defaultPrevented) { return; } + + // Notify the input-latency profiler about the visible-surface beforeinput before it is + // marked/forwarded, so a supported keystroke is timed from its earliest observable point. + if (event.type === 'beforeinput') { + this.#onBeforeInput?.({ + inputType: (event as InputEvent).inputType ?? 'insertText', + isComposing: (event as InputEvent).isComposing ?? false, + }); + } + this.#markForwardedByBridge(event); const dispatchSyntheticEvent = () => { diff --git a/packages/super-editor/src/editors/v1/core/presentation-editor/tests/PresentationInputBridge.test.ts b/packages/super-editor/src/editors/v1/core/presentation-editor/tests/PresentationInputBridge.test.ts index 4e9abb5450..d76c4f6115 100644 --- a/packages/super-editor/src/editors/v1/core/presentation-editor/tests/PresentationInputBridge.test.ts +++ b/packages/super-editor/src/editors/v1/core/presentation-editor/tests/PresentationInputBridge.test.ts @@ -365,3 +365,67 @@ describe('PresentationInputBridge - Context Menu Handling', () => { }); }); }); + +describe('PresentationInputBridge - Input Latency Hook', () => { + let bridge: PresentationInputBridge; + let layoutSurface: HTMLElement; + let targetDom: HTMLElement; + let getTargetDom: () => HTMLElement | null; + let isEditable: () => boolean; + let windowRoot: Window; + let calls: string[]; + + beforeEach(() => { + layoutSurface = document.createElement('div'); + targetDom = document.createElement('div'); + document.body.appendChild(layoutSurface); + document.body.appendChild(targetDom); + + getTargetDom = vi.fn(() => targetDom); + isEditable = vi.fn(() => true); + windowRoot = window; + calls = []; + + bridge = new PresentationInputBridge(windowRoot, layoutSurface, getTargetDom, isEditable, undefined, { + onBeforeInput: ({ inputType, isComposing }) => { + calls.push(`hook:${inputType}:${isComposing}`); + }, + }); + targetDom.addEventListener('beforeinput', () => calls.push('forwarded')); + bridge.bind(); + }); + + it('invokes the hook synchronously before forwarding the beforeinput', async () => { + layoutSurface.dispatchEvent( + new InputEvent('beforeinput', { + data: 'a', + inputType: 'insertText', + bubbles: true, + cancelable: true, + }), + ); + + expect(calls).toEqual(['hook:insertText:false']); + await Promise.resolve(); + expect(calls).toEqual(['hook:insertText:false', 'forwarded']); + }); + + it.each(['input', 'textInput'])('does not profile %s events', async (eventType) => { + layoutSurface.dispatchEvent(new InputEvent(eventType, { data: 'a', bubbles: true })); + await Promise.resolve(); + expect(calls.some((entry) => entry.startsWith('hook:'))).toBe(false); + }); + + it('does not profile the same forwarded beforeinput twice', async () => { + const event = new InputEvent('beforeinput', { + data: 'a', + inputType: 'insertText', + bubbles: true, + cancelable: true, + }); + layoutSurface.dispatchEvent(event); + await Promise.resolve(); + targetDom.dispatchEvent(event); + expect(calls.filter((entry) => entry.startsWith('hook:'))).toHaveLength(1); + }); +}); From 76fd674ef36e174d088d7c849492206c620ecec3 Mon Sep 17 00:00:00 2001 From: Dmytro Harastovych Date: Mon, 20 Jul 2026 23:04:50 +0300 Subject: [PATCH 05/15] feat(super-editor): trace input through presentation paint --- .../presentation-editor/PresentationEditor.ts | 56 ++++- .../tests/PresentationEditor.test.ts | 215 ++++++++++++++++++ 2 files changed, 268 insertions(+), 3 deletions(-) diff --git a/packages/super-editor/src/editors/v1/core/presentation-editor/PresentationEditor.ts b/packages/super-editor/src/editors/v1/core/presentation-editor/PresentationEditor.ts index dfd6dbc94d..b16d5f6511 100644 --- a/packages/super-editor/src/editors/v1/core/presentation-editor/PresentationEditor.ts +++ b/packages/super-editor/src/editors/v1/core/presentation-editor/PresentationEditor.ts @@ -211,6 +211,11 @@ import { installBundledSubstitutes } from '@superdoc/font-system/bundled'; import { FontReadinessGate } from './fonts/FontReadinessGate'; import { DocumentFontController, type EmbeddedFontFace } from './fonts/DocumentFontController'; import { planFontFaces, type FontPlan } from './fonts/font-load-planner'; +import { + createInputLatencyProfiler, + type InputLatencyProfiler, + type InputLatencyStage, +} from './performance/InputLatencyProfiler.js'; import type { FontsChangedPayload } from '../types/EditorEvents'; import type { FontFamilyConfig } from '../types/EditorConfig'; import type { @@ -574,6 +579,8 @@ export class PresentationEditor extends EventEmitter { #compositionTargetCleanup: Array<() => void> = []; #compositionTargetDom: HTMLElement | null = null; #selectionSync = new SelectionSyncCoordinator(); + /** Opt-in input-latency profiler; null unless `SD_DEBUG_INPUT_LATENCY` / the debug global is set. */ + #inputLatencyProfiler: InputLatencyProfiler | null = null; /** Load-before-measure gate: awaits required fonts before measurement, reflows on late load. */ #fontGate: FontReadinessGate | null = null; /** @@ -777,6 +784,8 @@ export class PresentationEditor extends EventEmitter { this.#visibleHost.tabIndex = 0; } const viewForPosition = this.#visibleHost.ownerDocument?.defaultView ?? window; + // Opt-in only: returns null (and allocates nothing) unless input-latency profiling is enabled. + this.#inputLatencyProfiler = createInputLatencyProfiler(viewForPosition); if (viewForPosition.getComputedStyle(this.#visibleHost).position === 'static') { this.#visibleHost.style.position = 'relative'; } @@ -5111,6 +5120,8 @@ export class PresentationEditor extends EventEmitter { this.#inputBridge?.notifyTargetChanged(); this.#inputBridge?.destroy(); this.#inputBridge = null; + this.#inputLatencyProfiler?.destroy(); + this.#inputLatencyProfiler = null; this.#teardownCompositionDeferral(); if (this.#a11ySelectionAnnounceTimeout != null) { @@ -5449,6 +5460,9 @@ export class PresentationEditor extends EventEmitter { } } this.#selectionSync.onLayoutStart(); + if (transaction?.docChanged) { + this.#inputLatencyProfiler?.recordRenderScheduled(); + } this.#scheduleRerender(); } // Update local cursor in awareness whenever document changes @@ -5498,8 +5512,11 @@ export class PresentationEditor extends EventEmitter { // When decoration state changes without a doc change (e.g. setFocus), we must // still run a full rerender so runs are split at the new decoration boundaries; // otherwise the bridge applies the class to whole runs and highlights too much. - const handleTransaction = (event?: { transaction?: Transaction }) => { + const handleTransaction = (event?: { transaction?: Transaction; duration?: number }) => { const tr = event?.transaction; + if (tr?.docChanged && typeof event?.duration === 'number') { + this.#inputLatencyProfiler?.recordTransaction(event.duration); + } this.#postPaintPipeline.recordDecorationTransaction(tr); const state = this.#editor?.view?.state; const decorationChanged = state && this.#postPaintPipeline.hasDecorationChanges(state); @@ -6078,6 +6095,7 @@ export class PresentationEditor extends EventEmitter { { useWindowFallback: true, getTargetEditor: () => this.getActiveEditor(), + onBeforeInput: (input) => this.#inputLatencyProfiler?.recordBeforeInput(input), }, ); this.#inputBridge.bind(); @@ -7234,8 +7252,9 @@ export class PresentationEditor extends EventEmitter { const activeHfEditor = sessionMode !== 'body' ? this.#headerFooterSession?.activeEditor : null; const hadHfFocus = activeHfEditor?.view?.hasFocus?.() ?? false; + const latencyRenderId = this.#inputLatencyProfiler?.beginRender() ?? null; try { - await this.#rerender(); + await this.#rerender(latencyRenderId); } finally { this.#isRerendering = false; if (this.#pendingDocChange) { @@ -7259,7 +7278,7 @@ export class PresentationEditor extends EventEmitter { } } - async #rerender() { + async #rerender(latencyRenderId: number | null = null) { this.#selectionSync.onLayoutStart(); let layoutCompleted = false; @@ -7268,11 +7287,17 @@ export class PresentationEditor extends EventEmitter { const viewWindow = this.#visibleHost.ownerDocument?.defaultView ?? window; const perf = viewWindow?.performance ?? GLOBAL_PERFORMANCE; const perfNow = () => (perf?.now ? perf.now() : Date.now()); + const recordLatencyStage = (stage: InputLatencyStage, start: number, end: number) => { + if (latencyRenderId != null) { + this.#inputLatencyProfiler?.recordStage(latencyRenderId, stage, start, end); + } + }; const startMark = perf?.now?.(); try { const getJsonStart = perfNow(); docJson = this.#editor.getJSON(); const getJsonEnd = perfNow(); + recordLatencyStage('get-json', getJsonStart, getJsonEnd); perfLog(`[Perf] getJSON: ${(getJsonEnd - getJsonStart).toFixed(2)}ms`); } catch (error) { this.#handleLayoutError('render', this.#decorateError(error, 'getJSON')); @@ -7421,6 +7446,7 @@ export class PresentationEditor extends EventEmitter { const positionMap = this.#editor?.state?.doc && docJson ? buildPositionMapFromPmDoc(this.#editor.state.doc, docJson) : null; const positionMapEnd = perfNow(); + recordLatencyStage('position-map', positionMapStart, positionMapEnd); perfLog(`[Perf] buildPositionMapFromPmDoc: ${(positionMapEnd - positionMapStart).toFixed(2)}ms`); const commentsEnabled = this.#documentMode !== 'viewing' || this.#layoutOptions.enableCommentsInViewing === true; @@ -7445,6 +7471,7 @@ export class PresentationEditor extends EventEmitter { ...(atomNodeTypes.length > 0 ? { atomNodeTypes } : {}), }); const toFlowBlocksEnd = perfNow(); + recordLatencyStage('to-flow-blocks', toFlowBlocksStart, toFlowBlocksEnd); perfLog( `[Perf] toFlowBlocks: ${(toFlowBlocksEnd - toFlowBlocksStart).toFixed(2)}ms (blocks=${result.blocks.length})`, ); @@ -7542,6 +7569,7 @@ export class PresentationEditor extends EventEmitter { // so it must load before measure or it reflows on late load. Reused unchanged for the // incrementalLayout call and the per-rId header/footer pass. const headerFooterInput = this.#buildHeaderFooterInput(); + const fontReadinessStart = perfNow(); // Load-before-measure gate (T3): wait for the fonts this document needs so the first // measurement pass uses real metrics instead of a fallback that would reflow on load. // Bounded by a per-font timeout; resolves to the cached summary once fonts are stable; @@ -7576,6 +7604,7 @@ export class PresentationEditor extends EventEmitter { } catch { /* font readiness must never break layout */ } + recordLatencyStage('font-readiness', fontReadinessStart, perfNow()); try { const incrementalLayoutStart = perfNow(); @@ -7597,6 +7626,7 @@ export class PresentationEditor extends EventEmitter { ); this.#footnoteReserveSeed = result?.footnoteReserveSeed ?? null; const incrementalLayoutEnd = perfNow(); + recordLatencyStage('incremental-layout', incrementalLayoutStart, incrementalLayoutEnd); perfLog(`[Perf] incrementalLayout: ${(incrementalLayoutEnd - incrementalLayoutStart).toFixed(2)}ms`); // Type guard: validate incrementalLayout return value @@ -7629,6 +7659,7 @@ export class PresentationEditor extends EventEmitter { resolveBlocks = bodyBlocksForPaint; resolveMeasures = bodyMeasuresForPaint; + const resolveLayoutStart = perfNow(); resolvedLayout = resolveLayout({ layout, flowMode: this.#layoutOptions.flowMode ?? 'paginated', @@ -7637,6 +7668,7 @@ export class PresentationEditor extends EventEmitter { fontSignature, bookmarks, }); + recordLatencyStage('resolve-layout', resolveLayoutStart, perfNow()); headerLayouts = result.headers; footerLayouts = result.footers; @@ -7711,7 +7743,9 @@ export class PresentationEditor extends EventEmitter { // Process per-rId header/footer content and decoration providers (paginated only) if (!isSemanticFlow) { + const headerFooterStart = perfNow(); await this.#layoutPerRIdHeaderFooters(headerFooterInput, layout, sectionMetadata); + recordLatencyStage('header-footer', headerFooterStart, perfNow()); this.#updateDecorationProviders(resolvedLayout); } @@ -7735,11 +7769,16 @@ export class PresentationEditor extends EventEmitter { }; this.#painterAdapter.paint(paintInput, this.#painterHost, mapping ?? undefined); const painterPaintEnd = perfNow(); + recordLatencyStage('paint', painterPaintStart, painterPaintEnd); + if (latencyRenderId != null) { + this.#inputLatencyProfiler?.recordDomPaint(latencyRenderId, painterPaintEnd); + } perfLog(`[Perf] painter.paint: ${(painterPaintEnd - painterPaintStart).toFixed(2)}ms`); const painterPostStart = perfNow(); this.#refreshEditorDomAugmentations(); this.#domIndexObserverManager?.resume(); const painterPostEnd = perfNow(); + recordLatencyStage('post-paint', painterPostStart, painterPostEnd); perfLog(`[Perf] painter.postPaint: ${(painterPostEnd - painterPostStart).toFixed(2)}ms`); this.#layoutEpoch = layoutEpoch; if (this.#updateHtmlAnnotationMeasurements(layoutEpoch)) { @@ -7765,6 +7804,14 @@ export class PresentationEditor extends EventEmitter { this.emit('layoutUpdated', payload); this.emit('paginationUpdate', payload); + if (latencyRenderId != null) { + this.#inputLatencyProfiler?.completeAfterNextFrame(latencyRenderId, { + documentSize: this.#editor.state.doc.content.size, + blockCount: blocksForLayout.length, + pageCount: layout.pages?.length ?? 0, + }); + } + // SD-3400: fragments are rebuilt on every paint — re-apply the active // note highlight and complete any pending scroll-to-note. this.#noteSessionCoordinator?.onPaint(); @@ -7785,6 +7832,9 @@ export class PresentationEditor extends EventEmitter { this.#remoteCursorManager.scheduleUpdate(); } } finally { + if (!layoutCompleted && latencyRenderId != null) { + this.#inputLatencyProfiler?.abortRender(latencyRenderId, 'render-aborted'); + } if (!layoutCompleted) { this.#selectionSync.onLayoutAbort(); } diff --git a/packages/super-editor/src/editors/v1/core/presentation-editor/tests/PresentationEditor.test.ts b/packages/super-editor/src/editors/v1/core/presentation-editor/tests/PresentationEditor.test.ts index 99b22a8763..40f1f3ee73 100644 --- a/packages/super-editor/src/editors/v1/core/presentation-editor/tests/PresentationEditor.test.ts +++ b/packages/super-editor/src/editors/v1/core/presentation-editor/tests/PresentationEditor.test.ts @@ -6447,4 +6447,219 @@ describe('PresentationEditor', () => { }); }); }); + + describe('input latency profiling', () => { + const debugGlobal = window as Window & { __SD_DEBUG_INPUT_LATENCY__?: boolean }; + let frameCallbacks: Map; + let nextFrameId: number; + let rafSpy: ReturnType; + let cancelSpy: ReturnType; + let measureSpy: ReturnType; + + const totalMeasures = () => measureSpy.mock.calls.filter(([name]) => name === 'superdoc.input-latency.total'); + + const anyProfilingMeasure = () => + measureSpy.mock.calls.some(([name]) => String(name).startsWith('superdoc.input-latency.')); + + // Flush every currently-scheduled frame, awaiting microtasks between rounds so the + // async #rerender pipeline (font gate, incrementalLayout, paint) can progress. Each + // round may schedule more frames (e.g. the profiler completion frame), so loop until + // drained or a bound is hit. + const pumpFrames = async (rounds = 30) => { + for (let round = 0; round < rounds && frameCallbacks.size > 0; round++) { + const batch = [...frameCallbacks.values()]; + frameCallbacks.clear(); + for (const cb of batch) { + try { + cb(performance.now()); + } catch { + // Later frames may run against a torn-down editor; profiling must not be affected. + } + await Promise.resolve(); + } + await Promise.resolve(); + } + }; + + // Repeatedly pump captured frames until the assertion holds, so the RAF-gated, + // async render pipeline gets driven forward while we wait. + const settle = async (assertion: () => void) => { + await vi.waitFor( + async () => { + await pumpFrames(); + assertion(); + }, + { timeout: 2000, interval: 10 }, + ); + }; + + // Fire exactly the frames queued right now (not any scheduled as a side effect), so a + // caller can advance the render one step without draining the profiler completion frame. + const pumpOnce = async () => { + const batch = [...frameCallbacks.values()]; + frameCallbacks.clear(); + for (const cb of batch) { + try { + cb(performance.now()); + } catch { + // ignore + } + await Promise.resolve(); + } + }; + + // Let the async #rerender promise chain settle without scheduling/firing more frames. + const drainAsync = async () => { + for (let i = 0; i < 12; i++) { + await new Promise((resolve) => setTimeout(resolve, 0)); + } + }; + + // Drive the RAF-gated async pipeline fully: fire the queued frame(s), let #rerender + // settle (which schedules the profiler completion frame), then fire that, and so on. + const runToIdle = async (maxSteps = 20) => { + for (let step = 0; step < maxSteps && frameCallbacks.size > 0; step++) { + await pumpOnce(); + await drainAsync(); + } + }; + + const getHandlers = () => { + const editorInstance = getLastEditorInstance(); + const onMock = editorInstance.on as unknown as Mock; + const calls = onMock.mock.calls; + // #setupEditorListeners registers 'update' then 'transaction' consecutively. Other + // subsystems (e.g. the history snapshot adapter) register their own 'transaction' + // earlier, so take the 'transaction' listener registered after the editor's 'update'. + const updateIndex = calls.findIndex(([event]) => event === 'update'); + const updateHandler = calls[updateIndex]![1]; + const transactionHandler = calls.slice(updateIndex).find(([event]) => event === 'transaction')![1]; + return { transactionHandler, updateHandler }; + }; + + const makeTransaction = () => ({ + docChanged: true, + mapping: { slice: vi.fn().mockReturnThis(), appendMapping: vi.fn() }, + getMeta: vi.fn(), + }); + + // Dispatch one visible insertText and drive the transaction/update it would produce. + const typeOneChar = async (duration = 6) => { + container.dispatchEvent( + new InputEvent('beforeinput', { + data: 'a', + inputType: 'insertText', + bubbles: true, + cancelable: true, + }), + ); + await Promise.resolve(); + const { transactionHandler, updateHandler } = getHandlers(); + const transaction = makeTransaction(); + transactionHandler({ transaction, duration }); + updateHandler({ transaction }); + }; + + const constructAndSettle = async (documentId: string) => { + editor = new PresentationEditor({ element: container, documentId }); + await settle(() => expect(mockIncrementalLayout).toHaveBeenCalled()); + await pumpFrames(); + measureSpy.mockClear(); + mockResolveLayout.mockClear(); + }; + + beforeEach(() => { + debugGlobal.__SD_DEBUG_INPUT_LATENCY__ = true; + frameCallbacks = new Map(); + nextFrameId = 1; + rafSpy = vi.spyOn(window, 'requestAnimationFrame').mockImplementation((callback) => { + const id = nextFrameId++; + frameCallbacks.set(id, callback); + return id; + }); + cancelSpy = vi.spyOn(window, 'cancelAnimationFrame').mockImplementation((id: number) => { + frameCallbacks.delete(id); + }); + measureSpy = vi.spyOn(performance, 'measure'); + }); + + afterEach(() => { + delete debugGlobal.__SD_DEBUG_INPUT_LATENCY__; + rafSpy.mockRestore(); + cancelSpy.mockRestore(); + measureSpy.mockRestore(); + }); + + it('emits a total measure for one input that reaches paint', async () => { + await constructAndSettle('latency-single-doc'); + + await typeOneChar(); + await runToIdle(); + + expect(totalMeasures()).toHaveLength(1); + expect(totalMeasures()[0]?.[1]).toMatchObject({ + detail: expect.objectContaining({ inputType: 'insertText', coalescedInputCount: 1 }), + }); + }); + + it('correlates two inputs with one coalesced presentation render', async () => { + await constructAndSettle('latency-coalesced-doc'); + + await typeOneChar(6); + await typeOneChar(4); + await runToIdle(); + + expect(totalMeasures()).toHaveLength(2); + const totals = totalMeasures(); + expect(totals[0]?.[1]).toMatchObject({ detail: { coalescedInputCount: 2 } }); + expect(totals[1]?.[1]).toMatchObject({ + detail: { renderId: totals[0]?.[1].detail.renderId, coalescedInputCount: 2 }, + }); + }); + + it('emits no measures when profiling is disabled', async () => { + delete debugGlobal.__SD_DEBUG_INPUT_LATENCY__; + await constructAndSettle('latency-disabled-doc'); + + await typeOneChar(); + await settle(() => expect(mockResolveLayout).toHaveBeenCalled()); + await pumpFrames(); + + expect(anyProfilingMeasure()).toBe(false); + }); + + it('discards the trace when layout fails', async () => { + await constructAndSettle('latency-layout-fail-doc'); + mockIncrementalLayout.mockRejectedValueOnce(new Error('layout failed')); + + await typeOneChar(); + await runToIdle(); + + expect(measureSpy).toHaveBeenCalledWith( + 'superdoc.input-latency.discarded', + expect.objectContaining({ detail: expect.objectContaining({ reason: 'render-aborted' }) }), + ); + expect(totalMeasures()).toHaveLength(0); + }); + + it('cancels profiler frame completion during destroy', async () => { + await constructAndSettle('latency-destroy-doc'); + + await typeOneChar(); + // Fire only the rerender frame, then let #rerender run to paint. It schedules the + // profiler completion frame synchronously, which we deliberately leave unfired. + await pumpOnce(); + await drainAsync(); + expect(mockResolveLayout).toHaveBeenCalled(); + expect(totalMeasures()).toHaveLength(0); + + cancelSpy.mockClear(); + editor.destroy(); + expect(cancelSpy).toHaveBeenCalled(); + + // Even if the (now-cancelled) completion frame is pumped, no total is emitted. + await pumpFrames(); + expect(totalMeasures()).toHaveLength(0); + }); + }); }); From 9430abbd83efae564bb1a1398e1e2263c1469fb4 Mon Sep 17 00:00:00 2001 From: Dmytro Harastovych Date: Mon, 20 Jul 2026 23:06:50 +0300 Subject: [PATCH 06/15] feat(devtools): compare input latency profiles --- devtools/input-latency/compare.mjs | 21 ++++ devtools/input-latency/report.mjs | 168 +++++++++++++++++++++++++ devtools/input-latency/report.test.mjs | 83 ++++++++++++ 3 files changed, 272 insertions(+) create mode 100644 devtools/input-latency/compare.mjs create mode 100644 devtools/input-latency/report.mjs create mode 100644 devtools/input-latency/report.test.mjs diff --git a/devtools/input-latency/compare.mjs b/devtools/input-latency/compare.mjs new file mode 100644 index 0000000000..aebb3f9b97 --- /dev/null +++ b/devtools/input-latency/compare.mjs @@ -0,0 +1,21 @@ +#!/usr/bin/env node +// Strict comparison CLI: reads two report JSON files, validates they are comparable, prints the +// JSON comparison to stdout, and optionally writes a Markdown summary. Exits non-zero on any +// parse, schema, or fingerprint error. +import fs from 'node:fs/promises'; +import { compareReports, renderMarkdownComparison } from './report.mjs'; + +const [baselinePath, afterPath, ...rest] = process.argv.slice(2); +if (!baselinePath || !afterPath) { + throw new Error('Usage: node compare.mjs [--markdown ]'); +} +const baseline = JSON.parse(await fs.readFile(baselinePath, 'utf8')); +const after = JSON.parse(await fs.readFile(afterPath, 'utf8')); +const comparison = compareReports(baseline, after); +const markdownIndex = rest.indexOf('--markdown'); +if (markdownIndex >= 0) { + const outputPath = rest[markdownIndex + 1]; + if (!outputPath) throw new Error('--markdown requires an output path'); + await fs.writeFile(outputPath, renderMarkdownComparison(comparison)); +} +process.stdout.write(`${JSON.stringify(comparison, null, 2)}\n`); diff --git a/devtools/input-latency/report.mjs b/devtools/input-latency/report.mjs new file mode 100644 index 0000000000..78b9d96f50 --- /dev/null +++ b/devtools/input-latency/report.mjs @@ -0,0 +1,168 @@ +// Deterministic statistics, scenario fingerprinting, and comparison for input-latency reports. +// +// This module is pure (no I/O, no clock, no randomness) so its behavior is fully reproducible +// and unit-testable. The recorder (profile.mjs) produces reports in the schema documented below; +// the comparator CLI (compare.mjs) consumes two reports and renders a delta. + +export const REPORT_SCHEMA_VERSION = 1; + +/** Linear-interpolation percentile. `ratio` in [0, 1]. */ +export function percentile(values, ratio) { + if (values.length === 0) return 0; + const sorted = [...values].sort((a, b) => a - b); + if (sorted.length === 1) return sorted[0]; + const index = (sorted.length - 1) * ratio; + const lower = Math.floor(index); + const upper = Math.ceil(index); + const weight = index - lower; + return sorted[lower] * (1 - weight) + sorted[upper] * weight; +} + +export function summarize(values) { + if (values.length === 0) { + return { count: 0, min: 0, average: 0, p50: 0, p95: 0, p99: 0, max: 0 }; + } + const total = values.reduce((sum, value) => sum + value, 0); + return { + count: values.length, + min: Math.min(...values), + average: total / values.length, + p50: percentile(values, 0.5), + p95: percentile(values, 0.95), + p99: percentile(values, 0.99), + max: Math.max(...values), + }; +} + +export function medianAbsoluteDeviation(values) { + if (values.length === 0) return 0; + const median = percentile(values, 0.5); + return percentile( + values.map((value) => Math.abs(value - median)), + 0.5, + ); +} + +/** + * Report-level fingerprint: everything that must match for two reports to be comparable, and + * nothing that legitimately varies between otherwise-identical runs. Deliberately EXCLUDES + * label, timestamp, git SHA, dirty status, absolute fixture path, and output path. + */ +export function buildReportFingerprint(report) { + return { + schemaVersion: report.schemaVersion, + os: report.environment?.os, + arch: report.environment?.arch, + browserName: report.environment?.browserName, + browserVersion: report.environment?.browserVersion, + fixtureSha256: report.fixture?.sha256, + fixtureSize: report.fixture?.size, + zoom: report.protocol?.zoom, + documentMode: report.protocol?.documentMode, + warmupRuns: report.protocol?.warmupRuns, + measuredRuns: report.protocol?.measuredRuns, + sequence: report.protocol?.sequence, + cadenceMs: report.protocol?.cadenceMs, + }; +} + +/** Per-scenario fingerprint: layout mode, CPU throttle, and the document shape it measured. */ +export function buildScenarioFingerprint(scenario) { + return { + name: scenario.name, + layoutEnabled: scenario.layoutEnabled, + cpuThrottle: scenario.cpuThrottle, + pageCount: scenario.pageCount, + blockCount: scenario.blockCount, + }; +} + +function assertFingerprintsMatch(context, baseline, after) { + for (const key of Object.keys(baseline)) { + if (baseline[key] !== after[key]) { + throw new Error( + `Reports are not comparable: ${context}.${key} differs (baseline=${JSON.stringify( + baseline[key], + )}, after=${JSON.stringify(after[key])})`, + ); + } + } +} + +/** Throw if the two reports do not share an identical fingerprint (env + protocol + scenarios). */ +export function validateComparableReports(baseline, after) { + assertFingerprintsMatch('report', buildReportFingerprint(baseline), buildReportFingerprint(after)); + + const baselineScenarios = baseline.scenarios ?? []; + const afterScenarios = after.scenarios ?? []; + if (baselineScenarios.length !== afterScenarios.length) { + throw new Error( + `Reports are not comparable: scenario count differs (baseline=${baselineScenarios.length}, after=${afterScenarios.length})`, + ); + } + for (let i = 0; i < baselineScenarios.length; i++) { + assertFingerprintsMatch( + `scenario[${i}]`, + buildScenarioFingerprint(baselineScenarios[i]), + buildScenarioFingerprint(afterScenarios[i]), + ); + } +} + +/** p95 materiality: larger than 5 ms and larger than twice the noisier baseline/after MAD. */ +export function isMaterialDelta(baselineP95, afterP95, baselineMadMs, afterMadMs) { + const thresholdMs = Math.max(5, 2 * Math.max(baselineMadMs ?? 0, afterMadMs ?? 0)); + return Math.abs(afterP95 - baselineP95) > thresholdMs; +} + +const COMPARED_METRICS = ['inputToNextFrameMs']; + +/** Validate comparability, then emit per-scenario p95 deltas for each compared metric. */ +export function compareReports(baseline, after) { + validateComparableReports(baseline, after); + + const scenarios = baseline.scenarios.map((baselineScenario, i) => { + const afterScenario = after.scenarios[i]; + const metrics = {}; + for (const metric of COMPARED_METRICS) { + const baselineMetric = baselineScenario.metrics?.[metric]; + const afterMetric = afterScenario.metrics?.[metric]; + const baselineP95 = baselineMetric?.p95 ?? 0; + const afterP95 = afterMetric?.p95 ?? 0; + const deltaMs = afterP95 - baselineP95; + const deltaPercent = baselineP95 === 0 ? 0 : (deltaMs / baselineP95) * 100; + metrics[metric] = { + p95: { + baseline: baselineP95, + after: afterP95, + deltaMs, + deltaPercent, + material: isMaterialDelta(baselineP95, afterP95, baselineMetric?.runP95Mad, afterMetric?.runP95Mad), + }, + }; + } + return { name: baselineScenario.name, metrics }; + }); + + return { schemaVersion: REPORT_SCHEMA_VERSION, scenarios }; +} + +/** Render a comparison as a Markdown document with one delta table per scenario. */ +export function renderMarkdownComparison(comparison) { + const lines = ['# Input latency comparison', '']; + for (const scenario of comparison.scenarios) { + lines.push(`## ${scenario.name}`, ''); + lines.push('| metric | baseline | after | deltaMs | deltaPercent | material |'); + lines.push('| --- | --- | --- | --- | --- | --- |'); + for (const [metric, values] of Object.entries(scenario.metrics)) { + const p95 = values.p95; + lines.push( + `| ${metric} p95 | ${p95.baseline.toFixed(2)} | ${p95.after.toFixed(2)} | ${p95.deltaMs.toFixed( + 2, + )} | ${p95.deltaPercent.toFixed(2)}% | ${p95.material ? 'yes' : 'no'} |`, + ); + } + lines.push(''); + } + return `${lines.join('\n')}\n`; +} diff --git a/devtools/input-latency/report.test.mjs b/devtools/input-latency/report.test.mjs new file mode 100644 index 0000000000..5b7aba21be --- /dev/null +++ b/devtools/input-latency/report.test.mjs @@ -0,0 +1,83 @@ +import assert from 'node:assert/strict'; +import test from 'node:test'; +import { + summarize, + medianAbsoluteDeviation, + validateComparableReports, + compareReports, + renderMarkdownComparison, +} from './report.mjs'; + +function makeReport({ fixtureSha256, p95 = 120 }) { + return { + schemaVersion: 1, + environment: { + os: 'darwin', + arch: 'arm64', + browserName: 'chromium', + browserVersion: 'test-version', + }, + fixture: { sha256: fixtureSha256, size: 280245 }, + protocol: { + zoom: 1, + documentMode: 'editing', + warmupRuns: 1, + measuredRuns: 5, + sequence: 'abcdefghijklmnopqrstuvwxyzabcdefghijklmn', + cadenceMs: 100, + }, + scenarios: [ + { + name: 'layout-on-cpu-4x', + layoutEnabled: true, + cpuThrottle: 4, + pageCount: 7, + blockCount: 680, + runs: Array.from({ length: 5 }, (_, runIndex) => ({ + runIndex, + samples: [{ inputId: runIndex + 1, inputToNextFrameMs: p95 }], + metrics: { inputToNextFrameMs: { ...summarize([p95]), p95 } }, + })), + metrics: { + inputToNextFrameMs: { + ...summarize([p95, p95, p95, p95, p95]), + p95, + runP95Values: [p95, p95, p95, p95, p95], + runP95Mad: 0, + }, + }, + }, + ], + }; +} + +test('summarize returns interpolated percentiles and raw count', () => { + assert.deepEqual(summarize([10, 20, 30, 40, 50]), { + count: 5, + min: 10, + average: 30, + p50: 30, + p95: 48, + p99: 49.6, + max: 50, + }); + assert.equal(medianAbsoluteDeviation([100, 105, 110, 95, 100]), 5); +}); + +test('comparison rejects a fixture mismatch', () => { + const baseline = makeReport({ fixtureSha256: 'aaa' }); + const after = makeReport({ fixtureSha256: 'bbb' }); + assert.throws(() => validateComparableReports(baseline, after), /fixtureSha256/); +}); + +test('comparison emits absolute and percentage delta', () => { + const baseline = makeReport({ fixtureSha256: 'same', p95: 120 }); + const after = makeReport({ fixtureSha256: 'same', p95: 90 }); + const comparison = compareReports(baseline, after); + assert.equal(comparison.scenarios[0].metrics.inputToNextFrameMs.p95.deltaMs, -30); + assert.equal(comparison.scenarios[0].metrics.inputToNextFrameMs.p95.deltaPercent, -25); + assert.match( + renderMarkdownComparison(comparison), + /\| inputToNextFrameMs p95 \| 120\.00 \| 90\.00 \| -30\.00 \| -25\.00% \|/, + ); +}); From c428864bccdfcd08a69689e889f1f1b8cb381c96 Mon Sep 17 00:00:00 2001 From: Dmytro Harastovych Date: Mon, 20 Jul 2026 23:13:05 +0300 Subject: [PATCH 07/15] feat(devtools): record browser input latency --- devtools/input-latency/profile.mjs | 427 +++++++++++++++++++++++++++++ package.json | 5 +- pnpm-lock.yaml | 250 ++++++++++++----- 3 files changed, 620 insertions(+), 62 deletions(-) create mode 100644 devtools/input-latency/profile.mjs diff --git a/devtools/input-latency/profile.mjs b/devtools/input-latency/profile.mjs new file mode 100644 index 0000000000..dbb6864fdb --- /dev/null +++ b/devtools/input-latency/profile.mjs @@ -0,0 +1,427 @@ +#!/usr/bin/env node +// Developer-only input-latency recorder. +// +// Drives a headed Chromium instance against a running SuperDoc Labs URL, types a fixed sequence +// into a large local DOCX, and records the profiler's User Timing entries into a schema-version-1 +// JSON report. Never runs in CI: it needs a browser and a live dev server. See README.md. +// +// Profiling is opt-in and privacy-preserving: only timings and document-shape counts are captured; +// no document text is transmitted or stored. +import crypto from 'node:crypto'; +import fs from 'node:fs/promises'; +import os from 'node:os'; +import path from 'node:path'; +import { execFile } from 'node:child_process'; +import { promisify } from 'node:util'; +import { summarize, medianAbsoluteDeviation, REPORT_SCHEMA_VERSION } from './report.mjs'; + +const execFileAsync = promisify(execFile); + +const DEFAULT_SEQUENCE = 'abcdefghijklmnopqrstuvwxyzabcdefghijklmn'; +const DEFAULT_CADENCE_MS = 100; +const DEFAULT_WARMUP_RUNS = 1; +const DEFAULT_MEASURED_RUNS = 5; +const DEFAULT_SCENARIOS = [ + { name: 'layout-on-cpu-1x', layoutEnabled: true, cpuThrottle: 1 }, + { name: 'layout-on-cpu-4x', layoutEnabled: true, cpuThrottle: 4 }, + { name: 'layout-off-cpu-1x', layoutEnabled: false, cpuThrottle: 1 }, +]; + +const HELP = `Record input latency for a running SuperDoc Labs instance. + +Usage: + node devtools/input-latency/profile.mjs --url --fixture --label