Files
Zachary Lowden c576281835 fix(test-perf): the module tracer never flushed under Vitest 4, so a traced run wrote nothing (#4441)
* fix(test-perf): the module tracer never flushed under Vitest 4, so a traced run wrote nothing

scripts/test-perf/trace-setup.ts flushed its counters only from process.on('exit') and a 15s
interval. Vitest's forks pool kills its workers rather than letting them exit, so the exit
handler never ran, and the README's own workflow - "trace one file at a time" - is a 5-10s run
that never reached the interval either.

The failure mode is the expensive kind: .test-perf/trace was never created at all, and
trace-report.mjs answered "no .test-perf/trace - run a traced suite first", which reads as
operator error rather than as a dead instrument. Since graph.mjs's model of what a worker loads
is validated against this tracer, the validation was unreproducible for as long as it was dead.

Flush from afterAll, which runs inside the worker before the pool can kill it. The exit handler
and the interval stay as backstops.

Verified on origin/main in a clean worktree: before the change the documented workflow creates no
trace directory; after it, trace-report.mjs prints a real report (1 worker snapshot, 45 distinct
modules).

The regression test spawns a real traced run and requires a snapshot naming the module the
fixture imported - asserting that this file contains the string "afterAll" would pass just as
happily with the hook registered somewhere it never fires. Both mutants die for their own
reason: reverting to the old exit-only flush fails on "expected 0 to be greater than 0", and a
flush that writes an empty snapshot fails on the module-name assertion. It runs in 1.7s.

TESTPERF_TRACE_DIR is new, so that test can redirect its snapshots instead of clobbering a trace
someone is reading.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01CuaBZXbMVSzwPkpEtHhvxh

* fix(test-perf): name the traced project apart, or its dep cache eats the unit suite's

Audit round 1 on this PR found the regression test was deploy-blocking, and reproducing it
independently was worse than the report: 16 of 53 files red, not 5 of 6.

Vitest keys a project's dep-optimizer cache on sha1(projectName) and Vite's config hash includes
the plugin names, so the traced project - which spread the unit project and kept its name while
adding the tracer plugin - resolved to the SAME node_modules/.vite/vitest/<hash>/deps_ssr as the
normal unit suite and hashed differently. Vite responds by deleting and re-bundling that
directory, while unrelated workers in the same shard are importing chunks out of it:
"Cannot find module '.../deps_ssr/prom-client.js'". assert-shard-ran.mjs would not have caught
it either - losing ~400 of ~5539 tests stays inside its band.

Naming the traced project unit-trace gives it its own cache dir. Same 53-file selection:
53 passed, 0 deps_ssr errors, two cache dirs on disk.

Also from the audit:
- trace-report.mjs now honours TESTPERF_TRACE_DIR, which trace-setup.ts already read. Exporting
  it used to reproduce this PR's own bug: snapshots on disk, report says "run a traced suite
  first".
- The trace dir is cleared at the start of each traced run. The report SUMS every snapshot it
  finds and snapshots outlive their run, so a second run silently reported roughly doubled
  numbers - a wrong number rather than a missing one.
- Snapshots are keyed by a per-worker id rather than bare pid. forks gives one process per file
  so pid was unique there, but threads puts every worker in one process (measured: 3 files gave
  3 snapshots on forks, 1 on threads), and per-file flushing would have several workers writing
  one path concurrently.
- The flush no longer swallows its error. A silently unwritten snapshot is the exact failure
  this PR exists to close.
- The child run's interval backstop is pushed to an hour, so afterAll is the only path that can
  satisfy the test. Otherwise a child that lives past 15s passes it through the timer with or
  without the fix.
- README: the traced invocation is --project unit-trace, and the paragraph claiming a multi-file
  traced run keeps only the last file's counters is no longer true.

Fixing the clear-at-start introduced its own regression, caught by re-running the battery: it
removed the caller-supplied directory rather than its snapshots, turning a clean assertion into
an ENOENT crash. It now unlinks *.json only.

Six mutants, six deaths, each on its own assertion: no afterAll -> expected 0 to be greater than
0; empty snapshot -> expected [] to include the fixture module; project renamed back to unit ->
startup error, no "1 passed"; clearing disabled -> expected 2 to be 1; bare pid -> filename shape.
The bare-pid case is killed by a filename-shape PROXY and is labelled as one in the test - the
real property needs a threads-pool child with several workers, which these tests do not build.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01CuaBZXbMVSzwPkpEtHhvxh

* fix(test-perf): close the rename's own coverage hole, and stop the fix round's new sharp edges

Delta re-audit of the previous round. Its verdict was "safe to merge"; its findings were not
empty, and the findings are what decide.

The gap that mattered: every assertion named unit-trace, so renaming the project back to unit in
BOTH the config and the test passed green while fully restoring the cache collision that took 16
of 53 files red. The previous tip was literally that configuration and shipped green. There is
now a case that runs the traced config with --project unit and requires it to FAIL with "No
projects matched", so the two spellings can no longer be reverted together in silence.

The bare-pid guard was a filename-shape proxy, and the audit was right that the real property is
cheap to test: two more three-line fixtures and one --pool=threads child. It now asserts the DATA
survived - all three fixture modules present in the merged snapshot - rather than the filename.
Reverting to a bare pid loses two workers' counters to a clean last-wins overwrite and the case
goes red.

That mutant also exposed a coupling the audit did not see: the writer's filename format and the
clear's delete predicate were two copies of one rule, and with a bare pid the clear silently
stopped matching, so a second run summed on top of the first. Both now come from
trace-snapshot-name.ts.

Other audit findings:
- trace-report.mjs created no .test-perf/ before writing trace.json, so with TESTPERF_TRACE_DIR
  set on a fresh clone the documented workflow crashed with a raw ENOENT after doing all the
  merge work. mkdirSync first.
- TESTPERF_TRACE_INTERVAL_MS ran through bare Number(), so abc/empty/-5 all became a 1ms
  synchronous whole-snapshot write loop inside every worker - measured 45 fires in 50ms - which
  charges its own cost to the measurement. Validated with the same idiom vitest.config.mts uses.
- The snapshot clear deleted every top-level *.json in a caller-supplied directory. Scoped to
  this tool's own filename shape, and wrapped: a throw there happens at config load and would
  abort the whole run with a raw stack.
- trace-config.mts advertised a bench.mjs invocation that its own rename breaks (bench hardcodes
  --project unit). Docstring corrected rather than widening bench's filter, which would drag
  unit-native into every yardstick run.
- Two comments corrected against measurement: the flush fires once per test FILE, not per suite,
  and the thread-pool failure is a silent last-wins overwrite, not a truncated read.
- README now discloses what the rename costs - a second 87MB dep bundle - and that under --watch
  only the first re-run clears.

Seven mutants, six dead on their own assertion: no afterAll -> expected 0 to be greater than 0;
empty snapshot -> expected [] to include; clearing disabled and bare pid -> expected 2 to be 1;
full rename -> expected +0 not to be 0. M7, reverting the interval validation, SURVIVES: no test
supplies garbage to that knob, so it is an unpinned defensive guard and is called one here rather
than counted as covered.

🔴 One of the previous round's mutants did not actually apply - backtick escaping - and its
"survived" reading was a fact about the harness, not the code. Every mutation in this round
asserts its own target was found before the run.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01CuaBZXbMVSzwPkpEtHhvxh

* fix(test-perf): pin the two behaviours the last round asserted but never checked

Round 3 of the delta audit. Verdict was "ship"; it still found two guards that no test could see,
and both are now killed by a mutant.

- The clear's PROTECTIVE half was unpinned. Widening SNAPSHOT_FILE_RE back to /\.json$/ left every
  test green while destroying a caller's other JSON - exactly what the README promises it will not
  do, and the whole reason trace-snapshot-name.ts exists. Only the drift direction was covered.
  Test 1 now writes important-notes.json into the trace dir and requires it to survive.
- The interval validation was called an unpinnable defensive guard. That was giving up early: the
  audit pointed out this PR had just established the pattern for pinning it. resolveIntervalMs is
  now a pure helper in the shared module with a nine-case table, no child process, and reverting
  it turns seven cases red.

Fixing that found a real hole in my own guard: Number.parseInt reads '1e10' as 1, which is the
1ms flush loop the check exists to prevent, and a case bare Number() handled correctly. It now
uses Number with an n >= 1 bound.

Also from the audit:
- The clear caught its error around the whole loop, so one undeletable snapshot abandoned every
  other stale file - and the survivors are summed into this run's numbers. Now per entry.
- The docstring said a typo'd --project unit "fails loudly". True, but not harmlessly: the clear
  runs at config load, before the project filter, so that invocation empties the trace directory
  first. Said so.
- The suffix comment claimed once per worker; measured once per test FILE under isolation.
- Fixture c's stated rationale was wrong - two files already discriminate, because the tracer
  re-initialises per file rather than per worker, so a scheduler batching them cannot hide an
  overwrite. Deleted it and the threads case runs on two.

Nine mutants, nine deaths, each on its own assertion: no afterAll / bare pid / writer filename
drift -> expected 0 to be greater than 0; empty snapshot -> expected [] to include; clearing
disabled -> expected 2 to be 1; full rename -> expected +0; interval validation reverted ->
expected NaN to be 15000; regex widened -> expected false to be true. Every mutation asserts its
target matched exactly once before the run.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01CuaBZXbMVSzwPkpEtHhvxh

* fix(test-perf): the interval guard had an upper bound problem, and the test asserted the broken value

Round 4 of the delta audit, and it caught my round-3 fix landing on the same pathology from the
other side.

resolveIntervalMs bounded the input below but not above. setInterval stores its delay in a 32-bit
signed int, so anything over TIMEOUT_MAX (2147483647) is clamped to 1ms - measured on Node
24.19.0, 1e10 fired 281 times in a 300ms window with "TimeoutOverflowWarning: Timeout duration was
set to 1", and it reproduces end to end in a real traced run. That is the ~900 writes/second
inside every worker that the function's own docstring exists to prevent, reachable from the "make
it huge so it never fires" direction. Worse, the it.each table I added asserted 1e10 -> 1e10 as
the correct answer, so the defect was enshrined as deliberate. Bounded at both ends now, with
cases at MIN-1, MIN, MAX, MAX+1 and 1e10.

Four behaviours the audit showed were unpinned or unmodelled:

- The per-entry catch in the clear was real and load-bearing - 0 survivors vs 5 - and no test
  could tell it from the pre-fix shape. The clear is now an exported clearStaleSnapshots with a
  synthetic-directory test including an EISDIR entry; reverting it to a rethrow goes red.
- mergeSnapshots in the test had stopped modelling trace-report.mjs: it filtered by the snapshot
  regex while the real reader took any *.json. Running the real reader against the directory this
  PR's own test creates gave "20 distinct modules | NaN executions | NaNs self time". The reader
  now accepts snapshots by SHAPE rather than extension - it is a .mjs file and the shared
  constants are TS, so a value check is what cannot drift - and a test spawns it against a foreign
  file and requires no NaN.
- Dropping the regex's $ anchor survived green: it still matches 1234-abcd.json.bak and .json.swp,
  i.e. editor and backup files next to a caller's data. The survives-set now includes one.
- The summing merge survived green too, because with clearing on there is only ever one snapshot.
  It is now pinned where two genuinely coexist - the threads case - against the sum of a module
  common to both files.

Also: TESTPERF_TRACE_DIR used ?? in all three readers, so an exported-but-empty value kept '',
mkdirSync('') threw, no snapshot was written and the report said "run a traced suite first" - the
dead-instrument failure this whole change exists to remove. Now || with a trim, single-sourced.
And trace-setup.ts's header rationale claimed globalThis makes counters survive across files;
measured, each file writes a disjoint snapshot on both pools and the totals are correct because
the report SUMS. The stale per-worker framing is gone from the report's label too - that count is
test files.

Thirteen mutants, thirteen deaths, each on its own assertion. Every mutation asserts its target
matched exactly once before the run.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01CuaBZXbMVSzwPkpEtHhvxh

* fix(test-perf): guard the tool, not the test's mirror of it — closing three named gaps

Round 5 of the delta audit named three fixes and a mechanical closing condition: re-run five
specific mutants rather than open a sixth round. All three are here and all five now die.

The pattern the audit named, which is what actually cost the last two rounds: the tests were
guarding their own mirror of the tool rather than the tool.

- The interval table derived every expectation from the constant it was testing, so it could no
  longer see a WRONG CONSTANT. DEFAULT -> 1 and MAX -> 2**31 both survived a green suite, and both
  are the 1ms flush loop the function exists to prevent - reachable on the default path a
  developer hits by not setting the variable at all. That is round 3's defect one notch out,
  introduced by round 3's own fix. Two literal rows now sit beside the derived ones.
- The shipped reader's sum was unpinned. mergeSnapshots in the test is a reimplementation, and it
  was the only thing any mutant could see; the single test that ran the real reader had a
  one-snapshot fixture, where summing and overwriting are identical. The fixture now holds two
  snapshots naming one module, asserted against the totals the tool itself prints.
- The .mjs reader cannot import the shared TS resolver, so it carries its own copy of the
  empty-string rule - the same drift the shared module exists to stop, one layer out where the
  module cannot reach. Reverting it to ?? was green while reintroducing half the dead-instrument
  failure this PR removes. A second spawn with TESTPERF_TRACE_DIR='' closes it.

Free corrections from the same round: trace-config.mts still documented one snapshot "per worker"
while trace-snapshot-name.ts three files away says that is not true; a test title and the README
carried the same stale framing; fixture b's comment counted three fixtures when there are two.

Closing condition, each mutation asserted applied and its mutant text confirmed on disk before the
run: DEFAULT->1 dies on `expected 1 to be 15000`; MAX->2**31 on `expected 2147483648 to be 15000`;
reader loads += -> = and selfMs += -> = both on the printed totals; .mjs ?? on the fallback path.
28 tests, 4.6s.

Not taken, deliberately: the report still exits with a raw ENOTDIR stack when TESTPERF_TRACE_DIR
names a regular file, and isSnapshot's guards are wider than the one test covering them. Both were
called optional, neither is a live defect, and adding more scaffolding to a gitignored dev tool is
the thing this ladder has been overdoing.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01CuaBZXbMVSzwPkpEtHhvxh

---------

Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
2026-08-26 22:07:00 -05:00

114 lines
4.2 KiB
JavaScript

#!/usr/bin/env node
/** Merges the per-file `.test-perf/trace/*.json` snapshots into a ranked report. */
import { readdirSync, readFileSync, writeFileSync, existsSync, mkdirSync } from 'fs';
import path from 'path';
import { fileURLToPath } from 'url';
const repoRoot = path.resolve(path.dirname(fileURLToPath(import.meta.url)), '../..');
// Must honour the same override `trace-setup.ts` writes to, or exporting it puts the snapshots
// somewhere this tool then reports as "run a traced suite first" — the exact silent-zero this
// tooling exists to avoid.
const envDir = process.env.TESTPERF_TRACE_DIR;
const dir = envDir && envDir.trim() ? envDir : path.join(repoRoot, '.test-perf/trace');
if (!existsSync(dir)) {
console.error(`no ${dir} — run a traced suite first`);
process.exit(2);
}
// 🔴 Accepted by SHAPE, not by extension. TESTPERF_TRACE_DIR is caller-supplied and the tracer
// deliberately leaves foreign files alone, so a plain `*.json` sweep reads someone's own JSON as a
// snapshot and adds `undefined` into every total: measured `20 distinct modules | NaN executions |
// NaNs self time`, with the file count inflated too. A NaN report is worse than a missing one —
// it looks like a measurement. This is a JS file and the shared constants are TS, so the check is
// on the VALUES rather than on a duplicated filename regex, which cannot drift.
const isSnapshot = (data) =>
data !== null &&
typeof data === 'object' &&
!Array.isArray(data) &&
Object.values(data).every(
(e) =>
e !== null &&
typeof e === 'object' &&
['loads', 'selfMs', 'totalMs'].every((k) => typeof e[k] === 'number' && Number.isFinite(e[k]))
);
const merged = new Map();
let snapshots = 0;
let skipped = 0;
for (const f of readdirSync(dir).filter((f) => f.endsWith('.json'))) {
let data;
try {
data = JSON.parse(readFileSync(path.join(dir, f), 'utf8'));
} catch {
skipped++;
continue;
}
if (!isSnapshot(data)) {
skipped++;
continue;
}
snapshots++;
for (const [id, e] of Object.entries(data)) {
const cur = merged.get(id) ?? { loads: 0, selfMs: 0, totalMs: 0 };
cur.loads += e.loads;
cur.selfMs += e.selfMs;
cur.totalMs += e.totalMs;
merged.set(id, cur);
}
}
if (skipped) console.error(`skipped ${skipped} file(s) in ${dir} that are not trace snapshots`);
const rows = [...merged.entries()].map(([module, e]) => ({
module,
loads: e.loads,
selfMs: Math.round(e.selfMs),
totalMs: Math.round(e.totalMs),
msPerLoad: +(e.selfMs / e.loads).toFixed(2),
}));
const totalSelf = rows.reduce((a, r) => a + r.selfMs, 0);
const totalLoads = rows.reduce((a, r) => a + r.loads, 0);
const out = {
generatedAt: new Date().toISOString(),
snapshots,
distinctModules: rows.length,
totalLoads,
totalSelfMs: totalSelf,
bySelfMs: [...rows].sort((a, b) => b.selfMs - a.selfMs).slice(0, 120),
byLoads: [...rows].sort((a, b) => b.loads - a.loads).slice(0, 120),
slowestPerLoad: [...rows]
.filter((r) => r.loads > 5)
.sort((a, b) => b.msPerLoad - a.msPerLoad)
.slice(0, 60),
all: rows,
};
// `.test-perf/` is gitignored, and with TESTPERF_TRACE_DIR pointed elsewhere nothing else creates
// it — so on a fresh clone this write used to throw ENOENT after all the merging was done and
// before anything was printed, which reads as operator error rather than as a missing directory.
const reportPath = path.join(repoRoot, '.test-perf/trace.json');
mkdirSync(path.dirname(reportPath), { recursive: true });
writeFileSync(reportPath, JSON.stringify(out, null, 2));
console.log(
`${snapshots} snapshots (one per traced test file) | ${
rows.length
} distinct modules | ${totalLoads.toLocaleString()} executions | ${(totalSelf / 1000).toFixed(
0
)}s self time`
);
console.log(
'\nTop 25 by total self time (the cost of the module body itself, excluding its imports):'
);
for (const r of out.bySelfMs.slice(0, 25))
console.log(
` ${String(Math.round(r.selfMs)).padStart(7)}ms x${String(r.loads).padStart(
5
)} ${r.msPerLoad.toFixed(2)}ms/load ${r.module}`
);
console.log('\nTop 25 by execution count (what isolation is making you re-run):');
for (const r of out.byLoads.slice(0, 25))
console.log(
` x${String(r.loads).padStart(5)} ${String(Math.round(r.selfMs)).padStart(7)}ms ${r.module}`
);