Make --timing opt-in rather than opt-out (--no-timing).

Author: KubaO

perf/README.md

@@ -23,20 +23,23 @@ at the bottom of this file.
 The command we reach for whenever CPU-profiling paged.js:
 
 ```
-node measure.mjs --no-timing --render-only --cpu-profile --cpu-sampling 100
+node measure.mjs --render-only --cpu-profile --cpu-sampling 100
 ```
 
-(`run.bat` forwards the same args.) The detach-pages handler is now
-injected by default, since it's the shipping fix and matching
-production is the right baseline for any profiling work. Pass
-`--no-detach-pages` if you specifically need the pre-fix O(n²)
-baseline for an A/B against the original quadratic.
+(`run.bat` forwards the same args.) Two defaults match what most
+profiling work needs:
+
+- **detach-pages is on.** It's the shipping fix; matching production
+  is the right baseline for any profiling work. Pass
+  `--no-detach-pages` for an A/B against the original O(n²) quadratic.
+- **timing is off.** The `timing-handler.js` per-page `console.log`
+  relay costs ~2 % of render self-time on the 1638-page book and
+  muddies bottom-up profile tables. Pass `--timing` when you want the
+  per-page CSV + first/last-quartile summary; otherwise `timing.csv`
+  is empty and `summary.txt` says so.
 
 Flag rationale:
 
-- `--no-timing` -- skip the per-page `console.log` relay from
-  `timing-handler.js`. The relay costs ~2 % of render self-time on
-  the 1638-page book and muddies the bottom-up view.
 - `--render-only` -- bail out after `PagedPolyfill.preview()`
   returns. Skips meta extraction, `parseOutline`, `page.pdf`, and
   the pdf-lib roundtrip / incremental writer. ~47 s saved per run
@@ -66,7 +69,7 @@ The harness and core probes:
 | --- | --- |
 | `measure.mjs` | Puppeteer harness. Drives the same flow as `docs/render-book.mjs` (loads the vendored paged.js bundle, runs `PagedPolyfill.preview()`, calls `page.pdf()`, then either the pdf-lib roundtrip or the incremental writer), with optional CPU profiling, in-page handler injection, and DOM-accessor instrumentation. Auto-pins to a fixed core mask on Windows via `pin-cpu.mjs` (see below) for stable measurements; pass `--no-affinity` to opt out. |
 | `pin-cpu.mjs` | Shared shim used by `measure.mjs`, `profile-load.mjs`, `profile-roundtrip.mjs`, and `ab-css.mjs`. On Windows, auto-relaunches the parent Node process under `start /affinity 0x5500 /high` (cores 4-7 physical, thread 0 each, on an 8C16T AMD Ryzen 7) so puppeteer's Chromium children inherit the mask + priority at spawn time. Reduces single-run CPU sample-time variance from ~15-25 % on a stock dev box to ~3 %. No-op on non-Windows; opt out per-invocation with `--no-affinity` or `PERF_PINNED=1`; override mask with `PERF_AFFINITY=<hex>`. |
-| `timing-handler.js` | `Paged.Handler` that records per-page wall time + heap into `window.__pagedTiming` and streams a line per page to the console. Always injected. |
+| `timing-handler.js` | `Paged.Handler` that records per-page wall time + heap into `window.__pagedTiming` and streams a line per page to the console. Injected when `--timing` is passed; off by default because the per-page console relay costs ~2 % of render self-time. |
 | `detach-pages.js` | `Paged.Handler` that hides each completed page from the layout tree (registered against `finalizePage`). The shipping fix. Injected by default (both by `measure.mjs` and by `docs/book.bat`); pass `--no-detach-pages` to measure the pre-fix baseline. |
 | `instrument-flush-ops.js` | Wraps `getComputedStyle`, `getBoundingClientRect`, and the `offsetWidth` / `clientWidth` / `scrollWidth` family with counters + per-call timing. Injected by `--instrument`. |
 | `instrument-detach.js` | Counters around `detach-pages.js`'s removeChild / restore cycle. |
