Time a whole run in one process, and keep a hitch from ending the session.

`make bench` is one recipe over one run now. `IW4L_BENCH=1` arms an in-process
recorder on the spans that already feed Perfetto, and at exit the run prints
two independent reports and writes them to `iw4l-artifacts/bench/<stamp>.txt`:
the waterfall from the shell command to a playable map, carrying the time each
load stage held the pool alone, and frame time as a span tree whose nesting is
recorded rather than declared. Neither needs a trace file or Trace Processor,
and either can be MISS while the other stands. `bench-demo` and `bench-load`
are gone — a goal after `bench` is a demo, `ZONE=` is a live map.

A bot is no longer minted onto an id a real client already owns. The roster
steps over the ids the authority and the local player hold, and a slot that
still lands on the local player is retired, because `is_bot` would otherwise
claim the player and nothing could drive the slot anyway.

A stretch with no authority ack re-adopts the next snapshot and counts one
stall; three of them still fail the link. Failing on the first turned every
long frame into a permanent disconnect.

The loading overlay comes down once the world is installed rather than waiting
on the class-select hop, which a replay never makes — it was playing the whole
demo behind `UiLayer::Loading`, with map ambience held back.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_013bHwyKwUjaYmtVG1F3Ttku

Cargo.toml

@@ -184,7 +184,7 @@ assertions_on_constants = "deny"
 # Measured and kept: wall p50 -5.7%, binary 183 MB -> 114 MB. Do not drop these
 # two lines without a new two-map A/B on the same protocol.
 #
-# Live recipes (`make map` / `play` / `bench-demo` / `bench-live` / …) do not use this profile.
+# Live recipes (`make map` / `play` / `bench` / `bench-live` / …) do not use this profile.
 # Fat LTO: `PROFILE=release` on a live target when the number must match S2-I11.
 # Fat LTO + one codegen unit stay on this profile only. `make deploy` does not
 # select it; that is `PROFILE=release`.
@@ -193,7 +193,7 @@ lto = true
 codegen-units = 1
 strip = "symbols"
 
-# The dev loop, including `make bench-demo` and the default Windows/master
+# The dev loop, including `make bench` and the default Windows/master
 # deploy path. Same opt-level as release (Bevy is unusable without it), minus
 # the two settings whose cost is paid at *link* time: fat LTO over the whole
 # dependency graph in one codegen unit is a single-threaded rustc at ~6.6 GB
@@ -208,7 +208,7 @@ strip = "symbols"
 # Separate profile rather than a relaxed `[profile.release]`: S2-I11's verdict
 # stands, and the binary its numbers describe has to stay buildable.
 # Frame-time cost of `play` vs `release` is NOT measured here — that A/B is
-# `make bench-demo` vs `make bench-demo PROFILE=release`.
+# `make bench <demo>` vs `make bench <demo> PROFILE=release`.
 [profile.play]
 inherits = "release"
 opt-level = 3

Makefile

@@ -10,7 +10,7 @@ endif
 GOAL := $(firstword $(MAKECMDGOALS))
 ARGS := $(wordlist 2,$(words $(MAKECMDGOALS)),$(MAKECMDGOALS))
 
-.PHONY: map export-gltf play bench bench-demo bench-load bench-load-session bench-live bench-overhead bench-perf menu menu-shots scenario chaos lifecycle-all lifecycle-swap lifecycle-replace lifecycle-play-in lifecycle-demo-out lifecycle-demo-map launcher deploy logs loc clean help
+.PHONY: map export-gltf play bench bench-load-session bench-live bench-overhead bench-perf menu menu-shots scenario chaos lifecycle-all lifecycle-swap lifecycle-replace lifecycle-play-in lifecycle-demo-out lifecycle-demo-map launcher deploy logs loc clean help
 .PHONY: build-windows setup-windows release publish provision
 .PHONY: mr publish-check
 .PHONY: $(ARGS)
@@ -97,32 +97,40 @@ play: require-games
 	@test -n "$(ARGS)" || { echo "usage: make play <demoname>   e.g. make play demo0000"; exit 1; }
 	cd $(ROOT) && $(CARGO) run $(PROFILE_ARG) -p launcher -- play $(ARGS) $(ZONE_ARG) $(CMDS_ARG)
 
-# Play a demo, write one native Perfetto run directory, then print its compact
-# percentile/hot-path report. AutoNoVsync matches renderer acceptance; Fifo
-# measures the monitor refresh queue rather than the engine. This recipe never
-# creates an FPS SQLite dump.
+# The bench. One process, two independent reports written at exit: where the
+# map load spent its time, and where a gameplay frame spends its time by span.
+# Both are in-process — no trace file and no Trace Processor — and both land in
+# iw4l-artifacts/bench/<stamp>.txt as well as on stdout.
 #
-# Same `[profile.play]` binary as `make play` — one cache, no fat-LTO wait.
-# LTO numbers: `make bench-demo demo0010 PROFILE=release`.
-# `make bench` is the old name of this recipe.
-bench-demo: require-games
-	@test -n "$(ARGS)" || { echo "usage: make bench-demo <demoname>   e.g. make bench-demo demo0011"; exit 1; }
-	cd $(ROOT) && IW4L_PERF=1 IW4L_PRESENT_MODE=AutoNoVsync $(CARGO) run $(PROFILE_ARG) -p launcher -- play $(ARGS) $(ZONE_ARG) $(CMDS_ARG)
-	cd $(ROOT) && $(CARGO) run --quiet -p xtask -- bench
+#   make bench demo0011            play a demo   (also: DEMO=demo0011)
+#   make bench ZONE=mp_boneyard    live map instead of a demo
+#   make bench demo0011 PROFILE=release          the LTO binary
+#
+# A goal after `bench` is always a demo name, never a zone: one goal cannot
+# tell the two apart, and ZONE= already names a map. `--demo` cannot be
+# written on the command line — make would read it as a flag of its own —
+# so the demo is a goal or DEMO=, and ZONE= still overrides a demo's header.
+# IW4L_PERF is on as well, so `cargo xtask bench` can still read the .pftrace
+# afterwards for the per-frame view this report deliberately does not give.
+# Same [profile.play] binary as `make play`; AutoNoVsync matches renderer
+# acceptance, Fifo would measure the monitor's refresh queue instead.
+BENCH_DEMO ?= $(DEMO)
+# The live-map script has to serve both halves: load the map, then stay long
+# enough that section two has gameplay frames to count. `force_match_start`
+# skips the 20 s warmup the controls are frozen through (docs/RUN.md).
+BENCH_MAP_CMDS ?= wait world; spawn assault; wait ambient; force_match_start; wait 10s; quit
+BENCH_DEMO_CMDS ?=
+bench: require-games
+	@test -n "$(or $(BENCH_DEMO),$(ZONE),$(ARGS))" || { echo "usage: make bench <demo>            e.g. make bench demo0011"; echo "       make bench ZONE=<zone>       e.g. make bench ZONE=mp_boneyard"; exit 1; }
+	cd $(ROOT) && IW4L_BENCH_STARTED_NS=$$(date +%s%N) IW4L_BENCH=1 IW4L_PERF=1 IW4L_PRESENT_MODE=AutoNoVsync $(CARGO) run $(PROFILE_ARG) -p launcher -- $(BENCH_TARGET)
 
-bench: bench-demo
-
-# Map-load bench, not a demo. Wall time from launch to a settled screenshot
-# of the spawned map, for eyeballing that all geometry arrived. The launcher
-# queues the screenshot itself (screenshots/bench-load/<zone>.png) and prints
-# the picture path plus total and stage timings to stdout — no xtask second
-# step. Script waits AND exits (quit waits out the owed picture); CMDS=
-# replaces the waits.
-# Zone from ZONE= / ARGS (mp_boneyard).
-BENCH_LOAD_CMDS ?= wait world; spawn assault; wait ambient; quit
-bench-load: require-games
-	@test -n "$(or $(ZONE),$(ARGS))" || { echo "usage: make bench-load <zone>   e.g. make bench-load mp_rust"; echo "       make bench-load ZONE=iw5:mp_overwatch  (colon is a make pattern)"; exit 1; }
-	cd $(ROOT) && IW4L_BENCH_LOAD_STARTED_NS=$$(date +%s%N) IW4L_PERF=1 IW4L_BENCH_LOAD=1 IW4L_PRESENT_MODE=AutoNoVsync $(CARGO) run $(PROFILE_ARG) -p launcher -- map $(or $(ZONE),$(ARGS)) --cmds '$(or $(CMDS),$(BENCH_LOAD_CMDS))'
+# `play <demo>` when a demo was named, `map <zone>` otherwise. A demo carries
+# its own zone in the header, so ZONE= only overrides it.
+ifneq ($(BENCH_DEMO)$(ARGS),)
+BENCH_TARGET = play $(or $(BENCH_DEMO),$(ARGS)) $(ZONE_ARG) $(if $(or $(CMDS),$(BENCH_DEMO_CMDS)),--cmds '$(or $(CMDS),$(BENCH_DEMO_CMDS))')
+else
+BENCH_TARGET = map $(or $(ZONE),$(ARGS)) --cmds '$(or $(CMDS),$(BENCH_MAP_CMDS))'
+endif
 
 # One menu process, two synchronous loads. Engine markers exclude Cargo and
 # process startup; the external reader subtracts their monotonic timestamps.
@@ -304,17 +312,15 @@ help:
 	@echo "make play <demo>  play iw4l-artifacts/demos/<demo>.iw4ldemo, then quit"
 	@echo "                  ZONE= overrides header"
 	@echo "                  CMDS='wait world; wait 5s; quit' mid-play"
-	@echo "make bench-demo <demo>  play and write a native Perfetto run directory"
-	@echo "                  alias: make bench <demo>"
+	@echo "make bench <demo>  the bench: map-load breakdown + frame time by span,"
+	@echo "                  printed at exit and written to iw4l-artifacts/bench/"
+	@echo "                  a goal is always a demo name; ZONE=mp_boneyard benches"
+	@echo "                  a live map instead, DEMO=demo0011 is the goal form"
 	@echo "                  same [profile.play] as map/play; PROFILE=release for LTO"
-	@echo "                  then prints p50/p90/p95/p99 and hot paths from .pftrace"
 	@echo "make bench-live [zone]  live map: force start, fire/walk/yaw hold, 16 bots,"
 	@echo "                  wait 10s, then flush trace.pftrace (default mp_boneyard)"
 	@echo "                  ZONE=iw5:mp_overwatch  (colon cannot be a make goal)"
 	@echo "                  then prints p50/p90/p95/p99 and hot paths from .pftrace"
-	@echo "make bench-load <zone>  map-load bench: launch → spawn → settled screenshot"
-	@echo "                  prints the picture path + total/zone_walk/spawn_gpu/ambient/screenshot"
-	@echo "                  timings to stdout; eyeball the picture for full geometry"
 	@echo "make bench-load-session  menu → Hanoi → Underpass; engine mark intervals"
 	@echo "make bench-overhead  paired default-off/on runs of one built binary;"
 	@echo "                  PERF_OVERHEAD_PAIRS=10, alternating order, paired 95% CI"

crates/asset_transport/src/lib.rs

