From 66dc2551e05c3638a5d78993ddd56ac36d47b79f Mon Sep 17 00:00:00 2001 From: "prompt.ac/@jeffrey" Date: Sat, 8 Aug 2026 18:42:21 -0700 Subject: [PATCH] Time the sim instead of the instrument watching it MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit perf-record was reporting probe.mjs's number, and that number is not the simulation. Its timed pass snapshots the world, canonicalizes it and SHA-256s it on every tick — about 30 µs against a sim that costs 21, so two thirds of the figure was the harness measuring itself. All that per-tick allocation also drives GC, which is where the 20-50% run-to-run spread came from; timing the bare loop lands inside a few percent. That spread was not cosmetic. It hid everything: a sweep across the eleven commits since 2fcb1b6f4 could not attribute the drift to any of them, and once flagged a commit at +42% whose successors measured faster, which is impossible. Timed bare, the same sweep is legible — 9.09 µs at the baseline against 21.00 at HEAD, bought by three commits: the framing and movement rebuild (+37%), making the entry screen a live fight (+36%), and folding diagnostics into the world (+11%). So the sim costs a third of what we believed, against a 16,667 µs tick: roughly 1000 real-time authoritative matches per core rather than 330. It was never near the budget, and it is not the thing to optimize. Two smaller corrections fall out. V8 has to see the sim hot before its numbers mean anything, so two warmup passes are thrown away rather than averaged in. And a reading now carries the metric that produced it, so these cannot be diffed against the older instrumented rows already in the ledger — a comparison that read as a 42% improvement and was only a change of ruler. --- xbox/live/perf-record.mjs | 77 +++++++++++++++++++++++++++++++-------- 1 file changed, 62 insertions(+), 15 deletions(-) diff --git a/xbox/live/perf-record.mjs b/xbox/live/perf-record.mjs index 689974eadd..b85d0ad8f4 100644 --- a/xbox/live/perf-record.mjs +++ b/xbox/live/perf-record.mjs @@ -5,9 +5,9 @@ // node xbox/live/perf-record.mjs --quick # cpu only, skip determinism // node xbox/live/perf-record.mjs --show # print the ledger's recent history // -// The point is drift. A single number says nothing — 52.97 µs per tick is only -// alarming next to the 27.66 µs the architecture was written against, which is -// how we learned the sim had roughly doubled in cost without anyone noticing. +// The point is drift. A single number says nothing — the sim costing 21 µs a +// tick only means something next to the 9 µs it cost at 2fcb1b6f4, which is how +// we learned it had more than doubled, and which three commits bought it. // So every reading is stamped with the commit and the machine and kept, and the // tool compares each one against the run before it on the same machine. // @@ -83,8 +83,11 @@ function probe(name, args = []) { return { text: out, json: lastJson(out) }; } +const METRIC = "bare-sim"; // bumped if what we time ever changes again + const reading = { at: new Date().toISOString(), + metric: METRIC, host: HOST, node: process.version, commit: git("rev-parse", "--short", "HEAD"), @@ -92,19 +95,57 @@ const reading = { dirty: git("status", "--porcelain").length > 0, }; -const cpu = probe("probe.mjs"); -if (!cpu.json?.performance) { - console.error("probe.mjs produced no performance block:\n" + cpu.text.slice(-800)); - process.exit(1); +// Time the simulation directly rather than reading probe.mjs's number, because +// that number is not the simulation. Its timed pass snapshots the world, walks +// it into a canonical form and SHA-256s it on every single tick — around 30 µs +// against a sim that costs 21, so roughly two thirds of what it reports is the +// instrument watching itself. Worse, all that per-tick allocation drives GC, +// which is where the 20-50% run-to-run spread came from; timing the bare loop +// lands inside 3% and only then is a regression visible at all. +const TICK_US = 16667; +const TICKS = 1800; +const REPEATS = 3; + +const { createHeadless, inputScript } = await import( + new URL("file://" + join(PROBES, "harness.mjs")).href); + +function timeBareSim() { + const script = inputScript(20260807, TICKS); // (seed, ticks) — in that order + const host = createHeadless({ withPaint: false }); + host.fight.enterGame(); + host.fight.startFight(); + const started = process.hrtime.bigint(); + for (let tick = 0; tick < script.length; tick++) { + host.setPads(script[tick]); + host.tick(TICK_US); + } + return Number(process.hrtime.bigint() - started) / 1000 / TICKS; } + +// V8 needs to see the sim hot before its numbers mean anything: timed cold, the +// first pass runs ~35% slow and drags the spread out past the signal. Throw the +// warmups away rather than averaging them in. +timeBareSim(); +timeBareSim(); +// The minimum is the least-disturbed run. Background load can only ever make a +// sample slower, never faster, so min is the honest estimator here. +const samples = Array.from({ length: REPEATS }, timeBareSim); +const usPerTick = +Math.min(...samples).toFixed(2); Object.assign(reading, { - usPerTick: cpu.json.performance.usPerTick, - ticksPerSecondPerCore: cpu.json.performance.ticksPerSecondPerCore, - realtimeMatchesPerCore: cpu.json.performance.realtimeMatchesPerCore, - resimulatePerTickUs: cpu.json.performance.resimulatePerTickUs, - hash: cpu.json.crossProcessHash ?? null, + usPerTick, + spread: +(Math.max(...samples) - Math.min(...samples)).toFixed(2), + ticksPerSecondPerCore: Math.round(1e6 / usPerTick), + realtimeMatchesPerCore: Math.round(1e6 / usPerTick / 60), }); +// The hash is the correctness signal and costs a full probe run, so it is worth +// it unless someone asked for speed. +if (!flags.has("--quick")) { + const cpu = probe("probe.mjs"); + reading.hash = cpu.json?.crossProcessHash ?? null; + reading.harnessUsPerTick = cpu.json?.performance?.usPerTick ?? null; +} + if (!flags.has("--quick")) { try { const determinism = probe("nondeterminism.mjs"); @@ -117,11 +158,17 @@ if (!flags.has("--quick")) { mkdirSync(LEDGER_DIR, { recursive: true }); appendFileSync(LEDGER, JSON.stringify(reading) + "\n"); -const previous = history().slice(0, -1).filter((row) => row.host === HOST).at(-1); +const previous = history().slice(0, -1) + .filter((row) => row.host === HOST && row.metric === METRIC).at(-1); console.log(`${reading.host} · ${reading.commit}${reading.dirty ? "+dirty" : ""} ` + `· node ${reading.node}`); -console.log(` ${reading.usPerTick} µs/tick · ` + - `${reading.realtimeMatchesPerCore} realtime worlds per core · hash ${reading.hash}`); +console.log(` ${reading.usPerTick} µs/tick (±${reading.spread}) · ` + + `${reading.realtimeMatchesPerCore} realtime worlds per core` + + (reading.hash ? ` · hash ${reading.hash}` : "")); +if (reading.harnessUsPerTick) { + console.log(` (probe.mjs reports ${reading.harnessUsPerTick} µs — that figure` + + " includes its own per-tick hashing, not just the sim)"); +} if (reading.deterministic === false) console.log(" ⚠️ determinism probe DIVERGED"); if (previous) { -- 2.51.2