@@ -168,6 +171,7 @@ run.bat                                   # defaults to ..\docs\_site-pdf\book.h
 run.bat path\to\some-other.html           # explicit input
 run.bat --out my-run                      # explicit output directory
 run.bat --no-detach-pages                 # opt out of the detach-pages fix (measure pre-fix O(n²) baseline)
+run.bat --timing                          # collect per-page wall time + heap (writes timing.csv + quartile summary)
 run.bat --cpu-profile                     # CPU-profile the render phase
 run.bat --render-only                     # bail out after render (skip generate + process, ~47s saved)
 run.bat --clone-count                     # report Layout.append clones appended vs survivors per page
@@ -189,17 +193,17 @@ Outputs land in `perf/results/<ISO-timestamp>/`:
 
 - `book.pdf`    -- the rendered PDF, byte-equivalent to what
   `book.bat` produces.
-- `timing.json` -- full record: phase totals, sub-phase breakdowns
-  (`parseOutline`, `page.pdf`, pdf-lib load / setOutline / save),
-  and the per-page render entries.
-- `timing.csv`  -- one row per page,
-  `page,dur_ms,heap_start_mb,heap_end_mb,elapsed_s`.
-- `summary.txt` -- the three phase totals, plus first-quarter vs
-  last-quarter average per-page render cost and ratio.
+- `timing.json` -- phase totals + sub-phase breakdowns
+  (`parseOutline`, `page.pdf`, pdf-lib load / setOutline / save).
+  Per-page render entries are populated only when `--timing` is set.
+- `timing.csv`  -- one row per page, `page,dur_ms,heap_start_mb,
+  heap_end_mb,elapsed_s`. Empty (header only) without `--timing`.
+- `summary.txt` -- the three phase totals; with `--timing` also adds
+  first-quarter vs last-quarter average per-page render cost + ratio.
 
 ## Reading the output
 
