`'s `content` fragment
+is owned by a separate "template contents owner document"
+that has no browsing context -- resources inside it never
+load. Moving a live `![]()
` into `template.content` triggers
+`adoptNode` to that inert document, which then runs the
+"update the image data" algorithm, creates a fresh request
+in state "unavailable", and flips `.complete` to false. The
+source image is now stuck in that state; clones into the live
+page wrappers inherit it without the synchronous cache-hit
+path firing in time for the sync `[PATCH: assert-sync]`
+`waitForImages` check.
+
+The `innerHTML` round-trip avoids this incidentally: the
+freshly-parsed `![]()
` elements in `template.content` are
+brand new (never live), they have no prior load state to
+disturb, and when their clones land in the live page wrappers
+Chromium's file:// cache lookup resolves them synchronously.
+
+A plain `DocumentFragment` is owned by the live document.
+Moving children into it is a same-document append -- no
+adoption, no "update the image data", no `.complete` reset.
+Clones from the fragment into the live page wrappers then
+take the same fast cache path the round-trip's parsed images
+did.
+
+### Re-entrancy
+
+The original returned `template.content`, so a second call
+finding the existing template just returned that same
+fragment. Under the move strategy `template.content` is
+empty (the children live in the plain fragment we returned),
+so the re-entrant branch reads the fragment back off a
+`template._pagedjsContent` expando on the marker template.
+Functionally equivalent for the one-call-per-render case
+that's actually exercised; preserves the multi-call contract
+in case anyone leans on it later.
+
+### Results
+
+Paired A/B, 2 runs each, `--detach-pages --no-timing
+--cpu-profile --cpu-sampling 100`:
+
+| run | pre | post |
+| --- | --- | --- |
+| 1 | 11.92 s | 10.72 s |
+| 2 | 11.60 s | 11.06 s |
+| **avg** | **11.76 s** | **10.89 s** |
+
+**Δ = -0.87 s render (-7.4 %).** Larger than the 260 ms the
+profile attributed to `wrapContent` itself -- the round-trip
+also allocated a transient 5.5 MB string that pushed GC and
+distributed sample noise into the surrounding rows; removing
+the allocation relieves pressure across the whole per-page
+hot path. The cpuprofile rows breakdown:
+
+| function | pre | post | Δ |
+| -------- | --- | ---- | --- |
+| `wrapContent` self | 260 ms | off-list (<25 ms) | **-260 ms+** |
+| `getBoundingClientRect` self | 4,281 ms | 4,036 ms | -245 ms |
+| `removeOverflow` self | 560 ms | 353 ms | -207 ms |
+| `removeChild` self | 1,871 ms | 1,730 ms | -141 ms |
+| `(program)` self | 2,298 ms | 2,152 ms | -146 ms |
+
+The `wrapContent` row is the only one outside the single-run
+noise band (the README's earlier methodology section pins
+that at 50-150 ms for sub-1 % rows on this machine). The
+others are plausibly real but inseparable from noise without
+more runs; the sample-count delta (-2,100 samples × 542 us
+= ~1,135 ms) matches the wall-clock delta closely enough that
+the distributed component is probably real GC-pressure
+relief, not just sampler jitter.
+
+PDF byte-equivalent to the pre-fix build (16.1 MB).
+
+### What the pattern leaves behind
+
+`removeOverflow` and `wrapContent` are both cases where V8
+rolled native DOM work (`Range.deleteContents`,
+HTML serialiser+parser) into the calling JS frame's
+self-time. The diagnostic move is the same one we used for
+gBCR attribution: `find-callees.mjs` on the suspect frame.
+If self-time is ~100 % of total, the work is happening
+inside a native callee the sampler didn't name -- read the
+JS body to find which DOM API is doing the work and whether
+it can be replaced with a cheaper equivalent.
+
+`find-callees.mjs` was added for this investigation and
+sits alongside `find-callers.mjs`; the two together cover
+both directions of the V8 attribution edge.
+
+## The per-page overflow-check rhythm: two bugs in the adaptive `maxChars`
+
+The "Attempt E: additive backoff" section above describes
+the per-page rhythm of `renderTo`'s overflow checks: append
+nodes, fire `findBreakToken` every `maxChars` chars of
+appended content, break out when it returns a non-null
+breakToken. `maxChars` defaults to 1500 and is meant to
+adapt up or down based on observed page capacity.
+
+The post-wrapContent profile showed `findOverflow` total
+2.24 s, almost all of it (1.96 s) in `hasOverflow`'s single
+gate gBCR -- one call per `findBreakToken`. Was the call
+count high because the page actually needs that many
+probes, or was the rhythm wrong?
+
+Instrumenting with `window.__breakCheckStats` and
+`window.__layoutMaxChars` answered it:
+
+```
+findBreakToken checks: 7,764 hits: 862 nulls: 6,902
+renderTo calls: 1651 checks/call avg: 4.70
+Layout.maxChars: first=1500 median=177 last=177 min=177 max=1500
+```
+
+Four findings:
+
+1. **89 % of checks (6,902 / 7,764) return null.** They're
+ "no overflow yet, keep appending" probes. Each is still
+ a full layout-flush gBCR. The actual overflow detections
+ are 862, slightly more than half of the 1651 pages
+ (the rest end naturally, or via CSS-driven breaks).
+
+2. **`Layout.maxChars` was locked at 177 for the entire
+ render** after page 1. That's an order of magnitude
+ below a typical page's capacity (which the @page CSS,
+ font size, and content density determine -- closer to
+ 4000-4500 chars of body text on this book). Page 1 ran
+ with the default 1500; pages 2-1651 ran with 177.
+
+3. The reason was a propagation gate in `Page.layout`:
+ ```js
+ if (!settings.maxChars && maxChars) {
+ settings.maxChars = maxChars;
+ }
+ ```
+ `settings` is shared across all pages (one object, set
+ by reference in the Chunker constructor). The chunker
+ maintains a running estimate in `this.maxChars` via
+ `recordCharLength` and passes it into each page's
+ `layout(..., maxChars)`. But `!settings.maxChars` is
+ only truthy on the first page that gets a defined value
+ -- the rest see settings.maxChars already populated and
+ skip the update. Whatever value page 2 picked up (177,
+ from a freak short page 1 that had been recorded as
+ capacity), every subsequent page kept.
+
+4. The recording itself is biased. `recordCharLength` pushes
+ `page.wrapper.textContent.length` after every layout and
+ averages the last 4 values. Short pages -- chapter
+ endings, part dividers -- get recorded alongside full
+ pages, dragging the average well below true capacity.
+ Even with propagation fixed, the average would land
+ around 1200, not 4500.
+
+### The fix
+
+Two patches in `docs/lib/paged.browser.js`, marked
+`// [PATCH: maxChars-propagate]` and `// [PATCH: maxChars-
+running-max]`:
+
+1. **`Page.layout`'s gate drops the staleness check**:
+ `if (maxChars) settings.maxChars = maxChars;`. Each page
+ now picks up the chunker's current estimate.
+
+2. **`Chunker.recordCharLength` tracks the running max over
+ the last 16 pages** instead of the running average over
+ 4. Max biases toward "the largest page recently seen,"
+ which approximates true capacity for our content. Short
+ pages still get pushed into the window but don't pull
+ the estimate down. The window of 16 is wide enough that
+ a transient stretch of short pages doesn't collapse the
+ estimate before a full page restores it.
+
+### Results
+
+Paired A/B, 2 runs each, `--detach-pages --no-timing`, no
+profiling:
+
+| run | pre | post |
+| --- | --- | --- |
+| 1 | 10.08 s | 8.15 s |
+| 2 | 11.86 s | 7.98 s |
+| **avg** | **10.97 s** | **8.07 s** |
+
+**Δ = -2.90 s render (-26 %).** CPU profile (single run,
+within noise band on the smaller rows):
+
+| metric | pre | post | Δ |
+| ------------------------ | ---------- | ---------- | --- |
+| `findOverflow` total | 2,236 ms | 1,690 ms | **-546 ms** |
+| ↳ `hasOverflow` total | 1,957 ms | 1,597 ms | -360 ms |
+| ↳ ↳ `gBCR` native | 1,945 ms | 1,587 ms | -358 ms |
+| ↳ `findOverflow` self | 142 ms | 47 ms | -95 ms |
+| ↳ walker-loop callees | ~135 ms | ~46 ms | -89 ms |
+| `removeOverflow` self | 353 ms | 122 ms | **-231 ms** |
+| `removeChild` self | 1,731 ms | 1,637 ms | flat (noise) |
+| `(program)` self | 2,152 ms | 2,215 ms | flat (noise) |
+
+The `removeOverflow` drop was the surprise. Going in, the
+concern was that bigger `maxChars` (now ~4500 instead of
+177) would mean larger overshoot when overflow fired -- so
+`extractContents` / `deleteContents` would have more nodes
+to detach. The opposite happened: `removeOverflow` self
+dropped two-thirds. The reason is the call count, not the
+per-call size. With `maxChars=177` the renderTo loop
+checked at every 177-char interval, but many of those
+checks were *near* the page boundary, where the walker in
+`findOverflow` did real work even when returning null
+(walking nodes to test text-break candidates that don't
+quite fit). With `maxChars=4500`, the very first check on
+most pages fires right at the overflow point; the walker
+runs once per page instead of several times, and the per-
+call work it does is roughly the same as before.
+
+PDF output is byte-identical to the pre-fix build
+(16.1 MB, same checksum on the raw Chromium output).
+
+### Why the average was the wrong statistic
+
+The textbook reason to track a running average is to
+estimate a stationary quantity in the presence of noise.
+The thing being estimated here -- "how many chars fit on a
+full page" -- is a tight ceiling, not a noisy reading: each
+page's textContent.length either equals page capacity
+(because the page broke for overflow) or is well below it
+(because content ran out / a CSS break fired). The
+distribution is bimodal, and the average sits between the
+modes -- exactly where it's worst as an estimator of
+either.
+
+The running max, by contrast, finds the upper mode and
+sticks to it. It only moves down if the entire window is
+sub-capacity pages, which means the document genuinely
+doesn't have full pages anymore (end of book, perhaps), at
+which point the estimate doesn't matter much.
+
+### Where this leaves the picture
+
+Render is now ~8 s on the 1651-page book, down from ~11 s
+post-wrapContent, down from ~104 s in the original
+baseline. Updated cumulative table:
+
+| fix | render saved | shipped |
+| ----------------------------------- | ------------ | ------- |
+| `--detach-pages` (display:none) | ~55 s | yes |
+| aggressive detach (`removeChild`) | ~22 s | yes |
+| `renderTo` additive backoff | ~4.25 s | yes |
+| skip dead `findEndToken` path | ~3.5 s | yes |
+| `findRef` fast-path | ~2.4 s | yes |
+| queue-tick: rAF -> queueMicrotask | ~2.6 s | yes |
+| `finalizePage` micro-optimisations | ~3 s | yes |
+| `wrapContent` move (skip innerHTML) | ~0.9 s | yes |
+| **`maxChars` propagation + max** | **~2.9 s** | **yes** |
+| (others, smaller) | ~3 s | yes |
+
+The strategic conclusion at the bottom of "Where this
+leaves the picture" updates accordingly: render is now
+roughly half the size of generate (~8 s vs ~32 s wall on
+the production build), and `pageRanges` sharding remains
+the only knob with a profile target large enough to move
+the wall-clock total meaningfully -- and that target is
+generate, not render.
+
+## What happened when we tried move-not-clone
+
+A fresh `--detach-pages --no-timing --cpu-profile
+--cpu-sampling 100` baseline run showed `cloneNode` at
+~146 ms self-time, all of it inside `Layout.append`'s per-
+source-node clone path. `Layout.append`'s body for the
+`!shallow` (deep-cloned leaf) yields was:
+
+```js
+let clone = cloneNode(node, !shallow); // deep clone
+// ... attach clone to dest ...
+return clone;
+```
+
+The user's question: source's read-only-template contract
+is just an artifact of paged.js's break-and-resume model.
+We're doing offline layout -- nothing reads source after
+the render finishes. Could we MOVE the source node into
+dest instead of cloning it, and avoid the allocation cost
+entirely? Best-case ceiling estimated at ~300-450 ms /
+~3-5 % of render (the cloneNode self plus distributed GC-
+pressure relief from not allocating ~250 k duplicate DOM
+nodes).
+
+### What the refactor required
+
+Three load-bearing assumptions in the chunker break the
+moment source is mutated:
+
+1. The walker traverses via live links
+ (`node.firstChild` / `nextSibling` / `parentNode`).
+ After a leaf yield, `walker = walk$2(nodeAfter(node,
+ source), source)` reads `nodeAfter` AFTER `append` has
+ moved `node` into dest -- the reads now go into dest's
+ tree, not source's. Fix: capture `nodeAfter(node,
+ source)` BEFORE the append call and pass it to the
+ walker reset.
+
+2. `BreakToken.node` stores a source-tree reference for
+ the next page's `getStart(source, breakToken)` to
+ resume from. `createBreakToken`'s four
+ `findElement(*, source)` call sites map rendered
+ (clone) nodes back to source via shared `data-ref`.
+ With moves, source has lost the leaves and findElement
+ returns the moved node now living in dest. Fix:
+ bypass `createBreakToken` entirely. Compute the
+ resume point from the extract-and-restore step
+ instead (see `restoreOverflow` below).
+
+3. `removeOverflow`'s `deleteContents` would drop the
+ moved content forever. In the clone model that was
+ fine -- source still held a pristine copy. In the
+ move model, source needs the overflow content back so
+ the next page can render it. Fix: replace with
+ `restoreOverflow` -- `extractContents` the overflow
+ range, walk the fragment depth-first collecting leaf
+ elements, and reinsert each leaf at its stashed
+ `_srcParent` / `_srcNextSibling` position. For the
+ boundary leaf that's partially overflowing,
+ `extractContents` produces a shallow clone of the
+ leaf in the fragment; we inherit its source position
+ via `source.indexOfRefs[ref]` (which still points at
+ the original-now-in-dest, which carries the stash).
+ Reverse-order iteration so each leaf's `_srcNextSibling`
+ target is back in source by the time we insert.
+
+### The bug that taught the real story
+
+First pass rendered the book to 1740 pages -- 89 more
+than the 1651-page baseline. Content was byte-identical
+modulo timestamps. Per-page char counts in the FAQ
+section showed pages 127+ with only ~50-500 chars each:
+
+```
+[BL p127] 3045 chars [EX p127] 438 chars
+[BL p128] 3732 chars [EX p128] 185 chars
+```
+
+Some FAQ pages had a single short paragraph. Instrumenting
+`shouldBreak` revealed it was returning true on every
+non-first yield inside the FAQ article:
+
+```
+[instrument] shouldBreak true: tag=P ref=6bv pba=- prevNode=ARTICLE
+[instrument] shouldBreak true: tag=B ref=6bx pba=- prevNode=ARTICLE
+[instrument] shouldBreak true: tag=P ref=6by pba=- prevNode=ARTICLE
+... (one per FAQ paragraph)
+```
+
+The `` elements have no `data-break-before` and no
+`data-previous-break-after`, so the fire is via
+`needsPageBreak(node, previousNode)` -- which checks
+whether `node`'s effective `data-page` differs from
+`previousNode`'s.
+
+`previousNode` is computed via
+`nodeBefore(node, limiter)`, which walks
+`node.previousSibling` then climbs via `parentNode` if
+no significant sibling exists. In the move model, after
+the previous yield was moved out of source, the current
+yield's `previousSibling` is `null` (the previous one no
+longer lives in source). The climb continues up:
+FAQ article (no `data-page`) -> looks at its previous
+sibling -> finds the **part-divider article** sitting
+right before the FAQ article in source, which DOES carry
+`data-page="divider"` (set by processBreaks for the CSS
+`page: divider;` rule on `article.part-divider`).
+
+So `needsPageBreak` saw a transition from
+`page="divider"` to (effectively) no page, fired true,
+and the chunker started a fresh page for every paragraph
+in the FAQ section. The chapter article's normal
+"siblings share the same effective page-name" property
+broke because the sibling-walk now escapes the chapter
+into the prior part-divider.
+
+### Fix: track previousLeaf in renderTo
+
+The chunker already knows the right answer: the last
+leaf it actually appended this page. Threaded through
+`shouldBreak` as a third argument, used by the
+`needsPageBreak` branch only (`needsBreakBefore` and the
+`parentBreakBefore` logic still use `nodeBefore`):
+
+```js
+let _moveLastLeaf = null;
+// ... in the loop ...
+if (hasRenderedContent &&
+ this.shouldBreak(node, start, _moveLastLeaf)) { ... }
+// ... after append ...
+if (!shallow) _moveLastLeaf = node;
+```
+
+In `shouldBreak`:
+
+```js
+let pageBreakRef = previousLeaf || nodeBefore(node, limiter);
+return ... || needsPageBreak(node, pageBreakRef);
+```
+
+With that, page count went 1740 -> 1653 (within 2 of
+baseline) and per-page content matched. PDF
+byte-equivalent to baseline within timestamp drift.
+
+### Profile diff
+
+Both runs `--detach-pages --cpu-profile --cpu-sampling
+100`, sample-time absolute, single run each (wall-clock
+on this machine is too noisy to be a useful signal --
+see "Methodology: compare profiles, not wall-clock"
+above):
+
+| function | baseline | move | Δ |
+| --- | --- | --- | --- |
+| `getBoundingClientRect` | 3539 ms | 4036 ms | **+497** |
+| `appendChild` | 137 ms | 390 ms | **+253** |
+| `restoreOverflow` (new) | -- | 168 ms | +168 |
+| `removeChild` | 1536 ms | 1635 ms | +99 |
+| `insertBefore` | <50 ms | 87 ms | ~+87 |
+| `getNodeWithNamedPage` | <50 ms | 108 ms | ~+85 |
+| `afterPageLayout` (AtPage) | 105 ms | 182 ms | +77 |
+| `(program)` | 2196 ms | 2266 ms | +70 |
+| `Layout` ctor | 23 ms | 31 ms | +8 |
+| `cloneNode` | 146 ms | <130 ms | **-146** |
+| `removeOverflow` | 124 ms | -- (replaced) | -124 |
+| **samples** | **17,481** | **19,590** | **+2,109** |
+| **CPU work** | **9.48 s** | **10.74 s** | **+1.26 s** |
+
+Net **+1.26 s of CPU work** -- the change is a clear
+regression in the opposite direction from the prediction.
+
+### Why the prediction was wrong
+
+The cloneNode self-time saving (-146 ms) shows up as
+expected, but three structural costs dwarf it:
+
+1. **`appendChild` on an attached node is roughly 2x
+ the cost of `appendChild` on a fresh clone (+253 ms).**
+ A move is internally detach-from-source-parent +
+ attach-to-dest-parent; both touch Blink's child-list
+ bookkeeping. cloneNode produces an unparented node,
+ so the subsequent attach is one-sided. Intrinsic to
+ any move-based design -- no implementation choice
+ avoids it.
+
+2. **Each move dirties Blink's layout state more than
+ each clone does, distributing cost into gBCR
+ (+497 ms).** The increase is spread across every
+ gBCR call site -- `Page.create` (+225 ms),
+ `hasOverflow` (+152 ms), `Layout` ctor (+58 ms),
+ `afterPageLayout` (+31 ms), `addResizeObserver`
+ (+31 ms) -- not localized to any new code. Each
+ gBCR call flushes pending mutations; with every move
+ counting as two mutations vs one for clone+append,
+ each flush has more to do. Same migration pattern
+ the README's "Attempt B: memoize `Page.create`'s gBCR"
+ documented above -- DOM mutation cost doesn't go
+ away by elimination, it migrates to whichever frame
+ next forces a layout flush.
+
+3. **The extract-and-restore cycle adds ~340 ms of new
+ JS work.** `restoreOverflow` (168 ms) builds an
+ `extractContents` fragment + walks it for leaves +
+ inserts each back into source. `previousLeaf` makes
+ `shouldBreak` call `getNodeWithNamedPage` (108 ms)
+ on every leaf yield (it climbs parent chains looking
+ for `data-page`). `insertBefore` (87 ms) is the
+ per-restore reinsertion.
+
+The deeper structural reason: paged.js's break-and-
+resume model touches each source leaf O(pages-spanning-
+that-leaf) times in the move model -- moved into page N,
+extracted to the fragment, reinserted into source,
+moved into page N+1. Each touch is a DOM mutation. The
+clone model touches each node O(1) times -- allocated
+once, attached, thrown away with the page. Cumulative
+mutation count is structurally higher under moves.
+
+The cloneNode time the profile attributes to its native
+frame is just the *allocator* portion of cloning work --
+not the total cost of "duplicating a subtree". The rest
+hides in V8 / Blink native frames not labeled
+`cloneNode`, and that rest doesn't disappear when you
+switch to moves; it shows up as appendChild +
+invalidation cost instead.
+
+### Where this leaves the picture
+
+Reverted. The cumulative table from the previous
+section is unchanged. No row added.
+
+The pattern this attempt taught is the inverse of the
+"distributed savings often exceed direct estimates"
+heuristic the README documents elsewhere: sometimes a
+change with a direct cost saving has bigger distributed
+*regressions* that aren't visible until you measure.
+The cloneNode saving was real; the appendChild + gBCR +
+restoreOverflow overhead was bigger.
+
+The only design that would avoid all three costs is one
+that never re-moves the same node -- a single-pass
+paginator with no break-and-resume. That's not paged.js;
+it's a different algorithm. Not a small refactor.
+
+The buffer variant (pre-clone source once at startup,
+move from buffer to dest) was considered and not
+prototyped: it'd shift the cloneNode allocation cost to
+one big startup call but every per-page move would
+still hit the same appendChild + gBCR dynamic that ate
+the savings here. No structural win.
+
+This experiment also clarifies why the "Profiling
+pdf-lib's load" and "Findings: removeChild" sections
+saw allocation savings show up as wall-clock gains:
+those operations didn't have a Blink layout-tree
+mutation step downstream. Mutations are where the cost
+that *looks* like JS allocation actually lives in this
+codebase.
diff --git a/perf/analyze-heap-profile.mjs b/perf/analyze-heap-profile.mjs
new file mode 100644
index 00000000..b8d17c94
--- /dev/null
+++ b/perf/analyze-heap-profile.mjs
@@ -0,0 +1,84 @@
+// Bottom-up heap sampling profile analyzer.
+//
+// Reads a V8 .heapprofile (the JSON returned by CDP's
+// HeapProfiler.stopSampling) and prints the top allocation sites by
+// self-bytes, aggregated by (function name + source location). Same
+// shape as Chrome DevTools' Memory tab "Allocation sampling"
+// bottom-up view, but in the terminal.
+//
+// Usage:
+// node analyze-heap-profile.mjs [--top N] [--min-pct P]
+//
+// Defaults: --top 30, --min-pct 0.1 (hide rows under 0.1% self-bytes).
+//
+// .heapprofile schema:
+// head: { callFrame, selfSize, id, children: [...] } (tree of nodes)
+// samples: [{ size, nodeId, ordinal }] (allocation events)
+// Each node's `selfSize` is the sum of bytes from samples whose
+// nodeId targeted that node directly (i.e. that node was the top of
+// the allocation stack). Same shape as cpuprofile self-time.
+
+import { readFileSync } from 'node:fs';
+import { resolve } from 'node:path';
+
+const args = process.argv.slice(2);
+let profilePath = null;
+let topN = 30;
+let minPct = 0.1;
+for (let i = 0; i < args.length; i++) {
+ const a = args[i];
+ if (a === '--top') topN = parseInt(args[++i], 10);
+ else if (a === '--min-pct') minPct = parseFloat(args[++i]);
+ else if (!profilePath) profilePath = a;
+}
+if (!profilePath) {
+ console.error('usage: node analyze-heap-profile.mjs [--top N] [--min-pct P]');
+ process.exit(2);
+}
+profilePath = resolve(process.cwd(), profilePath);
+
+const profile = JSON.parse(readFileSync(profilePath, 'utf8'));
+
+// Flatten the tree into a list of nodes, keyed by call-frame.
+const byKey = new Map();
+let totalBytes = 0;
+const walk = (node) => {
+ const cf = node.callFrame || {};
+ const fn = cf.functionName || '(anonymous)';
+ const url = cf.url || '';
+ const line = cf.lineNumber != null ? cf.lineNumber + 1 : '?';
+ const key = `${fn} @ ${url || '(no url)'}:${line}`;
+ const cur = byKey.get(key) || { bytes: 0, fn, url, line };
+ cur.bytes += node.selfSize || 0;
+ byKey.set(key, cur);
+ totalBytes += node.selfSize || 0;
+ for (const c of node.children || []) walk(c);
+};
+walk(profile.head);
+
+const rows = [...byKey.values()]
+ .map(r => ({
+ ...r,
+ pct: 100 * r.bytes / totalBytes,
+ }))
+ .sort((a, b) => b.bytes - a.bytes)
+ .filter(r => r.pct >= minPct)
+ .slice(0, topN);
+
+const fmtBytes = (n) => {
+ if (n >= 1024 * 1024) return (n / 1024 / 1024).toFixed(2) + ' MB';
+ if (n >= 1024) return (n / 1024).toFixed(1) + ' KB';
+ return n + ' B';
+};
+const fmtPct = (n, w) => n.toFixed(2).padStart(w);
+console.log(`profile: ${profilePath}`);
+console.log(`samples: ${profile.samples ? profile.samples.length : '?'} total selfSize: ${fmtBytes(totalBytes)}`);
+console.log(`top ${topN} by self-bytes (min ${minPct}%):`);
+console.log('');
+console.log(' self_bytes self_% function @ source');
+console.log(' ---------- ------ ----------------------------------------------');
+for (const r of rows) {
+ const where = `${r.url ? r.url.replace(/^file:\/\/\//, '') : '(no url)'}:${r.line}`;
+ const fn = r.fn || '(anonymous)';
+ console.log(` ${fmtBytes(r.bytes).padStart(11)} ${fmtPct(r.pct, 5)}% ${fn} @ ${where}`);
+}
diff --git a/perf/diff-heap-profile.mjs b/perf/diff-heap-profile.mjs
new file mode 100644
index 00000000..0b229442
--- /dev/null
+++ b/perf/diff-heap-profile.mjs
@@ -0,0 +1,52 @@
+import { readFileSync } from 'node:fs';
+
+function loadByFn(p) {
+ const profile = JSON.parse(readFileSync(p, 'utf8'));
+ const byKey = new Map();
+ let total = 0;
+ const walk = (n) => {
+ const cf = n.callFrame || {};
+ const fn = cf.functionName || '(anonymous)';
+ const line = cf.lineNumber != null ? cf.lineNumber + 1 : '?';
+ const url = (cf.url || '').replace(/^file:\/\/\//, '');
+ const tail = url ? url.split(/[\\/]/).pop() : '';
+ const key = tail ? fn + ' @ ' + tail + ':' + line : fn;
+ byKey.set(key, (byKey.get(key) || 0) + (n.selfSize || 0));
+ total += n.selfSize || 0;
+ for (const c of n.children || []) walk(c);
+ };
+ walk(profile.head);
+ return { byKey, total, samples: profile.samples ? profile.samples.length : 0 };
+}
+
+const [prePath, postPath] = process.argv.slice(2);
+const pre = loadByFn(prePath);
+const post = loadByFn(postPath);
+const keys = new Set([...pre.byKey.keys(), ...post.byKey.keys()]);
+const rows = [];
+for (const k of keys) {
+ const preB = pre.byKey.get(k) || 0;
+ const postB = post.byKey.get(k) || 0;
+ rows.push({ k, pre: preB, post: postB, delta: postB - preB });
+}
+
+const fmtB = b => {
+ const a = Math.abs(b);
+ if (a >= 1024 * 1024) return (b / 1024 / 1024).toFixed(2) + ' MB';
+ if (a >= 1024) return (b / 1024).toFixed(1) + ' KB';
+ return b + ' B';
+};
+const pad = (s, w) => s.padStart(w);
+
+console.log('pre samples=' + pre.samples + ', total=' + fmtB(pre.total));
+console.log('post samples=' + post.samples + ', total=' + fmtB(post.total));
+console.log('total delta : ' + fmtB(post.total - pre.total));
+console.log();
+console.log('top 20 by |delta|:');
+console.log(' PRE POST Δ function');
+console.log(' ---------- ---------- ---------- ------------------------');
+rows.sort((a, b) => Math.abs(b.delta) - Math.abs(a.delta));
+for (const r of rows.slice(0, 20)) {
+ const sign = r.delta > 0 ? '+' : '';
+ console.log(' ' + pad(fmtB(r.pre), 10) + ' ' + pad(fmtB(r.post), 10) + ' ' + pad(sign + fmtB(r.delta), 10) + ' ' + r.k);
+}
diff --git a/perf/find-callees.mjs b/perf/find-callees.mjs
new file mode 100644
index 00000000..858425ee
--- /dev/null
+++ b/perf/find-callees.mjs
@@ -0,0 +1,69 @@
+// Companion to find-callers.mjs: shows where a function spends its time
+// across direct callees. Reports self-time + per-callee subtree totals so
+// you can see whether the cost lives in the function body or in what it
+// calls.
+//
+// Usage:
+// node perf/find-callees.mjs
+//
+// Example:
+// node perf/find-callees.mjs results/.../render.cpuprofile removeOverflow
+
+import { readFileSync } from 'node:fs';
+
+const [profilePath, targetName] = process.argv.slice(2);
+if (!profilePath || !targetName) {
+ console.error('usage: node find-callees.mjs ');
+ process.exit(2);
+}
+
+const profile = JSON.parse(readFileSync(profilePath, 'utf8'));
+const usPerSample = (profile.endTime - profile.startTime) / profile.samples.length;
+
+const byId = new Map();
+for (const n of profile.nodes) byId.set(n.id, n);
+
+const subtreeHits = (rootId) => {
+ const stack = [rootId];
+ const seen = new Set();
+ let hits = 0;
+ while (stack.length) {
+ const id = stack.pop();
+ if (seen.has(id)) continue;
+ seen.add(id);
+ const n = byId.get(id);
+ hits += n.hitCount || 0;
+ for (const c of n.children || []) stack.push(c);
+ }
+ return hits;
+};
+
+let selfHits = 0;
+let totalHits = 0;
+const calleeHits = new Map();
+
+for (const n of profile.nodes) {
+ const fn = n.callFrame?.functionName || '';
+ if (fn !== targetName) continue;
+ selfHits += n.hitCount || 0;
+ totalHits += subtreeHits(n.id);
+ for (const cid of n.children || []) {
+ const c = byId.get(cid);
+ const fnC = c.callFrame?.functionName || '(anon)';
+ const url = (c.callFrame?.url || '').replace(/^file:\/\/\//, '');
+ const line = (c.callFrame?.lineNumber ?? -1) + 1;
+ const key = `${fnC} @ ${url || '(native)'}:${line}`;
+ calleeHits.set(key, (calleeHits.get(key) || 0) + subtreeHits(cid));
+ }
+}
+
+const ms = (hits) => (hits * usPerSample / 1000).toFixed(2);
+
+console.log(`${targetName}: self=${ms(selfHits)}ms, total=${ms(totalHits)}ms (callees combined=${ms(totalHits - selfHits)}ms)`);
+console.log('per direct callee (subtree total ms):');
+[...calleeHits.entries()]
+ .sort((a, b) => b[1] - a[1])
+ .forEach(([k, h]) => {
+ const v = h * usPerSample / 1000;
+ if (v >= 0.5) console.log(` ${ms(h).padStart(8)} ms ${k}`);
+ });
diff --git a/perf/grep-profile.mjs b/perf/grep-profile.mjs
new file mode 100644
index 00000000..0b864e43
--- /dev/null
+++ b/perf/grep-profile.mjs
@@ -0,0 +1,37 @@
+// One-off: list every node in a .cpuprofile whose functionName matches
+// the given regex, with self-time and source location. Helpful for
+// "is this frame in the profile at all, and what's it called?"
+
+import { readFileSync } from 'node:fs';
+
+const [profilePath, pattern] = process.argv.slice(2);
+if (!profilePath || !pattern) {
+ console.error('usage: node grep-profile.mjs ');
+ process.exit(2);
+}
+
+const profile = JSON.parse(readFileSync(profilePath, 'utf8'));
+const usPerSample = (profile.endTime - profile.startTime) / profile.samples.length;
+const re = new RegExp(pattern);
+
+const rows = [];
+for (const n of profile.nodes) {
+ const fn = n.callFrame?.functionName || '';
+ if (!re.test(fn)) continue;
+ const ms = (n.hitCount || 0) * usPerSample / 1000;
+ rows.push({
+ ms,
+ fn,
+ url: (n.callFrame?.url || '').replace(/^file:\/\/\//, '') || '(native)',
+ line: (n.callFrame?.lineNumber ?? -1) + 1,
+ hits: n.hitCount || 0,
+ });
+}
+rows.sort((a, b) => b.ms - a.ms);
+
+let total = 0;
+for (const r of rows) {
+ total += r.ms;
+ console.log(` ${r.ms.toFixed(2).padStart(8)} ms ${r.fn} @ ${r.url}:${r.line} hits=${r.hits}`);
+}
+console.log(` -------- ${total.toFixed(2)} ms total across ${rows.length} matching nodes`);
diff --git a/perf/instrument-clones.js b/perf/instrument-clones.js
new file mode 100644
index 00000000..7358d47c
--- /dev/null
+++ b/perf/instrument-clones.js
@@ -0,0 +1,128 @@
+// One-off probe: count how many Layout.append clones survive into the
+// finalized page wrapper vs. how many get rolled back by removeOverflow.
+//
+// Mechanism:
+// - Wrap Layout.prototype.append to (a) count calls and (b) tag every
+// returned clone with an expando __pagedjs_clone_tag = true.
+// - Wrap Node.prototype.cloneNode globally so we can also report the
+// gross cloneNode call count (which includes rebuildAncestors and
+// anything else outside Layout.append).
+// - At finalizePage, walk the just-finalized page wrapper counting
+// tagged survivors. (removeOverflow has already fired by this point.)
+// - At afterRendered, summarise totals + per-page distribution.
+//
+// Cost: O(1) per append + one tree walk per finalized page. Run with
+// --detach-pages --no-timing --additional-script ..\perf\instrument-clones.js
+// from a measure.mjs invocation. Numbers are reported via console.log
+// which measure.mjs forwards to stdout.
+
+(() => {
+ const Layout = window.PagedLayout;
+ if (!Layout) {
+ console.log('[clone-count] ERROR: window.PagedLayout not exposed; bundle patch missing.');
+ return;
+ }
+ const origAppend = Layout.prototype.append;
+ let appendCalls = 0;
+ Layout.prototype.append = function (...args) {
+ const clone = origAppend.apply(this, args);
+ appendCalls++;
+ if (clone) clone.__pagedjs_clone_tag = true;
+ return clone;
+ };
+
+ const origCloneNode = Node.prototype.cloneNode;
+ let cloneNodeCalls = 0;
+ Node.prototype.cloneNode = function (deep) {
+ cloneNodeCalls++;
+ return origCloneNode.call(this, deep);
+ };
+
+ const perPage = []; // { appended, kept }
+ let appendAtPageStart = 0;
+
+ class CloneCountHandler extends Paged.Handler {
+ beforePageLayout() {
+ appendAtPageStart = appendCalls;
+ }
+ finalizePage(pageElement) {
+ const appendedThisPage = appendCalls - appendAtPageStart;
+ let kept = 0;
+ const walker = document.createTreeWalker(
+ pageElement,
+ NodeFilter.SHOW_ELEMENT | NodeFilter.SHOW_TEXT
+ );
+ let n;
+ while ((n = walker.nextNode())) {
+ if (n.__pagedjs_clone_tag) kept++;
+ }
+ perPage.push({ appended: appendedThisPage, kept });
+ }
+ afterRendered(pages) {
+ let totalAppended = 0;
+ let totalKept = 0;
+ let pagesWithOvershoot = 0;
+ let maxOvershoot = 0;
+ let maxOvershootPage = -1;
+ const pcts = [];
+ perPage.forEach((entry, idx) => {
+ totalAppended += entry.appended;
+ totalKept += entry.kept;
+ const over = entry.appended - entry.kept;
+ if (over > 0) pagesWithOvershoot++;
+ if (over > maxOvershoot) {
+ maxOvershoot = over;
+ maxOvershootPage = idx;
+ }
+ pcts.push(entry.appended > 0 ? (over / entry.appended) * 100 : 0);
+ });
+ const totalOvershoot = totalAppended - totalKept;
+ const pct = totalAppended > 0
+ ? (totalOvershoot / totalAppended) * 100
+ : 0;
+
+ console.log(`[clone-count] pages=${pages.length}`);
+ console.log(`[clone-count] Layout.append calls (source-walker leaf clones): ${totalAppended}`);
+ console.log(`[clone-count] survivors in finalized pages: ${totalKept}`);
+ console.log(`[clone-count] overshoot (appended-then-removed): ${totalOvershoot} (${pct.toFixed(1)}%)`);
+ console.log(`[clone-count] pages with any overshoot: ${pagesWithOvershoot}/${pages.length}`);
+ console.log(`[clone-count] max overshoot on one page: ${maxOvershoot} (page index ${maxOvershootPage}, appended=${perPage[maxOvershootPage]?.appended ?? 0})`);
+ console.log(`[clone-count] gross Node.cloneNode calls (incl. rebuildAncestors, handlers, etc.): ${cloneNodeCalls}`);
+ console.log(`[clone-count] non-Layout.append clones: ${cloneNodeCalls - totalAppended}`);
+
+ // Per-page overshoot % buckets.
+ const buckets = [
+ { lo: 0, hi: 1 },
+ { lo: 1, hi: 5 },
+ { lo: 5, hi: 10 },
+ { lo: 10, hi: 20 },
+ { lo: 20, hi: 30 },
+ { lo: 30, hi: 50 },
+ { lo: 50, hi: 101 },
+ ];
+ const counts = buckets.map(() => 0);
+ for (const p of pcts) {
+ for (let i = 0; i < buckets.length; i++) {
+ if (p >= buckets[i].lo && p < buckets[i].hi) {
+ counts[i]++;
+ break;
+ }
+ }
+ }
+ console.log(`[clone-count] per-page overshoot % distribution:`);
+ for (let i = 0; i < buckets.length; i++) {
+ const b = buckets[i];
+ const hi = b.hi === 101 ? '100' : String(b.hi);
+ console.log(`[clone-count] ${String(b.lo).padStart(3)} - ${hi.padStart(3)}%: ${counts[i]} pages`);
+ }
+
+ // Cumulative percentile cutpoints.
+ const sortedPcts = pcts.slice().sort((a, b) => a - b);
+ const pickPct = (q) => sortedPcts[Math.min(sortedPcts.length - 1, Math.floor(q * sortedPcts.length))];
+ console.log(`[clone-count] per-page overshoot %: p50=${pickPct(0.5).toFixed(1)}% p90=${pickPct(0.9).toFixed(1)}% p99=${pickPct(0.99).toFixed(1)}% max=${pickPct(0.999).toFixed(1)}%`);
+ }
+ }
+
+ Paged.registerHandlers(CloneCountHandler);
+ console.log('[clone-count] handler registered');
+})();
diff --git a/perf/instrument-detach.js b/perf/instrument-detach.js
new file mode 100644
index 00000000..73afa9d6
--- /dev/null
+++ b/perf/instrument-detach.js
@@ -0,0 +1,97 @@
+// Per-call timing for the detach-pages.js removeChild path.
+//
+// Wraps detach-pages.js's removeChild call so we can see whether the
+// cost is roughly flat per call (some Blink-internal fixed overhead) or
+// scales with the page's descendant count (LayoutObject teardown).
+//
+// Loaded as an --additional-script AFTER detach-pages.js so the
+// instrumentation can monkey-patch the prototype that detach-pages.js
+// uses. Records per-call ns + descendant count + first-quarter /
+// last-quarter buckets. Dump at afterRendered through the [instrument]
+// prefix so the harness pipes it to stdout.
+
+(() => {
+ const origRemoveChild = Node.prototype.removeChild;
+ const samples = []; // { ns, descendants, isPage }
+ let totalNs = 0;
+ let pageDetachCount = 0;
+ let otherCount = 0;
+
+ Node.prototype.removeChild = function (child) {
+ // count descendants quickly — only meaningful on Element children
+ let descendants = 0;
+ let isPage = false;
+ if (child && child.nodeType === 1) {
+ // Element.children.length is just direct kids; we want a count
+ // estimate of the subtree, but a full walk would skew the timing.
+ // Use childElementCount as a cheap proxy plus a textContent length
+ // bucket so we can correlate with size.
+ descendants = child.getElementsByTagName ? child.getElementsByTagName('*').length : 0;
+ isPage = child.classList && child.classList.contains('pagedjs_page');
+ }
+ const t0 = performance.now();
+ const r = origRemoveChild.call(this, child);
+ const ns = (performance.now() - t0) * 1e6;
+ totalNs += ns;
+ if (isPage) {
+ pageDetachCount++;
+ samples.push({ ns, descendants });
+ } else {
+ otherCount++;
+ }
+ return r;
+ };
+
+ class DetachInstrument extends Paged.Handler {
+ afterRendered(pages) {
+ const total = pages.length;
+ const pageSamples = samples.slice();
+ pageSamples.sort((a, b) => a.ns - b.ns);
+ const median = pageSamples.length ? pageSamples[Math.floor(pageSamples.length / 2)].ns : 0;
+ const p90 = pageSamples.length ? pageSamples[Math.floor(pageSamples.length * 0.9)].ns : 0;
+ const p99 = pageSamples.length ? pageSamples[Math.floor(pageSamples.length * 0.99)].ns : 0;
+ const sumDesc = pageSamples.reduce((s, x) => s + x.descendants, 0);
+ const sumNs = pageSamples.reduce((s, x) => s + x.ns, 0);
+
+ console.log(`[instrument] removeChild wrapper: ${pageDetachCount} page detaches, ${otherCount} other`);
+ console.log(`[instrument] total removeChild wall: ${(totalNs / 1e6).toFixed(1)} ms`);
+ console.log(`[instrument] page-detach total: ${(sumNs / 1e6).toFixed(1)} ms`);
+ console.log(`[instrument] page-detach avg: ${(sumNs / pageDetachCount / 1e6).toFixed(3)} ms/call`);
+ console.log(`[instrument] page-detach median: ${(median / 1e6).toFixed(3)} ms/call`);
+ console.log(`[instrument] page-detach p90: ${(p90 / 1e6).toFixed(3)} ms/call`);
+ console.log(`[instrument] page-detach p99: ${(p99 / 1e6).toFixed(3)} ms/call`);
+ console.log(`[instrument] avg descendants/page: ${(sumDesc / pageDetachCount).toFixed(1)}`);
+
+ // Bucket by descendant count to see proportionality.
+ const buckets = [
+ { lo: 0, hi: 100, n: 0, ns: 0, desc: 0 },
+ { lo: 100, hi: 200, n: 0, ns: 0, desc: 0 },
+ { lo: 200, hi: 400, n: 0, ns: 0, desc: 0 },
+ { lo: 400, hi: 800, n: 0, ns: 0, desc: 0 },
+ { lo: 800, hi: 1600, n: 0, ns: 0, desc: 0 },
+ { lo: 1600,hi: Infinity, n: 0, ns: 0, desc: 0 },
+ ];
+ for (const s of pageSamples) {
+ const b = buckets.find(bk => s.descendants >= bk.lo && s.descendants < bk.hi);
+ if (b) { b.n++; b.ns += s.ns; b.desc += s.descendants; }
+ }
+ console.log(`[instrument] removeChild cost by descendant-count bucket:`);
+ console.log(`[instrument] desc-range count total_ms avg_ms avg_desc ms_per_desc`);
+ for (const b of buckets) {
+ if (!b.n) continue;
+ const avgMs = b.ns / b.n / 1e6;
+ const avgDesc = b.desc / b.n;
+ const msPerDesc = avgDesc > 0 ? (avgMs / avgDesc) * 1000 : 0;
+ const range = b.hi === Infinity ? `${b.lo}+` : `${b.lo}-${b.hi}`;
+ console.log(
+ `[instrument] ${range.padEnd(10)} ${String(b.n).padStart(6)} ${avgMs.toFixed(3).padStart(8)} ${(b.ns/1e6).toFixed(1).padStart(8)} ${avgDesc.toFixed(0).padStart(10)} ${msPerDesc.toFixed(2).padStart(13)}`
+ );
+ }
+
+ // Restore so afterRendered's own removeChild (when re-appending) isn't double-charged.
+ Node.prototype.removeChild = origRemoveChild;
+ }
+ }
+ Paged.registerHandlers(DetachInstrument);
+ console.log('[instrument] removeChild wrapper installed');
+})();
diff --git a/perf/measure.mjs b/perf/measure.mjs
index 94eedcef..c9df9cf6 100644
--- a/perf/measure.mjs
+++ b/perf/measure.mjs
@@ -22,8 +22,22 @@
// Usage:
// node measure.mjs [path/to/book.html] [--out ] [--keep-open]
// [--cpu-profile] [--cpu-sampling ]
+// [--heap-profile] [--heap-sampling ]
// [--detach-pages] [--instrument] [--time-hooks]
-// [--incremental] [--chrome-outline]
+// [--incremental] [--chrome-outline] [--no-timing]
+// [--clone-count] [--render-only]
+//
+// --render-only bails out after the render phase. Skips meta extraction,
+// parseOutline, page.pdf, and the pdf-lib roundtrip / incremental writer.
+// Useful for cpu-profile / instrumentation runs where only the render
+// phase matters; trims ~45s off the full ~55s book run. No book.pdf is
+// written, and the timing.json / summary.txt omit generate/process.
+//
+// --no-timing skips the per-page timing-handler.js injection. The handler
+// adds a per-page console.log relayed via CDP that costs ~2% of render
+// self-time on the 1638-page book. Use when profiling for the cleanest
+// possible bottom-up table; loses the per-page CSV and the first/last
+// quartile summary in return.
//
// --detach-pages also injects detach-pages.js -- a Paged.Handler that
// hides each completed page from the layout tree -- to test whether
@@ -75,22 +89,32 @@ let outArg = null;
let keepOpen = false;
let cpuProfile = false;
let cpuSampling = 1000; // microseconds
+let heapProfile = false;
+let heapSampling = 32768; // bytes between samples (CDP default)
let detachPages = false;
let instrument = false;
let timeHooks = false;
let incremental = false;
let chromeOutline = false;
+let noTiming = false;
+let cloneCount = false;
+let renderOnly = false;
for (let i = 0; i < args.length; i++) {
const a = args[i];
if (a === '--out') outArg = args[++i];
else if (a === '--keep-open') keepOpen = true;
else if (a === '--cpu-profile') cpuProfile = true;
else if (a === '--cpu-sampling') cpuSampling = parseInt(args[++i], 10);
+ else if (a === '--heap-profile') heapProfile = true;
+ else if (a === '--heap-sampling') heapSampling = parseInt(args[++i], 10);
else if (a === '--detach-pages') detachPages = true;
else if (a === '--instrument') instrument = true;
else if (a === '--time-hooks') timeHooks = true;
else if (a === '--incremental') incremental = true;
else if (a === '--chrome-outline') chromeOutline = true;
+ else if (a === '--no-timing') noTiming = true;
+ else if (a === '--clone-count') cloneCount = true;
+ else if (a === '--render-only') renderOnly = true;
else if (!inputArg) inputArg = a;
else { console.error(`unknown arg: ${a}`); process.exit(2); }
}
@@ -110,10 +134,13 @@ const handlerPath = resolve(__dirname, 'timing-handler.js');
const detachPagesPath = resolve(__dirname, 'detach-pages.js');
const instrumentPath = resolve(__dirname, 'instrument-flush-ops.js');
const timeHooksPath = resolve(__dirname, 'time-hooks.js');
-const required = [pagedScriptPath, handlerPath];
+const cloneCountPath = resolve(__dirname, 'instrument-clones.js');
+const required = [pagedScriptPath];
+if (!noTiming) required.push(handlerPath);
if (detachPages) required.push(detachPagesPath);
if (instrument) required.push(instrumentPath);
if (timeHooks) required.push(timeHooksPath);
+if (cloneCount) required.push(cloneCountPath);
for (const p of required) {
if (!existsSync(p)) {
console.error(`missing required file: ${p}`);
@@ -160,7 +187,8 @@ try {
page.on('console', (msg) => {
const t = msg.text();
if (t.startsWith('[paged-timing]') || t.startsWith('[detach-pages]') ||
- t.startsWith('[instrument]') || t.startsWith(' ')) {
+ t.startsWith('[instrument]') || t.startsWith('[clone-count]') ||
+ t.startsWith(' ')) {
console.log(t);
}
});
@@ -183,7 +211,9 @@ try {
});
await page.addScriptTag({ path: pagedScriptPath });
- await page.addScriptTag({ path: handlerPath });
+ if (!noTiming) {
+ await page.addScriptTag({ path: handlerPath });
+ }
if (detachPages) {
await page.addScriptTag({ path: detachPagesPath });
}
@@ -193,19 +223,30 @@ try {
if (timeHooks) {
await page.addScriptTag({ path: timeHooksPath });
}
+ if (cloneCount) {
+ await page.addScriptTag({ path: cloneCountPath });
+ }
// RENDER ----------------------------------------------------------
- // Optionally wrap just this phase in a V8 CPU profile. CDP Profiler
- // attaches to the renderer for this page; we stop before the generate
- // phase so the trace stays focused on paged.js layout work.
+ // Optionally wrap just this phase in a V8 CPU and/or heap sampling
+ // profile. CDP attaches to the renderer for this page; we stop
+ // before the generate phase so the traces stay focused on paged.js
+ // layout work.
let cdp = null;
- if (cpuProfile) {
+ if (cpuProfile || heapProfile) {
cdp = await page.createCDPSession();
+ }
+ if (cpuProfile) {
await cdp.send('Profiler.enable');
await cdp.send('Profiler.setSamplingInterval', { interval: cpuSampling });
await cdp.send('Profiler.start');
console.log(`[harness] cpu profile: sampling every ${cpuSampling}us`);
}
+ if (heapProfile) {
+ await cdp.send('HeapProfiler.enable');
+ await cdp.send('HeapProfiler.startSampling', { samplingInterval: heapSampling });
+ console.log(`[harness] heap profile: sampling every ${heapSampling} bytes`);
+ }
const tRenderStart = Date.now();
await page.evaluate(async () => {
@@ -226,17 +267,39 @@ try {
const renderMs = tRenderEnd - tRenderStart;
let profilePath = null;
+ let heapProfilePath = null;
if (cdp) {
- const { profile } = await cdp.send('Profiler.stop');
+ if (cpuProfile) {
+ const { profile } = await cdp.send('Profiler.stop');
+ profilePath = join(outDir, 'render.cpuprofile');
+ const profileJson = JSON.stringify(profile);
+ writeFileSync(profilePath, profileJson);
+ console.log(`[harness] cpu profile: ${profilePath} (${(profileJson.length / 1024 / 1024).toFixed(1)} MB)`);
+ }
+ if (heapProfile) {
+ const { profile } = await cdp.send('HeapProfiler.stopSampling');
+ heapProfilePath = join(outDir, 'render.heapprofile');
+ const profileJson = JSON.stringify(profile);
+ writeFileSync(heapProfilePath, profileJson);
+ const totalBytes = profile.samples.reduce((s, x) => s + x.size, 0);
+ console.log(`[harness] heap profile: ${heapProfilePath} (${(profileJson.length / 1024 / 1024).toFixed(1)} MB, ${profile.samples.length} samples, ${(totalBytes / 1024 / 1024).toFixed(1)} MB allocated)`);
+ }
await cdp.detach();
- profilePath = join(outDir, 'render.cpuprofile');
- const profileJson = JSON.stringify(profile);
- writeFileSync(profilePath, profileJson);
- console.log(`[harness] cpu profile: ${profilePath} (${(profileJson.length / 1024 / 1024).toFixed(1)} MB)`);
}
console.log(`[harness] render ${fmtMs(renderMs)}`);
+ // Declared outside the generate/process blocks so the persistence /
+ // summary code can read them either way. --render-only leaves them null.
+ let generateMs = null;
+ let parseOutlineMs = null;
+ let pdfMs = null;
+ let rawPdfBytes = null;
+ let processMs = null;
+ let processBreakdown = null;
+ let finalPdf = null;
+
+ if (!renderOnly) {
// GENERATE --------------------------------------------------------
// meta extraction + outline DOM walk + Chromium DOM->PDF.
const tGenStart = Date.now();
@@ -258,7 +321,7 @@ try {
// would get overwritten by Chrome's /Outlines anyway.
const tParseOutlineStart = Date.now();
const outline = chromeOutline ? [] : await parseOutline(page, outlineTags);
- const parseOutlineMs = Date.now() - tParseOutlineStart;
+ parseOutlineMs = Date.now() - tParseOutlineStart;
const tPdfStart = Date.now();
const rawPdf = await page.pdf({
@@ -274,10 +337,11 @@ try {
// both on would have our setOutline overwrite Chrome's /Outlines.
...(chromeOutline ? { outline: true, tagged: true } : {}),
});
- const pdfMs = Date.now() - tPdfStart;
+ pdfMs = Date.now() - tPdfStart;
+ rawPdfBytes = rawPdf.length;
const tGenEnd = Date.now();
- const generateMs = tGenEnd - tGenStart;
+ generateMs = tGenEnd - tGenStart;
console.log(`[harness] generate ${fmtMs(generateMs)} (parseOutline=${fmtMs(parseOutlineMs)}, page.pdf=${fmtMs(pdfMs)}, ${(rawPdf.length / 1024 / 1024).toFixed(1)}MB)`);
// PROCESS ---------------------------------------------------------
@@ -294,8 +358,6 @@ try {
// Either way we time the full phase plus the meaningful sub-steps so the
// breakdown matches across runs.
const tProcStart = Date.now();
- let finalPdf;
- let processBreakdown;
if (incremental) {
const tIncStart = Date.now();
const { bytes, stats } = await applyOutlineAndMetadataIncremental(rawPdf, outline, meta);
@@ -327,25 +389,30 @@ try {
processBreakdown = { loadMs, setOutlineMs, saveMs };
}
const tProcEnd = Date.now();
- const processMs = tProcEnd - tProcStart;
+ processMs = tProcEnd - tProcStart;
if (incremental) {
console.log(`[harness] process ${fmtMs(processMs)} (incremental=${fmtMs(processBreakdown.incrementalMs)}, +${processBreakdown.appendedBytes}B, ${processBreakdown.newObjectCount} new objs)`);
} else {
console.log(`[harness] process ${fmtMs(processMs)} (load=${fmtMs(processBreakdown.loadMs)}, setOutline=${fmtMs(processBreakdown.setOutlineMs)}, save=${fmtMs(processBreakdown.saveMs)})`);
}
+ } // end if (!renderOnly)
- const totalMs = tProcEnd - tRenderStart;
+ const totalMs = Date.now() - tRenderStart;
console.log(`[harness] total ${fmtMs(totalMs)}`);
// Persist results -------------------------------------------------
- const timing = await page.evaluate(() => window.__pagedTiming);
- const pdfPath = join(outDir, 'book.pdf');
- writeFileSync(pdfPath, Buffer.from(finalPdf));
+ const timing = noTiming
+ ? { pages: [], phases: {}, pageCount: null }
+ : await page.evaluate(() => window.__pagedTiming);
+ if (finalPdf) {
+ const pdfPath = join(outDir, 'book.pdf');
+ writeFileSync(pdfPath, Buffer.from(finalPdf));
+ }
const record = {
input: inputPath,
pageCount: timing.pageCount,
- pdfBytes: finalPdf.length,
+ pdfBytes: finalPdf ? finalPdf.length : null,
cpuProfile: profilePath,
phases: {
render: {
@@ -353,20 +420,22 @@ try {
perPage: timing.pages,
phaseMarks: timing.phases,
},
- generate: {
- ms: generateMs,
- parseOutlineMs,
- pagePdfMs: pdfMs,
- rawPdfBytes: rawPdf.length,
- },
- process: {
- ms: processMs,
- mode: incremental ? 'incremental' : 'pdf-lib-roundtrip',
- ...processBreakdown,
- },
},
totalMs,
};
+ if (!renderOnly) {
+ record.phases.generate = {
+ ms: generateMs,
+ parseOutlineMs,
+ pagePdfMs: pdfMs,
+ rawPdfBytes,
+ };
+ record.phases.process = {
+ ms: processMs,
+ mode: incremental ? 'incremental' : 'pdf-lib-roundtrip',
+ ...processBreakdown,
+ };
+ }
writeFileSync(join(outDir, 'timing.json'), JSON.stringify(record, null, 2));
const csv = ['page,dur_ms,heap_start_mb,heap_end_mb,elapsed_s'];
@@ -385,11 +454,17 @@ try {
const summary = [];
summary.push(`input : ${inputPath}`);
summary.push(`pages : ${pages.length}`);
- summary.push(`pdf size : ${(finalPdf.length / 1024 / 1024).toFixed(1)} MB`);
+ if (finalPdf) {
+ summary.push(`pdf size : ${(finalPdf.length / 1024 / 1024).toFixed(1)} MB`);
+ }
summary.push('');
summary.push(`render : ${fmtMs(renderMs)} (per-page layout via paged.js)`);
- summary.push(`generate : ${fmtMs(generateMs)} (parseOutline + page.pdf)`);
- summary.push(`process : ${fmtMs(processMs)} (${incremental ? 'incremental update (append outline + updated catalog/info)' : 'pdf-lib load + setOutline + save'})`);
+ if (!renderOnly) {
+ summary.push(`generate : ${fmtMs(generateMs)} (parseOutline + page.pdf)`);
+ summary.push(`process : ${fmtMs(processMs)} (${incremental ? 'incremental update (append outline + updated catalog/info)' : 'pdf-lib load + setOutline + save'})`);
+ } else {
+ summary.push(`(generate + process skipped: --render-only)`);
+ }
summary.push(`total : ${fmtMs(totalMs)}`);
summary.push('');
if (pages.length >= 4) {