diff --git a/.changeset/quiet-text-leaves.md b/.changeset/quiet-text-leaves.md new file mode 100644 index 0000000000..997eddc008 --- /dev/null +++ b/.changeset/quiet-text-leaves.md @@ -0,0 +1,5 @@ +--- +'posthog-js': patch +--- + +Reduce session recording overhead by avoiding empty child-list reads for text nodes during mutation processing. diff --git a/packages/browser/scripts/benchmark-replay-hotspots.md b/packages/browser/scripts/benchmark-replay-hotspots.md new file mode 100644 index 0000000000..d65a41ada0 --- /dev/null +++ b/packages/browser/scripts/benchmark-replay-hotspots.md @@ -0,0 +1,77 @@ +# Remaining replay hotspots after #4811 + +Baseline: `9e3a6f22553b55bda60422e0631bc672d2be9d99`, stacked on all four prior synchronous improvements. No asynchronous recording, geometry cache or mutation deduplication is introduced here. + +## Profiling without mirror wrappers + +The benchmark now accepts `REPLAY_BENCH_MIRROR_COUNTERS=0` to disable the existing mirror wrappers while retaining CPU profiling. It also reports CDP `LayoutDuration` and `RecalcStyleDuration` deltas as `layoutCpuMs` and `styleCpuMs`. + +```sh +REPLAY_BENCH_PREPROCESSING=1 REPLAY_BENCH_PROFILE=1 \ + REPLAY_BENCH_MIRROR_COUNTERS=0 REPLAY_BENCH_NODES=50000 \ + REPLAY_BENCH_SHAPES=table,flat,deep,shadow REPLAY_BENCH_RUNS=1 \ + REPLAY_BENCH_COMPRESSION=on pnpm --filter posthog-js benchmark:replay +``` + +Separate `REPLAY_BENCH_LAYOUT_COUNTERS=1` runs wrap `Element.getBoundingClientRect` and report its calls, distinct nodes and elapsed time. These counters require profiling and are never enabled in timing comparisons. The default mirror-counter behavior remains unchanged. + +Sampled CPU attribution for 11 moves at approximately 50k nodes, compression on: + +| Shape | Preprocessing | Other emission | Serialization | Encoding | +| ------------------ | ------------- | -------------- | ------------- | -------- | +| Table | 224 ms | 37 ms | 95 ms | 46 ms | +| Flat | 220 ms | 48 ms | 100 ms | 45 ms | +| Deep (32 wrappers) | 200 ms | 51 ms | 101 ms | 47 ms | +| Shadow | 122 ms | 64 ms | 85 ms | 48 ms | + +These are sampled diagnostics, not exact phase wall times. `genAdds`, `deepDelete` and child-list access remain visible hot paths. + +## Layout was not a repeated-read opportunity + +A separate diagnostic found one rectangle read per repeated-move phase for table/flat/deep and two for shadow, matching the blocked placeholders. The reads took approximately 32, 51, 34 and 38 ms respectively. Recording-off controls made no JS rectangle calls, but still incurred nearly the same browser layout/style work: + +| Shape | Layout + style, recording off | Layout + style, recording on | +| ------ | ----------------------------- | ---------------------------- | +| Table | 19.2 + 13.6 ms | 19.3 + 12.5 ms | +| Flat | 39.7 + 10.9 ms | 39.6 + 11.0 ms | +| Deep | 19.2 + 15.3 ms | 19.5 + 14.9 ms | +| Shadow | 19.1 + 13.4 ms | 23.5 + 14.6 ms | + +The recorder forces layout earlier, but most of this is also ordinary page layout after the move. It is not evidence of an extra 30–50 ms that can simply be eliminated. No geometry caching was attempted: stale blocked-element dimensions or positions would corrupt replay, and the same element was not repeatedly measured here. + +## Small candidate: text-node child-list fast path + +After a text node is classified and added to the appropriate set, `genAdds` still fetches its empty child list and checks for a shadow root. `deepDelete` likewise reads an empty list after deleting the text from the set. Valid DOM text nodes cannot have children or shadow roots. + +The candidate skips those reads, but deliberately keeps the `isBlocked` call before the `genAdds` fast path. `classMatchesRegex` can use a stateful regular expression, so skipping blocking checks could change later decisions. A regression verifies that a global regexp is still evaluated and its `lastIndex` is updated. + +The work-count regression failed before the change with 2,200 text child-list accesses instead of 100. Afterward, only the unchanged `processRemoves` walk accounts for those 100 accesses. Text nodes remain in the moved set and still pass through normal serialization/masking. Diagnostic node visits and set-operation counts match the baseline at 10k nodes / 11 moves across all four shapes, including mixed moves. + +## Unprofiled comparison + +Apple M4 Pro, Chromium 136.0.7103.25, approximately 50k nodes, compression on, no throttling, three alternating baseline/candidate runs per shape. No concurrent builds/tests/diagnostics. Both builds used harness SHA256 `0ef2f2fcdffa8dbb502ddb1c785de6a51b6d17814277a755024e1a2b35b7caab`. All 24 scenario arms passed replay/input/privacy/drop checks. + +| Shape | Repeated-move longest task | Repeated-move input delay | Mixed-move longest task | +| ------ | -------------------------- | ------------------------- | ----------------------- | +| Table | 374 / 365 ms | 379.5 / 370.5 ms | 370 / 349 ms | +| Flat | 380 / 368 ms | 387.5 / 375.2 ms | 391 / 366 ms | +| Deep | 396 / 388 ms | 402.5 / 394.0 ms | 395 / 380 ms | +| Shadow | 308 / 300 ms | 315.0 / 305.6 ms | 302 / 290 ms | + +Values are before / after medians. This is a **smaller, provisional result**: roughly 2–3% on repeated moves and 4–6% on mixed moves. Individual runs overlap, for example table baseline `[374, 365, 385]` versus candidate `[360, 366, 365]`. Three desktop samples do not establish statistical significance or typical customer benefit. Startup and removal were effectively flat. A zero longest-task value in raw results means no task reached 50 ms, not zero blocking. + +The recorder increased by 63 raw bytes / 14 gzip bytes. Baseline SHA256: `cc2e258054c110319d605af0dbbb18106d204c0e18c3780cfed6f2417a982c8f`. Candidate: `ccd60e2fb1d540c5564c5b07abd74a94c866b3396132e8122a11125c0b779557`. + +## Validation and recommendation + +- 329 recording/accessor tests passed, 2 skipped, including two new text-leaf tests and existing light/shadow traversal, masking, mirror and iframe/lifecycle coverage. +- Nine browser masking tests passed across Chromium, Firefox and WebKit. +- Small table/flat/deep/shadow/CSS preprocessing fixtures and table/deep/shadow churn fixtures passed with compression on/off. +- 10k table/flat/deep fixtures passed with 4x page-only throttling and compression on. +- SDK/dependency builds/typechecks, targeted lint/format, syntax and ES5/ES6 checks passed. + +The relevant incident risk remains silent serializer corruption. This does not change style serialization, masking rules, node IDs, lazy-load contracts, session rotation or recording-volume policy. Blocking checks, set updates and node visits remain intact. This section records the investigation results; PR closeout review is reported separately. + +Keep this as a small follow-up candidate, not another large performance claim. The dominant remaining cost is repeated O(moves × descendants) bookkeeping. Safely reducing those visits needs separate parent/order/cancellation analysis. Geometry caching and async offload are not justified by this investigation. Issue #4217 remains unresolved. + +Evidence: `/tmp/4217-hotspots-profile-layout-{0,1}/`, `/tmp/4217-hotspots-attribution.json`, `/tmp/4217-hotspots-{baseline,candidate}-{1,2,3}/`, `/tmp/4217-hotspots-counters/`, and `/tmp/4217-hotspots-*.log`. diff --git a/packages/browser/scripts/benchmark-replay.md b/packages/browser/scripts/benchmark-replay.md index 62d248ec54..32f0e0c9f3 100644 --- a/packages/browser/scripts/benchmark-replay.md +++ b/packages/browser/scripts/benchmark-replay.md @@ -11,6 +11,8 @@ For repeated moves, flat sibling lists and mirror cleanup counters, see [the ordering investigation](benchmark-replay-ordering.md). For repeated preprocessing, deep trees, mixed moves and diagnostic visit counters, see [the preprocessing investigation](benchmark-replay-preprocessing.md). +For wrapper-free profiles, layout attribution and the text-leaf candidate, see +[the remaining-hotspots investigation](benchmark-replay-hotspots.md). ## Run diff --git a/packages/browser/scripts/benchmark-replay.mjs b/packages/browser/scripts/benchmark-replay.mjs index 8a14527a29..f01992110e 100644 --- a/packages/browser/scripts/benchmark-replay.mjs +++ b/packages/browser/scripts/benchmark-replay.mjs @@ -22,6 +22,9 @@ const shapes = (process.env.REPLAY_BENCH_SHAPES || 'table,css').split(',') const profiling = process.env.REPLAY_BENCH_PROFILE === '1' const preprocessingWorkloads = process.env.REPLAY_BENCH_PREPROCESSING === '1' const orderingWorkloads = preprocessingWorkloads || process.env.REPLAY_BENCH_ORDERING === '1' +const mirrorCounters = orderingWorkloads && profiling && process.env.REPLAY_BENCH_MIRROR_COUNTERS !== '0' +const layoutCounters = process.env.REPLAY_BENCH_LAYOUT_COUNTERS === '1' +assert(!layoutCounters || profiling, 'Layout counters require profiling') const depth = Number(process.env.REPLAY_BENCH_DEPTH || 32) assert(Number.isInteger(depth) && depth >= 1 && depth <= 128) const mutationWorkloads = orderingWorkloads || process.env.REPLAY_BENCH_MUTATIONS === '1' @@ -281,7 +284,7 @@ try { }), ]) }) - if (orderingWorkloads && profiling) + if (mirrorCounters) await page.evaluate(() => { const mirror = window.__PosthogExtensions__.rrweb.record.mirror let seen, @@ -317,6 +320,29 @@ try { }) const metrics = [] const checkpoints = [] + if (layoutCounters) + await page.evaluate(() => { + const original = Element.prototype.getBoundingClientRect + window.resetLayoutStats = () => { + window.layoutStats = { calls: 0, distinctNodes: 0, elapsedMs: 0 } + window.layoutSeen = new WeakSet() + } + window.resetLayoutStats() + Element.prototype.getBoundingClientRect = function (...args) { + const stats = window.layoutStats + stats.calls++ + if (!window.layoutSeen.has(this)) { + window.layoutSeen.add(this) + stats.distinctNodes++ + } + const start = performance.now() + try { + return original.apply(this, args) + } finally { + stats.elapsedMs += performance.now() - start + } + } + }) const phases = preprocessingWorkloads ? ['off-repeat-move', 'off-mixed-move', 'start', 'repeat-move', 'mixed-move', 'remove'] : orderingWorkloads @@ -360,7 +386,8 @@ try { }) await page.waitForTimeout(100) } - if (orderingWorkloads && profiling) await page.evaluate(() => window.resetMirrorStats()) + if (mirrorCounters) await page.evaluate(() => window.resetMirrorStats()) + if (layoutCounters) await page.evaluate(() => window.resetLayoutStats()) if (preprocessingProbe) await page.evaluate(() => window.__rrwebMutationProbe.reset()) const startIndex = wireEvents.length const bytesBefore = requestBytes @@ -559,6 +586,7 @@ try { definitions, inputDelays, mirrorStats: window.mirrorStats || null, + layoutStats: window.layoutStats || null, preprocessingStats: window.__rrwebMutationProbe?.snapshot() || null, maxFrameGapMs, @@ -627,6 +655,12 @@ try { inputDelayMs: observation.inputDelays[0] ?? null, mirrorStats: observation.mirrorStats, preprocessingStats: observation.preprocessingStats, + layoutStats: observation.layoutStats, + layoutCpuMs: + 1000 * (metric(after, 'LayoutDuration') - metric(before, 'LayoutDuration')), + styleCpuMs: + 1000 * + (metric(after, 'RecalcStyleDuration') - metric(before, 'RecalcStyleDuration')), maxTaskMs: Math.max(0, ...observation.longTasks.map((t) => t.duration)), longTaskCount: observation.longTasks.length, maxFrameGapMs: observation.maxFrameGapMs, @@ -852,6 +886,8 @@ try { cpu: os.cpus()[0]?.model, cpuRate, profiling, + mirrorCounters, + layoutCounters, benchmarkSha256: createHash('sha256') .update(await readFile(fileURLToPath(import.meta.url))) .digest('hex'), diff --git a/packages/rrweb/rrweb/src/record/mutation.ts b/packages/rrweb/rrweb/src/record/mutation.ts index ae05beff2b..e1e80a076f 100644 --- a/packages/rrweb/rrweb/src/record/mutation.ts +++ b/packages/rrweb/rrweb/src/record/mutation.ts @@ -978,6 +978,9 @@ export default class MutationBuffer { // if this node is blocked `serializeNode` will turn it into a placeholder element // but we have to remove it's children otherwise they will be added as placeholders too if (!isBlocked(n, this.blockClass, this.blockSelector, false)) { + // Text nodes cannot have children or a shadow root. Keep the blocking + // check above: skipping it can change stateful RegExp behavior. + if (n.nodeType === n.TEXT_NODE) return; // Avoid a callback per node on repeated subtree walks. Like forEach, // capture the initial length but read each child from the live list. const children = dom.childNodes(n); @@ -1010,6 +1013,7 @@ function deepDelete(addsSet: Set, n: Node) { while (stack.length) { const next = stack.pop()!; addsSet.delete(next); + if (next.nodeType === next.TEXT_NODE) continue; const children = dom.childNodes(next); for (let i = 0, length = children.length; i < length; i++) { const childN = children[i]; diff --git a/packages/rrweb/rrweb/test/record/mutation-text-leaf.test.ts b/packages/rrweb/rrweb/test/record/mutation-text-leaf.test.ts new file mode 100644 index 0000000000..12c171494a --- /dev/null +++ b/packages/rrweb/rrweb/test/record/mutation-text-leaf.test.ts @@ -0,0 +1,68 @@ +// @vitest-environment jsdom +import { afterEach, expect, it, vi } from 'vitest'; +import dom from '@posthog/rrweb-utils'; +import record from '../../src/record'; +import { mutationBuffers } from '../../src/record/observer'; + +const settle = () => new Promise((resolve) => setTimeout(resolve, 20)); +let stop: (() => void) | undefined; +afterEach(() => { + vi.restoreAllMocks(); + stop?.(); + document.body.innerHTML = ''; +}); + +it.each([ + { blockClass: /blocked/g, initialIndex: 2, finalIndex: 0 }, + { blockClass: /isibl/g, initialIndex: 1, finalIndex: 6 }, +])( + 'still evaluates the blocking regexp $blockClass for a text leaf', + async ({ blockClass, initialIndex, finalIndex }) => { + // Record the text before adding a class that the matching case would block. + document.body.innerHTML = 'value'; + const span = document.querySelector('span')!; + const text = span.firstChild!; + stop = record({ emit: () => {}, blockClass }); + await settle(); + const buffer = mutationBuffers.find((b) => b.bufferDoc() === document)!; + expect(buffer['mirror'].hasNode(text)).toBe(true); + buffer.lock(); + span.className = 'visible'; + const test = vi.spyOn(blockClass, 'test'); + blockClass.lastIndex = initialIndex; + buffer['genAdds'](text); + expect(blockClass.lastIndex).toBe(finalIndex); + expect(test).toHaveBeenCalledTimes(1); + expect(test).toHaveBeenCalledWith('visible'); + expect(buffer['movedSet'].has(text)).toBe(true); + }, +); + +it('does not fetch empty text child lists during repeated add/delete walks', async () => { + document.body.innerHTML = + '
' + 'value'.repeat(100) + '
'; + const root = document.querySelector('main')!; + const destination = document.querySelector('aside')!; + const texts = new Set( + Array.from(root.children, (node) => node.firstChild!), + ); + stop = record({ emit: () => {} }); + await settle(); + const buffer = mutationBuffers.find((b) => b.bufferDoc() === document)!; + buffer.lock(); + const children = vi.spyOn(dom, 'childNodes'); + for (let round = 0; round < 5; round++) { + destination.append(root); + document.body.insertBefore(root, destination); + } + destination.append(root); + await settle(); + expect(texts.size).toBe(100); + for (const text of texts) expect(buffer['movedSet'].has(text)).toBe(true); + // The unchanged processRemoves walk still reads each text's list once. + expect(children.mock.calls.filter(([node]) => texts.has(node)).length).toBe( + 100, + ); + buffer.unlock(); + await settle(); +}); diff --git a/packages/rrweb/rrweb/test/record/webgl.test.ts b/packages/rrweb/rrweb/test/record/webgl.test.ts index 15b59278f2..62e06e09cc 100644 --- a/packages/rrweb/rrweb/test/record/webgl.test.ts +++ b/packages/rrweb/rrweb/test/record/webgl.test.ts @@ -14,6 +14,7 @@ import { assertSnapshot, launchPuppeteer, stripBase64, + waitForCondition, waitForRAF, } from '../utils'; import type { ICanvas } from '@posthog/rrweb-snapshot'; @@ -262,7 +263,8 @@ describe('record webgl', function (this: ISuite) { }); }); - await ctx.page.waitForTimeout(50); + // Wait for the final batch to reach the exposed emit callback as well. + await waitForCondition(() => ctx.events.length >= 5); await assertSnapshot(ctx.events); expect(ctx.events.length).toEqual(5); diff --git a/packages/rrweb/rrweb/test/replayer.test.ts b/packages/rrweb/rrweb/test/replayer.test.ts index e45af62c65..568599e24f 100644 --- a/packages/rrweb/rrweb/test/replayer.test.ts +++ b/packages/rrweb/rrweb/test/replayer.test.ts @@ -1002,12 +1002,15 @@ describe('replayer', function () { it('replays same timestamp events in correct order', async () => { await page.evaluate(`events = ${JSON.stringify(orderingEvents)}`); - await page.evaluate(` - const { Replayer } = rrweb; - const replayer = new Replayer(events); - replayer.play(); - `); - await page.waitForTimeout(50); + await page.evaluate((finishEvent) => { + const win = window as IWindow; + const replayer = new win.rrweb.Replayer(win.events); + // A loaded runner may not deliver the first frame within 50 ms. + return new Promise((resolve) => { + replayer.on(finishEvent, () => resolve()); + replayer.play(); + }); + }, ReplayerEvents.Finish); await assertDomSnapshot(page); });