perf_bench: PERF_BENCH_TRACE, each load's timeline for Horizon and vanilla

Horizon's status every 50 ms after each teleport, and the vanilla driver's
loaded chunk count and the chunks it holds within the render distance minus
one, in one JSON-lines file: when the columns arrive against when the load
ends.

Co-Authored-By: Claude Opus 5.5 <[email protected]>

docs/benchmark.md

@@ -55,7 +55,7 @@ python3 tools/perf_bench.py --game vanilla-mods --label mods-mine
 python3 tools/perf_bench.py --table horizon-mine vanilla-mine mods-mine
 ```
 
-Options: `--distances 8,16`, `--sizes 1920x1080`, `--scenes village,ocean`, `--seconds 20`, `--repeats 5`, `--heap 4G` (vanilla), `--offscreen` (Horizon, for locked or headless sessions). Results go to `benchmarks/perf/<label>-rd<N>.json` at 1280x720 and `<label>-1080p-rd<N>.json` at 1920x1080 (other sizes `<label>-<W>x<H>-rd<N>.json`; `--table` takes those labels), one [benchmark report](benchmark-report.md) per window size and render distance (the same format the game's `--benchmark` and the launcher write), with the load average before each game; each game's log, and the vanilla driver's event log, stay in `.local/perf-bench/`. Keep the machine otherwise idle, plugged in, and the window on a screen.
+Options: `--distances 8,16`, `--sizes 1920x1080`, `--scenes village,ocean`, `--seconds 20`, `--repeats 5`, `--heap 4G` (vanilla), `--offscreen` (Horizon, for locked or headless sessions). Results go to `benchmarks/perf/<label>-rd<N>.json` at 1280x720 and `<label>-1080p-rd<N>.json` at 1920x1080 (other sizes `<label>-<W>x<H>-rd<N>.json`; `--table` takes those labels), one [benchmark report](benchmark-report.md) per window size and render distance (the same format the game's `--benchmark` and the launcher write), with the load average before each game; each game's log, and the vanilla driver's event log, stay in `.local/perf-bench/`. Keep the machine otherwise idle, plugged in, and the window on a screen. `PERF_BENCH_TRACE=<file>` appends each load's timeline to that file, one JSON line per sample: Horizon's status every 50 ms after a line for each teleport (resident and generated chunks, chunks still pending, stage counts), and the vanilla driver's loaded chunk count and the chunks it holds within the render distance minus one; compare when the columns arrive with when the load ends.
 
 ### Many-entity stress scenes
 

mods/horizon/src/bench/java/dev/horizonlab/bench/VanillaBench.java

@@ -55,6 +55,8 @@ public final class VanillaBench implements ClientModInitializer {
     private long phaseStart;
     private long lastFrame;
     private long readyCheck;
+    private long lastTrace;
+    private static final boolean TRACE = System.getProperty("horizon.bench.trace") != null;
     private int lastLoaded = -1;
     private long lastChange;
     private final List<Float> frames = new ArrayList<>();
@@ -161,6 +163,16 @@ public final class VanillaBench implements ClientModInitializer {
                 Vec3 from = vec(s.getAsJsonArray("from"));
                 // Once the teleport has arrived, hold the player there, flying.
                 if (mc.player != null && mc.player.position().distanceToSqr(from) < 1024.0) place(mc, s, 0);
+                if (TRACE && now - lastTrace >= 50_000_000L && mc.level != null) {
+                    // PERF_BENCH_TRACE: when the columns arrive, to compare with Horizon's trace.
+                    lastTrace = now;
+                    JsonObject e = named(s);
+                    e.addProperty("ms", (now - phaseStart) / 1e6);
+                    e.addProperty("chunks", mc.level.getChunkSource().getLoadedChunksCount());
+                    e.addProperty("compiled", mc.levelRenderer.hasRenderedAllSections());
+                    if (mc.player != null) e.addProperty("around", around(mc));
+                    event("progress", e);
+                }
                 if (ready(mc, from, now)) {
                     JsonObject e = named(s);
                     e.addProperty("load_ms", (lastChange - phaseStart) / 1e6);
@@ -274,6 +286,21 @@ public final class VanillaBench implements ClientModInitializer {
         return true;
     }
 
+    /** The chunks chunksAround waits for that are on the client, and how many it waits for. */
+    private static String around(Minecraft mc) {
+        int r = Math.max(1, mc.options.getEffectiveRenderDistance() - 1), have = 0, all = 0;
+        var center = mc.player.chunkPosition();
+        var chunks = mc.level.getChunkSource();
+        for (int dx = -r; dx <= r; dx++) {
+            for (int dz = -r; dz <= r; dz++) {
+                if (dx * dx + dz * dz > r * r) continue;
+                all++;
+                if (chunks.hasChunk(center.x() + dx, center.z() + dz)) have++;
+            }
+        }
+        return have + "/" + all;
+    }
+
     /** Puts the player on the scene's line at fraction t, facing along it, as Horizon's flight. */
     private static void place(Minecraft mc, JsonObject s, double t) {
         LocalPlayer player = mc.player;

tools/perf_bench.py

@@ -427,6 +427,10 @@ def poll(control, check, limit, interval=0.05):
 # Fewer section meshes than this in a second is the game remeshing blocks that change (random
 # ticks), not loading.
 QUIET_MESHES_PER_S = 100
+# PERF_BENCH_TRACE=<file>: where a load spends its time, one JSON line each: every status Horizon's wait_loaded
+# reads, after a {"tp", "scene"} line per teleport; the vanilla driver's "progress" every 50 ms while it loads
+# (its loaded chunk count, and "around": the chunks within the render distance minus one it holds, of all).
+TRACE = os.environ.get("PERF_BENCH_TRACE")
 
 
 def view_chunks(distance):
@@ -458,6 +462,11 @@ def wait_loaded(control, near, limit, min_chunks=0):
             s = {}
         player = s.get("player")
         now = time.time()
+        if TRACE:
+            with open(TRACE, "a") as out:
+                out.write(json.dumps({"t": now, "chunks": s.get("chunks"), "generated": s.get("generated_chunks"),
+                                      "pending": s.get("pending_chunks"), "meshed": s.get("meshed_sections"),
+                                      "streaming": s.get("streaming"), "fps": s.get("fps")}) + "\n")
         if not player or not near(player["position"]) or s.get("pending_chunks") != 0 or s.get("screen") == "title":
             last, changed, previous, meshing = None, now, None, now
         else:
@@ -642,6 +651,9 @@ def run_horizon(args, distance):
             meshed = control("status")["meshed_sections"]
             scene_commands(args, control, start, pitch)
             tp = time.time()
+            if TRACE:
+                with open(TRACE, "a") as out:
+                    out.write(json.dumps({"tp": tp, "scene": name}) + "\n")
             # A zero-length flight holds the player at the start, flying.
             control("fly {0} {1} {2} {0} {1} {2} 0.1 {3}".format(*start, pitch))
             control(f"look {yaw(start, end):.3f} {pitch}")
@@ -818,6 +830,7 @@ def run_vanilla(args, distance):
                "--enable-native-access=ALL-UNNAMED",
                f"-Djava.library.path={natives}", f"-Dorg.lwjgl.system.SharedLibraryExtractPath={natives}",
                f"-Dhorizon.bench.script={script}", f"-Dhorizon.bench.out={events}",
+               *([f"-Dhorizon.bench.trace={TRACE}"] if TRACE else []),
                "-Dfabric.log.disableAnsi=true",
                "-cp", os.pathsep.join(map(str, game_jars + fabric)),
                "net.fabricmc.loader.impl.launch.knot.KnotClient",
@@ -862,6 +875,9 @@ def driven(args, distance, command, game_dir, env, log, events, options, loaded_
         stop(proc)
         sampler.stop.set()
     lines = [json.loads(l) for l in events.read_text().splitlines()] if events.exists() else []
+    if TRACE:
+        with open(TRACE, "a") as out:
+            out.writelines(json.dumps(e) + "\n" for e in lines if e["event"] == "progress")
     by = lambda name: [e for e in lines if e["event"] == name]
     if not by("done") or by("timeout"):
         raise RuntimeError(f"{args.game} run failed: {lines[-1:] if lines else 'no events'}; see {log.name}")