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(); + }); +});