@@ -21,7 +21,7 @@ pub use iwd::{
 };
 pub use namespace_trees::{NamespaceSoundIwd, NamespaceTree, NamespaceTrees};
 pub use progress::{
-    LoadLaneView, LoadOverflow, LoadProgress, LoadStage, peak_resident_bytes,
+    LoadLaneTiming, LoadLaneView, LoadOverflow, LoadProgress, LoadStage, peak_resident_bytes,
     process_resident_bytes,
 };
 pub use zone::{

crates/asset_transport/src/progress.rs

@@ -150,6 +150,47 @@ pub struct LoadLaneView {
     started: Option<Instant>,
 }
 
+/// One stage of a load, as the bench report reads it: when it opened relative
+/// to the first stage, how long it held, and what it cost in memory.
+#[derive(Clone, Debug, PartialEq)]
+pub struct LoadLaneTiming {
+    pub label: String,
+    pub at: Duration,
+    pub elapsed: Duration,
+    pub done: u64,
+    pub total: u64,
+    pub running: bool,
+    pub rss_delta: Option<i64>,
+    pub heap_delta: Option<i64>,
+}
+
+impl LoadLaneTiming {
+    pub fn end(&self) -> Duration {
+        self.at + self.elapsed
+    }
+
+    /// The `rss=+NMiB heap=+NMiB` tail, empty when the platform reports neither.
+    pub fn mem_suffix(&self) -> String {
+        fn one(name: &str, delta: Option<i64>) -> String {
+            match delta {
+                Some(delta) => format!(" {name}={:+.0}MiB", delta as f64 / (1024.0 * 1024.0)),
+                None => String::new(),
+            }
+        }
+        format!(
+            "{}{}",
+            one("rss", self.rss_delta),
+            one("heap", self.heap_delta)
+        )
+    }
+}
+
+fn delta(started: Option<u64>, ended: Option<u64>) -> Option<i64> {
+    let started = i64::try_from(started?).ok()?;
+    let ended = i64::try_from(ended?).ok()?;
+    Some(ended - started)
+}
+
 #[derive(Clone, Copy, Debug, PartialEq, Eq)]
 pub enum LoadOverflow {
     Running(usize),
@@ -436,40 +477,60 @@ impl LoadProgress {
             .collect()
     }
 
-    pub fn timing_report(&self) -> Vec<String> {
+    /// Every stage this load opened, in the order it opened them, with the
+    /// window it occupied. Stages run in parallel on the load pool, so the
+    /// offsets are what says which of them overlapped and which one nobody
+    /// else was covering; `timing_report` is this, flattened to lines, and the
+    /// bench report is this, analysed.
+    pub fn lane_timings(&self) -> Vec<LoadLaneTiming> {
         let Ok(lanes) = self.0.lanes.lock() else {
             return Vec::new();
         };
-        let mut rows = Vec::with_capacity(lanes.len() + 1);
-        let mut total = Duration::ZERO;
-
-        let origin = lanes
+        let Some(origin) = lanes
             .iter()
             .filter(|lane| !lane.note)
             .map(|lane| lane.started)
-            .min();
-        for lane in lanes.iter().filter(|lane| !lane.note) {
-            let elapsed = lane.elapsed.unwrap_or_else(|| lane.started.elapsed());
-            total += elapsed;
-            let at_ms = origin.map_or(0.0, |origin| {
-                lane.started.saturating_duration_since(origin).as_secs_f32() * 1000.0
-            });
+            .min()
+        else {
+            return Vec::new();
+        };
+        lanes
+            .iter()
+            .filter(|lane| !lane.note)
+            .map(|lane| {
+                let ended_mem = lane.ended_mem.unwrap_or_else(MemSample::now);
+                LoadLaneTiming {
+                    label: lane.label.clone(),
+                    at: lane.started.saturating_duration_since(origin),
+                    elapsed: lane.elapsed.unwrap_or_else(|| lane.started.elapsed()),
+                    done: lane.done,
+                    total: lane.total,
+                    running: lane.elapsed.is_none(),
+                    rss_delta: delta(lane.started_mem.rss, ended_mem.rss),
+                    heap_delta: delta(lane.started_mem.heap, ended_mem.heap),
+                }
+            })
+            .collect()
+    }
+
+    pub fn timing_report(&self) -> Vec<String> {
+        let lanes = self.lane_timings();
+        let mut total = Duration::ZERO;
+        let mut rows = Vec::with_capacity(lanes.len() + 1);
+        for lane in &lanes {
+            total += lane.elapsed;
             let items = match lane.total {
                 0 if lane.done == 0 => String::new(),
                 0 => format!(" items={}", lane.done),
-                total => format!(" items={}/{total}", lane.done),
+                whole => format!(" items={}/{whole}", lane.done),
             };
-            let ended_mem = lane.ended_mem.unwrap_or_else(MemSample::now);
             rows.push(format!(
-                "load stage: {} at=+{at_ms:.0}ms {:.1}ms{items}{}{}",
+                "load stage: {} at=+{:.0}ms {:.1}ms{items}{}{}",
                 lane.label,
-                elapsed.as_secs_f32() * 1000.0,
-                MemSample::suffix(lane.started_mem, ended_mem),
-                if lane.elapsed.is_none() {
-                    " (still running)"
-                } else {
-                    ""
-                },
+                lane.at.as_secs_f32() * 1000.0,
+                lane.elapsed.as_secs_f32() * 1000.0,
+                lane.mem_suffix(),
+                if lane.running { " (still running)" } else { "" },
             ));
         }
         rows.push(format!(

crates/assets/src/lib.rs

@@ -392,7 +392,7 @@ pub use prepared::{
     PreparedXModelWalkCensus, SessionCompass,
 };
 pub use progress::{
-    LoadLaneView, LoadOverflow, LoadProgress, LoadStage, peak_resident_bytes,
+    LoadLaneTiming, LoadLaneView, LoadOverflow, LoadProgress, LoadStage, peak_resident_bytes,
     process_resident_bytes,
 };
 pub use projectile_mesh_catalog::{

crates/bootstrap/src/bench/frame_report.rs

@@ -0,0 +1,266 @@
+//! Section two: where a gameplay frame goes.
+//!
+//! The tree is not a table someone wrote down: a span's parent is whichever
+//! span was open when it began, recorded by the same instrumentation that
+//! timed it. Move a system between sets and this report follows; the only
+//! declared relation is that `wall` is the frame clock, which encloses no
+//! scope because it is opened in one frame and closed in the next.
+
+use perf::{Phase, Span, SpanStats};
+
+use crate::bench::table::{Align, Table, ms, percent};
+
+/// A leaf worth naming: either it is expensive on its own, or it is a big share
+/// of a frame that nothing else explains.
+const HOT_AVG_NS: u64 = 500_000;
+const HOT_SHARE: f64 = 5.0;
+
+pub(crate) fn render(out: &mut Vec<String>) {
+    let stats = perf::stats::snapshot(Phase::Live);
+    out.push("[2/2] FRAME TIME".to_owned());
+    let Some(wall) = stats
+        .iter()
+        .find(|row| row.span == Span::FramesWallFrameMs)
+        .copied()
+    else {
+        out.push(
+            "  MISS — no gameplay frame was clocked. The run never reached a playable map, or it quit at the first one."
+                .to_owned(),
+        );
+        return;
+    };
+    header(&wall, out);
+    out.push(String::new());
+    tree(&stats, &wall, out);
+    out.push(String::new());
+    hot(&stats, &wall, out);
+    anomalies(out);
+}
+
+fn header(wall: &SpanStats, out: &mut Vec<String>) {
+    let seconds = wall.sum_ns as f64 / 1e9;
+    let fps = |ns: u64| {
+        if ns == 0 {
+            "—".to_owned()
+        } else {
+            format!("{:.0}", 1e9 / ns as f64)
+        }
+    };
+    out.push(format!(
+        "  {} frames over {seconds:.2}s of gameplay, {} fps average",
+        wall.count,
+        fps(wall.avg_ns()),
+    ));
+    out.push(format!(
+        "  frame ms   avg {}  p50 {}  p95 {}  p99 {}  max {}  min {}",
+        ms(wall.avg_ns()),
+        ms(wall.p50_ns),
+        ms(wall.p95_ns),
+        ms(wall.p99_ns),
+        ms(wall.max_ns),
+        ms(wall.min_ns),
+    ));
+    out.push(format!(
+        "  same as fps  avg {}  p50 {}  p95 {}  p99 {}  min {}   (a slow frame is a low fps: the columns line up with the row above)",
+        fps(wall.avg_ns()),
+        fps(wall.p50_ns),
+        fps(wall.p95_ns),
+        fps(wall.p99_ns),
+        fps(wall.max_ns),
+    ));
+    out.push(format!(
+        "  percentiles are histogram midpoints, exact to ±{:.1}%; counts, sums and extremes are exact.",
+        perf::stats::PRECISION * 100.0
+    ));
+}
+
+fn tree(stats: &[SpanStats], wall: &SpanStats, out: &mut Vec<String>) {
+    let mut table = Table::new(
+        2,
+        &[
+            ("span", Align::Left),
+            ("n", Align::Right),
+            ("avg", Align::Right),
+            ("p50", Align::Right),
+            ("p95", Align::Right),
+            ("p99", Align::Right),
+            ("max", Align::Right),
+            ("total", Align::Right),
+            ("%frame", Align::Right),
+            ("self", Align::Right),
+        ],
+    );
+    let mut placed: Vec<Span> = Vec::with_capacity(stats.len());
+    push(&mut table, wall, wall, 0, self_ns(stats, wall, None));
+    walk(stats, wall, None, 1, &mut table, &mut placed);
+
+    // A span whose recorded parent is not itself reachable from the root — a
+    // parent that took no sample in this window, or two spans that raced and
+    // each recorded the other. Dropping them silently would hide numbers that
+    // were measured, so they are shown, under their own heading, with the
+    // parent each of them recorded.
+    let mut orphans: Vec<&SpanStats> = stats
+        .iter()
+        .filter(|row| row.span != Span::FramesWallFrameMs && !placed.contains(&row.span))
+        .collect();
+    table.render(out);
+    out.push(
+        "  `self` is the span's own time: its total minus the totals of the spans that nested inside it."
+            .to_owned(),
+    );
+    if orphans.is_empty() {
+        return;
+    }
+    orphans.sort_by_key(|row| std::cmp::Reverse(row.sum_ns));
+    out.push(String::new());
+    out.push(
+        "  not placed in the tree — the parent each recorded is not itself reachable from the frame, so their nesting is unknown:"
+            .to_owned(),
+    );
+    let mut table = Table::new(
+        2,
+        &[
+            ("span", Align::Left),
+            ("n", Align::Right),
+            ("avg", Align::Right),
+            ("p95", Align::Right),
+            ("total", Align::Right),
+            ("%frame", Align::Right),
+            ("recorded under", Align::Left),
+        ],
+    );
+    for row in orphans {
+        table.row([
+            format!(
+                "{}{}",
+                row.span.name(),
+                if row.parent_varies { " *" } else { "" }
+            ),
+            row.count.to_string(),
+            ms(row.avg_ns()),
+            ms(row.p95_ns),
+            ms(row.sum_ns),
+            percent(row.sum_ns, wall.sum_ns),
+            row.parent
+                .map_or_else(|| "—".to_owned(), |parent| parent.name().to_owned()),
+        ]);
+    }
+    table.render(out);
+}
+
+/// Children of `parent`, heaviest first, then their children. `wall` is the
+/// root of the printed tree but the parent of nothing, so the spans with no
+/// recorded parent hang directly under it. `placed` is both the record of what
+/// has been printed and the guard that keeps a parent cycle from recursing
+/// forever.
+fn walk(
+    stats: &[SpanStats],
+    wall: &SpanStats,
+    parent: Option<Span>,
+    depth: usize,
+    table: &mut Table,
+    placed: &mut Vec<Span>,
+) {
+    let mut children: Vec<&SpanStats> = stats
+        .iter()
+        .filter(|row| row.span != Span::FramesWallFrameMs && row.parent == parent)
+        .filter(|row| !placed.contains(&row.span))
+        .collect();
+    children.sort_by_key(|row| std::cmp::Reverse(row.sum_ns));
+    for child in children {
+        placed.push(child.span);
+        push(
+            table,
+            child,
+            wall,
+            depth,
+            self_ns(stats, child, Some(child.span)),
+        );
+        walk(stats, wall, Some(child.span), depth + 1, table, placed);
+    }
+}
+
+/// A span's total minus what its children accounted for. For `wall` the
+/// children are the spans that recorded no parent at all — the roots of each
+/// schedule — which is what makes the remainder "the frame outside our spans".
+fn self_ns(stats: &[SpanStats], row: &SpanStats, parent: Option<Span>) -> u64 {
+    let children: u64 = stats
+        .iter()
+        .filter(|candidate| candidate.span != Span::FramesWallFrameMs && candidate.parent == parent)
+        .map(|candidate| candidate.sum_ns)
+        .sum();
+    row.sum_ns.saturating_sub(children)
+}
+
+fn push(table: &mut Table, row: &SpanStats, wall: &SpanStats, depth: usize, self_ns: u64) {
+    let varies = if row.parent_varies { " *" } else { "" };
+    table.row([
+        format!("{}{}{varies}", "  ".repeat(depth), row.span.name()),
+        row.count.to_string(),
+        ms(row.avg_ns()),
+        ms(row.p50_ns),
+        ms(row.p95_ns),
+        ms(row.p99_ns),
+        ms(row.max_ns),
+        ms(row.sum_ns),
+        percent(row.sum_ns, wall.sum_ns),
+        ms(self_ns),
+    ]);
+}
+
+fn hot(stats: &[SpanStats], wall: &SpanStats, out: &mut Vec<String>) {
+    let mut leaves: Vec<&SpanStats> = stats
+        .iter()
+        .filter(|row| row.span != Span::FramesWallFrameMs)
+        .filter(|row| !stats.iter().any(|child| child.parent == Some(row.span)))
+        .filter(|row| {
+            row.avg_ns() >= HOT_AVG_NS
+                || row.sum_ns as f64 * 100.0 / wall.sum_ns.max(1) as f64 >= HOT_SHARE
+        })
+        .collect();
+    leaves.sort_by_key(|row| std::cmp::Reverse(row.sum_ns));
+    if leaves.is_empty() {
+        out.push(format!(
+            "  hot leaves: none — no span with nothing under it reached {} ms average or {HOT_SHARE:.0}% of the frame.",
+            ms(HOT_AVG_NS)
+        ));
+        return;
+    }
+    out.push(format!(
+        "  hot leaves (nothing nested inside them; ≥{} ms average or ≥{HOT_SHARE:.0}% of the frame)",
+        ms(HOT_AVG_NS)
+    ));
+    let mut table = Table::new(
+        4,
+        &[
+            ("span", Align::Left),
+            ("avg", Align::Right),
+            ("p95", Align::Right),
+            ("%frame", Align::Right),
+            ("under", Align::Left),
+        ],
+    );
+    for leaf in leaves {
+        table.row([
+            leaf.span.name().to_owned(),
+            ms(leaf.avg_ns()),
+            ms(leaf.p95_ns),
+            percent(leaf.sum_ns, wall.sum_ns),
+            leaf.parent
+                .map_or_else(|| "—".to_owned(), |parent| parent.name().to_owned()),
+        ]);
+    }
+    table.render(out);
+}
+
+fn anomalies(out: &mut Vec<String>) {
+    let anomalies = perf::stats::anomalies();
+    if anomalies.unmatched_end == 0 && anomalies.reopened == 0 {
+        return;
+    }
+    out.push(String::new());
+    out.push(format!(
+        "  recorder: {} span ends closed nothing, {} spans were opened while already open — those instances are missing from the numbers above.",
+        anomalies.unmatched_end, anomalies.reopened
+    ));
+}

crates/bootstrap/src/bench/load_report.rs

@@ -0,0 +1,326 @@
+//! Section one: where the time between the command and a playable map went.
+//!
+//! Two views of the same window, because one alone lies. The **waterfall** is
+//! the serial story — request, walk, install, spawn, first drawn frame — and it
+//! is what a player waits through. The **stages** are the parallel story: the
+//! walk runs on the load pool, so a stage's own duration says nothing about
+//! whether removing it would shorten anything. What answers that is the time a
+//! stage held the load *alone*, which is what `exclusive` below measures.
+
+use std::time::{Duration, Instant};
+
+use assets::LoadLaneTiming;
+
+use crate::bench::milestones::Milestones;
+use crate::bench::table::{Align, Table, bytes, items, mib, ms, secs};
+
+/// Stages listed by name before the report rolls the rest into one line.
+const TOP_STAGES: usize = 16;
+
+pub(crate) fn render(bench: &Milestones, command_start: Option<Instant>, out: &mut Vec<String>) {
+    out.push("[1/2] MAP LOAD".to_owned());
+    waterfall(bench, command_start, out);
+    out.push(String::new());
+    stages(&bench.lanes, out);
+    out.push(String::new());
+    picture(bench, out);
+}
+
+fn waterfall(bench: &Milestones, command_start: Option<Instant>, out: &mut Vec<String>) {
+    let origin = command_start.unwrap_or(bench.t0);
+    let source = if command_start.is_some() {
+        "the shell command"
+    } else {
+        "process start"
+    };
+    match bench.playable() {
+        Some(playable) => out.push(format!(
+            "  command → playable: {} (from {source})",
+            secs(playable.saturating_duration_since(origin))
+        )),
+        None => out.push(format!(
+            "  command → playable: MISS — the map never became playable (from {source})"
+        )),
+    }
+    out.push(String::new());
+
+    let mut table = Table::new(
+        2,
+        &[
+            ("milestone", Align::Left),
+            ("at", Align::Right),
+            ("+step", Align::Right),
+            ("what happened in the step", Align::Left),
+        ],
+    );
+    let mut steps: Vec<(&str, Option<Instant>, &str)> = vec![
+        (
+            "process start",
+            Some(bench.t0),
+            "argument parsing, window, plugins",
+        ),
+        ("load requested", bench.request, "zone discovery"),
+        ("match installed", bench.installed, "the load-pool walk"),
+        (
+            "world spawned",
+            bench.spawned,
+            "scene conversion, GPU upload",
+        ),
+        (
+            "loading screen down",
+            bench.overlay_down,
+            "overlay torn down",
+        ),
+        ("in game", bench.ingame, "session handed over"),
+        (
+            "first drawn frame",
+            bench.rendered_spawn,
+            "pipelines compiled",
+        ),
+        ("ambient booted", bench.ambient, "map ambience started"),
+    ];
+    // In the order they actually happened, not the order they are listed: two
+    // of these race, and a "+step" measured against a later milestone would
+    // read as a zero rather than as the overlap it is. A milestone that was
+    // never reached sorts to the end, where it reads as a gap in the story
+    // rather than as its beginning.
+    steps.sort_by_key(|(_, at, _)| (at.is_none(), *at));
+    let mut previous: Option<Instant> = command_start;
+    for (name, at, note) in steps {
+        let Some(at) = at else {
+            table.row([
+                name.to_owned(),
+                "MISS".to_owned(),
+                "—".to_owned(),
+                note.to_owned(),
+            ]);
+            continue;
+        };
+        let step = previous.map(|previous| at.saturating_duration_since(previous));
+        table.row([
+            name.to_owned(),
+            secs(at.saturating_duration_since(origin)),
+            step.map_or_else(|| "—".to_owned(), secs),
+            note.to_owned(),
+        ]);
+        previous = Some(at);
+    }
+    table.render(out);
+}
+
+fn stages(lanes: &[LoadLaneTiming], out: &mut Vec<String>) {
+    if lanes.is_empty() {
+        out.push("  load stages: MISS — the walk opened no stage on this run".to_owned());
+        return;
+    }
+    let window = lanes
+        .iter()
+        .map(LoadLaneTiming::end)
+        .max()
+        .unwrap_or(Duration::ZERO);
+    let held: Duration = lanes.iter().map(|lane| lane.elapsed).sum();
+    let covered = union(lanes);
+    let exclusive = exclusive(lanes);
+
+    let parallel = if covered.is_zero() {
+        "—".to_owned()
+    } else {
+        format!("{:.1}x", held.as_secs_f64() / covered.as_secs_f64())
+    };
+    out.push(format!(
+        "  load stages: {} stages holding {} across a {} window — {parallel} parallel, {} covered by no stage",
+        lanes.len(),
+        secs(held),
+        secs(window),
+        secs(window.saturating_sub(covered)),
+    ));
+    out.push(
+        "  `exclusive` is the time a stage was the only one running: the part of the load it, alone, lengthened."
+            .to_owned(),
+    );
+
+    let mut ordered: Vec<(usize, &LoadLaneTiming)> = lanes.iter().enumerate().collect();
+    ordered.sort_by_key(|(index, lane)| (std::cmp::Reverse(lane.elapsed), *index));
+
+    let mut table = Table::new(
+        2,
+        &[
+            ("stage", Align::Left),
+            ("at", Align::Right),
+            ("held", Align::Right),
+            ("exclusive", Align::Right),
+            ("items", Align::Right),
+            ("memory", Align::Left),
+        ],
+    );
+    for (index, lane) in ordered.iter().take(TOP_STAGES) {
+        table.row([
+            format!(
+                "{}{}",
+                lane.label,
+                if lane.running { " (running)" } else { "" }
+            ),
+            secs(lane.at),
+            secs(lane.elapsed),
+            secs(exclusive[*index]),
+            items(lane.done, lane.total),
+            lane.mem_suffix().trim().to_owned(),
+        ]);
+    }
+    table.render(out);
+    if ordered.len() > TOP_STAGES {
+        let rest: Duration = ordered
+            .iter()
+            .skip(TOP_STAGES)
+            .map(|(_, lane)| lane.elapsed)
+            .sum();
+        out.push(format!(
+            "  … and {} shorter stages holding {}",
+            ordered.len() - TOP_STAGES,
+            secs(rest)
+        ));
+    }
+}
+
+fn picture(bench: &Milestones, out: &mut Vec<String>) {
+    let mut lines = Vec::new();
+    if let Some(bytes) = bench.progress.zone_image_bytes() {
+        lines.push(format!("zone image {}", mib(bytes)));
+    }
+    match (
+        bench.progress.rss_at_open_bytes(),
+        assets::peak_resident_bytes(),
+    ) {
+        (Some(open), Some(peak)) => lines.push(format!("rss {} → {}", mib(open), mib(peak))),
+        (_, Some(peak)) => lines.push(format!("rss peak {}", mib(peak))),
+        _ => {}
+    }
+    if !lines.is_empty() {
+        out.push(format!("  memory: {}", lines.join(", ")));
+    }
+
+    let frames = perf::stats::snapshot(perf::Phase::Load)
+        .into_iter()
+        .find(|stats| stats.span == perf::Span::FramesWallFrameMs);
+    match frames {
+        Some(frames) => out.push(format!(
+            "  frames drawn while loading: {} at {} ms average (the loading screen)",
+            frames.count,
+            ms(frames.avg_ns())
+        )),
+        None => out.push("  frames drawn while loading: none reached the frame clock".to_owned()),
+    }
+
+    match (bench.screenshot_bytes(), bench.shot) {
+        (Some(size), _) => out.push(format!(
+            "  screenshot: {} ({}, {} world batches, g0 {})",
+            bench.screenshot.display(),
+            bytes(size),
+            bench
+                .batches_at_shot
+                .map_or_else(|| "MISS".to_owned(), |n| n.to_string()),
+            bench
+                .g0_at_shot
+                .map_or_else(|| "MISS".to_owned(), |n| n.to_string()),
+        )),
+        _ => out.push(format!(
+            "  screenshot: MISS — nothing was written to {}",
+            bench.screenshot.display()
+        )),
+    }
+}
+
+/// Total time during which at least one stage was running.
+fn union(lanes: &[LoadLaneTiming]) -> Duration {
+    let mut windows: Vec<(Duration, Duration)> =
+        lanes.iter().map(|lane| (lane.at, lane.end())).collect();
+    windows.sort();
+    let mut covered = Duration::ZERO;
+    let mut open: Option<(Duration, Duration)> = None;
+    for (start, end) in windows {
+        match open {
+            Some((from, until)) if start <= until => open = Some((from, until.max(end))),
+            Some((from, until)) => {
+                covered += until.saturating_sub(from);
+                open = Some((start, end));
+            }
+            None => open = Some((start, end)),
+        }
+    }
+    if let Some((from, until)) = open {
+        covered += until.saturating_sub(from);
+    }
+    covered
+}
+
+/// Per stage, the time it was the only stage running. A sweep over the edges:
+/// between two consecutive edges the set of running stages does not change, so
+/// a gap with exactly one stage open belongs to that stage.
+fn exclusive(lanes: &[LoadLaneTiming]) -> Vec<Duration> {
+    let mut edges: Vec<(Duration, isize, usize)> = Vec::with_capacity(lanes.len() * 2);
+    for (index, lane) in lanes.iter().enumerate() {
+        edges.push((lane.at, 1, index));
+        edges.push((lane.end(), -1, index));
+    }
+    // Closing edges first at the same instant: a stage that ends where another
+    // begins was never alone with it.
+    edges.sort_by_key(|(at, delta, index)| (*at, -*delta, *index));
+
+    let mut out = vec![Duration::ZERO; lanes.len()];
+    let mut open: Vec<usize> = Vec::new();
+    let mut previous = edges
+        .first()
+        .map(|(at, _, _)| *at)
+        .unwrap_or(Duration::ZERO);
+    for (at, delta, index) in edges {
+        if at > previous && open.len() == 1 {
+            out[open[0]] += at - previous;
+        }
+        previous = at;
+        if delta > 0 {
+            open.push(index);
+        } else if let Some(position) = open.iter().position(|open| *open == index) {
+            open.remove(position);
+        }
+    }
+    out
+}
+
+#[cfg(test)]
+mod tests {
+    use super::*;
+
+    fn lane(at_ms: u64, elapsed_ms: u64) -> LoadLaneTiming {
+        LoadLaneTiming {
+            label: format!("stage at {at_ms}"),
+            at: Duration::from_millis(at_ms),
+            elapsed: Duration::from_millis(elapsed_ms),
+            done: 0,
+            total: 0,
+            running: false,
+            rss_delta: None,
+            heap_delta: None,
+        }
+    }
+
+    #[test]
+    fn union_merges_overlapping_stages_and_keeps_the_gap_out() {
+        let lanes = [lane(0, 100), lane(50, 100), lane(400, 100)];
+        assert_eq!(union(&lanes), Duration::from_millis(250));
+    }
+
+    #[test]
+    fn exclusive_credits_only_the_stage_nobody_overlapped() {
+        // 0..100 alone, 100..150 shared, 150..200 alone on the second stage.
+        let lanes = [lane(0, 150), lane(100, 100)];
+        let exclusive = exclusive(&lanes);
+        assert_eq!(exclusive[0], Duration::from_millis(100));
+        assert_eq!(exclusive[1], Duration::from_millis(50));
+    }
+
+    #[test]
+    fn a_stage_that_shared_its_whole_window_is_credited_nothing() {
+        let lanes = [lane(0, 200), lane(50, 50)];
+        assert_eq!(exclusive(&lanes)[1], Duration::ZERO);
+    }
+}

crates/bootstrap/src/bench/milestones.rs

@@ -0,0 +1,211 @@
+//! What the run reached, and when. One `Last` system watches the resources the
+//! load transaction publishes and stamps the first frame each became true; the
+//! report turns those stamps into the waterfall.
+
+use std::path::{Path, PathBuf};
+use std::time::Instant;
+
+use assets::{LoadLaneTiming, LoadProgress, LoadingScreen, MatchLoadBusy, MatchLoadRequest};
+use audio::MapAmbientBooted;
+use bevy::prelude::*;
+use render_frontend::prepare::scene::cull::DpvsFrameStats;
+use render_frontend::prepare::scene::world::WorldScene;
+use session::MatchInstalled;
+
+/// Consecutive frames with a working colour set before the picture counts as
+/// rendered: one frame can hit while a pipeline is still compiling.
+const READY_FRAMES: u32 = 2;
+
+pub(crate) struct Milestones {
+    pub(crate) zone: String,
+    pub(crate) screenshot: PathBuf,
+    pub(crate) progress: LoadProgress,
+    pub(crate) t0: Instant,
+    pub(crate) request: Option<Instant>,
+    pub(crate) installed: Option<Instant>,
+    pub(crate) spawned: Option<Instant>,
+    pub(crate) overlay_down: Option<Instant>,
+    pub(crate) ingame: Option<Instant>,
+    pub(crate) rendered_spawn: Option<Instant>,
+    pub(crate) ambient: Option<Instant>,
+    pub(crate) shot: Option<Instant>,
+    pub(crate) lanes: Vec<LoadLaneTiming>,
+    pub(crate) batches_at_shot: Option<u32>,
+    pub(crate) g0_at_shot: Option<u32>,
+    overlay_seen: bool,
+    ready_frames: u32,
+    last_batches: Option<u32>,
+    last_g0: Option<u32>,
+    pub(crate) last_spawned: bool,
+}
+
+impl Milestones {
+    pub(crate) fn new(zone: String, screenshot: PathBuf, progress: LoadProgress) -> Self {
+        Self {
+            zone,
+            screenshot,
+            progress,
+            t0: Instant::now(),
+            request: None,
+            installed: None,
+            spawned: None,
+            overlay_down: None,
+            ingame: None,
+            rendered_spawn: None,
+            ambient: None,
+            shot: None,
+            lanes: Vec::new(),
+            batches_at_shot: None,
+            g0_at_shot: None,
+            overlay_seen: false,
+            ready_frames: 0,
+            last_batches: None,
+            last_g0: None,
+            last_spawned: false,
+        }
+    }
+
+    /// The first moment the map was drawn and nothing was left in front of it.
+    /// It is where the load report stops and the frame report starts.
+    ///
+    /// The drawn frame is what decides; the overlay only pushes the moment
+    /// later when it outlives that frame. It cannot be required: a run that
+    /// never raised an overlay at all would otherwise file every frame it
+    /// drew as load cost.
+    pub(crate) fn playable(&self) -> Option<Instant> {
+        let rendered = self.rendered_spawn?;
+        Some(match self.overlay_down {
+            Some(overlay) => rendered.max(overlay),
+            None => rendered,
+        })
+    }
+
+    /// Lanes as of now. Called once the walk is done and again at exit, so a
+    /// stage that closed late is still in the report.
+    pub(crate) fn take_lane_snapshot(&mut self) {
+        let lanes = self.progress.lane_timings();
+        if lanes.len() >= self.lanes.len() {
+            self.lanes = lanes;
+        }
+    }
+
+    pub(crate) fn screenshot_bytes(&self) -> Option<u64> {
+        std::fs::metadata(&self.screenshot)
+            .ok()
+            .map(|meta| meta.len())
+            .filter(|len| *len > 0)
+    }
+}
+
+static MILESTONES: std::sync::Mutex<Option<Milestones>> = std::sync::Mutex::new(None);
+
+pub(crate) fn install(state: Milestones) {
+    *MILESTONES
+        .lock()
+        .unwrap_or_else(|poison| poison.into_inner()) = Some(state);
+}
+
+pub(crate) fn with<T>(read: impl FnOnce(&mut Milestones) -> T) -> Option<T> {
+    let mut guard = MILESTONES
+        .lock()
+        .unwrap_or_else(|poison| poison.into_inner());
+    guard.as_mut().map(read)
+}
+
+pub(crate) fn screenshot_path(artifacts: &Path, zone: &str) -> PathBuf {
+    artifacts
+        .join("screenshots")
+        .join("bench")
+        .join(format!("{}.png", sanitize(zone)))
+}
+
+fn sanitize(zone: &str) -> String {
+    let mut out = String::with_capacity(zone.len());
+    for ch in zone.chars() {
+        if ch.is_ascii_alphanumeric() || ch == '-' || ch == '_' || ch == '.' {
+            out.push(ch);
+        } else {
+            out.push('_');
+        }
+    }
+    let trimmed = out.trim_start_matches('.');
+    if trimmed.is_empty() {
+        "unknown".to_owned()
+    } else {
+        trimmed.to_owned()
+    }
+}
+
+#[allow(clippy::too_many_arguments)]
+pub(crate) fn poll(
+    request: Option<Res<MatchLoadRequest>>,
+    busy: Option<Res<MatchLoadBusy>>,
+    mut installed: MessageReader<MatchInstalled>,
+    scene: Option<Res<WorldScene>>,
+    loading: Option<Res<LoadingScreen>>,
+    screen: Option<Res<ui::AppScreen>>,
+    ambient: Option<Res<MapAmbientBooted>>,
+    stats: Option<Res<DpvsFrameStats>>,
+    working: Option<Res<render::ColourWorkingSet>>,
+) {
+    let now = Instant::now();
+    let saw_request = request.is_some() || busy.is_some_and(|busy| busy.0);
+    let saw_installed = installed.read().next().is_some();
+    let spawned_now = scene.as_deref().is_some_and(|scene| scene.spawned);
+    let overlay_now = loading.is_some();
+    let ingame_now = screen.is_some_and(|screen| matches!(*screen, ui::AppScreen::InGame));
+    let ambient_now = ambient.is_some_and(|ambient| ambient.0);
+    let census = stats
+        .as_deref()
+        .map(|stats| (stats.submitted_batches, stats.g0_world_surfs.len() as u32));
+    let ready_now = working
+        .as_ref()
+        .is_some_and(|set| set.hits > 0 && set.pipeline_not_ready == 0);
+
+    with(|bench| {
+        if bench.request.is_none() && saw_request {
+            bench.request = Some(now);
+        }
+        if bench.installed.is_none() && saw_installed {
+            bench.installed = Some(now);
+            bench.take_lane_snapshot();
+        }
+        if spawned_now {
+            bench.last_spawned = true;
+            if bench.spawned.is_none() {
+                bench.spawned = Some(now);
+                bench.take_lane_snapshot();
+            }
+        }
+        if overlay_now {
+            bench.overlay_seen = true;
+        } else if bench.overlay_down.is_none() && bench.overlay_seen {
+            bench.overlay_down = Some(now);
+        }
+        if bench.ingame.is_none() && ingame_now {
+            bench.ingame = Some(now);
+        } else if ingame_now && bench.rendered_spawn.is_none() {
+            bench.ready_frames = if ready_now { bench.ready_frames + 1 } else { 0 };
+            if bench.ready_frames >= READY_FRAMES {
+                bench.rendered_spawn = Some(now);
+            }
+        }
+        if bench.ambient.is_none() && ambient_now {
+            bench.ambient = Some(now);
+        }
+        if let Some((batches, g0)) = census {
+            bench.last_batches = Some(batches);
+            bench.last_g0 = Some(g0);
+        }
+        if bench.shot.is_none() && bench.screenshot_bytes().is_some() {
+            bench.shot = Some(now);
+            bench.batches_at_shot = bench.last_batches;
+            bench.g0_at_shot = bench.last_g0;
+        }
+        // Everything recorded from the first playable frame on is gameplay, and
+        // belongs to the frame report rather than to the cost of the load.
+        if bench.playable().is_some() {
+            perf::stats::mark_live();
+        }
+    });
+}

crates/bootstrap/src/bench/mod.rs

@@ -0,0 +1,223 @@
+//! `make bench`: one run, two independent reports.
+//!
+//! [`load_report`] is the cost of getting a map on screen; [`frame_report`] is
+//! the cost of a frame once it is there. They share a process and nothing else
+//! — either can be MISS while the other stands — and the split between them is
+//! the first playable frame, where the recorder switches phase.
+//!
+//! Both are printed to stdout at exit and written to
+//! `iw4l-artifacts/bench/<stamp>.txt`, so a run can be diffed against
+//! the one before it. Off unless `IW4L_BENCH` is set.
+
+mod frame_report;
+mod load_report;
+mod milestones;
+mod table;
+
+use std::path::{Path, PathBuf};
+use std::sync::OnceLock;
+use std::sync::atomic::{AtomicBool, Ordering};
+use std::time::Instant;
+
+use assets::LoadProgress;
+use bevy::prelude::*;
+use render::diag::capture::{CaptureQueue, CaptureRequest};
+
+use crate::bench::milestones::Milestones;
+
+/// When the shell command was typed, when the recipe passes it. `make` stamps
+/// `IW4L_BENCH_STARTED_NS` so the report can charge cargo and process startup
+/// to the load instead of quietly starting the clock after them.
+static COMMAND_START: OnceLock<Instant> = OnceLock::new();
+
+/// Where the report is written, remembered so the exit hook can reach it.
+static ARTIFACTS: OnceLock<PathBuf> = OnceLock::new();
+
+/// The report is printed once, by whichever path gets there first.
+static REPORTED: AtomicBool = AtomicBool::new(false);
+
+/// Called before anything else in the process. Reads the environment once so no
+/// later code pays for a `getenv` per span.
+pub fn arm() {
+    perf::stats::arm();
+    if !enabled() {
+        return;
+    }
+    let now = Instant::now();
+    match std::env::var("IW4L_BENCH_STARTED_NS") {
+        Ok(stamp) => match shell_start(&stamp, now) {
+            Some(started) => {
+                let _ = COMMAND_START.set(started);
+            }
+            None => eprintln!(
+                "bench: IW4L_BENCH_STARTED_NS is not a unix nanosecond stamp; the report will time from process start"
+            ),
+        },
+        Err(std::env::VarError::NotPresent) => {}
+        Err(error) => eprintln!("bench: IW4L_BENCH_STARTED_NS: {error}"),
+    }
+}
+
+fn shell_start(stamp: &str, now: Instant) -> Option<Instant> {
+    let stamp = stamp.parse::<u128>().ok()?;
+    let elapsed = std::time::SystemTime::now()
+        .duration_since(std::time::UNIX_EPOCH)
+        .ok()?
+        .as_nanos()
+        .checked_sub(stamp)?;
+    now.checked_sub(std::time::Duration::from_nanos(
+        u64::try_from(elapsed).ok()?,
+    ))
+}
+
+/// Whether this process collects a bench report. The recorder in `perf` reads
+/// the same variable; this is the one answer both use.
+pub fn enabled() -> bool {
+    perf::stats::enabled()
+}
+
+/// Arm the milestone watcher and queue the settled screenshot of the spawned
+/// world. Called once, with the app assembled and the load request in place.
+///
+/// The capture waits for the loading overlay to come down, which a demo now
+/// does as soon as the first snapshot is presented — so it settles during the
+/// load, long before `quit` could be left owing it.
+pub fn insert(app: &mut App, zone: &str, artifacts: &Path, progress: LoadProgress) {
+    let screenshot = milestones::screenshot_path(artifacts, zone);
+    if let Some(parent) = screenshot.parent()
+        && let Err(error) = std::fs::create_dir_all(parent)
+    {
+        diag::error!(Launch, "bench: create {}: {error}", parent.display());
+        return;
+    }
+    let _ = std::fs::remove_file(&screenshot);
+    app.world_mut()
+        .get_resource_mut::<CaptureQueue>()
+        .expect("CaptureQueue: RenderPlugin must be added before the bench capture")
+        .push(CaptureRequest {
+            path: screenshot.clone(),
+            exit_after_capture: false,
+        });
+    diag::info!(Launch, "bench: screenshot {}", screenshot.display());
+    milestones::install(Milestones::new(zone.to_owned(), screenshot, progress));
+    let _ = ARTIFACTS.set(artifacts.to_path_buf());
+    arm_exit_hook();
+    app.add_systems(Last, milestones::poll);
+}
+
+/// Playing a demo ends in `std::process::exit` (`console::exit_replay_process`),
+/// so `App::run` never returns and nothing after it runs. Perfetto survives that
+/// on an `atexit` handler; the report needs the same one, or `make bench <demo>`
+/// would measure a whole run and print nothing.
+#[cfg(unix)]
+fn arm_exit_hook() {
+    static ARMED: AtomicBool = AtomicBool::new(false);
+    if ARMED.swap(true, Ordering::SeqCst) {
+        return;
+    }
+    unsafe extern "C" {
+        fn atexit(callback: extern "C" fn()) -> i32;
+    }
+    extern "C" fn report_at_exit() {
+        let Some(artifacts) = ARTIFACTS.get() else {
+            return;
+        };
+        // This hook was armed after Perfetto's, and `atexit` runs last-armed
+        // first, so the trace is still open here; flushing it is what gives the
+        // heading a run directory to name. Flushing twice is a no-op.
+        let trace = perf::flush().ok().flatten();
+        let _ = std::panic::catch_unwind(std::panic::AssertUnwindSafe(|| {
+            report(artifacts, trace);
+        }));
+    }
+    let _ = unsafe { atexit(report_at_exit) };
+}
+
+#[cfg(not(unix))]
+fn arm_exit_hook() {}
+
+/// Print both reports and write them next to the run. `trace` is the Perfetto
+/// run directory when one was recorded — the report names it rather than
+/// reading it, because the two are different tools over the same run.
+pub fn finish(artifacts: &Path, trace: Option<PathBuf>) {
+    report(artifacts, trace);
+}
+
+fn report(artifacts: &Path, trace: Option<PathBuf>) {
+    if REPORTED.swap(true, Ordering::SeqCst) {
+        return;
+    }
+    let lines = match milestones::with(|bench| {
+        bench.take_lane_snapshot();
+        let mut lines = Vec::new();
+        heading(&bench.zone, trace.as_deref(), &mut lines);
+        load_report::render(bench, COMMAND_START.get().copied(), &mut lines);
+        lines.push(String::new());
+        frame_report::render(&mut lines);
+        lines
+    }) {
+        Some(lines) => lines,
+        None => {
+            let mut lines = Vec::new();
+            heading("<none>", trace.as_deref(), &mut lines);
+            lines.push(
+                "[1/2] MAP LOAD: MISS — this run loaded no map, so there was nothing to time."
+                    .to_owned(),
+            );
+            lines.push(String::new());
+            frame_report::render(&mut lines);
+            lines
+        }
+    };
+
+    let mut lines = lines;
+    match write_report(artifacts, &lines) {
+        Ok(path) => lines.push(format!("report: {}", path.display())),
+        Err(error) => lines.push(format!("report: not written ({error})")),
+    }
+    for line in &lines {
+        diag::announce_stdout(line);
+    }
+    diag::info!(Launch, "bench: {} report lines", lines.len());
+}
+
+fn heading(zone: &str, trace: Option<&Path>, out: &mut Vec<String>) {
+    let rule = "=".repeat(96);
+    out.push(rule.clone());
+    out.push(format!(
+        "IW4L bench — zone={zone} command={:?}",
+        std::env::args().collect::<Vec<_>>().join(" ")
+    ));
+    match trace {
+        Some(dir) => out.push(format!(
+            "perfetto run: {} (`cargo xtask bench` reads it; this report does not)",
+            dir.join("trace.pftrace").display()
+        )),
+        None => out.push(
+            "perfetto run: none — IW4L_PERF was off, or the flush failed. The report below is in-process and does not need it."
+                .to_owned(),
+        ),
+    }
+    out.push(rule);
+    out.push(String::new());
+}
+
+fn write_report(artifacts: &Path, lines: &[String]) -> Result<PathBuf, String> {
+    let dir = artifacts.join("bench");
+    std::fs::create_dir_all(&dir).map_err(|error| format!("create {}: {error}", dir.display()))?;
+    let path = dir.join(format!("{}.txt", stamp()));
+    let mut body = lines.join("\n");
+    body.push('\n');
+    std::fs::write(&path, body).map_err(|error| format!("write {}: {error}", path.display()))?;
+    Ok(path)
+}
+
+/// Seconds since the epoch, zero-padded: the reports sort by name in the order
+/// they were run, on every platform, with no date library.
+fn stamp() -> String {
+    let seconds = std::time::SystemTime::now()
+        .duration_since(std::time::UNIX_EPOCH)
+        .map(|since| since.as_secs())
+        .unwrap_or(0);
+    format!("{seconds:012}")
+}

crates/bootstrap/src/bench/table.rs

@@ -0,0 +1,119 @@
+//! Plain-text column layout. The bench report is read in a terminal and kept in
+//! a file that gets diffed against the last run, so columns line up and nothing
+//! wraps.
+
+use std::time::Duration;
+
+#[derive(Clone, Copy, PartialEq, Eq)]
+pub(crate) enum Align {
+    Left,
+    Right,
+}
+
+pub(crate) struct Table {
+    align: Vec<Align>,
+    headers: Vec<String>,
+    rows: Vec<Vec<String>>,
+    indent: usize,
+}
+
+impl Table {
+    pub(crate) fn new(indent: usize, columns: &[(&str, Align)]) -> Self {
+        Self {
+            align: columns.iter().map(|(_, align)| *align).collect(),
+            headers: columns.iter().map(|(name, _)| (*name).to_owned()).collect(),
+            rows: Vec::new(),
+            indent,
+        }
+    }
+
+    pub(crate) fn row<const N: usize>(&mut self, cells: [String; N]) {
+        self.rows.push(cells.into_iter().collect());
+    }
+
+    pub(crate) fn render(&self, out: &mut Vec<String>) {
+        let mut widths: Vec<usize> = self
+            .headers
+            .iter()
+            .map(|name| name.chars().count())
+            .collect();
+        for row in &self.rows {
+            for (index, cell) in row.iter().enumerate() {
+                let width = cell.chars().count();
+                if width > widths[index] {
+                    widths[index] = width;
+                }
+            }
+        }
+        out.push(self.line(&self.headers, &widths));
+        for row in &self.rows {
+            out.push(self.line(row, &widths));
+        }
+    }
+
+    fn line(&self, cells: &[String], widths: &[usize]) -> String {
+        let mut line = " ".repeat(self.indent);
+        for (index, cell) in cells.iter().enumerate() {
+            if index > 0 {
+                line.push_str("  ");
+            }
+            let pad = widths[index].saturating_sub(cell.chars().count());
+            match self.align.get(index).copied().unwrap_or(Align::Left) {
+                Align::Left if index + 1 == cells.len() => line.push_str(cell),
+                Align::Left => {
+                    line.push_str(cell);
+                    line.push_str(&" ".repeat(pad));
+                }
+                Align::Right => {
+                    line.push_str(&" ".repeat(pad));
+                    line.push_str(cell);
+                }
+            }
+        }
+        line.trim_end().to_owned()
+    }
+}
+
+/// Nanoseconds as milliseconds, the unit every frame number in the report uses.
+pub(crate) fn ms(ns: u64) -> String {
+    format!("{:.2}", ns as f64 / 1e6)
+}
+
+pub(crate) fn secs(duration: Duration) -> String {
+    format!("{:.3}s", duration.as_secs_f64())
+}
+
+pub(crate) fn percent(part: u64, whole: u64) -> String {
+    if whole == 0 {
+        return "—".to_owned();
+    }
+    format!("{:.1}", part as f64 * 100.0 / whole as f64)
+}
+
+/// Bytes at the scale a reader can hold: a screenshot in KiB, a zone in MiB.
+pub(crate) fn bytes(bytes: u64) -> String {
+    if bytes < 1024 * 1024 {
+        format!("{} KiB", bytes / 1024)
+    } else {
+        mib(bytes)
+    }
+}
+
+pub(crate) fn mib(bytes: u64) -> String {
+    let mib = bytes as f64 / (1024.0 * 1024.0);
+    if mib >= 1024.0 {
+        format!("{:.2}GiB", mib / 1024.0)
+    } else {
+        format!("{mib:.0}MiB")
+    }
+}
+
+/// `done/total`, `done`, or nothing — a stage that counted no items says so by
+/// staying silent rather than printing a zero it never measured.
+pub(crate) fn items(done: u64, total: u64) -> String {
+    match (done, total) {
+        (0, 0) => String::new(),
+        (done, 0) => done.to_string(),
+        (done, total) => format!("{done}/{total}"),
+    }
+}

crates/bootstrap/src/bench_load.rs

@@ -1,350 +0,0 @@
-use std::path::{Path, PathBuf};
-use std::time::Instant;
-
-use assets::{LoadingScreen, MatchLoadBusy, MatchLoadRequest};
-use audio::MapAmbientBooted;
-use bevy::prelude::*;
-use render::diag::capture::{CaptureQueue, CaptureRequest};
-use render_frontend::prepare::scene::cull::DpvsFrameStats;
-use render_frontend::prepare::scene::world::WorldScene;
-use session::MatchInstalled;
-
-static COMMAND_START: std::sync::OnceLock<(Instant, &'static str)> = std::sync::OnceLock::new();
-
-pub fn begin_command() {
-    if !enabled() {
-        return;
-    }
-    let now = Instant::now();
-    let clock = match std::env::var("IW4L_BENCH_LOAD_STARTED_NS") {
-        Ok(stamp) => {
-            let elapsed = stamp
-                .parse::<u128>()
-                .ok()
-                .and_then(|stamp| {
-                    std::time::SystemTime::now()
-                        .duration_since(std::time::UNIX_EPOCH)
-                        .ok()?
-                        .as_nanos()
-                        .checked_sub(stamp)
-                })
-                .and_then(|ns| u64::try_from(ns).ok());
-            elapsed
-                .and_then(|ns| now.checked_sub(std::time::Duration::from_nanos(ns)))
-                .map(|at| (at, "make"))
-        }
-        Err(std::env::VarError::NotPresent) => Some((now, "process")),
-        Err(_) => None,
-    };
-    if let Some(clock) = clock {
-        let _ = COMMAND_START.set(clock);
-    } else {
-        eprintln!("bench-load: invalid command timestamp; command timings will be MISS");
-    }
-}
-
-pub fn enabled() -> bool {
-    match std::env::var("IW4L_BENCH_LOAD") {
-        Ok(value)
-            if value.is_empty()
-                || value == "0"
-                || value.eq_ignore_ascii_case("false")
-                || value.eq_ignore_ascii_case("off") =>
-        {
-            false
-        }
-        Ok(_) => true,
-        Err(_) => false,
-    }
-}
-
-pub fn screenshot_path(artifacts: &Path, zone: &str) -> PathBuf {
-    artifacts
-        .join("screenshots")
-        .join("bench-load")
-        .join(format!("{}.png", sanitize_zone(zone)))
-}
-
-fn sanitize_zone(zone: &str) -> String {
-    let mut out = String::with_capacity(zone.len());
-    for ch in zone.chars() {
-        if ch.is_ascii_alphanumeric() || ch == '-' || ch == '_' || ch == '.' {
-            out.push(ch);
-        } else {
-            out.push('_');
-        }
-    }
-    let trimmed = out.trim_start_matches('.');
-    if trimmed.is_empty() {
-        "unknown".to_owned()
-    } else {
-        trimmed.to_owned()
-    }
-}
-
-struct BenchLoad {
-    zone: String,
-    path: PathBuf,
-    t0: Instant,
-    request: Option<Instant>,
-    installed: Option<Instant>,
-    spawned: Option<Instant>,
-    overlay_down: Option<Instant>,
-    overlay_seen: bool,
-    ingame: Option<Instant>,
-    rendered_spawn: Option<Instant>,
-    ready_frames: u32,
-    ambient: Option<Instant>,
-    shot: Option<Instant>,
-    batches_at_shot: Option<u32>,
-    g0_at_shot: Option<u32>,
-    last_batches: Option<u32>,
-    last_g0: Option<u32>,
-    last_spawned: bool,
-}
-
-static BENCH: std::sync::Mutex<Option<BenchLoad>> = std::sync::Mutex::new(None);
-
-fn bench_mut(fill: impl FnOnce(&mut BenchLoad)) {
-    let mut guard = BENCH.lock().unwrap_or_else(|poison| poison.into_inner());
-    if let Some(bench) = guard.as_mut() {
-        fill(bench);
-    }
-}
-
-impl BenchLoad {
-    fn new(zone: String, path: PathBuf) -> Self {
-        Self {
-            zone,
-            path,
-            t0: Instant::now(),
-            request: None,
-            installed: None,
-            spawned: None,
-            overlay_down: None,
-            overlay_seen: false,
-            ingame: None,
-            rendered_spawn: None,
-            ready_frames: 0,
-            ambient: None,
-            shot: None,
-            batches_at_shot: None,
-            g0_at_shot: None,
-            last_batches: None,
-            last_g0: None,
-            last_spawned: false,
-        }
-    }
-}
-
-pub fn insert(app: &mut App, zone: &str, artifacts: &Path) {
-    let path = screenshot_path(artifacts, zone);
-    if let Some(parent) = path.parent()
-        && let Err(error) = std::fs::create_dir_all(parent)
-    {
-        diag::error!(Launch, "bench-load: create {}: {error}", parent.display());
-        return;
-    }
-
-    let _ = std::fs::remove_file(&path);
-    app.world_mut()
-        .get_resource_mut::<CaptureQueue>()
-        .expect("CaptureQueue: RenderPlugin must be added before the bench-load capture")
-        .push(CaptureRequest {
-            path: path.clone(),
-            exit_after_capture: false,
-        });
-    *BENCH.lock().unwrap_or_else(|poison| poison.into_inner()) =
-        Some(BenchLoad::new(zone.to_owned(), path.clone()));
-    app.add_systems(Last, poll_bench_load);
-    diag::info!(Launch, "bench-load: screenshot {}", path.display());
-}
-
-#[allow(clippy::too_many_arguments)]
-fn poll_bench_load(
-    request: Option<Res<MatchLoadRequest>>,
-    busy: Option<Res<MatchLoadBusy>>,
-    mut installed: MessageReader<MatchInstalled>,
-    scene: Option<Res<WorldScene>>,
-    loading: Option<Res<LoadingScreen>>,
-    screen: Option<Res<ui::AppScreen>>,
-    ambient: Option<Res<MapAmbientBooted>>,
-    stats: Option<Res<DpvsFrameStats>>,
-    working: Option<Res<render::ColourWorkingSet>>,
-) {
-    let now = Instant::now();
-    let saw_request = request.is_some() || busy.is_some_and(|b| b.0);
-    let saw_installed = installed.read().next().is_some();
-    let spawned_now = scene.as_deref().is_some_and(|s| s.spawned);
-    let overlay_now = loading.is_some();
-    let ingame_now = screen.is_some_and(|s| matches!(*s, ui::AppScreen::InGame));
-    let ambient_now = ambient.is_some_and(|b| b.0);
-    let census = stats
-        .as_deref()
-        .map(|s| (s.submitted_batches, s.g0_world_surfs.len() as u32));
-    bench_mut(|bench| {
-        if bench.request.is_none() && saw_request {
-            bench.request = Some(now);
-        }
-        if bench.installed.is_none() && saw_installed {
-            bench.installed = Some(now);
-        }
-        if spawned_now {
-            bench.last_spawned = true;
-            if bench.spawned.is_none() {
-                bench.spawned = Some(now);
-            }
-        }
-        if overlay_now {
-            bench.overlay_seen = true;
-        } else if bench.overlay_down.is_none() && bench.overlay_seen {
-            bench.overlay_down = Some(now);
-        }
-        if bench.ingame.is_none() && ingame_now {
-            bench.ingame = Some(now);
-        } else if ingame_now && bench.rendered_spawn.is_none() {
-            let ready = working
-                .as_ref()
-                .is_some_and(|set| set.hits > 0 && set.pipeline_not_ready == 0);
-            bench.ready_frames = if ready { bench.ready_frames + 1 } else { 0 };
-            if bench.ready_frames >= 2 {
-                bench.rendered_spawn = Some(now);
-            }
-        }
-        if bench.ambient.is_none() && ambient_now {
-            bench.ambient = Some(now);
-        }
-        if let Some((batches, g0)) = census {
-            bench.last_batches = Some(batches);
-            bench.last_g0 = Some(g0);
-        }
-
-        if bench.shot.is_none()
-            && let Ok(meta) = std::fs::metadata(&bench.path)
-            && meta.len() > 0
-        {
-            bench.shot = Some(now);
-            bench.batches_at_shot = bench.last_batches;
-            bench.g0_at_shot = bench.last_g0;
-        }
-    });
-}
-
-fn offset(t0: Instant, t: Option<Instant>) -> String {
-    match t {
-        Some(t) => format!("{:.1}s", t.duration_since(t0).as_secs_f64()),
-        None => "MISS".to_owned(),
-    }
-}
-
-fn stage(first: Option<Instant>, second: Option<Instant>) -> String {
-    match (first, second) {
-        (Some(first), Some(second)) if second >= first => {
-            format!("{:.1}s", (second - first).as_secs_f64())
-        }
-
-        (Some(_), Some(_)) => "overlap".to_owned(),
-        _ => "MISS".to_owned(),
-    }
-}
-
-fn kib(bytes: u64) -> String {
-    if bytes < 1024 {
-        format!("{bytes} B")
-    } else {
-        format!("{} KiB", bytes / 1024)
-    }
-}
-
-fn png_dimensions(bytes: &[u8]) -> Option<(u32, u32)> {
-    if bytes.len() < 24 || &bytes[..8] != b"\x89PNG\r\n\x1a\n" || &bytes[12..16] != b"IHDR" {
-        return None;
-    }
-    let width = u32::from_be_bytes(bytes[16..20].try_into().ok()?);
-    let height = u32::from_be_bytes(bytes[20..24].try_into().ok()?);
-    (width != 0 && height != 0).then_some((width, height))
-}
-
-pub fn print_summary(trace: Option<PathBuf>) {
-    let guard = BENCH.lock().unwrap_or_else(|poison| poison.into_inner());
-    let Some(bench) = guard.as_ref() else {
-        diag::announce_stdout(
-            "bench-load: MISS (no bench state — IW4L_BENCH_LOAD without insert?)",
-        );
-        return;
-    };
-    let total = bench.t0.elapsed();
-    let mut lines = vec![format!("bench-load: zone={}", bench.zone)];
-    let command_offset = |end: Option<Instant>| match (COMMAND_START.get(), end) {
-        (Some((start, _)), Some(end)) => {
-            format!("{:.3}s", end.duration_since(*start).as_secs_f64())
-        }
-        _ => "MISS".to_owned(),
-    };
-    let playable = bench
-        .rendered_spawn
-        .zip(bench.overlay_down)
-        .map(|(spawn, overlay)| spawn.max(overlay));
-    lines.push(format!(
-        "bench-load: command_to_spawn={} command_to_rendered_spawn={} command_to_playable={} start={}",
-        command_offset(bench.ingame), command_offset(bench.rendered_spawn), command_offset(playable),
-        COMMAND_START.get().map_or("MISS", |(_, source)| *source),
-    ));
-    match std::fs::metadata(&bench.path) {
-        Ok(meta) if meta.len() > 0 => {
-            let dims = std::fs::read(&bench.path)
-                .ok()
-                .and_then(|bytes| png_dimensions(&bytes))
-                .map(|(w, h)| format!(", {w}x{h}"))
-                .unwrap_or(String::new());
-            lines.push(format!(
-                "bench-load: screenshot={} ({}{dims})",
-                bench.path.display(),
-                kib(meta.len())
-            ));
-        }
-        _ => lines.push(format!(
-            "bench-load: screenshot=MISS (no file at {})",
-            bench.path.display()
-        )),
-    }
-    lines.push(format!(
-        "bench-load: t=request={} installed={} spawned={} overlay_down={} ingame={} ambient={} shot={}",
-        offset(bench.t0, bench.request),
-        offset(bench.t0, bench.installed),
-        offset(bench.t0, bench.spawned),
-        offset(bench.t0, bench.overlay_down),
-        offset(bench.t0, bench.ingame),
-        offset(bench.t0, bench.ambient),
-        offset(bench.t0, bench.shot),
-    ));
-    lines.push(format!(
-        "bench-load: total={:.1}s zone_walk={} spawn_gpu={} ambient={} screenshot={}",
-        total.as_secs_f64(),
-        stage(bench.request, bench.installed),
-        stage(bench.installed, bench.spawned),
-        stage(bench.spawned, bench.ambient),
-        stage(bench.ambient, bench.shot),
-    ));
-    match (bench.batches_at_shot, bench.g0_at_shot) {
-        (Some(batches), Some(g0)) => lines.push(format!(
-            "bench-load: world_batches={batches} g0={g0} spawned={}",
-            i32::from(bench.last_spawned)
-        )),
-        _ => lines.push(format!(
-            "bench-load: world_batches=MISS spawned={}",
-            i32::from(bench.last_spawned)
-        )),
-    }
-    match trace {
-        Some(dir) => lines.push(format!(
-            "bench-load: trace={}",
-            dir.join("trace.pftrace").display()
-        )),
-        None => lines.push("bench-load: trace=MISS (perf off or flush failed)".to_owned()),
-    }
-    for line in &lines {
-        diag::announce_stdout(line);
-        diag::info!(Launch, "{line}");
-    }
-}

crates/bootstrap/src/launch.rs

@@ -21,7 +21,7 @@ use ui::{
 };
 
 use crate::args::{AcceptanceLaunch, LaunchMode};
-use crate::bench_load;
+use crate::bench;
 use crate::plugins::{add_runtime_plugins, add_runtime_plugins_with_role};
 
 #[derive(Clone, Copy, Debug, PartialEq, Eq)]
@@ -462,7 +462,7 @@ fn run_map(
             progress: progress.clone(),
         })
         .insert_resource(LoadingScreen::new(
-            progress,
+            progress.clone(),
             loading_title,
             sim::host_game_mode_kind().display_name().to_owned(),
         ))
@@ -504,14 +504,14 @@ fn run_map(
     if let Some(capture) = CaptureRequest::from_env() {
         queue_launch_capture(&mut app, capture);
     }
-    let bench = bench_load::enabled();
+    let bench = bench::enabled();
     if bench {
-        bench_load::insert(&mut app, &zone, &config.artifacts);
+        bench::insert(&mut app, &zone, &config.artifacts, progress.clone());
     }
     app.run();
     let trace = flush_perf();
     if bench {
-        bench_load::print_summary(trace);
+        bench::finish(&config.artifacts, trace);
     }
 }
 

crates/bootstrap/src/lib.rs

@@ -1,5 +1,5 @@
 pub mod args;
-pub mod bench_load;
+pub mod bench;
 mod frame_owner;
 mod launch;
 mod plugins;

crates/bots/src/plugin.rs

@@ -41,6 +41,7 @@ impl Plugin for BotsPlugin {
                 (
                     drain_bot_add_queue,
                     reset_roster_on_match_torn_down,
+                    evict_bots_claiming_local_client,
                     boot_bots,
                     apply_bot_tp,
                 )
@@ -48,7 +49,8 @@ impl Plugin for BotsPlugin {
             )
             .add_systems(
                 FixedUpdate,
-                think_bots
+                (evict_bots_claiming_local_client, think_bots)
+                    .chain()
                     .in_set(AuthoritySet::Ingress)
                     .run_if(authority_should_tick),
             );
@@ -67,9 +69,29 @@ fn reset_roster_on_match_torn_down(
     *pool = BotClassPool::default();
 }
 
-fn drain_bot_add_queue(mut queue: ResMut<BotAddQueue>, mut roster: ResMut<BotRoster>) {
-    for count in queue.drain() {
-        let added = roster.add_bots(count);
+fn drain_bot_add_queue(
+    mut queue: ResMut<BotAddQueue>,
+    mut roster: ResMut<BotRoster>,
+    local: Res<LocalPresentClient>,
+    world: Option<Res<AuthorityWorld>>,
+) {
+    let requests = queue.drain();
+    if requests.is_empty() {
+        return;
+    }
+    let mut taken = vec![local.0];
+    if let Some(world) = world.as_ref() {
+        taken.extend(world.0.clients_scoreboard().into_iter().map(|(id, _)| id));
+    }
+    for count in requests {
+        let added = roster.add_bots(count, &taken);
+        if added.len() < count as usize {
+            diag::warn!(
+                Sim,
+                "bots: add {count} — only {} minted, the roster is full",
+                added.len()
+            );
+        }
         diag::info!(
             Sim,
             "bots: add {count} → clients {:?}",
@@ -78,11 +100,25 @@ fn drain_bot_add_queue(mut queue: ResMut<BotAddQueue>, mut roster: ResMut<BotRos
     }
 }
 
+// The link hands the local player its real id during signon, which can land
+// after a bot was already minted. A slot holding that id would make `is_bot`
+// claim the player, so retire it — loudly, because by then it is a bug.
+fn evict_bots_claiming_local_client(mut roster: ResMut<BotRoster>, local: Res<LocalPresentClient>) {
+    if !roster.is_bot(local.0) {
+        return;
+    }
+    roster.bots.retain(|bot| bot.id != local.0);
+    diag::warn!(
+        Sim,
+        "bots: retired the slot on client {} — that id is the local player",
+        local.0.0
+    );
+}
+
 fn boot_bots(
     mut roster: ResMut<BotRoster>,
     mut actions: ResMut<ClientActionInbox>,
     mut request_ids: ResMut<net::ActionRequestIds>,
-    local: Res<LocalPresentClient>,
     pool: Res<BotClassPool>,
 ) {
     if !pool.ready {
@@ -90,9 +126,6 @@ fn boot_bots(
     }
     let seed = roster.seed;
     for bot in &mut roster.bots {
-        if bot.id == local.0 {
-            continue;
-        }
         if bot.joined {
             continue;
         }
@@ -168,14 +201,9 @@ fn apply_bot_tp(
         .flatten();
     for request in requests {
         let ids: Vec<sim::ClientId> = match request.target {
-            BotTpTarget::All => roster
-                .bots
-                .iter()
-                .map(|b| b.id)
-                .filter(|id| *id != local.0)
-                .collect(),
+            BotTpTarget::All => roster.bots.iter().map(|b| b.id).collect(),
             BotTpTarget::Id(id) => {
-                if roster.is_bot(id) && id != local.0 {
+                if roster.is_bot(id) {
                     vec![id]
                 } else {
                     diag::warn!(Sim, "bots: tp skipped — client {} is not a bot", id.0);
@@ -243,7 +271,6 @@ struct ThinkBots<'w> {
     cmds: ResMut<'w, ClientCommandInbox>,
     hold: Res<'w, BotHold>,
     fire: ResMut<'w, BotFireQueue>,
-    local: Res<'w, LocalPresentClient>,
 }
 
 fn think_bots(mut p: ThinkBots) {
@@ -253,9 +280,6 @@ fn think_bots(mut p: ThinkBots) {
     let mut budget = TraceBudget::new(TRACE_QUOTA);
     let mut astar = ASTAR_QUOTA;
     for bot in &mut p.roster.bots {
-        if bot.id == p.local.0 {
-            continue;
-        }
         let mut queried = Budgeted {
             world: &mut p.world.0,
             budget: &mut budget,

crates/bots/src/roster.rs

@@ -109,14 +109,20 @@ impl BotRoster {
         self.bots.iter().any(|bot| bot.id == id)
     }
 
-    pub fn add_bots(&mut self, count: u32) -> Vec<ClientId> {
+    // `taken` are the ids real clients already own. A bot minted onto one of
+    // them *is* that client as far as the roster is concerned: `is_bot` claims
+    // the player, and the slot is dead weight because no system can drive an
+    // id someone else is already playing.
+    pub fn add_bots(&mut self, count: u32, taken: &[ClientId]) -> Vec<ClientId> {
         let room = MAX_HOST_BOTS.saturating_sub(self.bots.len() as u32);
         let count = count.min(room);
+        let seed = self.seed;
         let mut added = Vec::with_capacity(count as usize);
         for i in 0..count {
-            let id = ClientId(self.next_client);
-            self.next_client = self.next_client.wrapping_add(1).max(1);
-            let brain = HostController::new(self.seed ^ (u64::from(id.0) << 32) ^ u64::from(i));
+            let Some(id) = self.claim_id(taken) else {
+                break;
+            };
+            let brain = HostController::new(seed ^ (u64::from(id.0) << 32) ^ u64::from(i));
             self.bots.push(BotSlot {
                 id,
                 brain,
@@ -127,4 +133,22 @@ impl BotRoster {
         }
         added
     }
+
+    fn claim_id(&mut self, taken: &[ClientId]) -> Option<ClientId> {
+        // Only `bots + taken` ids are spoken for, so one candidate more than
+        // that always turns up a free one.
+        let candidates = self
+            .bots
+            .len()
+            .saturating_add(taken.len())
+            .saturating_add(1);
+        for _ in 0..candidates {
+            let id = ClientId(self.next_client);
+            self.next_client = self.next_client.wrapping_add(1).max(1);
+            if !taken.contains(&id) && !self.is_bot(id) {
+                return Some(id);
+            }
+        }
+        None
+    }
 }

crates/bots/src/tests.rs

@@ -398,9 +398,41 @@ fn budget_exhaust_is_not_a_miss() {
 #[test]
 fn roster_stops_at_twenty() {
     let mut roster = crate::BotRoster::default();
-    let first = roster.add_bots(20);
+    let first = roster.add_bots(20, &[]);
     assert_eq!(first.len(), MAX_HOST_BOTS as usize);
-    assert!(roster.add_bots(3).is_empty());
+    assert!(roster.add_bots(3, &[]).is_empty());
+}
+
+#[test]
+fn roster_steps_over_ids_real_clients_own() {
+    // The host holds ClientId(1) in a listen match: minting a bot onto it
+    // hands the roster the player themself.
+    let mut roster = crate::BotRoster::default();
+    let ids = roster.add_bots(3, &[ClientId(1), ClientId(3)]);
+
+    assert_eq!(ids, vec![ClientId(2), ClientId(4), ClientId(5)]);
+    assert!(!roster.is_bot(ClientId(1)), "the local player is not a bot");
+    assert!(!roster.is_bot(ClientId(3)));
+}
+
+#[test]
+fn roster_mints_every_bot_that_was_asked_for() {
+    let mut roster = crate::BotRoster::default();
+    let taken: Vec<ClientId> = (1..=4).map(ClientId).collect();
+
+    assert_eq!(roster.add_bots(10, &taken).len(), 10);
+    assert_eq!(roster.bots.len(), 10);
+    assert!(taken.iter().all(|id| !roster.is_bot(*id)));
+}
+
+#[test]
+fn roster_never_mints_an_id_twice() {
+    let mut roster = crate::BotRoster::default();
+    let first = roster.add_bots(4, &[]);
+    let second = roster.add_bots(4, &[]);
+
+    assert!(first.iter().all(|id| !second.contains(id)));
+    assert_eq!(roster.bots.len(), 8);
 }
 
 fn floor_world(extra: Vec<SimBrush>) -> SimWorld {
@@ -1821,7 +1853,7 @@ fn pmove_max_roster_walks_on_shared_budget() {
     let digest = world.content_digest();
     let graph = crate::nav::bake(&mut world, bounds, digest);
     let mut roster = BotRoster::default();
-    let ids = roster.add_bots(MAX_HOST_BOTS);
+    let ids = roster.add_bots(MAX_HOST_BOTS, &[]);
     assert_eq!(ids.len(), MAX_HOST_BOTS as usize);
     for (i, id) in ids.iter().enumerate() {
         let col = (i / 10) as f32;

crates/launcher/src/main.rs

@@ -6,7 +6,7 @@ use assets::{ensure_artifacts_dir, games_root_from_env};
 static PROCESS_ALLOCATOR: diag::ProcessCountingAllocator = diag::ProcessCountingAllocator;
 
 fn main() {
-    bootstrap::bench_load::begin_command();
+    bootstrap::bench::arm();
     prepare_process_root().unwrap_or_else(|e| {
         diag::exit_launch_error(&e);
     });

crates/net/src/authority/runtime.rs

@@ -1469,7 +1469,9 @@ pub fn register_listen_runtime(app: &mut App) {
             .add_systems(
                 FixedUpdate,
                 (
-                    begin_fixed_census.before(AuthoritySet::Advance),
+                    begin_fixed_census
+                        .before(AuthoritySet::Advance)
+                        .before(frame::AuthorityEdge(0)),
                     advance_authority_clock.in_set(AuthoritySet::Advance),
                     ingress_authority.in_set(AuthoritySet::Ingress),
                     gather_authority_input.in_set(AuthoritySet::Gather),
@@ -1495,7 +1497,9 @@ pub fn register_listen_runtime(app: &mut App) {
         app.add_systems(
             FixedUpdate,
             (
-                begin_fixed_census.before(AuthoritySet::Advance),
+                begin_fixed_census
+                    .before(AuthoritySet::Advance)
+                    .before(frame::AuthorityEdge(0)),
                 advance_authority_clock.in_set(AuthoritySet::Advance),
                 ingress_authority.in_set(AuthoritySet::Ingress),
                 gather_authority_input.in_set(AuthoritySet::Gather),

crates/net/src/client/predict.rs

@@ -376,6 +376,20 @@ impl ClientPrediction {
         Some((seq, cmd))
     }
 
+    /// Drop the unacknowledged history so the next snapshot is adopted whole —
+    /// the same recovery `MAX_UNACKED_SNAPSHOTS` performs, on demand. The
+    /// pending send window is deliberately left alone: the authority consumes a
+    /// client's commands in sequence, so a hole punched in that window wedges it
+    /// for good.
+    pub fn force_resync(&mut self) {
+        self.snapshots_since_ack = 0;
+        if self.history.is_empty() {
+            return;
+        }
+        self.history.clear();
+        self.metrics.forced_adopts += 1;
+    }
+
     pub fn retire_acks(&mut self, ack: Option<CmdSeq>) {
         if !self.armed {
             return;

crates/net/src/client/runtime.rs

@@ -824,6 +824,53 @@ pub fn sample_client_input(
     template.ready = true;
 }
 
+/// A stall is a stretch in which the authority acked none of the local client's
+/// commands. Both measures of one — the age of the oldest command still waiting
+/// to be acked, and the command time spanned by the unacknowledged history — are
+/// wall-clock spans, so a single long frame fills either on its own. Failing the
+/// session on the first of them turned every hitch into a permanent disconnect.
+pub const BACKLOG_STALL_MS: i32 = 1000;
+
+/// How many stalls the link may take before the session is failed for real. A
+/// hitch costs one and is recovered from; an authority that has genuinely gone
+/// away keeps earning them and still fails, a few seconds later than before.
+pub const BACKLOG_STALLS_BEFORE_FAIL: u32 = 3;
+
+#[derive(Debug, Default)]
+pub struct BacklogStalls {
+    counted: u32,
+
+    acks_at_last: u64,
+
+    last_ms: Option<i32>,
+}
+
+impl BacklogStalls {
+    /// Count a stall, at most one per `BACKLOG_STALL_MS` and only while the
+    /// authority has acked nothing since the last one. `None` means the caller
+    /// has already acted on the stall still in progress.
+    fn note(&mut self, now_ms: i32, acks: u64) -> Option<u32> {
+        if acks != self.acks_at_last {
+            self.acks_at_last = acks;
+            self.counted = 0;
+            self.last_ms = None;
+        }
+        if self
+            .last_ms
+            .is_some_and(|last| now_ms.saturating_sub(last) < BACKLOG_STALL_MS)
+        {
+            return None;
+        }
+        self.last_ms = Some(now_ms);
+        self.counted = self.counted.saturating_add(1);
+        Some(self.counted)
+    }
+
+    fn clear(&mut self) {
+        *self = Self::default();
+    }
+}
+
 pub fn enforce_client_work_limits(
     pending: Res<PendingClientSends>,
     mut prediction: ResMut<ClientPredictionState>,
@@ -834,6 +881,7 @@ pub fn enforce_client_work_limits(
     bridge: Option<Res<crate::MasterBridge>>,
     mut gate: ResMut<AuthorityInputGate>,
     actions: Res<ClientActionInbox>,
+    mut stalls: Local<BacklogStalls>,
 ) {
     if signon.phase.is_failed() {
         gate.local_cmds_enabled = false;
@@ -842,11 +890,17 @@ pub fn enforce_client_work_limits(
     let oldest = pending.iter().next().map(|(_, cmd, _)| cmd.server_time);
     let duration =
         queued_command_duration(prediction.0.history().iter().map(|row| row.cmd.server_time));
+    let stalled = oldest.is_some_and(|oldest| cg.time().saturating_sub(oldest) > BACKLOG_STALL_MS)
+        || duration > BACKLOG_STALL_MS;
+    let stall = if stalled {
+        stalls.note(cg.time(), prediction.0.metrics().acks_matched)
+    } else {
+        stalls.clear();
+        None
+    };
     let reason = if actions.timed_out() {
         Some("ActionOutcomeUnknown: authority outcome deadline exceeded")
-    } else if oldest.is_some_and(|oldest| cg.time().saturating_sub(oldest) > 1000)
-        || duration > 1000
-    {
+    } else if stall.is_some_and(|counted| counted >= BACKLOG_STALLS_BEFORE_FAIL) {
         Some("InputBacklogExceeded")
     } else if gate.local_cmds_enabled
         && prediction.0.is_armed()
@@ -859,20 +913,32 @@ pub fn enforce_client_work_limits(
     } else {
         None
     };
-    if let Some(reason) = reason {
-        gate.local_cmds_enabled = false;
-        prediction.0.disarm();
-        if let Some(bridge) = bridge {
-            bridge.fail(reason);
+    let Some(reason) = reason else {
+        // Under the limit the stall is the authority falling behind, not the
+        // client flooding it — that case is `PredictionHistoryExhausted`, which
+        // counts commands instead of milliseconds. Re-adopt and play on.
+        if let Some(counted) = stall {
+            diag::warn!(
+                Net,
+                "input backlog: no authority ack in {BACKLOG_STALL_MS} ms \
+                 (stall {counted}/{BACKLOG_STALLS_BEFORE_FAIL}) — re-adopting"
+            );
+            prediction.0.force_resync();
         }
-        signon.set_phase(crate::SignonPhase::Failed(
-            crate::SignonFailReason::Transport {
-                source: reason.to_owned(),
-                stage: crate::FailStage::Transport,
-                match_key: frame::MatchKey::NONE,
-            },
-        ));
+        return;
+    };
+    gate.local_cmds_enabled = false;
+    prediction.0.disarm();
+    if let Some(bridge) = bridge {
+        bridge.fail(reason);
     }
+    signon.set_phase(crate::SignonPhase::Failed(
+        crate::SignonFailReason::Transport {
+            source: reason.to_owned(),
+            stage: crate::FailStage::Transport,
+            match_key: frame::MatchKey::NONE,
+        },
+    ));
 }
 
 fn queued_command_duration(times: impl IntoIterator<Item = i32>) -> i32 {
@@ -1414,3 +1480,120 @@ pub fn register_client_runtime(app: &mut App) {
 pub fn register_listen_prediction_arm(app: &mut App) {
     app.add_systems(Update, arm_listen_prediction.in_set(ClientSet::Load));
 }
+
+#[cfg(test)]
+mod work_limit_tests {
+    use super::*;
+    use bevy::ecs::system::SystemId;
+    use sim::ClientId;
+
+    fn stalled_world() -> (World, SystemId) {
+        let mut world = World::new();
+        world.insert_resource(PendingClientSends::default());
+        world.insert_resource(ClientPredictionState(ClientPrediction::new(ClientId(1))));
+        world.insert_resource(CgFrameClock::default());
+        world.insert_resource(ClsRealtime::default());
+        world.insert_resource(ClientCmdTemplate::default());
+        world.insert_resource(crate::SignonState::default());
+        world.insert_resource(AuthorityInputGate {
+            local_cmds_enabled: true,
+        });
+        world.insert_resource(ClientActionInbox::default());
+
+        // One command sent and never acked: every tick from here on is a stall.
+        world.resource_mut::<PendingClientSends>().push(
+            CmdSeq(1),
+            UserCmd::default(),
+            sim::ShotSampleProvenance::NO_CLAIM,
+        );
+        let id = world.register_system(enforce_client_work_limits);
+        (world, id)
+    }
+
+    fn at(world: &mut World, id: SystemId, now_ms: i32) {
+        world
+            .resource_mut::<CgFrameClock>()
+            .assign_server_time(now_ms);
+        world.run_system(id).expect("work limits ran");
+    }
+
+    fn failed(world: &World) -> bool {
+        world.resource::<crate::SignonState>().phase.is_failed()
+    }
+
+    #[test]
+    fn a_single_stall_re_adopts_instead_of_failing_the_session() {
+        let (mut world, id) = stalled_world();
+
+        at(&mut world, id, BACKLOG_STALL_MS + 1);
+
+        assert!(!failed(&world), "a hitch must not disconnect the session");
+        assert!(
+            world.resource::<AuthorityInputGate>().local_cmds_enabled,
+            "the local player keeps their input"
+        );
+    }
+
+    #[test]
+    fn a_stall_that_never_lifts_still_fails_the_session() {
+        let (mut world, id) = stalled_world();
+
+        for stall in 1..BACKLOG_STALLS_BEFORE_FAIL {
+            at(&mut world, id, (stall as i32 + 1) * BACKLOG_STALL_MS);
+            assert!(!failed(&world), "failed on stall {stall}");
+        }
+        at(
+            &mut world,
+            id,
+            (BACKLOG_STALLS_BEFORE_FAIL as i32 + 1) * BACKLOG_STALL_MS,
+        );
+
+        assert!(failed(&world), "a dead authority must still fail the link");
+        assert!(!world.resource::<AuthorityInputGate>().local_cmds_enabled);
+    }
+
+    #[test]
+    fn frames_inside_one_stall_are_not_counted_separately() {
+        let (mut world, id) = stalled_world();
+
+        // 110 frames at 60 Hz span under two stall windows, so they are worth
+        // two stalls. Without the debounce each frame would count its own and
+        // the session would be gone inside three of them.
+        for frame in 0..110 {
+            at(&mut world, id, BACKLOG_STALL_MS + 1 + frame * 16);
+        }
+
+        assert!(!failed(&world), "frames were counted as separate stalls");
+    }
+
+    #[test]
+    fn an_ack_clears_the_stalls_that_came_before_it() {
+        let mut stalls = BacklogStalls::default();
+
+        assert_eq!(stalls.note(1_000, 0), Some(1));
+        assert_eq!(stalls.note(2_000, 0), Some(2));
+        assert_eq!(stalls.note(3_000, 1), Some(1), "the ack reset the count");
+    }
+
+    #[test]
+    fn a_stall_is_counted_once_per_window() {
+        let mut stalls = BacklogStalls::default();
+
+        assert_eq!(stalls.note(1_000, 0), Some(1));
+        assert_eq!(stalls.note(1_000 + BACKLOG_STALL_MS - 1, 0), None);
+        assert_eq!(stalls.note(1_000 + BACKLOG_STALL_MS, 0), Some(2));
+    }
+
+    #[test]
+    fn a_resync_drops_the_history_the_authority_never_acked() {
+        let mut prediction = ClientPrediction::new(ClientId(1));
+        prediction.install_world(sim::SimWorld::new());
+        prediction.predict(UserCmd::default(), ServerTime::from_ms(50));
+        assert!(!prediction.history().is_empty());
+
+        prediction.force_resync();
+
+        assert!(prediction.history().is_empty());
+        assert_eq!(prediction.metrics().forced_adopts, 1);
+    }
+}

crates/perf/src/lib.rs

@@ -8,6 +8,7 @@ mod session;
 #[cfg(not(all(unix, feature = "native")))]
 #[path = "session_noop.rs"]
 mod session;
+pub mod stats;
 #[cfg(all(unix, feature = "native"))]
 mod vocabulary;
 #[cfg(not(all(unix, feature = "native")))]
@@ -22,4 +23,5 @@ pub use event::{
     world_ready,
 };
 pub use session::{RunMetadata, enabled, flush, start};
+pub use stats::{Anomalies, Phase, SpanStats};
 pub use vocabulary::{Counter, Span, SpanGuard};

crates/perf/src/stats.rs

@@ -0,0 +1,399 @@
+//! In-process span statistics: what `make bench` reads.
+//!
+//! Perfetto answers "what happened in this one frame"; this answers "where did
+//! the time go over the whole run", without a trace file and without Trace
+//! Processor. It is the same instrumentation — every [`Span`] begin/end already
+//! in the tree feeds both — so there is no second set of call sites to keep in
+//! step.
+//!
+//! Off unless `IW4L_BENCH` is set, and off it costs one relaxed load per
+//! begin/end. On, it costs two `Instant::now()` and a handful of relaxed atomic
+//! adds per span instance: no allocation, no lock, nothing to flush.
+//!
+//! Durations land in a log-scale histogram, [`SUB`] buckets per octave, so a
+//! percentile is exact to within [`PRECISION`] of its own value. Counts, sums,
+//! minima and maxima are exact.
+
+use std::sync::OnceLock;
+use std::sync::atomic::{AtomicBool, AtomicU8, AtomicU32, AtomicU64, Ordering};
+use std::time::Instant;
+
+use crate::vocabulary_types::Span;
+
+const ENV: &str = "IW4L_BENCH";
+
+/// Sub-buckets per octave, as a shift. Four bits is sixteen buckets per octave.
+const SUB_BITS: u32 = 4;
+const SUB: u64 = 1 << SUB_BITS;
+/// One row of `SUB` buckets for values below `SUB`, then one row per octave up
+/// to the largest `u64` low edge that does not overflow.
+const BUCKETS: usize = 61 * SUB as usize;
+
+/// Worst-case relative error of a percentile read out of the histogram: half a
+/// bucket width over that bucket's low edge.
+pub const PRECISION: f64 = 0.5 / SUB as f64;
+
+/// Which half of the run a sample belongs to. The two are independent reports:
+/// [`Phase::Load`] is everything up to the first playable frame, [`Phase::Live`]
+/// the frames after it.
+#[derive(Clone, Copy, Debug, PartialEq, Eq)]
+pub enum Phase {
+    Load,
+    Live,
+}
+
+impl Phase {
+    const COUNT: usize = 2;
+
+    const fn index(self) -> usize {
+        match self {
+            Self::Load => 0,
+            Self::Live => 1,
+        }
+    }
+}
+
+const NO_PARENT: u8 = u8::MAX;
+
+struct Histogram {
+    count: AtomicU64,
+    sum_ns: AtomicU64,
+    min_ns: AtomicU64,
+    max_ns: AtomicU64,
+    buckets: [AtomicU32; BUCKETS],
+}
+
+impl Histogram {
+    #[allow(clippy::declare_interior_mutable_const)]
+    const ZERO: Self = Self {
+        count: AtomicU64::new(0),
+        sum_ns: AtomicU64::new(0),
+        min_ns: AtomicU64::new(u64::MAX),
+        max_ns: AtomicU64::new(0),
+        buckets: [const { AtomicU32::new(0) }; BUCKETS],
+    };
+
+    #[inline]
+    fn record(&self, ns: u64) {
+        self.count.fetch_add(1, Ordering::Relaxed);
+        self.sum_ns.fetch_add(ns, Ordering::Relaxed);
+        self.min_ns.fetch_min(ns, Ordering::Relaxed);
+        self.max_ns.fetch_max(ns, Ordering::Relaxed);
+        self.buckets[bucket_of(ns)].fetch_add(1, Ordering::Relaxed);
+    }
+}
+
+static ARMED: AtomicBool = AtomicBool::new(false);
+static PHASE: AtomicU8 = AtomicU8::new(0);
+static PARENT: [AtomicU8; Span::COUNT] = [const { AtomicU8::new(NO_PARENT) }; Span::COUNT];
+static PARENT_VARIES: [AtomicBool; Span::COUNT] = [const { AtomicBool::new(false) }; Span::COUNT];
+static UNMATCHED_END: AtomicU64 = AtomicU64::new(0);
+static REOPENED: AtomicU64 = AtomicU64::new(0);
+static HISTOGRAMS: [[Histogram; Span::COUNT]; Phase::COUNT] =
+    [const { [const { Histogram::ZERO }; Span::COUNT] }; Phase::COUNT];
+
+/// When each span opened, as nanoseconds since [`BASE`] plus one; zero is
+/// closed. Global rather than thread-local on purpose: Bevy runs `FixedUpdate`,
+/// `PreUpdate` and `PostUpdate` on the task pool, so a span's begin and its end
+/// are not promised the same thread — which is also why the Perfetto side gives
+/// every span its own named track. One slot per span is enough because a span
+/// is a single scope: it is never open twice at once.
+static OPEN_AT: [AtomicU64; Span::COUNT] = [const { AtomicU64::new(0) }; Span::COUNT];
+
+/// The zero of the recorder's clock, fixed by [`arm`] before the first span.
+static BASE: OnceLock<Instant> = OnceLock::new();
+
+/// Read `IW4L_BENCH` once, before the first span. Until this is called nothing
+/// is recorded.
+pub fn arm() {
+    let _ = BASE.set(Instant::now());
+    ARMED.store(env_enabled(), Ordering::Relaxed);
+}
+
+/// Nanoseconds since the recorder's zero. Wraps in 584 years.
+#[inline]
+fn now_ns() -> u64 {
+    BASE.get().map_or(0, |base| {
+        u64::try_from(base.elapsed().as_nanos()).unwrap_or(u64::MAX)
+    })
+}
+
+/// Whether this process was asked to collect bench statistics.
+#[inline]
+pub fn enabled() -> bool {
+    ARMED.load(Ordering::Relaxed)
+}
+
+fn env_enabled() -> bool {
+    match std::env::var(ENV) {
+        Ok(value)
+            if value.is_empty()
+                || value == "0"
+                || value.eq_ignore_ascii_case("false")
+                || value.eq_ignore_ascii_case("off") =>
+        {
+            false
+        }
+        Ok(_) => true,
+        Err(_) => false,
+    }
+}
+
+/// Everything recorded from here on belongs to [`Phase::Live`]. Called once the
+/// map is on screen; before it, the samples are the cost of getting there.
+pub fn mark_live() {
+    PHASE.store(Phase::Live.index() as u8, Ordering::Relaxed);
+}
+
+#[inline]
+pub(crate) fn begin(span: Span) {
+    if !enabled() {
+        return;
+    }
+    if span != Span::FramesWallFrameMs {
+        remember_parent(span, innermost_open());
+    }
+    if OPEN_AT[span as usize].swap(now_ns() + 1, Ordering::Relaxed) != 0 {
+        REOPENED.fetch_add(1, Ordering::Relaxed);
+    }
+}
+
+#[inline]
+pub(crate) fn end(span: Span) {
+    if !enabled() {
+        return;
+    }
+    let now = now_ns();
+    let started = OPEN_AT[span as usize].swap(0, Ordering::Relaxed);
+    if started == 0 {
+        UNMATCHED_END.fetch_add(1, Ordering::Relaxed);
+        return;
+    }
+    record(span, now.saturating_sub(started - 1));
+}
+
+/// The open span that began most recently — the one this span is nesting
+/// inside. `wall` is excluded: it is the frame clock, opened in one frame and
+/// closed in the next, so it encloses no scope and is the root of the printed
+/// tree instead of a parent in it.
+fn innermost_open() -> Option<Span> {
+    let mut innermost: Option<(u64, Span)> = None;
+    for span in Span::ALL {
+        if span == Span::FramesWallFrameMs {
+            continue;
+        }
+        let at = OPEN_AT[span as usize].load(Ordering::Relaxed);
+        if at != 0 && innermost.is_none_or(|(latest, _)| at > latest) {
+            innermost = Some((at, span));
+        }
+    }
+    innermost.map(|(_, span)| span)
+}
+
+fn remember_parent(span: Span, parent: Option<Span>) {
+    let seen = parent.map_or(NO_PARENT, |parent| parent as u8);
+    let slot = &PARENT[span as usize];
+    match slot.compare_exchange(NO_PARENT, seen, Ordering::Relaxed, Ordering::Relaxed) {
+        Ok(_) => {}
+        Err(known) if known == seen => {}
+        Err(_) => PARENT_VARIES[span as usize].store(true, Ordering::Relaxed),
+    }
+}
+
+#[inline]
+fn record(span: Span, ns: u64) {
+    let phase = (PHASE.load(Ordering::Relaxed) as usize).min(Phase::COUNT - 1);
+    HISTOGRAMS[phase][span as usize].record(ns);
+}
+
+/// Values below [`SUB`] are their own bucket; above it, `SUB` buckets cover
+/// each octave.
+fn bucket_of(ns: u64) -> usize {
+    if ns < SUB {
+        return ns as usize;
+    }
+    let octave = u64::from(63 - ns.leading_zeros()) - u64::from(SUB_BITS);
+    let sub = (ns >> octave) & (SUB - 1);
+    ((octave + 1) * SUB + sub) as usize
+}
+
+fn bucket_low_ns(index: usize) -> u64 {
+    let index = index as u64;
+    if index < SUB {
+        return index;
+    }
+    let octave = u32::try_from(index / SUB - 1).unwrap_or(u32::MAX);
+    let step = 1u64.checked_shl(octave).unwrap_or(u64::MAX);
+    (SUB | (index % SUB)).saturating_mul(step)
+}
+
+/// What one span cost over one phase. Times are nanoseconds; the percentiles
+/// are bucket midpoints, exact to [`PRECISION`].
+#[derive(Clone, Copy, Debug)]
+pub struct SpanStats {
+    pub span: Span,
+    pub parent: Option<Span>,
+    pub parent_varies: bool,
+    pub count: u64,
+    pub sum_ns: u64,
+    pub min_ns: u64,
+    pub max_ns: u64,
+    pub p50_ns: u64,
+    pub p95_ns: u64,
+    pub p99_ns: u64,
+}
+
+impl SpanStats {
+    pub fn avg_ns(&self) -> u64 {
+        self.sum_ns.checked_div(self.count).unwrap_or(0)
+    }
+}
+
+/// Every span that produced at least one sample in `phase`, in declaration
+/// order. An empty result means the phase was never reached.
+pub fn snapshot(phase: Phase) -> Vec<SpanStats> {
+    let histograms = &HISTOGRAMS[phase.index()];
+    Span::ALL
+        .into_iter()
+        .filter_map(|span| {
+            let histogram = &histograms[span as usize];
+            let count = histogram.count.load(Ordering::Relaxed);
+            if count == 0 {
+                return None;
+            }
+            let quantiles = quantiles(histogram, count, &[0.50, 0.95, 0.99]);
+            Some(SpanStats {
+                span,
+                parent: parent_of(span),
+                parent_varies: PARENT_VARIES[span as usize].load(Ordering::Relaxed),
+                count,
+                sum_ns: histogram.sum_ns.load(Ordering::Relaxed),
+                min_ns: histogram.min_ns.load(Ordering::Relaxed),
+                max_ns: histogram.max_ns.load(Ordering::Relaxed),
+                p50_ns: quantiles[0],
+                p95_ns: quantiles[1],
+                p99_ns: quantiles[2],
+            })
+        })
+        .collect()
+}
+
+fn parent_of(span: Span) -> Option<Span> {
+    let parent = PARENT[span as usize].load(Ordering::Relaxed);
+    if parent == NO_PARENT {
+        return None;
+    }
+    Span::ALL
+        .into_iter()
+        .find(|candidate| *candidate as u8 == parent)
+}
+
+fn quantiles(histogram: &Histogram, count: u64, wanted: &[f64]) -> Vec<u64> {
+    let mut out = Vec::with_capacity(wanted.len());
+    let mut cursor = 0usize;
+    // Samples in the buckets *before* `cursor`, so a later quantile can resume
+    // from here without counting the bucket it stopped on twice.
+    let mut seen = 0u64;
+    for quantile in wanted {
+        let rank = ((count as f64 * quantile).ceil() as u64).clamp(1, count);
+        while cursor < BUCKETS {
+            let n = u64::from(histogram.buckets[cursor].load(Ordering::Relaxed));
+            if seen + n >= rank {
+                break;
+            }
+            seen += n;
+            cursor += 1;
+        }
+        let index = cursor.min(BUCKETS - 1);
+        let low = bucket_low_ns(index);
+        let high = bucket_low_ns(index + 1).max(low);
+        out.push(low + (high - low) / 2);
+    }
+    out
+}
+
+/// Bookkeeping the report prints, so a reader can tell a real number from one
+/// the recorder could not close.
+#[derive(Clone, Copy, Debug, Default)]
+pub struct Anomalies {
+    pub unmatched_end: u64,
+    pub reopened: u64,
+}
+
+pub fn anomalies() -> Anomalies {
+    Anomalies {
+        unmatched_end: UNMATCHED_END.load(Ordering::Relaxed),
+        reopened: REOPENED.load(Ordering::Relaxed),
+    }
+}
+
+#[cfg(test)]
+mod tests {
+    use super::*;
+
+    #[test]
+    fn every_value_lands_in_a_bucket_that_contains_it() {
+        for ns in [
+            0,
+            1,
+            15,
+            16,
+            17,
+            31,
+            32,
+            1_000,
+            1_000_000,
+            16 * 1_000_000,
+            u64::MAX / 2,
+        ] {
+            let index = bucket_of(ns);
+            assert!(index < BUCKETS, "{ns} landed outside the histogram");
+            let low = bucket_low_ns(index);
+            let high = bucket_low_ns(index + 1);
+            assert!(low <= ns, "{ns} is below its bucket's low edge {low}");
+            assert!(
+                ns < high,
+                "{ns} is at or above its bucket's high edge {high}"
+            );
+        }
+    }
+
+    #[test]
+    fn bucket_low_edges_never_go_backwards() {
+        let mut previous = 0;
+        for index in 1..BUCKETS {
+            let low = bucket_low_ns(index);
+            assert!(low > previous, "bucket {index} low {low} <= {previous}");
+            previous = low;
+        }
+    }
+
+    #[test]
+    fn percentiles_read_back_the_values_that_were_recorded() {
+        let histogram = Histogram::ZERO;
+        for ms in 1..=100u64 {
+            histogram.record(ms * 1_000_000);
+        }
+        let read = quantiles(&histogram, 100, &[0.50, 0.95, 0.99]);
+        for (got, want) in read.into_iter().zip([50u64, 95, 99]) {
+            let want = want * 1_000_000;
+            let error = (got as f64 - want as f64).abs() / want as f64;
+            assert!(error <= PRECISION, "read {got} for {want}: off by {error}");
+        }
+    }
+
+    #[test]
+    fn sum_count_and_extremes_stay_exact() {
+        let histogram = Histogram::ZERO;
+        for ns in [7u64, 1_234_567, 42, 999_999_999] {
+            histogram.record(ns);
+        }
+        assert_eq!(histogram.count.load(Ordering::Relaxed), 4);
+        assert_eq!(
+            histogram.sum_ns.load(Ordering::Relaxed),
+            7 + 1_234_567 + 42 + 999_999_999
+        );
+        assert_eq!(histogram.min_ns.load(Ordering::Relaxed), 7);
+        assert_eq!(histogram.max_ns.load(Ordering::Relaxed), 999_999_999);
+    }
+}

crates/perf/src/vocabulary.rs

@@ -74,6 +74,7 @@ impl Span {
 
     #[inline]
     pub fn begin(self) {
+        crate::stats::begin(self);
         macro_rules! begin {
             ($category:literal, $name:literal) => {
                 perfetto_sdk::track_event_begin!($category, $name, |ctx: &mut EventContext| {
@@ -118,6 +119,7 @@ impl Span {
     }
     #[inline]
     pub fn end(self) {
+        crate::stats::end(self);
         macro_rules! end {
             ($category:literal) => {
                 perfetto_sdk::track_event_end!($category, |ctx: &mut EventContext| {

crates/perf/src/vocabulary_noop.rs

@@ -1,8 +1,14 @@
 pub use crate::vocabulary_types::Span;
 
 impl Span {
-    pub fn begin(self) {}
-    pub fn end(self) {}
+    pub fn begin(self) {
+        crate::stats::begin(self);
+    }
+
+    pub fn end(self) {
+        crate::stats::end(self);
+    }
+
     pub fn enter(self) -> SpanGuard {
         SpanGuard
     }

crates/perf/src/vocabulary_types.rs

@@ -91,3 +91,83 @@ pub enum Counter {
 
     SmodelIbSkip,
 }
+
+impl Span {
+    pub const COUNT: usize = Self::TocUi as usize + 1;
+
+    /// Every span, in declaration order. The report walks this; the recorder
+    /// indexes its arrays by `span as usize`, so the two must not drift.
+    pub const ALL: [Self; Self::COUNT] = [
+        Self::FixedTocAdvance,
+        Self::FixedTocBookkeeping,
+        Self::FixedTocFanout,
+        Self::FixedTocGather,
+        Self::FixedTocIngress,
+        Self::FixedTocSnapshot,
+        Self::FixedTocStep,
+        Self::FramesDiagMs,
+        Self::FramesEffectsMs,
+        Self::FramesFixedMs,
+        Self::FramesPostupdateMs,
+        Self::FramesPredictMs,
+        Self::FramesPresentMs,
+        Self::FramesPreupdateMs,
+        Self::FramesUpdateMs,
+        Self::FramesWallFrameMs,
+        Self::HostFxPresentCpuMs,
+        Self::HostFxUpdateCpuMs,
+        Self::HostPostExecuteMs,
+        Self::HostPostRebuildMs,
+        Self::HostSkinModelMs,
+        Self::RenderColourSubmitMs,
+        Self::RenderCullCpuMs,
+        Self::RenderRenderExtractWaitMs,
+        Self::RenderRenderRenderMs,
+        Self::RenderRenderThreadMs,
+        Self::TocInput,
+        Self::TocLoad,
+        Self::TocReceive,
+        Self::TocReconcile,
+        Self::TocSend,
+        Self::TocUi,
+    ];
+
+    /// The name the span carries in a trace and in the bench report. It is the
+    /// Perfetto event name without the `span.` track prefix.
+    pub const fn name(self) -> &'static str {
+        match self {
+            Self::FixedTocAdvance => "Advance",
+            Self::FixedTocBookkeeping => "Bookkeeping",
+            Self::FixedTocFanout => "Fanout",
+            Self::FixedTocGather => "Gather",
+            Self::FixedTocIngress => "Ingress",
+            Self::FixedTocSnapshot => "Snapshot",
+            Self::FixedTocStep => "Step",
+            Self::FramesDiagMs => "Diag",
+            Self::FramesEffectsMs => "Effects",
+            Self::FramesFixedMs => "FixedUpdate",
+            Self::FramesPostupdateMs => "PostUpdate",
+            Self::FramesPredictMs => "Predict",
+            Self::FramesPresentMs => "Present",
+            Self::FramesPreupdateMs => "PreUpdate",
+            Self::FramesUpdateMs => "Update",
+            Self::FramesWallFrameMs => "wall",
+            Self::HostFxPresentCpuMs => "fx_present",
+            Self::HostFxUpdateCpuMs => "fx_update",
+            Self::HostPostExecuteMs => "post_execute",
+            Self::HostPostRebuildMs => "post_rebuild",
+            Self::HostSkinModelMs => "skin_model",
+            Self::RenderColourSubmitMs => "colour_submit",
+            Self::RenderCullCpuMs => "cull",
+            Self::RenderRenderExtractWaitMs => "extract_wait",
+            Self::RenderRenderRenderMs => "render_render",
+            Self::RenderRenderThreadMs => "render_thread",
+            Self::TocInput => "Input",
+            Self::TocLoad => "Load",
+            Self::TocReceive => "Receive",
+            Self::TocReconcile => "Reconcile",
+            Self::TocSend => "Send",
+            Self::TocUi => "Ui",
+        }
+    }
+}

crates/session/src/admission.rs

@@ -66,10 +66,18 @@ pub fn drive_class_select_screen(
         }
         return;
     }
-    if admitted && matches!(*screen, AppScreen::Loading | AppScreen::MainMenu) && world_installed {
-        if let Some(loading) = loading.as_deref_mut() {
-            loading.finish();
-        }
+    if !admitted || !world_installed {
+        return;
+    }
+    // The overlay comes down on its own terms, the class-select hop on the
+    // screen's. A replay is already `InGame` by the time this runs — the first
+    // presented snapshot arms it in `ClientSet::Present`, one set ahead of here —
+    // and gating the overlay on the screen too left it up for the whole demo,
+    // hiding the world behind `UiLayer::Loading` and holding back map ambience.
+    if let Some(loading) = loading.as_deref_mut() {
+        loading.finish();
+    }
+    if matches!(*screen, AppScreen::Loading | AppScreen::MainMenu) {
         *screen = AppScreen::ClassSelect;
     }
 }

docs/BENCH.md

@@ -0,0 +1,49 @@
+# `make bench` — two reports, one run
+
+`IW4L_BENCH=1` turns on an in-process recorder. At exit it prints two
+independent reports and writes them to `iw4l-artifacts/bench/<stamp>.txt`.
+Neither needs a trace file or Trace Processor; either can be MISS while the
+other stands.
+
+```bash
+make bench demo0011              # play a demo   (a goal is always a demo name)
+make bench DEMO=demo0011         # the same, spelled out
+make bench ZONE=mp_boneyard      # a live map instead
+make bench demo0011 PROFILE=release        # the fat-LTO binary
+make bench ZONE=mp_rust CMDS='wait world; spawn; wait 20s; quit'
+```
+
+**[1/2] Map load** — the waterfall from the shell command to a playable map
+(`make` stamps the command time, so cargo and process startup are charged to
+the load, not hidden before it), then the load-pool stages. A stage's own
+duration says nothing on a parallel walk, so the table also carries
+`exclusive`: the time that stage was the *only* one running, which is the part
+of the load it alone lengthened. Plus stage memory deltas, the process RSS
+peak, the frames drawn behind the loading screen, and a settled screenshot of
+the spawned world under `screenshots/bench/<zone>.png`; eyeball it for geometry
+that never arrived. A demo gets one too: the overlay comes down as soon as the
+first recorded snapshot is presented, so the capture settles during the load.
+
+**[2/2] Frame time** — every typed span from [`PERF.md`](PERF.md), as a tree,
+for the frames *after* the first playable one. `n / avg / p50 / p95 / p99 /
+max / total / %frame / self`, where `self` is a span's total minus the spans
+that nested inside it. The tree is not a table anyone wrote down: a span's
+parent is whichever span was open when it began, so moving a system between
+sets moves it here. `wall` is the frame clock and encloses nothing — it opens
+in one frame and closes in the next — so it is printed as the root everything
+else is a share of. A `*` after a name means that span was seen under more than
+one parent.
+
+Percentiles come from a log-scale histogram, 16 buckets per octave: exact to
+±3.1% of their own value. Counts, sums, minima and maxima are exact. Recording
+costs two clock reads and a few relaxed atomic adds per span instance; off, it
+is one relaxed load.
+
+A demo ends in `std::process::exit`, so the report is written from an `atexit`
+hook rather than after `App::run` returns — the same way the Perfetto flush
+survives that exit. On a platform without `atexit` the report needs the process
+to return normally, which a live map does and a demo does not.
+
+The bench is not the trace. It answers "where did the run spend its time";
+`.pftrace` answers "what happened in this one frame", and `make bench` records
+one too, so [`PERF.md`](PERF.md) still applies to the same run.

docs/INDEX.md

@@ -10,6 +10,7 @@ game. Keep them this short: nobody opens a long file twice.
 | [`DEPLOY.md`](DEPLOY.md) | `make release` / `publish` / `deploy`: the play profile, hashed `.zst`, master by SHA, provision kept separate | shipping a release, "why is the player on an old version" |
 | [`MASTER.md`](MASTER.md) | your own master over ssh from the machine with the clone: `cargo xtask master install`, a self-signed certificate with no domain, what to hand players | standing up a relay for yourself or your friends |
 | [`PERF.md`](PERF.md) | native `.pftrace` — the only runtime truth; picking a UUID, the manifest, `IW4L_PERF`, SQL | traces, scenario SQL, why a frame took 80 ms |
+| [`BENCH.md`](BENCH.md) | `make bench`: the map-load waterfall and stage `exclusive` time, then frame time as a span tree; in-process, no trace needed | "where did this run spend its time" |
 | [`RENDER.md`](RENDER.md) | the nine crates of the island, the frame path `IR → cull → one drawsurf list → tess → material → SM3 → wgpu`, GPU-side ownership, the `d3d9_*` border | touching the picture, techsets, lighting |
 | [`ANIM.md`](ANIM.md) | three floors: `anim_iw4` (facts and curves), `xmodel_runtime` (tree and pose), who picks the clip (`sim` / `render_frontend/adapters/anim/`) | viewmodel, skeleton, bone hits |
 | [`MAP-LOAD.md`](MAP-LOAD.md) | map load: the `session` → `assets` → install transaction, the `load_prepared_match` walk, the lane by `ZoneGame`, the artifact cache | a zone won't load, an asset went missing, "why didn't the match come up" |

docs/PERF.md

@@ -1,7 +1,9 @@
 # Native Perfetto
 
 Runtime observation is `iw4l-artifacts/runs/<uuid>/trace.pftrace`. Recording
-is off unless `IW4L_PERF=1` (`make bench-live` / `make bench-demo` / `make scenario` / `make chaos` / `make lifecycle-*` force it on).
+is off unless `IW4L_PERF=1` (`make bench` / `make bench-live` / `make scenario` /
+`make chaos` / `make lifecycle-*` force it on). Where the *run* spent its time,
+rather than one frame, is [`BENCH.md`](BENCH.md).
 
 ```bash
 make bench-live                            # record + compact p50/p90/p95/p99/hot-path report

docs/RUN.md

@@ -11,8 +11,8 @@ cargo run --profile play -p launcher -- map iw5:mp_overwatch --cmds '…'
 `make` passes no foreign flags through: in the `Makefile` it is `CMDS`, on the
 binary `--cmds`. The colon is a GNU make pattern, so `make map iw5:…` fails —
 write `make map ZONE=iw5:mp_overwatch` or use `cargo run`. Recipes: `make
-scenario`, `chaos`, `bench-demo`, `bench-live`, `lifecycle-*` (`*_CMDS` in the
-`Makefile`). Live recipes use `[profile.play]`; for LTO, `PROFILE=release`.
+scenario`, `chaos`, `bench` ([`BENCH.md`](BENCH.md)), `bench-live`, `lifecycle-*`
+(`*_CMDS` in the `Makefile`). Live recipes use `[profile.play]`; LTO is `PROFILE=release`.
 
 **Controls are frozen until the match starts.** `sim::step` allows movement only
 in `MatchPhase::Playing`; `hold +attack`, `+forward` and `move` do nothing before