diff --git a/Cargo.toml b/Cargo.toml index 64c60cf..9d78e42 100644 --- a/Cargo.toml +++ b/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 ` vs `make bench PROFILE=release`. [profile.play] inherits = "release" opt-level = 3 diff --git a/Makefile b/Makefile index 2002b54..9f77a09 100644 --- a/Makefile +++ b/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 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/.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 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 e.g. make bench demo0011"; echo " make bench 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/.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 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 ` when a demo was named, `map ` 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 play iw4l-artifacts/demos/.iw4ldemo, then quit" @echo " ZONE= overrides header" @echo " CMDS='wait world; wait 5s; quit' mid-play" - @echo "make bench-demo play and write a native Perfetto run directory" - @echo " alias: make bench " + @echo "make bench 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 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" diff --git a/crates/asset_transport/src/lib.rs b/crates/asset_transport/src/lib.rs index 1e8565e..2eba592 100644 --- a/crates/asset_transport/src/lib.rs +++ b/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::{ diff --git a/crates/asset_transport/src/progress.rs b/crates/asset_transport/src/progress.rs index 817d56c..ebd6544 100644 --- a/crates/asset_transport/src/progress.rs +++ b/crates/asset_transport/src/progress.rs @@ -150,6 +150,47 @@ pub struct LoadLaneView { started: Option, } +/// 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, + pub heap_delta: Option, +} + +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) -> 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, ended: Option) -> Option { + 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 { + /// 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 { 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 { + 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!( diff --git a/crates/assets/src/lib.rs b/crates/assets/src/lib.rs index 9ba761a..3ca1459 100644 --- a/crates/assets/src/lib.rs +++ b/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::{ diff --git a/crates/bootstrap/src/bench/frame_report.rs b/crates/bootstrap/src/bench/frame_report.rs new file mode 100644 index 0000000..4921f02 --- /dev/null +++ b/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) { + 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) { + 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) { + 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 = 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, + depth: usize, + table: &mut Table, + placed: &mut Vec, +) { + 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) -> 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) { + 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) { + 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 + )); +} diff --git a/crates/bootstrap/src/bench/load_report.rs b/crates/bootstrap/src/bench/load_report.rs new file mode 100644 index 0000000..84683ea --- /dev/null +++ b/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, out: &mut Vec) { + 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, out: &mut Vec) { + 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, &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 = 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) { + 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) { + 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 { + 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 = 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); + } +} diff --git a/crates/bootstrap/src/bench/milestones.rs b/crates/bootstrap/src/bench/milestones.rs new file mode 100644 index 0000000..f90b5b5 --- /dev/null +++ b/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, + pub(crate) installed: Option, + pub(crate) spawned: Option, + pub(crate) overlay_down: Option, + pub(crate) ingame: Option, + pub(crate) rendered_spawn: Option, + pub(crate) ambient: Option, + pub(crate) shot: Option, + pub(crate) lanes: Vec, + pub(crate) batches_at_shot: Option, + pub(crate) g0_at_shot: Option, + overlay_seen: bool, + ready_frames: u32, + last_batches: Option, + last_g0: Option, + 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 { + 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 { + std::fs::metadata(&self.screenshot) + .ok() + .map(|meta| meta.len()) + .filter(|len| *len > 0) + } +} + +static MILESTONES: std::sync::Mutex> = 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(read: impl FnOnce(&mut Milestones) -> T) -> Option { + 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>, + busy: Option>, + mut installed: MessageReader, + scene: Option>, + loading: Option>, + screen: Option>, + ambient: Option>, + stats: Option>, + working: Option>, +) { + 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(); + } + }); +} diff --git a/crates/bootstrap/src/bench/mod.rs b/crates/bootstrap/src/bench/mod.rs new file mode 100644 index 0000000..bb28872 --- /dev/null +++ b/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/.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 = OnceLock::new(); + +/// Where the report is written, remembered so the exit hook can reach it. +static ARTIFACTS: OnceLock = 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 { + let stamp = stamp.parse::().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::() + .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 ` +/// 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) { + report(artifacts, trace); +} + +fn report(artifacts: &Path, trace: Option) { + 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("", 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) { + let rule = "=".repeat(96); + out.push(rule.clone()); + out.push(format!( + "IW4L bench — zone={zone} command={:?}", + std::env::args().collect::>().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 { + 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}") +} diff --git a/crates/bootstrap/src/bench/table.rs b/crates/bootstrap/src/bench/table.rs new file mode 100644 index 0000000..4d4c312 --- /dev/null +++ b/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, + headers: Vec, + rows: Vec>, + 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(&mut self, cells: [String; N]) { + self.rows.push(cells.into_iter().collect()); + } + + pub(crate) fn render(&self, out: &mut Vec) { + let mut widths: Vec = 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}"), + } +} diff --git a/crates/bootstrap/src/bench_load.rs b/crates/bootstrap/src/bench_load.rs deleted file mode 100644 index 5a61ef6..0000000 --- a/crates/bootstrap/src/bench_load.rs +++ /dev/null @@ -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::() - .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, - installed: Option, - spawned: Option, - overlay_down: Option, - overlay_seen: bool, - ingame: Option, - rendered_spawn: Option, - ready_frames: u32, - ambient: Option, - shot: Option, - batches_at_shot: Option, - g0_at_shot: Option, - last_batches: Option, - last_g0: Option, - last_spawned: bool, -} - -static BENCH: std::sync::Mutex> = 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::() - .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>, - busy: Option>, - mut installed: MessageReader, - scene: Option>, - loading: Option>, - screen: Option>, - ambient: Option>, - stats: Option>, - working: Option>, -) { - 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) -> String { - match t { - Some(t) => format!("{:.1}s", t.duration_since(t0).as_secs_f64()), - None => "MISS".to_owned(), - } -} - -fn stage(first: Option, second: Option) -> 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) { - 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| 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}"); - } -} diff --git a/crates/bootstrap/src/launch.rs b/crates/bootstrap/src/launch.rs index 91ac0cb..52a140c 100644 --- a/crates/bootstrap/src/launch.rs +++ b/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); } } diff --git a/crates/bootstrap/src/lib.rs b/crates/bootstrap/src/lib.rs index dbf1833..688b3ef 100644 --- a/crates/bootstrap/src/lib.rs +++ b/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; diff --git a/crates/bots/src/plugin.rs b/crates/bots/src/plugin.rs index e0dbff8..2d151e4 100644 --- a/crates/bots/src/plugin.rs +++ b/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, mut roster: ResMut) { - for count in queue.drain() { - let added = roster.add_bots(count); +fn drain_bot_add_queue( + mut queue: ResMut, + mut roster: ResMut, + local: Res, + world: Option>, +) { + 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, mut roster: ResMut, local: Res) { + 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, mut actions: ResMut, mut request_ids: ResMut, - local: Res, pool: Res, ) { 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 = 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, diff --git a/crates/bots/src/roster.rs b/crates/bots/src/roster.rs index 5420ee8..bb07fa5 100644 --- a/crates/bots/src/roster.rs +++ b/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 { + // `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 { 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 { + // 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 + } } diff --git a/crates/bots/src/tests.rs b/crates/bots/src/tests.rs index 53ca284..4775f34 100644 --- a/crates/bots/src/tests.rs +++ b/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 = (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) -> 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; diff --git a/crates/launcher/src/main.rs b/crates/launcher/src/main.rs index 2c1e2fd..bcd7e2d 100644 --- a/crates/launcher/src/main.rs +++ b/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); }); diff --git a/crates/net/src/authority/runtime.rs b/crates/net/src/authority/runtime.rs index fab49fa..54c9fb8 100644 --- a/crates/net/src/authority/runtime.rs +++ b/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), diff --git a/crates/net/src/client/predict.rs b/crates/net/src/client/predict.rs index de5be5e..b64e99e 100644 --- a/crates/net/src/client/predict.rs +++ b/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) { if !self.armed { return; diff --git a/crates/net/src/client/runtime.rs b/crates/net/src/client/runtime.rs index 6cc6e33..3f2c6cd 100644 --- a/crates/net/src/client/runtime.rs +++ b/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, +} + +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 { + 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, mut prediction: ResMut, @@ -834,6 +881,7 @@ pub fn enforce_client_work_limits( bridge: Option>, mut gate: ResMut, actions: Res, + mut stalls: Local, ) { 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) -> 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::().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::() + .assign_server_time(now_ms); + world.run_system(id).expect("work limits ran"); + } + + fn failed(world: &World) -> bool { + world.resource::().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::().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::().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); + } +} diff --git a/crates/perf/src/lib.rs b/crates/perf/src/lib.rs index daa2ec2..44ccfa9 100644 --- a/crates/perf/src/lib.rs +++ b/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}; diff --git a/crates/perf/src/stats.rs b/crates/perf/src/stats.rs new file mode 100644 index 0000000..ea4cbf1 --- /dev/null +++ b/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 = 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 { + 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) { + 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, + 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 { + 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 { + 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 { + 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); + } +} diff --git a/crates/perf/src/vocabulary.rs b/crates/perf/src/vocabulary.rs index aa9b331..57e6546 100644 --- a/crates/perf/src/vocabulary.rs +++ b/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| { diff --git a/crates/perf/src/vocabulary_noop.rs b/crates/perf/src/vocabulary_noop.rs index d5a8cf2..0a575ef 100644 --- a/crates/perf/src/vocabulary_noop.rs +++ b/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 } diff --git a/crates/perf/src/vocabulary_types.rs b/crates/perf/src/vocabulary_types.rs index f559475..2d6a79c 100644 --- a/crates/perf/src/vocabulary_types.rs +++ b/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", + } + } +} diff --git a/crates/session/src/admission.rs b/crates/session/src/admission.rs index febebe0..1ae171d 100644 --- a/crates/session/src/admission.rs +++ b/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; } } diff --git a/docs/BENCH.md b/docs/BENCH.md new file mode 100644 index 0000000..d8c5f26 --- /dev/null +++ b/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/.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/.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. diff --git a/docs/INDEX.md b/docs/INDEX.md index 3f90f46..e60a8fc 100644 --- a/docs/INDEX.md +++ b/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" | diff --git a/docs/PERF.md b/docs/PERF.md index 56eb877..fdf3256 100644 --- a/docs/PERF.md +++ b/docs/PERF.md @@ -1,7 +1,9 @@ # Native Perfetto Runtime observation is `iw4l-artifacts/runs//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 diff --git a/docs/RUN.md b/docs/RUN.md index d88cba7..9a2bf2e 100644 --- a/docs/RUN.md +++ b/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