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) {