-The summary prints something like:
+With `--timing`, the summary prints something like:
 
 ```
 pages        : 1638

perf/ab-css.mjs

@@ -165,7 +165,7 @@ if (swappedHtml === BOOK_HTML) {
 function runOnce(outDir) {
   const r = spawnSync('node', [
     'measure.mjs', SWAP_HTML_PATH,
-    '--no-timing', '--render-only', '--tracing',
+    '--render-only', '--tracing',
     '--out', outDir,
   ], { stdio: ['ignore', 'pipe', 'pipe'] });
   const err = r.stderr?.toString() ?? '';

perf/instrument-clones.js

@@ -12,9 +12,11 @@
 //   - At afterRendered, summarise totals + per-page distribution.
 //
 // Cost: O(1) per append + one tree walk per finalized page. Run with
-//   --no-timing --additional-script ..\perf\instrument-clones.js
+//   --additional-script ..\perf\instrument-clones.js
 // from a measure.mjs invocation. (detach-pages.js is on by default;
-// add --no-detach-pages to compare against the pre-fix baseline.)
+// add --no-detach-pages to compare against the pre-fix baseline.
+// The timing handler is off by default; if you also pass --timing,
+// its per-page console relay will mix with this probe's output.)
 // Numbers are reported via console.log which measure.mjs forwards
 // to stdout.
 

perf/measure.mjs

@@ -25,7 +25,7 @@
 //                    [--heap-profile] [--heap-sampling <bytes>]
 //                    [--tracing]
 //                    [--no-detach-pages] [--instrument] [--time-hooks]
-//                    [--incremental] [--chrome-outline] [--no-timing]
+//                    [--incremental] [--chrome-outline] [--timing]
 //                    [--clone-count] [--render-only]
 //
 // --render-only bails out after the render phase. Skips meta extraction,
@@ -34,11 +34,13 @@
 // 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.
+// --timing injects timing-handler.js. The handler records per-page wall
+// time + heap to window.__pagedTiming (so the harness can emit
+// timing.csv and the first/last-quartile summary) and streams a per-page
+// console.log relayed via CDP. The relay costs ~2 % of render self-time
+// on the 1638-page book, which is why the handler isn't on by default --
+// profile-clean runs and most A/B comparisons don't need it. Pass it
+// when you want the per-page CSV.
 //
 // detach-pages.js is injected by default -- a Paged.Handler that hides
 // each completed page from the layout tree. This is the shipping fix
@@ -115,7 +117,7 @@ let instrument = false;
 let timeHooks = false;
 let incremental = false;
 let chromeOutline = false;
-let noTiming = false;
+let timing = false;
 let cloneCount = false;
 let renderOnly = false;
 let tracing = false;
@@ -133,7 +135,8 @@ for (let i = 0; i < args.length; i++) {
   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 === '--timing') timing = true;
+  else if (a === '--no-timing') timing = false;             // accepted for backwards compat; default since the relay cost was measured
   else if (a === '--clone-count') cloneCount = true;
   else if (a === '--render-only') renderOnly = true;
   else if (a === '--tracing') tracing = true;
@@ -159,7 +162,7 @@ const instrumentPath   = resolve(__dirname, 'instrument-flush-ops.js');
 const timeHooksPath    = resolve(__dirname, 'time-hooks.js');
 const cloneCountPath   = resolve(__dirname, 'instrument-clones.js');
 const required = [pagedScriptPath];
-if (!noTiming)  required.push(handlerPath);
+if (timing)     required.push(handlerPath);
 if (detachPages) required.push(detachPagesPath);
 if (instrument)  required.push(instrumentPath);
 if (timeHooks)   required.push(timeHooksPath);
@@ -241,7 +244,7 @@ try {
   });
 
   await page.addScriptTag({ path: pagedScriptPath });
-  if (!noTiming) {
+  if (timing) {
     await page.addScriptTag({ path: handlerPath });
   }
   if (detachPages) {
@@ -471,24 +474,24 @@ try {
   console.log(`[harness] total    ${fmtMs(totalMs)}`);
 
   // Persist results -------------------------------------------------
-  const timing = noTiming
-    ? { pages: [], phases: {}, pageCount: null }
-    : await page.evaluate(() => window.__pagedTiming);
+  const timingData = timing
+    ? await page.evaluate(() => window.__pagedTiming)
+    : { pages: [], phases: {}, pageCount: null };
   if (finalPdf) {
     const pdfPath = join(outDir, 'book.pdf');
     writeFileSync(pdfPath, Buffer.from(finalPdf));
   }
 
   const record = {
     input: inputPath,
-    pageCount: timing.pageCount,
+    pageCount: timingData.pageCount,
     pdfBytes: finalPdf ? finalPdf.length : null,
     cpuProfile: profilePath,
     phases: {
       render: {
         ms: renderMs,
-        perPage: timing.pages,
-        phaseMarks: timing.phases,
+        perPage: timingData.pages,
+        phaseMarks: timingData.phases,
       },
     },
     totalMs,
@@ -509,7 +512,7 @@ try {
   writeFileSync(join(outDir, 'timing.json'), JSON.stringify(record, null, 2));
 
   const csv = ['page,dur_ms,heap_start_mb,heap_end_mb,elapsed_s'];
-  for (const p of timing.pages) {
+  for (const p of timingData.pages) {
     csv.push([
       p.idx,
       p.dur.toFixed(2),
@@ -520,10 +523,14 @@ try {
   }
   writeFileSync(join(outDir, 'timing.csv'), csv.join('\n'));
 
-  const pages = timing.pages;
+  const pages = timingData.pages;
   const summary = [];
   summary.push(`input        : ${inputPath}`);
-  summary.push(`pages        : ${pages.length}`);
+  if (timing) {
+    summary.push(`pages        : ${pages.length}`);
+  } else {
+    summary.push(`pages        : (per-page timing not collected; pass --timing for the CSV)`);
+  }
   if (finalPdf) {
     summary.push(`pdf size     : ${(finalPdf.length / 1024 / 1024).toFixed(1)} MB`);
   }