From 16227e370404fb2e7813c05ead6d1126b77d6635 Mon Sep 17 00:00:00 2001 From: Chris Lorenzo Date: Fri, 28 Aug 2026 23:20:10 -0400 Subject: [PATCH] feat(core): add opt-in per-phase timing to the post-mutation flush `runPostMutation` runs as a microtask after a mutation batch, doing three things in sequence: the delete flush, the layout flush, and the focus apply. Its cost was not observable from outside, which made it impossible to say whether it was the fixed per-row cost a device investigation had cornered. That investigation, on a TV SoC running a virtualised row list, had measured a ~50ms cost to mount each new row, landing on the frame that handles the navigation keypress. A linear fit across item counts put roughly two thirds of it in cost that does NOT scale with the number of items in the row: halving items per row cut mount cost only 11% and moved frame rate not at all. The renderer's own share was ruled out by measurement (node creation is 0.054ms per node). A Chrome trace then caught `runPostMutation` at 36.7ms across five row mounts, roughly a third again on top of the keypress handler itself, which put it at the top of the list of suspects and left nothing to measure it with. Adds `Config.postMutationDebug` and a `postMutationTiming` counters object carrying call count, total and max, and the same pair for each of the three phases, plus `resetPostMutationTiming()` so a consumer can sample over an interval. `Config` is the established runtime debug seam here (`debug`, `focusDebug`, `keyDebug`, `focusHistoryDebug`) and is toggleable at runtime, which a benchmark page needs. Counters are mutated in place rather than passed to a callback so sampling allocates nothing. Off by default and free when off: `runPostMutation` reads the flag once and delegates to a separate `runPostMutationTimed`, so the default path never reaches a clock or takes a per-phase branch. Getting there meant extracting the three phase bodies into `flushDeletes` / `flushLayout` / `flushFocus` so both drivers share them; those bodies are unchanged. Worth knowing when reading the numbers: `schedulePostMutation` registers both `stage.reprocessUpdates(runPostMutation)` and `queueMicrotask(runPostMutation)`, and `runPostMutation` has no already-drained guard, so every mutation runs it twice. The second pass early-returns from all three phases on empty queues and costs nothing, but it halves any per-call mean. The trace above showed ten calls for five mounts, so the real per-call figure was 7.34ms rather than 3.67ms. The new `calls` counter makes this visible; the duplicate itself is left alone here since removing it is a behaviour change, not instrumentation. Tests: 4 new, covering silence when disabled, per-phase accumulation, that totals keep accumulating across flushes, and that reset zeroes everything. 113 pass, tsc clean. Co-Authored-By: Claude Opus 5 --- docs/essentials/render.md | 23 ++++++ src/core/config.ts | 11 +++ src/core/elementNode.ts | 130 ++++++++++++++++++++++++++---- tests/postMutationTiming.test.tsx | 114 ++++++++++++++++++++++++++ 4 files changed, 264 insertions(+), 14 deletions(-) create mode 100644 tests/postMutationTiming.test.tsx diff --git a/docs/essentials/render.md b/docs/essentials/render.md index d5bd6c2..750d336 100644 --- a/docs/essentials/render.md +++ b/docs/essentials/render.md @@ -110,6 +110,29 @@ Besides `rendererOptions`, the `Config` object exposes several properties specif Logs focus management events to help debug spatial navigation. - **keyDebug**: `boolean` (Default: `false`) Logs all key input events. +- **postMutationDebug**: `boolean` (Default: `false`) + Accumulates per-phase timings for the post-mutation flush (delete, layout, focus) into the exported `postMutationTiming` counters. The flush runs as a microtask after the key handler returns, so its cost does not show up under the handler in a profile. + + ```jsx + import { + Config, + postMutationTiming, + resetPostMutationTiming, + } from '@solidtv/solid'; + + Config.postMutationDebug = true; + + setInterval(() => { + const { calls, total, max, deleteTotal, layoutTotal, focusTotal } = + postMutationTiming; + console.log( + `post-mutation ${calls} calls, ${total.toFixed(1)}ms (max ${max.toFixed(1)}ms)`, + { deleteTotal, layoutTotal, focusTotal }, + ); + resetPostMutationTiming(); + }, 1000); + ``` + - **animationsEnabled**: `boolean` (Default: `true`) Global toggle to enable or disable animations. - **animationSettings**: `AnimationSettings` diff --git a/src/core/config.ts b/src/core/config.ts index 2b6e055..53c1593 100644 --- a/src/core/config.ts +++ b/src/core/config.ts @@ -51,6 +51,16 @@ export interface Config { domRendererEnabled: boolean; keyDebug: boolean; focusHistoryDebug: number; + /** + * Accumulate per-phase timings for the post-mutation flush into + * {@link postMutationTiming}. The flush runs as a microtask after the key + * handler returns, so its cost is invisible in a handler-scoped profile; + * this is the only way to attribute it to delete, layout or focus. + * + * Off by default and safe to toggle at runtime: the scheduler reads this + * once per flush and takes no timestamps while it is false. + */ + postMutationDebug: boolean; animationSettings?: AnimationSettings; animationsEnabled: boolean; fontSettings: Partial; @@ -78,6 +88,7 @@ export const Config: Config = { focusDebug: false, keyDebug: false, focusHistoryDebug: 0, + postMutationDebug: false, animationsEnabled: true, animationSettings: { duration: 250, diff --git a/src/core/elementNode.ts b/src/core/elementNode.ts index 56fd234..f05fb6c 100644 --- a/src/core/elementNode.ts +++ b/src/core/elementNode.ts @@ -100,21 +100,21 @@ function schedulePostMutation() { queueMicrotask(runPostMutation); } -function runPostMutation() { - postMutationQueued = false; +// Phase 1: delete-flush +function flushDeletes() { + if (elementDeleteQueue.length === 0) return; - // Phase 1: delete-flush - if (elementDeleteQueue.length > 0) { - for (const el of elementDeleteQueue) { - if ((el._queueDelete ?? 0) < 0) { - el.destroy(); - } - el._queueDelete = undefined; + for (const el of elementDeleteQueue) { + if ((el._queueDelete ?? 0) < 0) { + el.destroy(); } - elementDeleteQueue.length = 0; + el._queueDelete = undefined; } + elementDeleteQueue.length = 0; +} - // Phase 2: layout +// Phase 2: layout +function flushLayout() { while (layoutQueue.size > 0) { const queue = [...layoutQueue]; layoutQueue.clear(); @@ -123,10 +123,12 @@ function runPostMutation() { node.updateLayout(); } } +} - // Phase 3: focus. setFocus() may have evaluated forwardFocus pre-render - // (when no children existed yet); deferredFocusElement re-runs setFocus - // here once the subtree has rendered, then setActiveElementCore is applied. +// Phase 3: focus. setFocus() may have evaluated forwardFocus pre-render +// (when no children existed yet); deferredFocusElement re-runs setFocus +// here once the subtree has rendered, then setActiveElementCore is applied. +function flushFocus() { if (deferredFocusElement !== null) { const el = deferredFocusElement; deferredFocusElement = null; @@ -138,6 +140,106 @@ function runPostMutation() { } } +/** + * Per-phase timings for the post-mutation flush, accumulated across calls + * while {@link Config.postMutationDebug} is on. Milliseconds, from + * `performance.now()`. + * + * The totals answer "what did this cost over the sample window"; the `*Max` + * fields answer "what was the worst single flush", which is the number that + * shows up as a dropped frame. + */ +export interface PostMutationTiming { + /** Flushes run since the last reset. */ + calls: number; + /** Wall time spent in the flush, all phases. */ + total: number; + /** Worst single flush. */ + max: number; + /** Phase 1: destroying nodes removed and not re-inserted. */ + deleteTotal: number; + deleteMax: number; + /** Phase 2: draining the flex layout queue. */ + layoutTotal: number; + layoutMax: number; + /** Phase 3: deferred forwardFocus resolution, then setActiveElementCore. */ + focusTotal: number; + focusMax: number; +} + +/** + * Live counters written by the post-mutation scheduler. Mutated in place, so + * sampling costs nothing beyond reading the fields. Call + * {@link resetPostMutationTiming} to start a new sample window. + */ +export const postMutationTiming: PostMutationTiming = { + calls: 0, + total: 0, + max: 0, + deleteTotal: 0, + deleteMax: 0, + layoutTotal: 0, + layoutMax: 0, + focusTotal: 0, + focusMax: 0, +}; + +/** Zeroes {@link postMutationTiming} so the next sample window starts clean. */ +export function resetPostMutationTiming(): void { + const t = postMutationTiming; + t.calls = 0; + t.total = 0; + t.max = 0; + t.deleteTotal = 0; + t.deleteMax = 0; + t.layoutTotal = 0; + t.layoutMax = 0; + t.focusTotal = 0; + t.focusMax = 0; +} + +function runPostMutation() { + postMutationQueued = false; + + // One flag read is the whole cost of instrumentation while it is off. The + // timed variant is a separate function so the default path never reaches a + // clock or a per-phase branch. + if (Config.postMutationDebug) { + runPostMutationTimed(); + return; + } + + flushDeletes(); + flushLayout(); + flushFocus(); +} + +function runPostMutationTimed() { + const start = performance.now(); + flushDeletes(); + const afterDelete = performance.now(); + flushLayout(); + const afterLayout = performance.now(); + flushFocus(); + const end = performance.now(); + + const deleteTime = afterDelete - start; + const layoutTime = afterLayout - afterDelete; + const focusTime = end - afterLayout; + const totalTime = end - start; + + const t = postMutationTiming; + t.calls++; + t.total += totalTime; + t.deleteTotal += deleteTime; + t.layoutTotal += layoutTime; + t.focusTotal += focusTime; + if (totalTime > t.max) t.max = totalTime; + if (deleteTime > t.deleteMax) t.deleteMax = deleteTime; + if (layoutTime > t.layoutMax) t.layoutMax = layoutTime; + if (focusTime > t.focusMax) t.focusMax = focusTime; +} + function addToLayoutQueue(node: ElementNode) { layoutQueue.add(node); schedulePostMutation(); diff --git a/tests/postMutationTiming.test.tsx b/tests/postMutationTiming.test.tsx new file mode 100644 index 0000000..b0cf805 --- /dev/null +++ b/tests/postMutationTiming.test.tsx @@ -0,0 +1,114 @@ +import * as v from 'vitest'; +import * as lng from '@solidtv/solid'; +import { renderer } from './setup.js'; + +const wait = (ms = 10) => new Promise((r) => setTimeout(r, ms)); + +// setFocus() on a rendered node is the cheapest way to schedule a real +// post-mutation flush from the public API: it parks the node in +// nextActiveElement and queues the scheduler, so all three phases run. +const flushPostMutation = async (node: lng.ElementNode) => { + node.setFocus(); + await wait(); +}; + +const renderFlexView = () => { + let node!: lng.ElementNode; + const dispose = renderer.render(() => ( + + + + + )); + return { node, dispose }; +}; + +v.describe('post-mutation timing', () => { + v.afterEach(() => { + lng.Config.postMutationDebug = false; + lng.resetPostMutationTiming(); + }); + + v.test('records nothing while Config.postMutationDebug is off', async () => { + const { node, dispose } = renderFlexView(); + await wait(); + + lng.resetPostMutationTiming(); + await flushPostMutation(node); + + v.assert.equal(lng.postMutationTiming.calls, 0, 'calls'); + v.assert.equal(lng.postMutationTiming.total, 0, 'total'); + v.assert.equal(lng.postMutationTiming.layoutTotal, 0, 'layoutTotal'); + + dispose(); + }); + + v.test('accumulates per-phase timings and a call count', async () => { + const { node, dispose } = renderFlexView(); + await wait(); + + lng.Config.postMutationDebug = true; + lng.resetPostMutationTiming(); + await flushPostMutation(node); + + const t = lng.postMutationTiming; + v.assert.isAbove(t.calls, 0, 'the flush ran and was counted'); + v.assert.isAtLeast(t.deleteTotal, 0, 'deleteTotal'); + v.assert.isAtLeast(t.layoutTotal, 0, 'layoutTotal'); + v.assert.isAtLeast(t.focusTotal, 0, 'focusTotal'); + + // Every phase is contained in the same start/end window, so no phase max + // can exceed the wall time attributed to the whole flush. + v.assert.isAtMost(t.max, t.total, 'max within total'); + v.assert.isAtMost(t.deleteMax, t.max, 'deleteMax within max'); + v.assert.isAtMost(t.layoutMax, t.max, 'layoutMax within max'); + v.assert.isAtMost(t.focusMax, t.max, 'focusMax within max'); + + dispose(); + }); + + v.test('keeps accumulating across flushes', async () => { + const { node, dispose } = renderFlexView(); + await wait(); + + lng.Config.postMutationDebug = true; + lng.resetPostMutationTiming(); + await flushPostMutation(node); + const firstPass = lng.postMutationTiming.calls; + + await flushPostMutation(node); + + v.assert.isAbove( + lng.postMutationTiming.calls, + firstPass, + 'counts add up rather than replacing the previous sample', + ); + + dispose(); + }); + + v.test('reset zeroes every counter', async () => { + const { node, dispose } = renderFlexView(); + await wait(); + + lng.Config.postMutationDebug = true; + lng.resetPostMutationTiming(); + await flushPostMutation(node); + v.assert.isAbove(lng.postMutationTiming.calls, 0, 'sampled something'); + + lng.resetPostMutationTiming(); + + const t = lng.postMutationTiming; + v.assert.equal(t.calls, 0, 'calls'); + v.assert.equal(t.total, 0, 'total'); + v.assert.equal(t.max, 0, 'max'); + v.assert.equal(t.deleteTotal, 0, 'deleteTotal'); + v.assert.equal(t.deleteMax, 0, 'deleteMax'); + v.assert.equal(t.layoutTotal, 0, 'layoutTotal'); + v.assert.equal(t.layoutMax, 0, 'layoutMax'); + v.assert.equal(t.focusTotal, 0, 'focusTotal'); + v.assert.equal(t.focusMax, 0, 'focusMax'); + + dispose(); + }); +});