diff --git a/Cargo.lock b/Cargo.lock index 7ccf72b..05c5343 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1812,6 +1812,7 @@ dependencies = [ "render", "render_frontend", "replay", + "serde_json", "session", "sim", "ui", diff --git a/Makefile b/Makefile index 9f77a09..96ecdf3 100644 --- a/Makefile +++ b/Makefile @@ -97,10 +97,12 @@ 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) -# 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. +# The bench. One process, three independent reports written at exit: where the +# map load spent its time, where a gameplay frame spends its time by span, and +# what that frame asked the machine to do. All three are in-process — no trace +# file and no Trace Processor — and land in iw4l-artifacts/bench/.txt as +# well as on stdout. The run's own directory gets report.txt, manifest.json and +# summary.json beside the .pftrace, so a number can be read months later. # # make bench demo0011 play a demo (also: DEMO=demo0011) # make bench ZONE=mp_boneyard live map instead of a demo @@ -170,9 +172,13 @@ bench-live: require-games # Alternating paired process benchmark. One binary and one script are used for # both arms; the runner requires >=5 measured pairs and reports a paired 95% CI. +# VAR picks which recorder the on-arm turns on: IW4L_PERF (the Perfetto session, +# the default) or IW4L_BENCH (the in-process recorder `make bench` reads). They +# are separate costs and each needs its own pairs. +PERF_OVERHEAD_VAR ?= IW4L_PERF bench-overhead: require-games cd $(ROOT) && $(CARGO) build $(PROFILE_ARG) -p launcher - cd $(ROOT) && $(CARGO) run --quiet -p xtask -- perf-overhead --pairs $(PERF_OVERHEAD_PAIRS) --warmup-pairs $(PERF_OVERHEAD_WARMUP_PAIRS) --bin $(PROFILE_BIN) --zone $(or $(ZONE),$(ARGS),$(SCENARIO_ZONE)) --cmds '$(or $(CMDS),$(BENCH_LIVE_CMDS))' + cd $(ROOT) && $(CARGO) run --quiet -p xtask -- perf-overhead --pairs $(PERF_OVERHEAD_PAIRS) --warmup-pairs $(PERF_OVERHEAD_WARMUP_PAIRS) --bin $(PROFILE_BIN) --zone $(or $(ZONE),$(ARGS),$(SCENARIO_ZONE)) --cmds '$(or $(CMDS),$(BENCH_LIVE_CMDS))' --var $(or $(VAR),$(PERF_OVERHEAD_VAR)) # Play the scripted match, then read player_tick events from the run's .pftrace. scenario: require-games @@ -312,8 +318,9 @@ 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 the bench: map-load breakdown + frame time by span," - @echo " printed at exit and written to iw4l-artifacts/bench/" + @echo "make bench the bench: map-load breakdown, frame time by span," + @echo " render/GPU/work counters; printed at exit, written to" + @echo " iw4l-artifacts/bench/ and the run dir as a package" @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" diff --git a/crates/asset_audio/src/sound_wma_t5.rs b/crates/asset_audio/src/sound_wma_t5.rs index aaa524d..0a7301b 100644 --- a/crates/asset_audio/src/sound_wma_t5.rs +++ b/crates/asset_audio/src/sound_wma_t5.rs @@ -1,9 +1,38 @@ +use std::collections::HashMap; use std::fmt; +use std::fs; use std::io::{ErrorKind, Read, Write}; +use std::path::{Path, PathBuf}; use std::process::{Command, Stdio}; +use std::sync::Once; +use std::sync::atomic::{AtomicU64, Ordering}; +use std::time::{Duration, Instant, SystemTime}; + +use asset_transport::{ + cache_flight, cache_get, cache_put, ensure_artifacts_dir, fnv1a64, fnv1a64_more, +}; pub const T5_WMA: i32 = 7; +/// Bumped whenever the bytes this decoder hands back for the same input +/// change. It is part of the key, so an entry written by an older decoder is +/// never read back as a current one — it is left to the cache sweep instead. +const XWMA_CACHE_FORMAT: u32 = 1; +const XWMA_CACHE_KIND: &str = "xwma_pcm"; +const XWMA_CACHE_MAGIC: &[u8; 8] = b"IWLXWMA\n"; +/// Magic, format, channels, rate, byte length — then the samples themselves. +const XWMA_CACHE_HEADER: usize = 8 + 4 * 4; + +/// How many clips one external process decodes. +/// +/// What this batching removes is process startup, not decoding: `ffmpeg` takes +/// ~40 ms to come up and ~2 ms to decode an average clip of these zones, so the +/// number only has to be large enough to amortise the first against the second. +/// It is bounded because a batch is one command line — 64 clips is ~8 KiB of +/// arguments, well inside the 32 KiB a Windows command line allows — and +/// because a batch that fails costs at most this many lone retries. +const XWMA_BATCH: usize = 64; + const WMAUDIO2: u16 = 353; const STEREO_BLOCK_ALIGN: u16 = 4096; const MONO_BLOCK_ALIGN: u16 = 2230; @@ -16,16 +45,25 @@ pub enum XwmaDecodeError { Spawn(String), Pipe(&'static str), Wait, - Process { status: Option, stderr: String }, + Process { + status: Option, + stderr: String, + }, EmptyPcm, + /// The batch had nowhere on disk to hand its clips over. + Scratch(String), } impl XwmaDecodeError { - pub fn is_transient(&self) -> bool { - matches!( - self, - Self::FfmpegMissing | Self::Spawn(_) | Self::Pipe(_) | Self::Wait - ) + /// Whether the batch this ended is worth asking again one clip at a time. + /// + /// Only a process that *ran* and refused says anything about the clips: it + /// opened one input it could not read and took the other sixty-three down + /// with it, and they deserve to be asked on their own. An `ffmpeg` that is + /// missing, unspawnable, or has nowhere to write is a fact about the + /// machine, and retrying it per clip only multiplies the same failure. + fn worth_retrying_alone(&self) -> bool { + matches!(self, Self::Process { .. } | Self::Pipe(_) | Self::Wait) } } @@ -45,6 +83,7 @@ impl fmt::Display for XwmaDecodeError { Ok(()) } Self::EmptyPcm => f.write_str("ffmpeg empty pcm"), + Self::Scratch(e) => write!(f, "xwma scratch: {e}"), } } } @@ -110,13 +149,416 @@ fn clip_stderr(bytes: &[u8]) -> String { String::from_utf8_lossy(slice).into_owned() } +/// One clip a batch was asked about: the zone's own bytes, and the two +/// numbers the samples have to come back at. +#[derive(Clone, Copy, Debug)] +pub struct XwmaClip<'a> { + pub packets: &'a [u8], + pub seek_table: &'a [u32], + pub channels: u32, + pub rate: u32, +} + +/// Decode one T5 XWMA clip to interleaved signed 16-bit LE samples, through +/// the artifact cache. +/// +/// A batch of one, which is what a clip asked for on its own is: no temporary +/// files, one `ffmpeg` over a pipe, exactly as before batching existed. The +/// clips a match prepares come through [`decode_t5_xwma_batch`] instead. pub fn decode_t5_xwma( packets: &[u8], seek_table: &[u32], channels: u32, rate: u32, ) -> Result, XwmaDecodeError> { - let xwma = mux_t5_xwma(packets, seek_table, channels, rate).ok_or(XwmaDecodeError::Mux)?; + let clip = XwmaClip { + packets, + seek_table, + channels, + rate, + }; + let mut results = decode_t5_xwma_batch(std::slice::from_ref(&clip)); + debug_assert_eq!(results.len(), 1, "one clip in, one result out"); + results.pop().unwrap_or(Err(XwmaDecodeError::EmptyPcm)) +} + +/// Decode a set of T5 XWMA clips, and answer each of them in the order asked. +/// +/// The clips the cache already holds cost a read. The rest are decoded by an +/// external `ffmpeg` — but by *one* process for up to [`XWMA_BATCH`] of them +/// rather than one process each, because starting `ffmpeg` costs twenty times +/// what decoding one of these clips costs. Only a decode that produced samples +/// is stored: a failure is counted and left uncached, because `ffmpeg` missing +/// from the PATH is a fact about this machine this minute and not about the +/// clip. +pub fn decode_t5_xwma_batch(clips: &[XwmaClip<'_>]) -> Vec, XwmaDecodeError>> { + let key_at = Instant::now(); + let keys: Vec = clips + .iter() + .map(|clip| cache_key(clip.packets, clip.seek_table, clip.channels, clip.rate)) + .collect(); + KEY_NS.fetch_add(key_at.elapsed().as_nanos() as u64, Ordering::Relaxed); + + let mut out: Vec, XwmaDecodeError>>> = vec![None; clips.len()]; + let mut pending = Vec::new(); + for (i, clip) in clips.iter().enumerate() { + match cached(&keys[i], clip.channels, clip.rate) { + Some(pcm) => out[i] = Some(Ok(pcm)), + None => pending.push(i), + } + } + + // One decode per key. The clip walk reaches the same payload from more than + // one alias and more than one namespace, and two `ffmpeg` runs for one clip + // is exactly the cost this cache exists to remove — so the second asker + // waits for the first and then reads what it wrote. Two batches can overlap + // on several keys, so they are taken in key order: whoever is first on the + // lowest key is first on all of them, and neither ends up holding what the + // other is waiting for. + pending.sort_unstable_by(|a, b| keys[*a].cmp(&keys[*b])); + let mut flights = Vec::new(); + let mut leaders = Vec::new(); + let mut followers = Vec::new(); + let mut leader_of: HashMap<&str, usize> = HashMap::new(); + for &i in &pending { + match leader_of.get(keys[i].as_str()) { + // The same payload twice inside one batch. It is one decode, and + // the second clip reads the answer rather than waiting on a flight + // this thread is itself holding. + Some(&leader) => followers.push((i, leader)), + None => { + leader_of.insert(keys[i].as_str(), i); + flights.push(cache_flight(XWMA_CACHE_KIND, &keys[i])); + leaders.push(i); + } + } + } + + let mut muxed: Vec<(usize, Vec)> = Vec::new(); + for &i in &leaders { + // Asked again now the flight is ours: whoever held it before may have + // been decoding this very clip. + if let Some(pcm) = cached(&keys[i], clips[i].channels, clips[i].rate) { + out[i] = Some(Ok(pcm)); + continue; + } + match mux_t5_xwma( + clips[i].packets, + clips[i].seek_table, + clips[i].channels, + clips[i].rate, + ) { + Some(xwma) => muxed.push((i, xwma)), + None => out[i] = Some(Err(XwmaDecodeError::Mux)), + } + } + + let decode_at = Instant::now(); + for chunk in muxed.chunks(XWMA_BATCH) { + for (i, decoded) in decode_chunk(chunk, clips) { + if let Ok(pcm) = &decoded { + MISS.fetch_add(1, Ordering::Relaxed); + PCM_BYTES.fetch_add(pcm.len() as u64, Ordering::Relaxed); + store(&keys[i], clips[i].channels, clips[i].rate, pcm); + } + out[i] = Some(decoded); + } + } + DECODE_NS.fetch_add(decode_at.elapsed().as_nanos() as u64, Ordering::Relaxed); + + for (i, leader) in followers { + let answer = match &out[leader] { + Some(Ok(pcm)) => { + HIT.fetch_add(1, Ordering::Relaxed); + PCM_BYTES.fetch_add(pcm.len() as u64, Ordering::Relaxed); + Ok(pcm.clone()) + } + Some(Err(error)) => Err(error.clone()), + None => Err(XwmaDecodeError::EmptyPcm), + }; + out[i] = Some(answer); + } + + out.into_iter() + .map(|answer| { + let answer = answer.unwrap_or(Err(XwmaDecodeError::EmptyPcm)); + if answer.is_err() { + FAILED.fetch_add(1, Ordering::Relaxed); + } + answer + }) + .collect() +} + +/// Decode one process' worth of clips, and ask again one at a time if that +/// process failed. +/// +/// `ffmpeg` opens every input before it decodes any of them, so one clip it +/// refuses ends the batch before a single sample is written and takes its +/// sixty-three neighbours with it. They are not guilty of anything, so they are +/// asked again on their own — which is the old cost for a batch that was going +/// to fail anyway, and leaves the one bad clip as the only failure. +fn decode_chunk( + chunk: &[(usize, Vec)], + clips: &[XwmaClip<'_>], +) -> Vec<(usize, Result, XwmaDecodeError>)> { + let alone = + |(i, xwma): &(usize, Vec)| (*i, run_ffmpeg(xwma, clips[*i].channels, clips[*i].rate)); + if chunk.len() == 1 { + return chunk.iter().map(alone).collect(); + } + match run_ffmpeg_batch(chunk, clips) { + Ok(decoded) => chunk.iter().map(|(i, _)| *i).zip(decoded).collect(), + Err(error) if error.worth_retrying_alone() => { + RETRIED.fetch_add(chunk.len() as u64, Ordering::Relaxed); + diag::warn!( + Audio, + "xwma batch of {} refused ({error}) — asking again one clip at a time", + chunk.len() + ); + chunk.iter().map(alone).collect() + } + Err(error) => chunk + .iter() + .map(|(i, _)| (*i, Err(error.clone()))) + .collect(), + } +} + +/// The clip as the cache holds it: what was asked for, then what came back, so +/// an entry cannot be read as an answer to a different question. +fn cache_encode(channels: u32, rate: u32, pcm: &[u8]) -> Vec { + let mut out = Vec::with_capacity(XWMA_CACHE_HEADER + pcm.len()); + out.extend_from_slice(XWMA_CACHE_MAGIC); + out.extend_from_slice(&XWMA_CACHE_FORMAT.to_le_bytes()); + out.extend_from_slice(&channels.to_le_bytes()); + out.extend_from_slice(&rate.to_le_bytes()); + out.extend_from_slice(&(pcm.len() as u32).to_le_bytes()); + out.extend_from_slice(pcm); + out +} + +/// `None` for anything that is not this decoder answering this question: a +/// short read, another format, another clip's channels or rate, a truncated +/// tail. The caller decodes again and overwrites, which is the cheap outcome +/// — handing back samples at the wrong rate is not. +fn cache_decode(bytes: &[u8], channels: u32, rate: u32) -> Option> { + if bytes.len() < XWMA_CACHE_HEADER || &bytes[..8] != XWMA_CACHE_MAGIC { + return None; + } + let word = |at: usize| -> Option { + Some(u32::from_le_bytes(bytes.get(at..at + 4)?.try_into().ok()?)) + }; + if word(8)? != XWMA_CACHE_FORMAT || word(12)? != channels || word(16)? != rate { + return None; + } + let len = word(20)? as usize; + let pcm = bytes.get(XWMA_CACHE_HEADER..XWMA_CACHE_HEADER + len)?; + (!pcm.is_empty()).then(|| pcm.to_vec()) +} + +fn cached(key: &str, channels: u32, rate: u32) -> Option> { + let io_at = Instant::now(); + let bytes = cache_get(XWMA_CACHE_KIND, key); + IO_NS.fetch_add(io_at.elapsed().as_nanos() as u64, Ordering::Relaxed); + let pcm = cache_decode(&bytes?, channels, rate)?; + HIT.fetch_add(1, Ordering::Relaxed); + PCM_BYTES.fetch_add(pcm.len() as u64, Ordering::Relaxed); + Some(pcm) +} + +fn store(key: &str, channels: u32, rate: u32, pcm: &[u8]) { + let io_at = Instant::now(); + if let Err(error) = cache_put(XWMA_CACHE_KIND, key, &cache_encode(channels, rate, pcm)) { + diag::warn!(Audio, "xwma cache store {key}: {error}"); + } + IO_NS.fetch_add(io_at.elapsed().as_nanos() as u64, Ordering::Relaxed); +} + +/// The whole input, not the alias that named it: two aliases over one payload +/// are one decode, and one alias over a payload the zone changed is two. +fn cache_key(packets: &[u8], seek_table: &[u32], channels: u32, rate: u32) -> String { + let mut hash = fnv1a64(&XWMA_CACHE_FORMAT.to_le_bytes()); + hash = fnv1a64_more(hash, &T5_WMA.to_le_bytes()); + hash = fnv1a64_more(hash, &channels.to_le_bytes()); + hash = fnv1a64_more(hash, &rate.to_le_bytes()); + hash = fnv1a64_more(hash, &(seek_table.len() as u64).to_le_bytes()); + for entry in seek_table { + hash = fnv1a64_more(hash, &entry.to_le_bytes()); + } + hash = fnv1a64_more(hash, &(packets.len() as u64).to_le_bytes()); + hash = fnv1a64_more(hash, packets); + format!("{XWMA_CACHE_FORMAT:08x}-{hash:016x}") +} + +static HIT: AtomicU64 = AtomicU64::new(0); +static MISS: AtomicU64 = AtomicU64::new(0); +static SPAWNED: AtomicU64 = AtomicU64::new(0); +static FAILED: AtomicU64 = AtomicU64::new(0); +static RETRIED: AtomicU64 = AtomicU64::new(0); +static PCM_BYTES: AtomicU64 = AtomicU64::new(0); +static DECODE_NS: AtomicU64 = AtomicU64::new(0); +static KEY_NS: AtomicU64 = AtomicU64::new(0); +static IO_NS: AtomicU64 = AtomicU64::new(0); + +/// What the XWMA path cost this process: how much of it the cache answered, +/// how much of it an external process answered, and what each side charged. +/// +/// The three durations are summed over whichever threads did the work — the +/// clip prep workers run several at a time — so they are worker time and not +/// a stretch of the load. Only their ratio to each other is safe to read. +#[derive(Clone, Copy, Debug, Default, PartialEq)] +pub struct XwmaDecodeCost { + /// Clips answered from the artifact cache, launching nothing. + pub hit: u64, + /// Clips decoded externally and then stored. + pub miss: u64, + /// External `ffmpeg` processes launched. + pub spawned: u64, + /// Decodes that produced no samples. Nothing is cached for these. + pub failed: u64, + /// Clips a refused batch sent back through a process of their own. + pub retried: u64, + /// Bytes of signed 16-bit samples handed back, cached or decoded. + pub pcm_bytes: u64, + /// Worker time inside the external decoder, handing it the clips and + /// reading its samples back included. + pub decode_ms: f64, + /// Worker time hashing payloads into cache keys. + pub key_ms: f64, + /// Worker time reading and writing the cache. + pub io_ms: f64, +} + +pub fn xwma_decode_cost() -> XwmaDecodeCost { + XwmaDecodeCost { + hit: HIT.load(Ordering::Relaxed), + miss: MISS.load(Ordering::Relaxed), + spawned: SPAWNED.load(Ordering::Relaxed), + failed: FAILED.load(Ordering::Relaxed), + retried: RETRIED.load(Ordering::Relaxed), + pcm_bytes: PCM_BYTES.load(Ordering::Relaxed), + decode_ms: DECODE_NS.load(Ordering::Relaxed) as f64 / 1.0e6, + key_ms: KEY_NS.load(Ordering::Relaxed) as f64 / 1.0e6, + io_ms: IO_NS.load(Ordering::Relaxed) as f64 / 1.0e6, + } +} + +/// A directory for one batch's files, under the artifacts root the decoded +/// samples end up in. +/// +/// Several inputs and several outputs in one command line is what makes one +/// process do the work of sixty-four, and `ffmpeg` takes each of them as a +/// path — so the clips are handed over on disk and taken back the same way. +/// The directory is removed as soon as the samples have been read. +fn scratch_dir() -> Result { + static NEXT: AtomicU64 = AtomicU64::new(0); + let root = ensure_artifacts_dir() + .map_err(XwmaDecodeError::Scratch)? + .join("scratch") + .join("xwma"); + let dir = root.join(format!( + "{}-{}", + std::process::id(), + NEXT.fetch_add(1, Ordering::Relaxed) + )); + fs::create_dir_all(&dir) + .map_err(|error| XwmaDecodeError::Scratch(format!("{}: {error}", dir.display())))?; + sweep_stale_scratch(&root); + Ok(dir) +} + +/// A batch that died with its process leaves its files behind, and nothing +/// else ever looks in here. Anything older than an hour belonged to a run that +/// is gone — the same age the artifact cache gives its own temporaries. +fn sweep_stale_scratch(root: &Path) { + static SWEPT: Once = Once::new(); + SWEPT.call_once(|| { + let stale = SystemTime::now() - Duration::from_secs(3600); + let Ok(listing) = fs::read_dir(root) else { + return; + }; + for entry in listing.filter_map(Result::ok) { + let Ok(meta) = entry.metadata() else { continue }; + if meta.is_dir() && meta.modified().is_ok_and(|at| at < stale) { + let _ = fs::remove_dir_all(entry.path()); + } + } + }); +} + +/// One `ffmpeg` over many clips: every clip is its own input with its own +/// demuxer and its own output file, so nothing is concatenated and no clip's +/// samples can run into the next one's. The order out is the order in. +/// +/// The outer error is the batch's: the process never ran, or ran and refused, +/// and nothing here says which clip it was about. The inner ones are a single +/// clip's — its output file is missing or empty while the rest are fine. +fn run_ffmpeg_batch( + chunk: &[(usize, Vec)], + clips: &[XwmaClip<'_>], +) -> Result, XwmaDecodeError>>, XwmaDecodeError> { + let dir = scratch_dir()?; + let decoded = decode_in(&dir, chunk, clips); + let _ = fs::remove_dir_all(&dir); + decoded +} + +fn decode_in( + dir: &Path, + chunk: &[(usize, Vec)], + clips: &[XwmaClip<'_>], +) -> Result, XwmaDecodeError>>, XwmaDecodeError> { + let mut command = Command::new("ffmpeg"); + command.args(["-nostdin", "-hide_banner", "-loglevel", "error"]); + let mut outputs = Vec::with_capacity(chunk.len()); + for (slot, (i, xwma)) in chunk.iter().enumerate() { + let input = dir.join(format!("{slot}.xwma")); + fs::write(&input, xwma) + .map_err(|error| XwmaDecodeError::Scratch(format!("{}: {error}", input.display())))?; + command.args(["-f", "xwma", "-i"]).arg(&input); + outputs.push((dir.join(format!("{slot}.pcm")), clips[*i])); + } + for (slot, (output, clip)) in outputs.iter().enumerate() { + command + .args(["-map", &format!("{slot}:a"), "-f", "s16le"]) + .args(["-ac", &clip.channels.max(1).to_string()]) + .args(["-ar", &clip.rate.max(1).to_string()]) + .arg("-y") + .arg(output); + } + let finished = match command + .stdin(Stdio::null()) + .stdout(Stdio::null()) + .stderr(Stdio::piped()) + .output() + { + Ok(finished) => { + SPAWNED.fetch_add(1, Ordering::Relaxed); + finished + } + Err(e) if e.kind() == ErrorKind::NotFound => return Err(XwmaDecodeError::FfmpegMissing), + Err(e) => return Err(XwmaDecodeError::Spawn(e.to_string())), + }; + if !finished.status.success() { + return Err(XwmaDecodeError::Process { + status: finished.status.code(), + stderr: clip_stderr(&finished.stderr), + }); + } + Ok(outputs + .iter() + .map(|(output, _)| match fs::read(output) { + Ok(pcm) if !pcm.is_empty() => Ok(pcm), + _ => Err(XwmaDecodeError::EmptyPcm), + }) + .collect()) +} + +/// One `ffmpeg` over one clip, handed over a pipe rather than a file. This is +/// what a clip asked for on its own costs, and what every clip cost before +/// batching: the process is the expensive part of it. +fn run_ffmpeg(xwma: &[u8], channels: u32, rate: u32) -> Result, XwmaDecodeError> { let ch = channels.max(1).to_string(); let ar = rate.max(1).to_string(); let mut child = match Command::new("ffmpeg") @@ -142,7 +584,10 @@ pub fn decode_t5_xwma( .stderr(Stdio::piped()) .spawn() { - Ok(child) => child, + Ok(child) => { + SPAWNED.fetch_add(1, Ordering::Relaxed); + child + } Err(e) if e.kind() == ErrorKind::NotFound => { return Err(XwmaDecodeError::FfmpegMissing); } @@ -152,7 +597,8 @@ pub fn decode_t5_xwma( let mut stdout = child.stdout.take().ok_or(XwmaDecodeError::Pipe("stdout"))?; let mut stderr = child.stderr.take().ok_or(XwmaDecodeError::Pipe("stderr"))?; - let write = std::thread::spawn(move || stdin.write_all(&xwma)); + let payload = xwma.to_vec(); + let write = std::thread::spawn(move || stdin.write_all(&payload)); let mut pcm = Vec::new(); stdout .read_to_end(&mut pcm) @@ -175,3 +621,110 @@ pub fn decode_t5_xwma( } Ok(pcm) } + +#[cfg(test)] +mod tests { + use super::*; + + /// A cache entry is an answer, and the question is stored with it. The key + /// is a hash, the sweep is free to drop files, and a decoder can change its + /// output — so an entry that does not match the clip being asked about has + /// to read as a miss. Handing back samples at the wrong rate is silent, and + /// decoding again is only slow. + #[test] + fn a_cache_entry_answers_only_the_clip_it_was_written_for() { + let pcm = [1u8, 0, 0xff, 0x7f]; + let blob = cache_encode(2, 48000, &pcm); + assert_eq!(cache_decode(&blob, 2, 48000).as_deref(), Some(&pcm[..])); + + assert_eq!(cache_decode(&blob, 1, 48000), None, "other channel count"); + assert_eq!(cache_decode(&blob, 2, 44100), None, "other sample rate"); + assert_eq!( + cache_decode(&blob[..blob.len() - 1], 2, 48000), + None, + "the samples the header promised are not all there" + ); + assert_eq!(cache_decode(&blob[..4], 2, 48000), None, "no header at all"); + assert_eq!( + cache_decode(&cache_encode(2, 48000, &[]), 2, 48000), + None, + "an empty decode is a failure, and is never stored as one" + ); + + let mut older = blob.clone(); + older[8] = older[8].wrapping_add(1); + assert_eq!(cache_decode(&older, 2, 48000), None, "another format"); + let mut alien = blob.clone(); + alien[0] = b'X'; + assert_eq!(cache_decode(&alien, 2, 48000), None, "another writer"); + } + + /// A batch is a list of questions and a list of answers, and the only + /// thing tying them together is position. A clip that the cache answered, + /// a clip that never reached the decoder, and the same clip asked for + /// twice all have to leave their neighbours where they were: an answer + /// that slid one place is another clip's samples at this clip's rate, and + /// nothing downstream can tell. + #[test] + fn a_batch_answers_every_clip_in_the_order_it_was_asked() { + let seek = [1u32, 2]; + let stored = |packets: &[u8], pcm: &[u8]| { + let key = cache_key(packets, &seek, 2, 48000); + cache_put(XWMA_CACHE_KIND, &key, &cache_encode(2, 48000, pcm)) + .expect("the test's own cache entry"); + }; + let known = |packets: &'static [u8]| XwmaClip { + packets, + seek_table: &seek, + channels: 2, + rate: 48000, + }; + stored(b"first", &[1, 0, 2, 0]); + stored(b"third", &[3, 0, 4, 0]); + + // Short of `seek_table.len() * block_align` bytes: this one never + // reaches `ffmpeg`, and asking for it twice must not leave the second + // asker waiting on a flight this thread is holding itself. + let unmuxable = known(b"too short to be two stereo blocks"); + let answers = decode_t5_xwma_batch(&[ + known(b"first"), + unmuxable, + known(b"third"), + unmuxable, + known(b"first"), + ]); + + assert_eq!( + answers, + vec![ + Ok(vec![1, 0, 2, 0]), + Err(XwmaDecodeError::Mux), + Ok(vec![3, 0, 4, 0]), + Err(XwmaDecodeError::Mux), + Ok(vec![1, 0, 2, 0]), + ] + ); + } + + /// The key covers every input the decode reads, and nothing else. Two + /// aliases over one payload have to land on one entry — that is the saving + /// — and a payload the zone changed has to land on a different one. + #[test] + fn the_key_covers_every_input_the_decode_reads() { + let packets = [7u8; 16]; + let seek = [1u32, 2]; + let key = cache_key(&packets, &seek, 2, 48000); + + assert_eq!(key, cache_key(&packets, &seek, 2, 48000)); + assert_ne!(key, cache_key(&[7u8; 17], &seek, 2, 48000), "payload bytes"); + assert_ne!(key, cache_key(&[9u8; 16], &seek, 2, 48000), "payload bytes"); + assert_ne!(key, cache_key(&packets, &[1, 3], 2, 48000), "seek table"); + assert_ne!( + key, + cache_key(&packets, &[1], 2, 48000), + "seek table length" + ); + assert_ne!(key, cache_key(&packets, &seek, 1, 48000), "channels"); + assert_ne!(key, cache_key(&packets, &seek, 2, 44100), "rate"); + } +} diff --git a/crates/assets/src/lib.rs b/crates/assets/src/lib.rs index 3ca1459..8c30618 100644 --- a/crates/assets/src/lib.rs +++ b/crates/assets/src/lib.rs @@ -415,7 +415,9 @@ pub use sound_catalog::{ pub use sound_load::{LoadedSoundBank, load_mp_sound_bank, load_sound_catalog, namespace_for_zone}; pub use sound_load_iw5::load_sound_catalog_iw5; pub use sound_load_t5::load_sound_catalog_t5; -pub use sound_wma_t5::{T5_WMA, decode_t5_xwma}; +pub use sound_wma_t5::{ + T5_WMA, XwmaClip, XwmaDecodeCost, decode_t5_xwma, decode_t5_xwma_batch, xwma_decode_cost, +}; pub use t5_code_remap::{ IW4_CUSTOM_SAMPLER_DEST, LEFTOVER_T5_CODE_BASE, T5_CODE_CUSTOMWIND_CENTER, T5_CODE_CUSTOMWIND_SPRING, T5_CODE_EXTRA_CAM_PARAM, T5_CODE_EYEOFFSET, T5_CODE_FOG, diff --git a/crates/audio/src/clip_store.rs b/crates/audio/src/clip_store.rs index 44cbd4d..8054c49 100644 --- a/crates/audio/src/clip_store.rs +++ b/crates/audio/src/clip_store.rs @@ -1,4 +1,5 @@ use std::collections::{HashMap, HashSet}; +use std::sync::atomic::{AtomicU64, Ordering}; use std::sync::mpsc::{Sender, channel}; use std::sync::{Arc, Mutex}; use std::time::Instant; @@ -19,6 +20,56 @@ pub(crate) enum ClipKey { }, } +/// A queued clip and the instant it was queued, so a worker can say how long +/// the job sat before anyone picked it up. The wait is the queue's, not the +/// clip's: it is what the store owed and could not pay yet. +struct ClipJob { + key: ClipKey, + queued_at: Instant, +} + +/// Which decoder a clip went through. Every clip takes exactly one of these, +/// and they cost wildly different things — an external process per XWMA clip, +/// a loop over bytes for everything else — so the report separates them rather +/// than averaging one number over all of them. +#[derive(Clone, Copy, Debug, PartialEq, Eq)] +pub enum ClipPath { + /// Linear PCM straight out of the zone, converted to float and nothing else. + Pcm, + /// T5 ADPCM, decoded in process. + Adpcm, + /// T5 XWMA, decoded by an external `ffmpeg` or read from the artifact cache. + Xwma, + /// A clip read out of an IWD rather than out of the zone. + Streamed, + /// No decoder claims the key: the bank holds nothing at that index, or it + /// holds a clip in a format none of the four above reads. Counted here so + /// it cannot hide inside another path's failures. + Unresolved, +} + +impl ClipPath { + pub const COUNT: usize = Self::Unresolved as usize + 1; + + pub const ALL: [Self; Self::COUNT] = [ + Self::Pcm, + Self::Adpcm, + Self::Xwma, + Self::Streamed, + Self::Unresolved, + ]; + + pub const fn name(self) -> &'static str { + match self { + Self::Pcm => "pcm", + Self::Adpcm => "t5 adpcm", + Self::Xwma => "t5 xwma", + Self::Streamed => "streamed", + Self::Unresolved => "unresolved", + } + } +} + #[derive(Clone, Debug)] pub(crate) enum ClipError { Decode, @@ -39,10 +90,16 @@ impl PreparedPcm { } } +/// How many queued jobs a worker takes at once. It bounds how long the store +/// can hold a clip's outcome back — every job in a batch is published when the +/// last of them is prepared — and it is the XWMA decoder's batch, which is the +/// only decoder here that gains anything from the grouping. +pub const PREP_BATCH: usize = 64; + #[derive(Resource)] pub struct ClipStore { bank: Arc, - tx: Sender, + tx: Sender, queued: HashSet, outcomes: Arc>>>, workers: usize, @@ -56,7 +113,7 @@ impl ClipStore { let workers = std::thread::available_parallelism() .map(|n| n.get().saturating_sub(2).clamp(1, 4)) .unwrap_or(1); - let (tx, rx) = channel::(); + let (tx, rx) = channel::(); let rx = Arc::new(Mutex::new(rx)); let outcomes = Arc::new(Mutex::new(HashMap::new())); let mut started_workers = 0; @@ -70,17 +127,37 @@ impl ClipStore { .name(format!("clip-prep-{slot}")) .spawn(move || { loop { - let job = { + // A match queues every clip it needs at once, and one + // of the decoders below is an external process whose + // startup costs more than the decode. So a worker takes + // what is already waiting rather than one job at a time: + // the queue is where the batch comes from. A clip asked + // for on its own — a late prepare, a reload — still + // arrives alone and is prepared alone. + let jobs = { let guard = rx.lock().unwrap_or_else(|poison| poison.into_inner()); - guard.recv() + let Ok(first) = guard.recv() else { + return; + }; + let mut jobs = vec![first]; + while jobs.len() < PREP_BATCH { + let Ok(next) = guard.try_recv() else { break }; + jobs.push(next); + } + jobs }; - let Ok(key) = job else { - return; - }; - let result = prepare_clip_now(&bank, iwd.as_deref(), &key); + for job in &jobs { + QUEUE_WAIT_NS.fetch_add( + job.queued_at.elapsed().as_nanos() as u64, + Ordering::Relaxed, + ); + } + let prepared = prepare_jobs(&bank, iwd.as_deref(), &jobs); let mut guard = outcomes.lock().unwrap_or_else(|poison| poison.into_inner()); - guard.insert(key, result); + for (job, result) in jobs.into_iter().zip(prepared) { + guard.insert(job.key, result); + } } }); match spawned { @@ -88,6 +165,7 @@ impl ClipStore { Err(e) => diag::warn!(Audio, "audio: clip prep worker {slot} not started ({e})"), } } + WORKERS.fetch_add(started_workers as u64, Ordering::Relaxed); Self { bank, tx, @@ -107,6 +185,10 @@ impl ClipStore { self.match_live = true; } + /// This store's count. A store lives as long as one installed sound bank, + /// so a map change starts a new one — which is the scope the console asks + /// about. The process total is in [`clip_prep_cost`], for the exit hook + /// that has no store to ask. pub fn late_prepares(&self) -> u32 { self.late_prepares } @@ -116,6 +198,7 @@ impl ClipStore { return; } self.late_prepares = self.late_prepares.saturating_add(1); + LATE.fetch_add(1, Ordering::Relaxed); diag::warn!(Audio, "audio: clip prepare after AudioReady ({key:?})"); } @@ -130,6 +213,7 @@ impl ClipStore { } pub(crate) fn request(&mut self, key: ClipKey) -> bool { + REQUESTS.fetch_add(1, Ordering::Relaxed); if self.ready(&key).is_some() { return false; } @@ -137,7 +221,12 @@ impl ClipStore { return false; } self.note_late(&key); - if self.tx.send(key.clone()).is_err() { + QUEUED.fetch_add(1, Ordering::Relaxed); + let job = ClipJob { + key: key.clone(), + queued_at: Instant::now(), + }; + if self.tx.send(job).is_err() { self.outcomes .lock() .unwrap_or_else(|poison| poison.into_inner()) @@ -285,19 +374,194 @@ pub(crate) fn clip_key_for_variant( .map(|(sns, dir, name)| ClipKey::Streamed { ns: sns, dir, name }) } +static WORKERS: AtomicU64 = AtomicU64::new(0); +static REQUESTS: AtomicU64 = AtomicU64::new(0); +static QUEUED: AtomicU64 = AtomicU64::new(0); +static QUEUE_WAIT_NS: AtomicU64 = AtomicU64::new(0); +static LATE: AtomicU64 = AtomicU64::new(0); +static PREPARED: [AtomicU64; ClipPath::COUNT] = [const { AtomicU64::new(0) }; ClipPath::COUNT]; +static FAILED: [AtomicU64; ClipPath::COUNT] = [const { AtomicU64::new(0) }; ClipPath::COUNT]; +static WALL_NS: [AtomicU64; ClipPath::COUNT] = [const { AtomicU64::new(0) }; ClipPath::COUNT]; +static SAMPLE_BYTES: [AtomicU64; ClipPath::COUNT] = [const { AtomicU64::new(0) }; ClipPath::COUNT]; + +/// One decoder's share of the clip preparation. +#[derive(Clone, Copy, Debug, Default, PartialEq)] +pub struct ClipPathCost { + pub prepared: u64, + pub failed: u64, + /// Worker time inside this decoder, summed over the prep threads. + pub wall_ms: f64, + /// Resident `f32` samples this decoder produced. The store keeps them for + /// the life of the match, so this is memory and not throughput. + pub sample_bytes: u64, +} + +/// What preparing the match's clips cost this process. +/// +/// `requests` counts asks and `queued` counts jobs: the walk reaches one clip +/// from several aliases and several weapons, and the difference between the +/// two is what the store's own dedupe already saves. Every duration is summed +/// over the prep workers, which run several at a time, so none of them is a +/// stretch of the load. +#[derive(Clone, Debug, Default, PartialEq)] +pub struct ClipPrepCost { + /// Prep threads that actually started, across every store this process + /// opened. A match teardown closes one store and a reload opens another. + pub workers: u64, + pub requests: u64, + pub queued: u64, + pub queue_wait_ms: f64, + pub late: u64, + pub paths: Vec<(ClipPath, ClipPathCost)>, +} + +pub fn clip_prep_cost() -> ClipPrepCost { + ClipPrepCost { + workers: WORKERS.load(Ordering::Relaxed), + requests: REQUESTS.load(Ordering::Relaxed), + queued: QUEUED.load(Ordering::Relaxed), + queue_wait_ms: QUEUE_WAIT_NS.load(Ordering::Relaxed) as f64 / 1.0e6, + late: LATE.load(Ordering::Relaxed), + paths: ClipPath::ALL + .into_iter() + .map(|path| { + let slot = path as usize; + ( + path, + ClipPathCost { + prepared: PREPARED[slot].load(Ordering::Relaxed), + failed: FAILED[slot].load(Ordering::Relaxed), + wall_ms: WALL_NS[slot].load(Ordering::Relaxed) as f64 / 1.0e6, + sample_bytes: SAMPLE_BYTES[slot].load(Ordering::Relaxed), + }, + ) + }) + .collect(), + } +} + +fn note_prepared(path: ClipPath, prepare_at: Instant, result: Result<&PreparedPcm, &ClipError>) { + note_wall(path, prepare_at.elapsed()); + note_outcome(path, result); +} + +/// Worker time this decoder spent, whether it spent it on one clip or on the +/// sixty-four it was handed together. A batched decoder has no per-clip time to +/// report — what it has is a total and a count, and the report divides them. +fn note_wall(path: ClipPath, wall: std::time::Duration) { + WALL_NS[path as usize].fetch_add(wall.as_nanos() as u64, Ordering::Relaxed); +} + +fn note_outcome(path: ClipPath, result: Result<&PreparedPcm, &ClipError>) { + let slot = path as usize; + match result { + Ok(prepared) => { + PREPARED[slot].fetch_add(1, Ordering::Relaxed); + SAMPLE_BYTES[slot].fetch_add( + (prepared.samples.len() * size_of::()) as u64, + Ordering::Relaxed, + ); + } + Err(_) => { + FAILED[slot].fetch_add(1, Ordering::Relaxed); + } + } +} + +/// One worker's drained jobs, prepared together. +/// +/// The XWMA clips among them go to their decoder in one call, because that +/// decoder leaves the process: one `ffmpeg` for the batch instead of one per +/// clip. Every other path is a loop over bytes in this process and is prepared +/// one clip at a time, exactly as before. +fn prepare_jobs( + bank: &SoundCatalog, + iwd: Option<&NamespaceSoundIwd>, + jobs: &[ClipJob], +) -> Vec> { + let mut out: Vec>> = vec![None; jobs.len()]; + + let asked: Vec<(usize, &assets::LoadedSoundPcm)> = jobs + .iter() + .enumerate() + .filter_map(|(i, job)| match job.key { + ClipKey::Loaded(index) => { + let sound = bank.pcm_at(index)?; + (loaded_path(sound) == Some(ClipPath::Xwma)).then_some((i, sound)) + } + ClipKey::Streamed { .. } => None, + }) + .collect(); + if !asked.is_empty() { + let clips: Vec> = asked + .iter() + .map(|(_, sound)| assets::XwmaClip { + packets: sound.encoded_bytes(), + seek_table: &sound.seek_table, + channels: sound.channels().max(0) as u32, + rate: sound.rate, + }) + .collect(); + let decode_at = Instant::now(); + let decoded = assets::decode_t5_xwma_batch(&clips); + note_wall(ClipPath::Xwma, decode_at.elapsed()); + for ((i, sound), pcm) in asked.into_iter().zip(decoded) { + let result = pcm + .map_err(|_| ClipError::Decode) + .and_then(|bytes| pcm_from_bytes(16, &bytes, sound.channels(), sound.rate)); + note_outcome(ClipPath::Xwma, result.as_ref()); + out[i] = Some(result); + } + } + + for (i, job) in jobs.iter().enumerate() { + if out[i].is_some() { + continue; + } + let prepare_at = Instant::now(); + let (path, result) = prepare_clip_now(bank, iwd, &job.key); + note_prepared(path, prepare_at, result.as_ref()); + out[i] = Some(result); + } + out.into_iter() + .map(|result| result.unwrap_or(Err(ClipError::Decode))) + .collect() +} + fn prepare_clip_now( bank: &SoundCatalog, iwd: Option<&NamespaceSoundIwd>, key: &ClipKey, -) -> Result { +) -> (ClipPath, Result) { match key { ClipKey::Loaded(index) => { - let sound = bank.pcm_at(*index).ok_or(ClipError::Decode)?; - prepare_loaded(sound) - } - ClipKey::Streamed { ns, dir, name } => { - prepare_streamed(iwd, *ns, dir, name)?.ok_or(ClipError::Decode) + let Some(sound) = bank.pcm_at(*index) else { + return (ClipPath::Unresolved, Err(ClipError::Decode)); + }; + let Some(path) = loaded_path(sound) else { + return (ClipPath::Unresolved, Err(ClipError::Decode)); + }; + (path, prepare_loaded(sound)) } + ClipKey::Streamed { ns, dir, name } => ( + ClipPath::Streamed, + prepare_streamed(iwd, *ns, dir, name).and_then(|pcm| pcm.ok_or(ClipError::Decode)), + ), + } +} + +/// Which decoder `prepare_loaded` will reach for, decided the same way it +/// decides — the two read the same fields in the same order, so a clip cannot +/// be counted under one path and decoded by another. +fn loaded_path(sound: &assets::LoadedSoundPcm) -> Option { + if sound.t5_adpcm_bytes().is_some() { + Some(ClipPath::Adpcm) + } else if sound.is_t5_xwma() { + Some(ClipPath::Xwma) + } else if sound.format() == assets::MSS_PCM { + Some(ClipPath::Pcm) + } else { + None } } @@ -332,6 +596,18 @@ fn prepare_loaded(sound: &assets::LoadedSoundPcm) -> Result Result { let mut samples: Vec = match bits { 8 => bytes.iter().map(|&b| (b as f32 - 128.0) / 128.0).collect(), 16 => bytes @@ -340,17 +616,16 @@ fn prepare_loaded(sound: &assets::LoadedSoundPcm) -> Result return Err(ClipError::Decode), }; - let channels = sound.channels().max(1) as usize; - samples.truncate(samples.len() / channels * channels); + let lanes = channels.max(1) as usize; + samples.truncate(samples.len() / lanes * lanes); if samples.is_empty() { return Err(ClipError::Decode); } - let samples = samples.into(); - let channels = u16::try_from(sound.channels().max(1)).map_err(|_| ClipError::Decode)?; + let channels = u16::try_from(channels.max(1)).map_err(|_| ClipError::Decode)?; Ok(PreparedPcm { - samples, + samples: samples.into(), channels, - sample_rate: sound.rate.max(1), + sample_rate: rate.max(1), }) } diff --git a/crates/audio/src/lib.rs b/crates/audio/src/lib.rs index f51fee5..19a7e73 100644 --- a/crates/audio/src/lib.rs +++ b/crates/audio/src/lib.rs @@ -25,7 +25,7 @@ pub use ambient::{ MAX_ACTIVE_MAP_EMITTERS, MIN_AUDIBLE_EMITTER_GAIN, MapAmbient, MapAmbientBooted, MapEmitter, SoundIwd, stop_map_ambient, update_map_emitter_gain, }; -pub use clip_store::ClipStore; +pub use clip_store::{ClipPath, ClipPathCost, ClipPrepCost, ClipStore, PREP_BATCH, clip_prep_cost}; pub use emit::{BobCycleTracker, emit_footstep_on_bob_wrap, emit_weapon_fire}; pub use match_set::AudioReady; pub use messages::{ diff --git a/crates/bootstrap/Cargo.toml b/crates/bootstrap/Cargo.toml index 83521c0..0f5fa22 100644 --- a/crates/bootstrap/Cargo.toml +++ b/crates/bootstrap/Cargo.toml @@ -24,6 +24,7 @@ session.workspace = true bots = { path = "../bots" } hud = { path = "../hud" } perf.workspace = true +serde_json.workspace = true [target.'cfg(target_os = "linux")'.dependencies] libc = "0.2" diff --git a/crates/bootstrap/build.rs b/crates/bootstrap/build.rs new file mode 100644 index 0000000..f4f78d0 --- /dev/null +++ b/crates/bootstrap/build.rs @@ -0,0 +1,164 @@ +//! What the bench manifest can only learn at build time. +//! +//! A run report has to be able to say which source produced the binary that +//! produced it. Asking `git` at runtime cannot: the process may be running from +//! a copied binary, from another checkout, or from a tree that has moved on +//! since it was built, and the answer would name the tree rather than the +//! build. So the revision, the dirty flag, the toolchain and the dependency +//! versions are read here, where they are facts about *this* compilation, and +//! baked in. +//! +//! Everything is optional. A build from a tarball with no `git` and no +//! `Cargo.lock` still compiles; the manifest then says the field is unknown, +//! which is true, instead of guessing. + +use std::path::{Path, PathBuf}; +use std::process::Command; + +fn main() { + let root = workspace_root(); + emit("IW4L_BUILD_GIT_SHA", git(&root, &["rev-parse", "HEAD"])); + emit( + "IW4L_BUILD_GIT_DESCRIBE", + git(&root, &["describe", "--always", "--dirty", "--tags"]), + ); + emit("IW4L_BUILD_GIT_DIRTY", git_dirty(&root)); + emit("IW4L_BUILD_RUSTC", rustc_version()); + // Two different answers, and the report needs the first one. `PROFILE` is + // only ever `debug` or `release` — a build script cannot see that this is + // `[profile.play]`, which inherits release and is the binary `make bench` + // actually runs. The target directory carries the real name. + emit("IW4L_BUILD_PROFILE", profile_dir()); + emit("IW4L_BUILD_PROFILE_KIND", std::env::var("PROFILE").ok()); + emit("IW4L_BUILD_TARGET", std::env::var("TARGET").ok()); + emit("IW4L_BUILD_OPT_LEVEL", std::env::var("OPT_LEVEL").ok()); + + let lock = root.join("Cargo.lock"); + let lock_text = std::fs::read_to_string(&lock).ok(); + emit("IW4L_BUILD_LOCK_HASH", lock_text.as_deref().map(fnv1a_hex)); + for package in ["bevy", "wgpu"] { + emit( + &format!("IW4L_BUILD_{}_VERSION", package.to_uppercase()), + lock_text + .as_deref() + .and_then(|text| locked_version(text, package)), + ); + } + + // The revision and the dirty flag are stale the moment a commit lands, and + // the lock hash the moment a dependency moves. Rebuilding on both is what + // keeps the manifest describing the binary rather than some earlier one. + println!("cargo:rerun-if-changed=build.rs"); + println!("cargo:rerun-if-changed={}", lock.display()); + for head in ["HEAD", "refs"] { + let path = root.join(".git").join(head); + if path.exists() { + println!("cargo:rerun-if-changed={}", path.display()); + } + } +} + +/// The name cargo built under — `play`, `release`, `debug`, or whatever else +/// the invocation named. `OUT_DIR` is `//build/-/ +/// out`, so the profile directory is the fourth ancestor counting `out` itself +/// as the first. `None` if the shape ever changes, which is better than +/// confidently naming the wrong profile. +fn profile_dir() -> Option { + let out = PathBuf::from(std::env::var("OUT_DIR").ok()?); + let dir = out.ancestors().nth(3)?; + let name = dir.file_name()?.to_str()?.to_owned(); + (!name.is_empty()).then_some(name) +} + +/// `OUT_DIR` is `//build/-/out`; the workspace +/// root is the manifest's parent twice over. `CARGO_MANIFEST_DIR` is this +/// crate, so `../..` from `crates/bootstrap`. +fn workspace_root() -> PathBuf { + let manifest = PathBuf::from(std::env::var("CARGO_MANIFEST_DIR").as_deref().unwrap_or("")); + manifest + .parent() + .and_then(Path::parent) + .map_or(manifest.clone(), Path::to_path_buf) +} + +fn emit(key: &str, value: Option) { + // An absent value is emitted as an empty string rather than left unset, so + // `env!` in the crate always compiles and the runtime side has exactly one + // shape of "not known" to handle. + println!("cargo:rustc-env={key}={}", value.as_deref().unwrap_or("")); +} + +fn git(root: &Path, args: &[&str]) -> Option { + let output = Command::new("git") + .current_dir(root) + .args(args) + .output() + .ok()?; + if !output.status.success() { + return None; + } + let value = String::from_utf8(output.stdout).ok()?.trim().to_owned(); + (!value.is_empty()).then_some(value) +} + +/// Whether the tracked tree had uncommitted changes at build time. `None` when +/// `git` could not answer at all, which is not the same as "clean". +fn git_dirty(root: &Path) -> Option { + let output = Command::new("git") + .current_dir(root) + .args(["status", "--porcelain", "--untracked-files=no"]) + .output() + .ok()?; + if !output.status.success() { + return None; + } + Some(if output.stdout.is_empty() { + "false".to_owned() + } else { + "true".to_owned() + }) +} + +fn rustc_version() -> Option { + let rustc = std::env::var("RUSTC").unwrap_or_else(|_| "rustc".to_owned()); + let output = Command::new(rustc).arg("--version").output().ok()?; + output + .status + .success() + .then(|| String::from_utf8(output.stdout).ok()) + .flatten() + .map(|value| value.trim().to_owned()) +} + +/// The version `Cargo.lock` pins for `package`. The lock is TOML, but this +/// build script has no TOML dependency and does not need one: the file is a +/// flat list of `[[package]]` tables with `name` and `version` on their own +/// lines, so the first `version` after the matching `name` is the answer. +fn locked_version(lock: &str, package: &str) -> Option { + let wanted = format!("name = \"{package}\""); + let mut lines = lock.lines(); + while let Some(line) = lines.next() { + if line.trim() != wanted { + continue; + } + for line in lines.by_ref().take(4) { + if let Some(version) = line.trim().strip_prefix("version = ") { + return Some(version.trim_matches('"').to_owned()); + } + } + return None; + } + None +} + +/// FNV-1a over the lock file. Not a cryptographic digest and not claimed to be +/// one — it answers "is this the same lock as the other run", which is the only +/// question the manifest asks of it, without pulling in a hash crate. +fn fnv1a_hex(text: &str) -> String { + let mut hash: u64 = 0xcbf2_9ce4_8422_2325; + for byte in text.as_bytes() { + hash ^= u64::from(*byte); + hash = hash.wrapping_mul(0x0000_0100_0000_01b3); + } + format!("{hash:016x}") +} diff --git a/crates/bootstrap/src/bench/counter_report.rs b/crates/bootstrap/src/bench/counter_report.rs new file mode 100644 index 0000000..3fe8247 --- /dev/null +++ b/crates/bootstrap/src/bench/counter_report.rs @@ -0,0 +1,309 @@ +//! Section three: the counters, which until now only ever reached a trace. +//! +//! `Counter::emit` writes a Perfetto counter track, and the bench report is a +//! different tool over the same run — so every render-stage timing, every GPU +//! pass and every draw census was invisible to `make bench` unless someone +//! opened the `.pftrace`. The recorder now keeps them, and this is where they +//! are read back. +//! +//! Three rules the tables here exist to keep: +//! +//! * a counter that took no sample prints MISS, never `0.00`. A pass the GPU +//! could not time and a pass that cost nothing are not the same fact; +//! * a sample is not a frame. `submit_prepare` fires once per submit and +//! `fx_update` twice per frame, so `avg` is the cost of one *call* and +//! `per frame` is the cost of the calls one frame made. The two columns are +//! printed side by side because comparing the wrong one to a frame budget is +//! the easiest mistake this report can invite; +//! * GPU passes are not added up. They overlap on the device and the driver +//! resolves them some frames after the CPU work that queued them, so the +//! measured `gpu_frame` interval is printed as its own row rather than as a +//! total of the rows above it. + +use perf::{Counter, CounterStats, Origin, Phase, SpanStats, Unit}; + +use crate::bench::table::{Align, Table}; + +/// CPU stage timings, in the order the work happens rather than by size: a +/// reader is looking for where a stage grew, and the sequence is the context. +const CPU_MS: [Counter; 8] = [ + Counter::RenderSubmitPrepareMs, + Counter::RenderSubmitGatherMs, + Counter::RenderSubmitArenaMs, + Counter::RenderSubmitRecordMs, + Counter::RenderSubmitSunMs, + Counter::RenderGraphRenderMs, + Counter::RenderGraphSubmitMs, + Counter::RenderGraphPresentMs, +]; + +/// GPU pass timings. `gpu_frame` is last and is the measured interval, not the +/// sum of the passes before it. +const GPU_MS: [Counter; 6] = [ + Counter::RenderGpuColourMs, + Counter::RenderGpuSunMs, + Counter::RenderGpuSpotMs, + Counter::RenderGpuFloatzMs, + Counter::RenderGpuPostfxMs, + Counter::RenderGpuFrameMs, +]; + +/// Per-frame work: what the CPU asked the GPU to do, and what it allocated +/// doing it. +const WORK: [Counter; 11] = [ + Counter::CounterDraws, + Counter::CounterDipsColour, + Counter::CounterDipsSun, + Counter::CounterSubmittedBatches, + Counter::CounterMultiDraws, + Counter::CounterMultiDrawCommands, + Counter::CounterBindGroup0, + Counter::CounterBindGroup1, + Counter::CounterCmdState, + Counter::CounterFxElemLive, + Counter::CounterProcessAllocations, +]; + +pub(crate) fn render(wall: &SpanStats, out: &mut Vec) { + let stats = perf::stats::counter_snapshot(Phase::Live); + let frames = wall.count; + out.push("[3/3] COUNTERS".to_owned()); + if stats.is_empty() { + out.push( + " MISS — no counter took a sample. Nothing emitted one on this workload, or the census that feeds them was compiled out." + .to_owned(), + ); + return; + } + out.push(format!( + " {} frames in the window. `n` is samples, not frames: `n/frame` says how often the counter fired, `avg` is one firing, `per frame` is what one frame paid.", + frames + )); + + out.push(String::new()); + out.push(" render stages, CPU (ms)".to_owned()); + ms_table(&stats, &CPU_MS, wall, frames, Share::Frame, out); + out.push( + " Stage timings from different points of the render schedule, in the order the work happens. Some of them run inside others, so this column is not a budget and does not add up to a frame." + .to_owned(), + ); + + out.push(String::new()); + out.push( + " GPU passes (ms) — measured on the device, resolved some frames after the CPU work that queued them. They overlap, so they are not summed; `gpu_frame` is the measured interval." + .to_owned(), + ); + ms_table(&stats, &GPU_MS, wall, frames, Share::Wall, out); + out.push( + " `%wall` is device-busy time against the CPU wall clock of the same window, not a share of any one frame: the GPU runs ahead of and behind the CPU that queued it." + .to_owned(), + ); + + out.push(String::new()); + out.push(" work per frame".to_owned()); + count_table(&stats, &WORK, frames, out); + if find(&stats, Counter::CounterProcessAllocations).is_none() { + out.push( + " process_allocations is MISS because the counting allocator is off; set IW4L_COUNTING_ALLOC to turn it on. It is not zero — nobody counted." + .to_owned(), + ); + } + + rejected(&stats, out); + untabled(&stats, out); + never_sampled(out); +} + +/// Counters that took a sample and are in none of the three tables above. The +/// tables are a curated set — the frame's cost and the frame's work — while +/// `summary.json` carries every counter the recorder held. Naming the rest is +/// what stops the report reading as the whole list when it is a selection. +fn untabled(stats: &[CounterStats], out: &mut Vec) { + let tabled: Vec = CPU_MS.into_iter().chain(GPU_MS).chain(WORK).collect(); + let rest: Vec<&str> = stats + .iter() + .filter(|row| !tabled.contains(&row.counter)) + .map(|row| row.counter.name()) + .collect(); + if rest.is_empty() { + return; + } + out.push(String::new()); + out.push(format!( + " sampled but not tabled above ({}), in summary.json with the rest: {}", + rest.len(), + rest.join(", ") + )); +} + +/// What the last column of a millisecond table divides by, and what it is +/// therefore allowed to be called. A CPU stage is part of the frame it was +/// measured in; a GPU pass is device time against the same wall clock and is +/// not a share of any one frame, so it gets its own name rather than borrowing +/// one that would read as a frame budget. +#[derive(Clone, Copy)] +enum Share { + Frame, + Wall, +} + +impl Share { + const fn header(self) -> &'static str { + match self { + Self::Frame => "%frame", + Self::Wall => "%wall", + } + } +} + +fn ms_table( + stats: &[CounterStats], + wanted: &[Counter], + wall: &SpanStats, + frames: u64, + share: Share, + out: &mut Vec, +) { + let wall_ms = wall.sum_ns as f64 / 1e6; + let mut table = Table::new( + 4, + &[ + ("counter", Align::Left), + ("n", Align::Right), + ("n/frame", Align::Right), + ("avg", Align::Right), + ("p50", Align::Right), + ("p95", Align::Right), + ("p99", Align::Right), + ("max", Align::Right), + ("per frame", Align::Right), + (share.header(), Align::Right), + ("where", Align::Left), + ], + ); + for counter in wanted { + let Some(row) = find(stats, *counter) else { + table.miss(counter.name()); + continue; + }; + debug_assert_eq!(row.unit, Unit::Milliseconds); + let per_frame = row.per_frame(frames); + table.row([ + counter.name().to_owned(), + row.samples.to_string(), + opt2(row.per_frame_samples(frames)), + num2(row.avg()), + num2(row.p50), + num2(row.p95), + num2(row.p99), + num2(row.max), + opt2(per_frame), + per_frame.map_or_else( + || "—".to_owned(), + |per_frame| { + if wall_ms <= 0.0 { + "—".to_owned() + } else { + format!("{:.1}", per_frame * 100.0 * frames as f64 / wall_ms) + } + }, + ), + match row.origin { + Origin::Cpu => "cpu", + Origin::Gpu => "gpu", + } + .to_owned(), + ]); + } + table.render(out); +} + +fn count_table(stats: &[CounterStats], wanted: &[Counter], frames: u64, out: &mut Vec) { + let mut table = Table::new( + 4, + &[ + ("counter", Align::Left), + ("n", Align::Right), + ("n/frame", Align::Right), + ("avg", Align::Right), + ("p50", Align::Right), + ("p95", Align::Right), + ("p99", Align::Right), + ("max", Align::Right), + ("per frame", Align::Right), + ("total", Align::Right), + ], + ); + for counter in wanted { + let Some(row) = find(stats, *counter) else { + table.miss(counter.name()); + continue; + }; + debug_assert_eq!(row.unit, Unit::Count); + table.row([ + counter.name().to_owned(), + row.samples.to_string(), + opt2(row.per_frame_samples(frames)), + num2(row.avg()), + num0(row.p50), + num0(row.p95), + num0(row.p99), + num0(row.max), + opt2(row.per_frame(frames)), + num0(row.sum), + ]); + } + table.render(out); +} + +/// Samples the recorder refused: not finite, or negative. A counter is a +/// non-negative quantity, so one of these is a bug at the emitter and the +/// report says so rather than folding it into an average. +fn rejected(stats: &[CounterStats], out: &mut Vec) { + let bad: Vec<&CounterStats> = stats.iter().filter(|row| row.rejected > 0).collect(); + if bad.is_empty() { + return; + } + out.push(String::new()); + for row in bad { + out.push(format!( + " {}: {} sample(s) were NaN, infinite or negative and are in none of the numbers above.", + row.counter.name(), + row.rejected + )); + } +} + +/// Counters this build declares that took no sample in either phase. Printing +/// the names is the difference between "this workload never did that" and +/// "nothing emits this any more", which the reader can tell apart and the +/// report cannot. +fn never_sampled(out: &mut Vec) { + let silent = perf::stats::counters_never_sampled(); + if silent.is_empty() { + return; + } + let names: Vec<&str> = silent.iter().map(|counter| counter.name()).collect(); + out.push(String::new()); + out.push(format!( + " declared but never sampled on this run ({}): {}", + silent.len(), + names.join(", ") + )); +} + +fn find(stats: &[CounterStats], counter: Counter) -> Option<&CounterStats> { + stats.iter().find(|row| row.counter == counter) +} + +fn num2(value: f64) -> String { + format!("{value:.2}") +} + +fn num0(value: f64) -> String { + format!("{value:.0}") +} + +fn opt2(value: Option) -> String { + value.map_or_else(|| "—".to_owned(), |value| format!("{value:.2}")) +} diff --git a/crates/bootstrap/src/bench/facts.rs b/crates/bootstrap/src/bench/facts.rs new file mode 100644 index 0000000..43c3ea0 --- /dev/null +++ b/crates/bootstrap/src/bench/facts.rs @@ -0,0 +1,104 @@ +//! Reading the manifest's runtime half out of the running app. +//! +//! The device, the surface and the pools do not exist when the bench is +//! inserted — the render plugin has not finished, the window has no size and +//! the task pools have not been asked for a thread. They all exist by the first +//! frame, and none of them changes after it, so this snapshots once and hands +//! the result to the exit hook, which runs with no `World` to ask. + +use std::sync::OnceLock; + +use bevy::prelude::*; +use bevy::render::renderer::{RenderAdapterInfo, RenderDevice}; +use bevy::window::PrimaryWindow; + +use crate::bench::manifest::{AdapterFacts, RuntimeFacts, WindowFacts}; + +static FACTS: OnceLock = OnceLock::new(); + +/// The workload, which is known when the bench is inserted rather than when +/// the device is. Kept beside the collected facts so `snapshot` returns one +/// complete answer. +static WORKLOAD: OnceLock<(String, Option, String)> = OnceLock::new(); + +/// What was asked for, recorded at insert time: zone, demo path and role. +pub(crate) fn workload(zone: &str, demo: Option<&str>, role: &str) { + let _ = WORKLOAD.set((zone.to_owned(), demo.map(str::to_owned), role.to_owned())); +} + +/// What was collected, or an empty set if the run never reached a frame. Every +/// field is optional, so "never reached a frame" reads as a manifest of nulls +/// rather than as a manifest of wrong values. +pub(crate) fn snapshot() -> RuntimeFacts { + let mut facts = match FACTS.get() { + Some(facts) => facts.clone(), + None => RuntimeFacts::default(), + }; + if let Some((zone, demo, role)) = WORKLOAD.get() { + facts.zone = Some(zone.clone()); + facts.demo = demo.clone(); + facts.role = Some(role.clone()); + } + facts +} + +/// Collect once, then do nothing. Runs every frame because the cost of the +/// `OnceLock` load is smaller than the cost of a run condition that has to be +/// evaluated to reach the same answer. +pub(crate) fn collect( + adapter: Option>, + device: Option>, + windows: Query<&Window, With>, +) { + if FACTS.get().is_some() { + return; + } + let facts = RuntimeFacts { + zone: None, + demo: None, + role: None, + adapter: adapter.map(|adapter| AdapterFacts { + name: adapter.0.name.clone(), + backend: format!("{:?}", adapter.0.backend), + device_type: format!("{:?}", adapter.0.device_type), + driver: adapter.0.driver.clone(), + driver_info: adapter.0.driver_info.clone(), + // Whether the *device* was created with the feature, not whether + // the adapter could have offered it: a pass can only be timed if + // the device we actually hold can resolve the query. + timestamp_queries: device.map(|device| { + device + .features() + .contains(bevy::render::render_resource::WgpuFeatures::TIMESTAMP_QUERY) + }), + }), + window: windows.single().ok().map(|window| WindowFacts { + width: window.resolution.physical_width(), + height: window.resolution.physical_height(), + scale: f64::from(window.resolution.scale_factor()), + }), + present_mode: windows + .single() + .ok() + .map(|window| format!("{:?}", window.present_mode)), + pools: pools(), + }; + let _ = FACTS.set(facts); +} + +/// Threads in each Bevy pool. The pools are global and already built by the +/// time a frame runs, so this reads them rather than constructing anything. +fn pools() -> Vec<(String, usize)> { + use bevy::tasks::{AsyncComputeTaskPool, ComputeTaskPool, IoTaskPool}; + let mut out = Vec::new(); + if let Some(pool) = ComputeTaskPool::try_get() { + out.push(("compute".to_owned(), pool.thread_num())); + } + if let Some(pool) = AsyncComputeTaskPool::try_get() { + out.push(("async_compute".to_owned(), pool.thread_num())); + } + if let Some(pool) = IoTaskPool::try_get() { + out.push(("io".to_owned(), pool.thread_num())); + } + out +} diff --git a/crates/bootstrap/src/bench/frame_report.rs b/crates/bootstrap/src/bench/frame_report.rs index 4921f02..d71ba57 100644 --- a/crates/bootstrap/src/bench/frame_report.rs +++ b/crates/bootstrap/src/bench/frame_report.rs @@ -10,14 +10,17 @@ 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; +/// A span worth naming: either its own time is large, or it is a big share of +/// a frame that nothing else explains. +const HOT_SELF_NS: u64 = 500_000; const HOT_SHARE: f64 = 5.0; +/// How many rows the self-time ranking prints before it stops. +const TOP_SELF: usize = 12; + pub(crate) fn render(out: &mut Vec) { let stats = perf::stats::snapshot(Phase::Live); - out.push("[2/2] FRAME TIME".to_owned()); + out.push("[2/3] FRAME TIME".to_owned()); let Some(wall) = stats .iter() .find(|row| row.span == Span::FramesWallFrameMs) @@ -33,8 +36,11 @@ pub(crate) fn render(out: &mut Vec) { out.push(String::new()); tree(&stats, &wall, out); out.push(String::new()); - hot(&stats, &wall, out); + top_self(&stats, &wall, out); + silent_spans(out); anomalies(out); + out.push(String::new()); + crate::bench::counter_report::render(&wall, out); } fn header(wall: &SpanStats, out: &mut Vec) { @@ -80,11 +86,13 @@ fn tree(stats: &[SpanStats], wall: &SpanStats, out: &mut Vec) { &[ ("span", Align::Left), ("n", Align::Right), + ("n/frame", Align::Right), ("avg", Align::Right), ("p50", Align::Right), ("p95", Align::Right), ("p99", Align::Right), ("max", Align::Right), + ("per frame", Align::Right), ("total", Align::Right), ("%frame", Align::Right), ("self", Align::Right), @@ -108,6 +116,10 @@ fn tree(stats: &[SpanStats], wall: &SpanStats, out: &mut Vec) { " `self` is the span's own time: its total minus the totals of the spans that nested inside it." .to_owned(), ); + out.push( + " `avg` is one call; `per frame` is what one frame paid for all of them. A span that runs twice a frame has an `avg` half its `per frame`, and only `per frame` belongs next to a frame budget." + .to_owned(), + ); if orphans.is_empty() { return; } @@ -194,63 +206,121 @@ fn self_ns(stats: &[SpanStats], row: &SpanStats, parent: Option) -> u64 { fn push(table: &mut Table, row: &SpanStats, wall: &SpanStats, depth: usize, self_ns: u64) { let varies = if row.parent_varies { " *" } else { "" }; + let frames = wall.count; table.row([ format!("{}{}{varies}", " ".repeat(depth), row.span.name()), row.count.to_string(), + per_frame_calls(row.count, frames), ms(row.avg_ns()), ms(row.p50_ns), ms(row.p95_ns), ms(row.p99_ns), ms(row.max_ns), + per_frame_ms(row.sum_ns, frames), 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 +/// How many times this span ran per frame of the window. `wall` itself is one +/// per frame by construction; anything else is a measured ratio, and it is the +/// number that makes `avg` comparable to `per frame`. +fn per_frame_calls(count: u64, frames: u64) -> String { + if frames == 0 { + return "—".to_owned(); + } + format!("{:.2}", count as f64 / frames as f64) +} + +/// A span's total spread over the frames of the window: what one frame paid for +/// this span, however many calls that took. +fn per_frame_ms(sum_ns: u64, frames: u64) -> String { + if frames == 0 { + return "—".to_owned(); + } + format!("{:.2}", sum_ns as f64 / frames as f64 / 1e6) +} + +/// The spans ranked by their *own* time, parents included. +/// +/// The previous version of this section ranked leaves only — a span with +/// nothing nested inside it — which is the one ranking that cannot see the +/// case it matters for. A parent whose children are cheap and whose own body +/// is expensive has all of that time in `self` and none of it in any leaf, so +/// it was absent from the summary while being the largest single cost in the +/// frame. Self time is defined for every span, so every span is ranked. +fn top_self(stats: &[SpanStats], wall: &SpanStats, out: &mut Vec) { + let frames = wall.count; + let mut ranked: Vec<(u64, &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 + .map(|row| (self_ns(stats, row, Some(row.span)), row)) + .filter(|(self_ns, _)| { + *self_ns >= HOT_SELF_NS.saturating_mul(frames.max(1)) + || *self_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() { + if ranked.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) + " top self: none — no span's own time reached {} ms per frame or {HOT_SHARE:.0}% of the frame.", + ms(HOT_SELF_NS) )); return; } + ranked.sort_by_key(|(self_ns, _)| std::cmp::Reverse(*self_ns)); out.push(format!( - " hot leaves (nothing nested inside them; ≥{} ms average or ≥{HOT_SHARE:.0}% of the frame)", - ms(HOT_AVG_NS) + " top self — every span, parents included, by its own time (≥{} ms per frame or ≥{HOT_SHARE:.0}% of the frame)", + ms(HOT_SELF_NS) )); let mut table = Table::new( 4, &[ ("span", Align::Left), - ("avg", Align::Right), - ("p95", Align::Right), + ("kind", Align::Left), + ("self/frame", Align::Right), + ("self total", Align::Right), ("%frame", Align::Right), + ("n/frame", Align::Right), ("under", Align::Left), ], ); - for leaf in leaves { + for (own, row) in ranked.into_iter().take(TOP_SELF) { + let has_children = stats.iter().any(|child| child.parent == Some(row.span)); table.row([ - leaf.span.name().to_owned(), - ms(leaf.avg_ns()), - ms(leaf.p95_ns), - percent(leaf.sum_ns, wall.sum_ns), - leaf.parent + row.span.name().to_owned(), + if has_children { "parent" } else { "leaf" }.to_owned(), + per_frame_ms(own, frames), + ms(own), + percent(own, wall.sum_ns), + per_frame_calls(row.count, frames), + row.parent .map_or_else(|| "—".to_owned(), |parent| parent.name().to_owned()), ]); } table.render(out); + out.push( + " `self` here is the same quantity as the tree's last column: the span's total minus what its own children accounted for. It is time the recorder could not attribute to a child — not proven useful work, and on a thread that waits it can be the wait." + .to_owned(), + ); +} + +/// Spans this build declares that opened in neither phase. The tree prints +/// what was sampled, so a span whose producer was deleted or compiled out is +/// absent from it in exactly the same way as a span the workload never +/// reached. Naming them is what tells those two apart. +fn silent_spans(out: &mut Vec) { + let silent = perf::stats::spans_never_sampled(); + if silent.is_empty() { + return; + } + let names: Vec<&str> = silent.iter().map(|span| span.name()).collect(); + out.push(String::new()); + out.push(format!( + " declared but never opened on this run ({}): {}", + silent.len(), + names.join(", ") + )); } fn anomalies(out: &mut Vec) { diff --git a/crates/bootstrap/src/bench/load_report.rs b/crates/bootstrap/src/bench/load_report.rs index 84683ea..10e0901 100644 --- a/crates/bootstrap/src/bench/load_report.rs +++ b/crates/bootstrap/src/bench/load_report.rs @@ -4,8 +4,13 @@ //! 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. +//! whether removing it would shorten anything. `exclusive` below narrows that: +//! the time a stage was the only one running is an *upper bound* on what +//! deleting it could save, and not a promise of saving it. Whatever else the +//! pool would have picked up in that window still has to run, and a stage that +//! was never alone can still be on the critical path by holding a dependency +//! everything behind it is waiting on. The number bounds the win; it does not +//! measure it. use std::time::{Duration, Instant}; @@ -18,11 +23,13 @@ use crate::bench::table::{Align, Table, bytes, items, mib, ms, secs}; 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()); + out.push("[1/3] MAP LOAD".to_owned()); waterfall(bench, command_start, out); out.push(String::new()); stages(&bench.lanes, out); out.push(String::new()); + audio(out); + out.push(String::new()); picture(bench, out); } @@ -122,20 +129,23 @@ fn stages(lanes: &[LoadLaneTiming], out: &mut Vec) { let covered = union(lanes); let exclusive = exclusive(lanes); - let parallel = if covered.is_zero() { + let occupancy = if covered.is_zero() { "—".to_owned() } else { - format!("{:.1}x", held.as_secs_f64() / covered.as_secs_f64()) + format!("{:.1}", held.as_secs_f64() / covered.as_secs_f64()) }; out.push(format!( - " load stages: {} stages holding {} across a {} window — {parallel} parallel, {} covered by no stage", + " load stages: {} stages holding {} across a {} window; {} of that window had no stage open", lanes.len(), secs(held), secs(window), secs(window.saturating_sub(covered)), )); + out.push(format!( + " mean occupancy {occupancy} stages while anything was open. That is how many stages overlapped on average — not a speed-up, and not a count of busy cores: a stage that spends its time waiting on I/O is open and occupying nothing." + )); out.push( - " `exclusive` is the time a stage was the only one running: the part of the load it, alone, lengthened." + " `exclusive` is the time a stage was the only one open. It is an upper bound on what deleting that stage could save, not the saving: the work behind it still has to run, and a stage that was never alone can still be what everything else is queued on." .to_owned(), ); @@ -182,6 +192,134 @@ fn stages(lanes: &[LoadLaneTiming], out: &mut Vec) { } } +/// What preparing the match's clips cost, split by the decoder each clip took. +/// +/// The stage table above has `preparing match audio` as one row holding one +/// number, which on every run so far has been the largest stage in the load — +/// and a single number cannot say whether that is thousands of cheap byte +/// loops or hundreds of external processes. These are the same clips counted +/// by the decoder that ran, so the two questions have different answers. +/// +/// Every duration here is summed over the prep workers, several of which run +/// at once. They are worker time, and adding them to a milestone is wrong. +fn audio(out: &mut Vec) { + let prep = audio::clip_prep_cost(); + if prep.requests == 0 { + out.push(" match audio: MISS — this run asked for no clip".to_owned()); + return; + } + let prepared: u64 = prep.paths.iter().map(|(_, cost)| cost.prepared).sum(); + let failed: u64 = prep.paths.iter().map(|(_, cost)| cost.failed).sum(); + out.push(format!( + " match audio: {prepared} clips prepared, {failed} failed, {} still in flight when the run ended", + prep.queued.saturating_sub(prepared + failed), + )); + out.push(format!( + " {} asks resolved to {} clips: {} of the asks were for a clip somebody had already asked for, and the store queued each clip once. {} clips were queued after AudioReady.", + prep.requests, + prep.queued, + prep.requests.saturating_sub(prep.queued), + prep.late, + )); + out.push(format!( + " a job waited {} on average before a worker took it ({} over {} jobs, {} prep workers). The sum is worker queue time, not a stretch of the load.", + ms_secs(prep.queue_wait_ms / prep.queued.max(1) as f64), + ms_secs(prep.queue_wait_ms), + prep.queued, + prep.workers, + )); + + let mut table = Table::new( + 2, + &[ + ("decoder", Align::Left), + ("prepared", Align::Right), + ("failed", Align::Right), + ("worker time", Align::Right), + ("per clip", Align::Right), + ("resident pcm", Align::Left), + ], + ); + let mut silent = Vec::new(); + for (path, cost) in &prep.paths { + let n = cost.prepared + cost.failed; + if n == 0 { + silent.push(path.name()); + continue; + } + table.row([ + path.name().to_owned(), + cost.prepared.to_string(), + cost.failed.to_string(), + ms_secs(cost.wall_ms), + format!("{:.2} ms", cost.wall_ms / n as f64), + mib(cost.sample_bytes), + ]); + } + table.render(out); + if !silent.is_empty() { + out.push(format!(" no clip on this run took: {}", silent.join(", "))); + } + xwma(out); +} + +/// The one decoder that leaves the process. Everything else on the table above +/// is a loop over bytes; this one is `ffmpeg`, and both numbers it is judged by +/// are here: how many clips it was asked about, and how many processes that +/// took. The artifact cache answers the second run of a zone; the batching is +/// what the first run gets. +fn xwma(out: &mut Vec) { + let cost = assets::xwma_decode_cost(); + if cost.hit + cost.miss + cost.failed == 0 { + out.push( + " t5 xwma: MISS — no clip reached the external decoder, so the cache answered nothing and nothing was stored." + .to_owned(), + ); + return; + } + out.push(format!( + " t5 xwma: {} cached, {} decoded, {} failed; {} external ffmpeg processes for {} of samples", + cost.hit, + cost.miss, + cost.failed, + cost.spawned, + mib(cost.pcm_bytes), + )); + if cost.spawned > 0 { + out.push(format!( + " {:.1} clips per process — starting ffmpeg costs more than decoding one of these clips, so the match's clips are decoded in batches of up to {}.{}", + (cost.miss + cost.failed) as f64 / cost.spawned as f64, + audio::PREP_BATCH, + if cost.retried == 0 { + String::new() + } else { + format!( + " {} clips were asked again one at a time after the batch holding them was refused.", + cost.retried + ) + }, + )); + } + out.push(format!( + " t5 xwma worker time: {} in ffmpeg, {} hashing payloads into keys, {} reading and writing the cache", + ms_secs(cost.decode_ms), + ms_secs(cost.key_ms), + ms_secs(cost.io_ms), + )); + if cost.miss == 0 && cost.failed == 0 { + out.push( + " the cache answered every clip. A warm cache is not a faster decoder: the first run on these zones still paid for all of it, and a zone that changes pays again." + .to_owned(), + ); + } +} + +/// Milliseconds as seconds. The audio numbers are sums over worker threads and +/// run to tens of seconds, where `ms` would print five digits. +fn ms_secs(ms: f64) -> String { + format!("{:.3}s", ms / 1000.0) +} + fn picture(bench: &Milestones, out: &mut Vec) { let mut lines = Vec::new(); if let Some(bytes) = bench.progress.zone_image_bytes() { @@ -197,6 +335,10 @@ fn picture(bench: &Milestones, out: &mut Vec) { } if !lines.is_empty() { out.push(format!(" memory: {}", lines.join(", "))); + out.push( + " RSS is the whole process. A stage's delta is what the process grew across its window, which on a parallel walk includes every other stage that was open — so the per-stage deltas do not add up to the peak and none of them is that stage's ownership." + .to_owned(), + ); } let frames = perf::stats::snapshot(perf::Phase::Load) diff --git a/crates/bootstrap/src/bench/manifest.rs b/crates/bootstrap/src/bench/manifest.rs new file mode 100644 index 0000000..cf802e3 --- /dev/null +++ b/crates/bootstrap/src/bench/manifest.rs @@ -0,0 +1,246 @@ +//! `manifest.json`: what this run *was*, so two reports can be compared. +//! +//! A number without a manifest is not a measurement, it is an anecdote. Two +//! runs differing by 3 ms mean nothing until the reader knows they were the +//! same binary, the same map, the same present mode and the same cache state — +//! and the most expensive mistake in this repository's history of benchmarking +//! is comparing a report against source that was never the source it was built +//! from. +//! +//! So every field here is one of three things and says which: +//! +//! * baked in at build time (`build.rs`) — the revision, the toolchain, the +//! locked `bevy` and `wgpu`. These describe the *binary*, not the tree the +//! process happens to be standing in; +//! * read from the running process — the adapter, the window, the pools; +//! * absent. An absent field is `null`. There is no default, no zero and no +//! "unknown" string that sorts next to a real value. +//! +//! Cache state is deliberately narrow. The manifest names the layers this +//! process controls — the prepared-artifact cache it can see on disk — and +//! says nothing about the OS page cache or the GPU driver's shader cache, +//! because it does not control them and calling a run "cold" on the strength of +//! a guess about them is how a cache hit gets reported as an optimisation. + +use std::path::{Path, PathBuf}; + +use serde_json::{Value, json}; + +/// A build-time string, or `null` when the build could not learn it. `build.rs` +/// emits an empty string for "not known" so `env!` always compiles. +macro_rules! built { + ($key:literal) => { + match env!($key) { + "" => Value::Null, + value => Value::String(value.to_owned()), + } + }; +} + +/// What the running process knows about itself that the build could not. +#[derive(Debug, Default, Clone)] +pub(crate) struct RuntimeFacts { + pub(crate) zone: Option, + pub(crate) demo: Option, + pub(crate) role: Option, + /// Adapter name, backend, device type and driver, as wgpu reported them. + pub(crate) adapter: Option, + pub(crate) window: Option, + pub(crate) present_mode: Option, + /// Threads in each Bevy pool, by pool name. + pub(crate) pools: Vec<(String, usize)>, +} + +#[derive(Debug, Clone)] +pub(crate) struct AdapterFacts { + pub(crate) name: String, + pub(crate) backend: String, + pub(crate) device_type: String, + pub(crate) driver: String, + pub(crate) driver_info: String, + /// Whether the device can resolve GPU timestamp queries. Without it every + /// `gpu_*` counter in the report is MISS, and the reader needs to know that + /// is a capability and not a workload that drew nothing. + pub(crate) timestamp_queries: Option, +} + +#[derive(Debug, Clone)] +pub(crate) struct WindowFacts { + pub(crate) width: u32, + pub(crate) height: u32, + pub(crate) scale: f64, +} + +pub(crate) fn build(facts: &RuntimeFacts, run_id: Option<&str>, artifacts: &Path) -> Value { + json!({ + "format": "iw4l-bench-1", + "run": run_id, + "build": { + "git_sha": built!("IW4L_BUILD_GIT_SHA"), + "git_describe": built!("IW4L_BUILD_GIT_DESCRIBE"), + "git_dirty": dirty(), + "rustc": built!("IW4L_BUILD_RUSTC"), + "profile": built!("IW4L_BUILD_PROFILE"), + "profile_kind": built!("IW4L_BUILD_PROFILE_KIND"), + "target": built!("IW4L_BUILD_TARGET"), + "opt_level": built!("IW4L_BUILD_OPT_LEVEL"), + "debug_assertions": cfg!(debug_assertions), + "cargo_lock_fnv1a": built!("IW4L_BUILD_LOCK_HASH"), + "bevy": built!("IW4L_BUILD_BEVY_VERSION"), + "wgpu": built!("IW4L_BUILD_WGPU_VERSION"), + }, + "binary": binary(), + "host": host(), + "gpu": facts.adapter.as_ref().map_or(Value::Null, |adapter| json!({ + "adapter": adapter.name, + "backend": adapter.backend, + "device_type": adapter.device_type, + "driver": adapter.driver, + "driver_info": adapter.driver_info, + "timestamp_queries": adapter.timestamp_queries, + })), + "window": facts.window.as_ref().map_or(Value::Null, |window| json!({ + "width": window.width, + "height": window.height, + "scale_factor": window.scale, + })), + "present_mode": facts.present_mode, + "pools": facts + .pools + .iter() + .map(|(name, threads)| json!({ "pool": name, "threads": threads })) + .collect::>(), + "workload": { + "zone": facts.zone, + "demo": facts.demo, + "role": facts.role, + "command_line": std::env::args().collect::>(), + }, + "env": toggles(), + "caches": caches(artifacts), + }) +} + +fn dirty() -> Value { + match env!("IW4L_BUILD_GIT_DIRTY") { + "true" => Value::Bool(true), + "false" => Value::Bool(false), + _ => Value::Null, + } +} + +/// The binary this process is running, by path, size and mtime. Enough to tell +/// two runs of "the same" build apart when one of them was rebuilt in between; +/// not a content hash, because reading a release binary at exit to digest it +/// costs more than the fact is worth. +fn binary() -> Value { + let Ok(path) = std::env::current_exe() else { + return Value::Null; + }; + let metadata = std::fs::metadata(&path).ok(); + json!({ + "path": path.display().to_string(), + "bytes": metadata.as_ref().map(std::fs::Metadata::len), + "modified_unix_s": metadata + .as_ref() + .and_then(|metadata| metadata.modified().ok()) + .and_then(|at| at.duration_since(std::time::UNIX_EPOCH).ok()) + .map(|since| since.as_secs()), + }) +} + +fn host() -> Value { + json!({ + "os": std::env::consts::OS, + "arch": std::env::consts::ARCH, + "kernel": kernel(), + "available_parallelism": std::thread::available_parallelism() + .map(std::num::NonZeroUsize::get) + .ok(), + "cpu_model": cpu_model(), + }) +} + +#[cfg(target_os = "linux")] +fn kernel() -> Option { + std::fs::read_to_string("/proc/sys/kernel/osrelease") + .ok() + .map(|value| value.trim().to_owned()) +} + +#[cfg(not(target_os = "linux"))] +fn kernel() -> Option { + None +} + +#[cfg(target_os = "linux")] +fn cpu_model() -> Option { + let text = std::fs::read_to_string("/proc/cpuinfo").ok()?; + text.lines() + .find(|line| line.starts_with("model name")) + .and_then(|line| line.split_once(':')) + .map(|(_, value)| value.trim().to_owned()) +} + +#[cfg(not(target_os = "linux"))] +fn cpu_model() -> Option { + None +} + +/// The `IW4L_*` variables that change what is measured. Recorded by name and +/// value because "the same command" is not the same run when one of these +/// differs, and the command line does not show them. +fn toggles() -> Value { + let mut set: Vec<(String, String)> = std::env::vars() + .filter(|(key, _)| key.starts_with("IW4L_")) + .collect(); + set.sort(); + Value::Object( + set.into_iter() + .map(|(key, value)| (key, Value::String(value))) + .collect(), + ) +} + +/// The cache layers this process can actually see. Each entry says what was +/// found, never whether the run was "cold": the OS page cache and the GPU +/// driver's shader cache are outside this process and are reported as unknown +/// rather than assumed empty. +fn caches(artifacts: &Path) -> Value { + json!({ + "prepared_artifacts": prepared_cache(artifacts), + "os_page_cache": Value::Null, + "driver_shader_cache": Value::Null, + "note": "os_page_cache and driver_shader_cache are outside this process; \ + they are reported as unknown rather than assumed cold.", + }) +} + +fn prepared_cache(artifacts: &Path) -> Value { + let dir = artifacts.join("cache"); + let Ok(entries) = std::fs::read_dir(&dir) else { + return json!({ "path": dir.display().to_string(), "present": false }); + }; + let mut files = 0u64; + let mut bytes = 0u64; + for entry in entries.flatten() { + if let Ok(metadata) = entry.metadata() + && metadata.is_file() + { + files += 1; + bytes += metadata.len(); + } + } + json!({ + "path": dir.display().to_string(), + "present": true, + "files": files, + "bytes": bytes, + }) +} + +pub(crate) fn write(path: &PathBuf, manifest: &Value) -> Result<(), String> { + let bytes = + serde_json::to_vec_pretty(manifest).map_err(|error| format!("encode manifest: {error}"))?; + std::fs::write(path, bytes).map_err(|error| format!("write {}: {error}", path.display())) +} diff --git a/crates/bootstrap/src/bench/mod.rs b/crates/bootstrap/src/bench/mod.rs index bb28872..bb90f77 100644 --- a/crates/bootstrap/src/bench/mod.rs +++ b/crates/bootstrap/src/bench/mod.rs @@ -1,17 +1,24 @@ -//! `make bench`: one run, two independent reports. +//! `make bench`: one run, three independent reports and a package. //! //! [`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. +//! the cost of a frame once it is there; [`counter_report`] is what the frame +//! asked the machine to do to cost that. They share a process and nothing else +//! — any of them can be MISS while the others stand — and the split between the +//! first two 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. +//! All three are printed to stdout at exit and written to +//! `iw4l-artifacts/bench/.txt`, so a run can be diffed against the one +//! before it. The same text, the [`manifest`] that says what the run *was* and +//! the [`summary`] of the same numbers as data go to the run's own directory, +//! next to the trace it recorded. Off unless `IW4L_BENCH` is set. +mod counter_report; +mod facts; mod frame_report; mod load_report; +mod manifest; mod milestones; +mod summary; mod table; use std::path::{Path, PathBuf}; @@ -82,7 +89,15 @@ pub fn enabled() -> bool { /// 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) { +pub fn insert( + app: &mut App, + zone: &str, + demo: Option<&str>, + role: &str, + artifacts: &Path, + progress: LoadProgress, +) { + facts::workload(zone, demo, role); let screenshot = milestones::screenshot_path(artifacts, zone); if let Some(parent) = screenshot.parent() && let Err(error) = std::fs::create_dir_all(parent) @@ -102,7 +117,7 @@ pub fn insert(app: &mut App, zone: &str, artifacts: &Path, progress: LoadProgres 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); + app.add_systems(Last, (milestones::poll, facts::collect)); } /// Playing a demo ends in `std::process::exit` (`console::exit_replay_process`), @@ -161,7 +176,7 @@ fn report(artifacts: &Path, trace: Option) { 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." + "[1/3] MAP LOAD: MISS — this run loaded no map, so there was nothing to time." .to_owned(), ); lines.push(String::new()); @@ -175,6 +190,9 @@ fn report(artifacts: &Path, trace: Option) { Ok(path) => lines.push(format!("report: {}", path.display())), Err(error) => lines.push(format!("report: not written ({error})")), } + for line in write_run_package(artifacts, &lines) { + lines.push(line); + } for line in &lines { diag::announce_stdout(line); } @@ -212,6 +230,46 @@ fn write_report(artifacts: &Path, lines: &[String]) -> Result { Ok(path) } +/// The run's own directory: `report.txt`, `manifest.json` and `summary.json` +/// next to the `trace.pftrace` the same run wrote. +/// +/// The flat `bench/.txt` above stays where it is — it is the file a +/// human diffs against the last run and nothing should move it. This is the +/// package: one directory per run id, holding everything needed to read the +/// report months later without knowing what else was true that afternoon. +fn write_run_package(artifacts: &Path, lines: &[String]) -> Vec { + let dir = match perf::run::dir() { + Ok(dir) => dir, + Err(error) => return vec![format!("run package: not written ({error})")], + }; + let mut out = Vec::new(); + + let mut body = lines.join("\n"); + body.push('\n'); + let report = dir.join("report.txt"); + if let Err(error) = std::fs::write(&report, body) { + out.push(format!( + "run package: {} not written ({error})", + report.display() + )); + } + + let facts = facts::snapshot(); + let path = dir.join("manifest.json"); + let manifest = manifest::build(&facts, perf::run::id().as_deref(), artifacts); + match manifest::write(&path, &manifest) { + Ok(()) => out.push(format!("run package: {}", dir.display())), + Err(error) => out.push(format!("run package: manifest not written ({error})")), + } + + let path = dir.join("summary.json"); + match summary::write(&path, &facts) { + Ok(()) => {} + Err(error) => out.push(format!("run package: summary not written ({error})")), + } + out +} + /// 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 { diff --git a/crates/bootstrap/src/bench/summary.rs b/crates/bootstrap/src/bench/summary.rs new file mode 100644 index 0000000..92407a4 --- /dev/null +++ b/crates/bootstrap/src/bench/summary.rs @@ -0,0 +1,158 @@ +//! `summary.json`: the same numbers as `report.txt`, for something that is not +//! a person. +//! +//! The text report is laid out to be read and diffed by eye, which makes it a +//! poor thing to parse: columns move when a name gets longer, and a row can be +//! MISS. This writes the same snapshot as data — every span and every counter, +//! both phases, with the units named — so an A/B comparison is a script and not +//! a careful reading of two terminals. +//! +//! It is a dump of what the recorder holds, deliberately not a verdict. There +//! is no "regression" field, no threshold and no pass/fail: deciding what a +//! difference means needs the manifest next to it and a human who knows what +//! changed. + +use std::path::Path; + +use perf::{CounterStats, Origin, Phase, SpanStats, Unit}; +use serde_json::{Value, json}; + +use crate::bench::manifest::RuntimeFacts; + +pub(crate) fn write(path: &Path, facts: &RuntimeFacts) -> Result<(), String> { + let value = build(facts); + let bytes = + serde_json::to_vec_pretty(&value).map_err(|error| format!("encode summary: {error}"))?; + std::fs::write(path, bytes).map_err(|error| format!("write {}: {error}", path.display())) +} + +fn build(facts: &RuntimeFacts) -> Value { + let anomalies = perf::stats::anomalies(); + json!({ + "format": "iw4l-bench-summary-1", + "run": perf::run::id(), + "zone": facts.zone, + "phases": { + "load": phase(Phase::Load), + "live": phase(Phase::Live), + }, + "audio": audio(), + "recorder": { + "percentile_relative_error": perf::stats::PRECISION, + "unmatched_end": anomalies.unmatched_end, + "reopened": anomalies.reopened, + "counters_never_sampled": perf::stats::counters_never_sampled() + .into_iter() + .map(|counter| counter.name()) + .collect::>(), + "spans_never_sampled": perf::stats::spans_never_sampled() + .into_iter() + .map(|span| span.name()) + .collect::>(), + }, + }) +} + +/// The load-side audio numbers the text report prints, as data. +/// +/// They are not in `phases` above: those are the recorder's per-frame +/// histograms, and these are process totals for work that happens once, on +/// worker threads, before a frame exists. Putting them in the same object +/// would invite a consumer to divide them by a frame count. +fn audio() -> Value { + let prep = audio::clip_prep_cost(); + let xwma = assets::xwma_decode_cost(); + json!({ + "workers": prep.workers, + "requests": prep.requests, + "queued": prep.queued, + "queue_wait_ms": prep.queue_wait_ms, + "late_prepares": prep.late, + "paths": prep.paths.iter().map(|(path, cost)| json!({ + "decoder": path.name(), + "prepared": cost.prepared, + "failed": cost.failed, + "worker_ms": cost.wall_ms, + "resident_pcm_bytes": cost.sample_bytes, + })).collect::>(), + "xwma": { + "cache_hit": xwma.hit, + "cache_miss": xwma.miss, + "ffmpeg_processes": xwma.spawned, + "failed": xwma.failed, + "retried_alone": xwma.retried, + "pcm_bytes": xwma.pcm_bytes, + "decode_ms": xwma.decode_ms, + "key_ms": xwma.key_ms, + "cache_io_ms": xwma.io_ms, + }, + }) +} + +fn phase(phase: Phase) -> Value { + let spans = perf::stats::snapshot(phase); + // The frame clock is the denominator for every per-frame figure, so it is + // named once here rather than recomputed by each consumer — and left null + // when the phase drew no frame, so a consumer dividing by it has to decide + // what that means instead of getting a silent zero. + let frames = spans + .iter() + .find(|row| row.span == perf::Span::FramesWallFrameMs) + .map(|wall| wall.count); + json!({ + "frames": frames, + "spans": spans.iter().map(|row| span(row, frames)).collect::>(), + "counters": perf::stats::counter_snapshot(phase) + .iter() + .map(|row| counter(row, frames)) + .collect::>(), + }) +} + +fn span(row: &SpanStats, frames: Option) -> Value { + json!({ + "name": row.span.name(), + "parent": row.parent.map(perf::Span::name), + "parent_varies": row.parent_varies, + "unit": "ns", + "calls": row.count, + "calls_per_frame": frames.map(|frames| ratio(row.count as f64, frames)), + "cost_per_call_ns": row.avg_ns(), + "cost_per_frame_ns": frames.map(|frames| ratio(row.sum_ns as f64, frames)), + "total_ns": row.sum_ns, + "min_ns": row.min_ns, + "max_ns": row.max_ns, + "p50_ns": row.p50_ns, + "p95_ns": row.p95_ns, + "p99_ns": row.p99_ns, + }) +} + +fn counter(row: &CounterStats, frames: Option) -> Value { + json!({ + "name": row.counter.name(), + "unit": match row.unit { + Unit::Milliseconds => "ms", + Unit::Count => "count", + }, + "origin": match row.origin { + Origin::Cpu => "cpu", + Origin::Gpu => "gpu", + }, + "samples": row.samples, + "rejected": row.rejected, + "samples_per_frame": frames.map(|frames| ratio(row.samples as f64, frames)), + "per_call": row.avg(), + "per_frame": frames.map(|frames| ratio(row.sum, frames)), + "total": row.sum, + "min": row.min, + "max": row.max, + "p50": row.p50, + "p95": row.p95, + "p99": row.p99, + }) +} + +fn ratio(value: f64, frames: u64) -> Option { + (frames > 0).then(|| value / frames as f64) +} diff --git a/crates/bootstrap/src/bench/table.rs b/crates/bootstrap/src/bench/table.rs index 4d4c312..035bf9b 100644 --- a/crates/bootstrap/src/bench/table.rs +++ b/crates/bootstrap/src/bench/table.rs @@ -31,6 +31,18 @@ impl Table { self.rows.push(cells.into_iter().collect()); } + /// A row for something that was asked for and did not answer. Every cell + /// but the name reads MISS, because a metric nobody sampled is not a zero + /// and a table that prints it as one is worse than no table. + pub(crate) fn miss(&mut self, name: &str) { + let mut row = vec![name.to_owned()]; + row.extend(std::iter::repeat_n( + "MISS".to_owned(), + self.headers.len().saturating_sub(1), + )); + self.rows.push(row); + } + pub(crate) fn render(&self, out: &mut Vec) { let mut widths: Vec = self .headers diff --git a/crates/bootstrap/src/launch.rs b/crates/bootstrap/src/launch.rs index 52a140c..4972aad 100644 --- a/crates/bootstrap/src/launch.rs +++ b/crates/bootstrap/src/launch.rs @@ -402,14 +402,7 @@ fn run_map( games_root: games.0.clone(), artifacts, }; - start_perf( - Some(zone.clone()), - match config.role { - Role::Listen => "listen", - Role::Client => "client", - Role::Replay => "replay", - }, - ); + start_perf(Some(zone.clone()), role_name(config.role)); let (menus, menu_report) = load_ui_menu_catalog(&games); for line in &menu_report { diag::info!(Launch, "{line}"); @@ -498,6 +491,13 @@ fn run_map( Role::Listen => add_runtime_plugins(&mut app), Role::Client => add_runtime_plugins_with_role(&mut app, net::RuntimeRole::Client), } + // The demo, before the playback moves into the world: it names the workload + // in the bench manifest, and "same demo" is what makes two runs comparable + // at all. The whole path, not a stem — a clip is `clips//clip.iw4ldemo`, + // whose stem is `clip` for every clip ever recorded. + let demo = playback + .as_ref() + .map(|playback| playback.path().display().to_string()); if let Some(playback) = playback { app.insert_resource(playback); } @@ -506,7 +506,14 @@ fn run_map( } let bench = bench::enabled(); if bench { - bench::insert(&mut app, &zone, &config.artifacts, progress.clone()); + bench::insert( + &mut app, + &zone, + demo.as_deref(), + role_name(config.role), + &config.artifacts, + progress.clone(), + ); } app.run(); let trace = flush_perf(); @@ -550,6 +557,14 @@ fn queue_launch_capture(app: &mut App, request: CaptureRequest) { .push(request); } +const fn role_name(role: Role) -> &'static str { + match role { + Role::Listen => "listen", + Role::Client => "client", + Role::Replay => "replay", + } +} + fn launch_present_mode(acceptance: bool) -> PresentMode { if acceptance { return ACCEPTANCE_PRESENT_MODE; diff --git a/crates/console/src/feature_dispatch.rs b/crates/console/src/feature_dispatch.rs index 688a2aa..b47126b 100644 --- a/crates/console/src/feature_dispatch.rs +++ b/crates/console/src/feature_dispatch.rs @@ -788,10 +788,24 @@ pub(crate) fn resume_lifecycle_commands( #[derive(Resource, Debug, Default, Clone, Copy)] pub struct DebugPosOverlay(pub bool); -pub(crate) fn bookend_wall_frame(mut wall_open: Local) { +/// The frame clock, and with it the one allocation figure that is per frame +/// rather than per system: the process-wide count since the previous bookend. +/// It is emitted where the clock closes so the count and the frame it belongs +/// to are the same interval. +pub(crate) fn bookend_wall_frame(mut wall_open: Local, mut allocations: Local>) { if *wall_open { perf::Span::FramesWallFrameMs.end(); } + // Only when the allocator is actually counting: otherwise the total is a + // constant zero and the delta would publish "no allocations this frame", + // which is a different claim from "nobody counted". + if perf::stats::enabled() && diag::counting_enabled() { + let total = diag::process_allocations().process_allocations; + if let Some(previous) = *allocations { + perf::Counter::CounterProcessAllocations.emit(total.saturating_sub(previous) as f64); + } + *allocations = Some(total); + } perf::Span::FramesWallFrameMs.begin(); *wall_open = true; } diff --git a/crates/diag/src/alloc_count.rs b/crates/diag/src/alloc_count.rs index 0d1c82a..90a4e36 100644 --- a/crates/diag/src/alloc_count.rs +++ b/crates/diag/src/alloc_count.rs @@ -75,7 +75,11 @@ fn record_dealloc(size: u64) { s.dealloc_bytes.fetch_add(size, Ordering::Relaxed); } -fn counting_enabled() -> bool { +/// Whether the counting allocator is actually counting. It is off unless +/// `IW4L_COUNTING_ALLOC` is set, so every figure derived from it is absent +/// rather than zero on an ordinary run — and a caller that cannot tell those +/// apart will report "no allocations" for "nobody was counting". +pub fn counting_enabled() -> bool { static STATE: AtomicU8 = AtomicU8::new(2); match STATE.load(Ordering::Relaxed) { 0 => false, diff --git a/crates/diag/src/lib.rs b/crates/diag/src/lib.rs index ef15f6d..a99bf87 100644 --- a/crates/diag/src/lib.rs +++ b/crates/diag/src/lib.rs @@ -3,9 +3,9 @@ pub mod gap; pub mod wgsl_dump; pub use alloc_count::{ - ProcessAllocationStats, ProcessCountingAllocator, process_allocation_saturated, - process_allocation_slots_used, process_allocations, process_live_heap_bytes, - release_freed_heap, + ProcessAllocationStats, ProcessCountingAllocator, counting_enabled, + process_allocation_saturated, process_allocation_slots_used, process_allocations, + process_live_heap_bytes, release_freed_heap, }; use std::{ diff --git a/crates/perf/src/lib.rs b/crates/perf/src/lib.rs index 44ccfa9..0223069 100644 --- a/crates/perf/src/lib.rs +++ b/crates/perf/src/lib.rs @@ -3,6 +3,7 @@ mod event; #[cfg(not(all(unix, feature = "native")))] #[path = "event_noop.rs"] mod event; +pub mod run; #[cfg(all(unix, feature = "native"))] mod session; #[cfg(not(all(unix, feature = "native")))] @@ -23,5 +24,16 @@ pub use event::{ world_ready, }; pub use session::{RunMetadata, enabled, flush, start}; -pub use stats::{Anomalies, Phase, SpanStats}; + +/// Whether *any* recorder is listening: the Perfetto session (`IW4L_PERF`) or +/// the in-process bench statistics (`IW4L_BENCH`). Census code that only asked +/// [`enabled`] was silently free on a `IW4L_BENCH=1` run, which left the bench +/// report's counter tables empty and indistinguishable from a workload that +/// genuinely never drew anything. +#[inline] +pub fn recording() -> bool { + stats::enabled() || enabled() +} +pub use stats::{Anomalies, CounterStats, Phase, SpanStats}; pub use vocabulary::{Counter, Span, SpanGuard}; +pub use vocabulary_types::{Origin, Unit}; diff --git a/crates/perf/src/run.rs b/crates/perf/src/run.rs new file mode 100644 index 0000000..4ee92f7 --- /dev/null +++ b/crates/perf/src/run.rs @@ -0,0 +1,38 @@ +//! One run, one directory. +//! +//! The trace, its manifest and the bench report are three views of a single +//! execution, and a reader comparing two runs should not have to pair them up +//! by timestamp. So the id is minted here rather than by whichever recorder +//! happens to start first, and a run has the same name whether `IW4L_PERF`, +//! `IW4L_BENCH` or both are set. +//! +//! Nothing is created until something asks. A process that records neither +//! leaves no directory behind. + +use std::path::PathBuf; +use std::sync::OnceLock; + +static RUN: OnceLock> = OnceLock::new(); + +fn slot() -> &'static Result<(PathBuf, String), String> { + RUN.get_or_init(|| { + let id = uuid::Uuid::new_v4().to_string(); + let dir = PathBuf::from("iw4l-artifacts/runs").join(&id); + std::fs::create_dir_all(&dir) + .map_err(|error| format!("create {}: {error}", dir.display()))?; + Ok((dir, id)) + }) +} + +/// This run's directory, created on the first ask, or the error that stopped it. +pub fn dir() -> Result { + match slot() { + Ok((dir, _)) => Ok(dir.clone()), + Err(error) => Err(error.clone()), + } +} + +/// This run's UUID — the name of [`dir`] — or `None` if it could not be made. +pub fn id() -> Option { + slot().as_ref().ok().map(|(_, id)| id.clone()) +} diff --git a/crates/perf/src/session.rs b/crates/perf/src/session.rs index 26e6e1f..0ced87b 100644 --- a/crates/perf/src/session.rs +++ b/crates/perf/src/session.rs @@ -68,9 +68,7 @@ pub fn start(metadata: RunMetadata) -> Result, String> { return Ok(Some(state.dir.clone())); } - let id = uuid::Uuid::new_v4(); - let dir = PathBuf::from("iw4l-artifacts/runs").join(id.to_string()); - std::fs::create_dir_all(&dir).map_err(|error| format!("create {}: {error}", dir.display()))?; + let dir = crate::run::dir()?; Producer::init( ProducerInitArgsBuilder::new() diff --git a/crates/perf/src/stats.rs b/crates/perf/src/stats.rs index ea4cbf1..437e614 100644 --- a/crates/perf/src/stats.rs +++ b/crates/perf/src/stats.rs @@ -18,7 +18,7 @@ use std::sync::OnceLock; use std::sync::atomic::{AtomicBool, AtomicU8, AtomicU32, AtomicU64, Ordering}; use std::time::Instant; -use crate::vocabulary_types::Span; +use crate::vocabulary_types::{Counter, Origin, Span, Unit}; const ENV: &str = "IW4L_BENCH"; @@ -92,6 +92,19 @@ static REOPENED: AtomicU64 = AtomicU64::new(0); static HISTOGRAMS: [[Histogram; Span::COUNT]; Phase::COUNT] = [const { [const { Histogram::ZERO }; Span::COUNT] }; Phase::COUNT]; +/// Counters get the same histogram as spans, one per phase. A [`Unit::Count`] +/// sample is stored as the count itself and a [`Unit::Milliseconds`] one as +/// nanoseconds, so both keep the histogram's precision without a second scale. +static COUNTERS: [[Histogram; Counter::COUNT]; Phase::COUNT] = + [const { [const { Histogram::ZERO }; Counter::COUNT] }; Phase::COUNT]; + +/// Samples an emitter handed us that the histogram cannot hold: NaN, infinity +/// or a negative value. Counted rather than clamped, because a counter that +/// goes negative is a bug in the emitter and silently recording a zero for it +/// would hide that behind a plausible number. +static COUNTER_REJECTED: [AtomicU64; Counter::COUNT] = + [const { AtomicU64::new(0) }; Counter::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 @@ -200,10 +213,34 @@ fn remember_parent(span: Span, parent: Option) { } } +/// One counter sample, in whatever unit [`Counter::unit`] declares. Called +/// from `Counter::emit` before the Perfetto category gate, so the bench report +/// sees the value whether or not a trace is being written. +#[inline] +pub(crate) fn count(counter: Counter, value: f64) { + if !enabled() { + return; + } + let phase = phase_index(); + if !value.is_finite() || value < 0.0 { + COUNTER_REJECTED[counter as usize].fetch_add(1, Ordering::Relaxed); + return; + } + let stored = match counter.unit() { + Unit::Milliseconds => value * 1e6, + Unit::Count => value, + }; + COUNTERS[phase][counter as usize].record(stored as u64); +} + +#[inline] +fn phase_index() -> usize { + (PHASE.load(Ordering::Relaxed) as usize).min(Phase::COUNT - 1) +} + #[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); + HISTOGRAMS[phase_index()][span as usize].record(ns); } /// Values below [`SUB`] are their own bucket; above it, `SUB` buckets cover @@ -278,6 +315,124 @@ pub fn snapshot(phase: Phase) -> Vec { .collect() } +/// What one counter recorded over one phase. `sum`, `min`, `max` and the +/// percentiles are in the counter's own [`Unit`]; nothing here is comparable +/// across units, which is why the unit travels with the row. +#[derive(Clone, Copy, Debug)] +pub struct CounterStats { + pub counter: Counter, + pub unit: Unit, + pub origin: Origin, + /// Samples the emitter produced. Not the frame count: a counter emitted + /// twice a frame has twice as many, and one the GPU could not resolve has + /// fewer. + pub samples: u64, + /// Samples refused as not finite or negative. They are in no other number + /// on this row. + pub rejected: u64, + pub sum: f64, + pub min: f64, + pub max: f64, + pub p50: f64, + pub p95: f64, + pub p99: f64, +} + +impl CounterStats { + /// The mean of one sample — the cost or size of a single emission. For a + /// counter emitted more than once a frame this is *not* the per-frame + /// figure; divide `sum` by the frame count for that. + pub fn avg(&self) -> f64 { + if self.samples == 0 { + return 0.0; + } + self.sum / self.samples as f64 + } + + /// How many samples this counter produced per frame of the phase. + pub fn per_frame_samples(&self, frames: u64) -> Option { + (frames > 0).then(|| self.samples as f64 / frames as f64) + } + + /// The counter's total spread over the frames of the phase. This is the + /// number to compare against a frame budget; `avg` is not. + pub fn per_frame(&self, frames: u64) -> Option { + (frames > 0).then(|| self.sum / frames as f64) + } +} + +/// Every counter that took at least one sample in `phase`, in declaration +/// order. A counter that was never emitted is absent rather than zero: the +/// report has to be able to say MISS. +pub fn counter_snapshot(phase: Phase) -> Vec { + let histograms = &COUNTERS[phase.index()]; + Counter::ALL + .into_iter() + .filter_map(|counter| { + let histogram = &histograms[counter as usize]; + let samples = histogram.count.load(Ordering::Relaxed); + let rejected = COUNTER_REJECTED[counter as usize].load(Ordering::Relaxed); + if samples == 0 && rejected == 0 { + return None; + } + let quantiles = quantiles(histogram, samples.max(1), &[0.50, 0.95, 0.99]); + let scale = |stored: u64| match counter.unit() { + Unit::Milliseconds => stored as f64 / 1e6, + Unit::Count => stored as f64, + }; + Some(CounterStats { + counter, + unit: counter.unit(), + origin: counter.origin(), + samples, + rejected, + sum: scale(histogram.sum_ns.load(Ordering::Relaxed)), + min: if samples == 0 { + 0.0 + } else { + scale(histogram.min_ns.load(Ordering::Relaxed)) + }, + max: scale(histogram.max_ns.load(Ordering::Relaxed)), + p50: scale(quantiles[0]), + p95: scale(quantiles[1]), + p99: scale(quantiles[2]), + }) + }) + .collect() +} + +/// Counters this build declares but that took no sample at all in either +/// phase. A name here is either instrumentation that never ran on this +/// workload or a counter nothing emits any more; the report prints them so a +/// reader does not mistake an absent row for a zero. +pub fn counters_never_sampled() -> Vec { + Counter::ALL + .into_iter() + .filter(|counter| { + COUNTERS + .iter() + .all(|phase| phase[*counter as usize].count.load(Ordering::Relaxed) == 0) + && COUNTER_REJECTED[*counter as usize].load(Ordering::Relaxed) == 0 + }) + .collect() +} + +/// Spans this build declares that opened in neither phase. The tree can only +/// print what took a sample, so without this a span whose producer was deleted +/// or compiled out looks exactly like a span the workload never reached — and +/// the first is a hole in the instrumentation while the second is a fact about +/// the run. +pub fn spans_never_sampled() -> Vec { + Span::ALL + .into_iter() + .filter(|span| { + HISTOGRAMS + .iter() + .all(|phase| phase[*span as usize].count.load(Ordering::Relaxed) == 0) + }) + .collect() +} + fn parent_of(span: Span) -> Option { let parent = PARENT[span as usize].load(Ordering::Relaxed); if parent == NO_PARENT { @@ -331,6 +486,32 @@ pub fn anomalies() -> Anomalies { mod tests { use super::*; + #[test] + fn the_declaration_order_arrays_index_their_own_enums() { + // The recorder indexes `COUNTERS` and `HISTOGRAMS` by `x as usize` and + // reads them back by walking `ALL`. If a variant is added to one and + // not the other, every row after it reports another row's samples. + for (index, span) in Span::ALL.into_iter().enumerate() { + assert_eq!(span as usize, index, "{} is out of order", span.name()); + } + for (index, counter) in Counter::ALL.into_iter().enumerate() { + assert_eq!( + counter as usize, + index, + "{} is out of order", + counter.name() + ); + } + } + + #[test] + fn a_millisecond_counter_reads_back_in_milliseconds() { + let histogram = Histogram::ZERO; + histogram.record((4.5 * 1e6) as u64); + let stored = histogram.sum_ns.load(Ordering::Relaxed); + assert!((stored as f64 / 1e6 - 4.5).abs() < 1e-6); + } + #[test] fn every_value_lands_in_a_bucket_that_contains_it() { for ns in [ diff --git a/crates/perf/src/vocabulary.rs b/crates/perf/src/vocabulary.rs index 57e6546..5eb03c0 100644 --- a/crates/perf/src/vocabulary.rs +++ b/crates/perf/src/vocabulary.rs @@ -19,7 +19,7 @@ pub(crate) fn register_categories() { pub use crate::vocabulary_types::Span; -const SPAN_COUNT: usize = Span::TocUi as usize + 1; +const SPAN_COUNT: usize = Span::COUNT; static SPAN_TRACKS: [OnceLock; SPAN_COUNT] = [const { OnceLock::new() }; SPAN_COUNT]; @@ -182,7 +182,7 @@ impl Drop for SpanGuard { pub use crate::vocabulary_types::Counter; -const COUNTER_COUNT: usize = Counter::SmodelIbSkip as usize + 1; +const COUNTER_COUNT: usize = Counter::COUNT; static COUNTER_TRACKS: [OnceLock; COUNTER_COUNT] = [const { OnceLock::new() }; COUNTER_COUNT]; @@ -195,43 +195,7 @@ enum CounterCategory { impl Counter { fn track_name(self) -> &'static str { - match self { - Self::CounterBindGroup0 => "bind0", - Self::CounterBindGroup1 => "bind1", - Self::CounterCmdState => "cmd_state", - Self::CounterMultiDraws => "multi_draw", - Self::CounterMultiDrawCommands => "multi_draw_cmds", - Self::CounterDipsColour => "dip_colour", - Self::CounterDipsSun => "dip_sun", - Self::CounterDraws => "draws", - Self::CounterFxElemAllocFail => "fx_elem_alloc_fail", - Self::CounterFxElemLive => "fx_elem_live", - Self::CounterProcessAllocations => "process_allocations", - Self::CounterSubmittedBatches => "batches", - Self::RenderGraphRenderMs => "graph_render", - Self::RenderGraphSubmitMs => "graph_submit", - Self::RenderSubmitSunMs => "submit_sun", - Self::RenderSubmitGatherMs => "submit_gather", - Self::RenderSubmitPrepareMs => "submit_prepare", - Self::RenderSubmitArenaMs => "submit_arena", - Self::RenderSubmitRecordMs => "submit_record", - Self::RenderGraphPresentMs => "graph_present", - Self::RenderGpuColourMs => "gpu_colour", - Self::RenderGpuSunMs => "gpu_sun", - Self::RenderGpuSpotMs => "gpu_spot", - Self::RenderGpuFloatzMs => "gpu_floatz", - Self::RenderGpuPostfxMs => "gpu_postfx", - Self::RenderGpuFrameMs => "gpu_frame", - Self::SpotShadowGpu => "spot_shadow_gpu", - Self::SpotShadowGpuMiss => "spot_shadow_gpu_miss", - Self::SpotShadowSlotN => "spot_shadow_slot_n", - Self::XmodelColourCameraFrustum => "xmodel_colour_camera_frustum", - Self::XmodelColourNoLighting => "xmodel_colour_no_lighting", - Self::XmodelLayoutOverlay => "xmodel_layout_overlay", - Self::FxLayoutOverlay => "fx_layout_overlay", - Self::WorldPretessSkip => "world_pretess_skip", - Self::SmodelIbSkip => "smodel_ib_skip", - } + self.name() } fn category(self) -> CounterCategory { @@ -254,6 +218,7 @@ impl Counter { #[inline] pub fn emit(self, value: f64) { + crate::stats::count(self, value); macro_rules! emit { ($category:literal) => {{ if !perfetto_sdk::track_event_category_enabled!($category) { diff --git a/crates/perf/src/vocabulary_noop.rs b/crates/perf/src/vocabulary_noop.rs index 0a575ef..67e0277 100644 --- a/crates/perf/src/vocabulary_noop.rs +++ b/crates/perf/src/vocabulary_noop.rs @@ -10,15 +10,26 @@ impl Span { } pub fn enter(self) -> SpanGuard { - SpanGuard + self.begin(); + SpanGuard { span: self } } } #[must_use = "the span closes when this guard drops"] -pub struct SpanGuard; +pub struct SpanGuard { + span: Span, +} + +impl Drop for SpanGuard { + fn drop(&mut self) { + self.span.end(); + } +} pub use crate::vocabulary_types::Counter; impl Counter { - pub fn emit(self, _value: f64) {} + pub fn emit(self, value: f64) { + crate::stats::count(self, value); + } } diff --git a/crates/perf/src/vocabulary_types.rs b/crates/perf/src/vocabulary_types.rs index 2d6a79c..3354a7d 100644 --- a/crates/perf/src/vocabulary_types.rs +++ b/crates/perf/src/vocabulary_types.rs @@ -171,3 +171,145 @@ impl Span { } } } + +/// What a counter's value means, so the report can label it and refuse to add +/// milliseconds to draw calls. A counter is one or the other for its whole +/// life; there is no counter whose unit depends on the frame. +#[derive(Clone, Copy, Debug, PartialEq, Eq)] +pub enum Unit { + /// A duration, emitted in milliseconds. + Milliseconds, + /// A count of things that happened in the frame the sample belongs to. + Count, +} + +impl Counter { + pub const COUNT: usize = Self::SmodelIbSkip as usize + 1; + + /// Every counter, in declaration order. The recorder indexes its arrays by + /// `counter as usize`, so this and the enum must not drift. + pub const ALL: [Self; Self::COUNT] = [ + Self::CounterBindGroup0, + Self::CounterBindGroup1, + Self::CounterCmdState, + Self::CounterMultiDraws, + Self::CounterMultiDrawCommands, + Self::CounterDipsColour, + Self::CounterDipsSun, + Self::CounterDraws, + Self::CounterFxElemAllocFail, + Self::CounterFxElemLive, + Self::CounterProcessAllocations, + Self::CounterSubmittedBatches, + Self::RenderGraphRenderMs, + Self::RenderGraphSubmitMs, + Self::RenderGraphPresentMs, + Self::RenderSubmitSunMs, + Self::RenderSubmitGatherMs, + Self::RenderSubmitPrepareMs, + Self::RenderSubmitArenaMs, + Self::RenderSubmitRecordMs, + Self::RenderGpuColourMs, + Self::RenderGpuSunMs, + Self::RenderGpuSpotMs, + Self::RenderGpuFloatzMs, + Self::RenderGpuPostfxMs, + Self::RenderGpuFrameMs, + Self::SpotShadowGpu, + Self::SpotShadowGpuMiss, + Self::SpotShadowSlotN, + Self::XmodelColourCameraFrustum, + Self::XmodelColourNoLighting, + Self::XmodelLayoutOverlay, + Self::FxLayoutOverlay, + Self::WorldPretessSkip, + Self::SmodelIbSkip, + ]; + + /// The name the counter carries in a trace and in the bench report. + pub const fn name(self) -> &'static str { + match self { + Self::CounterBindGroup0 => "bind0", + Self::CounterBindGroup1 => "bind1", + Self::CounterCmdState => "cmd_state", + Self::CounterMultiDraws => "multi_draw", + Self::CounterMultiDrawCommands => "multi_draw_cmds", + Self::CounterDipsColour => "dip_colour", + Self::CounterDipsSun => "dip_sun", + Self::CounterDraws => "draws", + Self::CounterFxElemAllocFail => "fx_elem_alloc_fail", + Self::CounterFxElemLive => "fx_elem_live", + Self::CounterProcessAllocations => "process_allocations", + Self::CounterSubmittedBatches => "batches", + Self::RenderGraphRenderMs => "graph_render", + Self::RenderGraphSubmitMs => "graph_submit", + Self::RenderGraphPresentMs => "graph_present", + Self::RenderSubmitSunMs => "submit_sun", + Self::RenderSubmitGatherMs => "submit_gather", + Self::RenderSubmitPrepareMs => "submit_prepare", + Self::RenderSubmitArenaMs => "submit_arena", + Self::RenderSubmitRecordMs => "submit_record", + Self::RenderGpuColourMs => "gpu_colour", + Self::RenderGpuSunMs => "gpu_sun", + Self::RenderGpuSpotMs => "gpu_spot", + Self::RenderGpuFloatzMs => "gpu_floatz", + Self::RenderGpuPostfxMs => "gpu_postfx", + Self::RenderGpuFrameMs => "gpu_frame", + Self::SpotShadowGpu => "spot_shadow_gpu", + Self::SpotShadowGpuMiss => "spot_shadow_gpu_miss", + Self::SpotShadowSlotN => "spot_shadow_slot_n", + Self::XmodelColourCameraFrustum => "xmodel_colour_camera_frustum", + Self::XmodelColourNoLighting => "xmodel_colour_no_lighting", + Self::XmodelLayoutOverlay => "xmodel_layout_overlay", + Self::FxLayoutOverlay => "fx_layout_overlay", + Self::WorldPretessSkip => "world_pretess_skip", + Self::SmodelIbSkip => "smodel_ib_skip", + } + } + + /// The unit the emitter passes. `emit` takes an `f64` either way, so this + /// is the only thing that tells a millisecond from a draw call. + pub const fn unit(self) -> Unit { + match self { + Self::RenderGraphRenderMs + | Self::RenderGraphSubmitMs + | Self::RenderGraphPresentMs + | Self::RenderSubmitSunMs + | Self::RenderSubmitGatherMs + | Self::RenderSubmitPrepareMs + | Self::RenderSubmitArenaMs + | Self::RenderSubmitRecordMs + | Self::RenderGpuColourMs + | Self::RenderGpuSunMs + | Self::RenderGpuSpotMs + | Self::RenderGpuFloatzMs + | Self::RenderGpuPostfxMs + | Self::RenderGpuFrameMs => Unit::Milliseconds, + _ => Unit::Count, + } + } + + /// Where the number was measured. A GPU counter is a timestamp the driver + /// resolved some frames after the CPU one next to it, which is why the + /// report never puts the two in the same total. + pub const fn origin(self) -> Origin { + match self { + Self::RenderGpuColourMs + | Self::RenderGpuSunMs + | Self::RenderGpuSpotMs + | Self::RenderGpuFloatzMs + | Self::RenderGpuPostfxMs + | Self::RenderGpuFrameMs + | Self::SpotShadowGpu + | Self::SpotShadowGpuMiss => Origin::Gpu, + _ => Origin::Cpu, + } + } +} + +/// Which side of the device a counter was measured on. +#[derive(Clone, Copy, Debug, PartialEq, Eq)] +pub enum Origin { + Cpu, + Gpu, +} diff --git a/crates/render_anim/src/occupancy/script_model.rs b/crates/render_anim/src/occupancy/script_model.rs index dcc1ef4..2c5d2d2 100644 --- a/crates/render_anim/src/occupancy/script_model.rs +++ b/crates/render_anim/src/occupancy/script_model.rs @@ -191,7 +191,7 @@ impl RenderFocusSelect { return Err(format!("{PERF_FOCUS_ENV} is not valid UTF-8")); } }; - if !perf::enabled() { + if !perf::recording() { return Err(format!( "{PERF_FOCUS_ENV} requires IW4L_PERF=1; focused facts exist only in .pftrace" )); diff --git a/crates/render_gpu/src/drawsurf/colour_submit/prepare_camera.rs b/crates/render_gpu/src/drawsurf/colour_submit/prepare_camera.rs index df5aacf..a3500de 100644 --- a/crates/render_gpu/src/drawsurf/colour_submit/prepare_camera.rs +++ b/crates/render_gpu/src/drawsurf/colour_submit/prepare_camera.rs @@ -52,7 +52,7 @@ pub(super) fn prepare_camera_colour( let extracted = ExtractedColourRefs::new(&world, &frame); let products = &extracted.frame.frame_products; *cam = CameraPrepareState::default(); - let census_on = perf::enabled(); + let census_on = perf::recording(); if census_on { reset_exact_colour_census(&mut census); } diff --git a/crates/render_gpu/src/drawsurf/colour_submit/record.rs b/crates/render_gpu/src/drawsurf/colour_submit/record.rs index 619345f..fe4bcf7 100644 --- a/crates/render_gpu/src/drawsurf/colour_submit/record.rs +++ b/crates/render_gpu/src/drawsurf/colour_submit/record.rs @@ -61,7 +61,7 @@ pub(super) fn draw_exact_colour( let extracted = ExtractedColourRefs::new(&world, &frame); let products = &extracted.frame.frame_products; let _colour_submit = perf::Span::RenderColourSubmitMs.enter(); - let census_on = perf::enabled(); + let census_on = perf::recording(); *working_set = crate::ColourWorkingSet::default(); if pipeline.ports.is_empty() { @@ -666,7 +666,7 @@ pub(super) fn copy_submit_prepare_ms( census: Res, slot: Option>, ) { - if !perf::enabled() { + if !perf::recording() { return; } diff --git a/docs/BENCH.md b/docs/BENCH.md index d8c5f26..7bf2fdb 100644 --- a/docs/BENCH.md +++ b/docs/BENCH.md @@ -1,49 +1,50 @@ -# `make bench` — two reports, one run +# `make bench` — three reports, one run -`IW4L_BENCH=1` turns on an in-process recorder. At exit it prints two +`IW4L_BENCH=1` turns on an in-process recorder. At exit it prints three 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. +Neither needs a trace file or Trace Processor; any can be MISS while the others +stand. ```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. +**[1/3] 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), then the load-pool stages. A stage's own duration says nothing on a +parallel walk, so the table carries `exclusive`: the time that stage was the +only one open, an *upper bound* on what deleting it could save and not the +saving. Mean occupancy is how many stages overlapped, not a speed-up and not +busy cores. A stage's RSS delta is the whole process across its window, so the +deltas do not add up and none is that stage's ownership. Match audio is split by +the decoder each clip took, in worker time: one stage row cannot tell a cheap +byte loop from an external `ffmpeg`. Plus the frames drawn behind the loading +screen and a settled screenshot under `screenshots/bench/.png`; eyeball it +for geometry that never arrived. -**[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. +**[2/3] Frame time** — every typed span from [`PERF.md`](PERF.md), as a tree, +for the frames *after* the first playable one. `avg` is one call and `per frame` +is what one frame paid for all of them; only the second belongs next to a frame +budget. `self` is a span's total minus the spans nested inside it — on a thread +that waits, that can be the wait. The ranking below the tree is by `self` and +includes parents: a parent with cheap children and an expensive body is in no +leaf. A span's parent is whichever span was open when it began; `*` means more +than one was seen. `wall` is the frame clock and encloses nothing. + +**[3/3] Counters** — the render stages (`submit_prepare/gather/arena/record`, +`graph_render/submit/present`), the GPU passes, and the per-frame work census +(draws, batches, multi-draw, bind groups). A counter nobody sampled prints MISS, +never `0.00`. GPU passes overlap and resolve some frames late, so they are never +summed; `gpu_frame` is the measured interval. Counters this build declares and +this run never sampled are named at the end. 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. +±3.1% of their own value. Counts, sums, minima and maxima are exact. -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. +The run's own directory holds `report.txt`, `manifest.json` (the revision, +toolchain, adapter, window, pools, env toggles and cache state — absent facts +are `null`, never a plausible default) and `summary.json` (the same spans, +counters and audio totals as data), beside the `trace.pftrace` the run recorded. diff --git a/docs/INDEX.md b/docs/INDEX.md index e60a8fc..1e900db 100644 --- a/docs/INDEX.md +++ b/docs/INDEX.md @@ -10,7 +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" | +| [`BENCH.md`](BENCH.md) | `make bench`: the map-load waterfall and stage `exclusive` time, frame time as a span tree, the render/GPU/work counters, and the run package (`manifest.json`, `summary.json`); 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/MAP-LOAD.md b/docs/MAP-LOAD.md index a7fee3b..e880b84 100644 --- a/docs/MAP-LOAD.md +++ b/docs/MAP-LOAD.md @@ -40,10 +40,11 @@ half-installed resources. Commit publishes it, boots the sim, writes ## Cache, and poking it: `iw4l-artifacts/cache//`, content-addressed -Leaf in `asset_transport::artifact_cache` (`cache_get` / `cache_put`, `fnv1a64`). -A miss is silent — the caller computes the value anyway — and a hit must be the -**same bytes** a miss would have written. The key names every input; if the -encoder changed, bump the format word. Live kinds: `mips`, `wgsl`. `IW4L_GAMES` -is the root holding the game trees; no folder name is hardcoded and the container -version picks the decoder. Live it is `make map mp_boneyard` ([`RUN.md`](RUN.md)), -with stages in `LoadProgress` and the `.pftrace`. +Leaf in `asset_transport::artifact_cache` (`cache_get` / `cache_put`, +`fnv1a64`). A miss is silent — the caller computes the value anyway — and a hit +must be the **same bytes** a miss would have written. The key names every input; +if the encoder changed, bump the format word. Live kinds: `mips`, `wgsl`, +`localize` and `xwma_pcm`, whose miss is a batched external `ffmpeg`. +`IW4L_GAMES` is the root holding the game trees; no folder name is hardcoded and +the container version picks the decoder. Live it is `make map mp_boneyard` +([`RUN.md`](RUN.md)), with stages in `LoadProgress` and the `.pftrace`. diff --git a/docs/PERF.md b/docs/PERF.md index fdf3256..6178ada 100644 --- a/docs/PERF.md +++ b/docs/PERF.md @@ -8,6 +8,7 @@ rather than one frame, is [`BENCH.md`](BENCH.md). ```bash make bench-live # record + compact p50/p90/p95/p99/hot-path report make bench-overhead # 10 alternating on/off pairs + paired 95% CI +make bench-overhead VAR=IW4L_BENCH # the same, for the in-process bench recorder cargo xtask perf-overhead --pairs 10 --bin target/play/iw4l --zone mp_highrise --cmds 'wait world; wait 8s; quit' --focus script_model:192 make scenario # scripted match: IW4L_PERF=1, then cargo xtask scenario make chaos # RPG splash run: IW4L_PERF=1, then cargo xtask chaos diff --git a/xtask/src/perf_overhead.rs b/xtask/src/perf_overhead.rs index ec5e8bc..6c78b1a 100644 --- a/xtask/src/perf_overhead.rs +++ b/xtask/src/perf_overhead.rs @@ -13,6 +13,35 @@ struct Config { zone: String, commands: String, focus: Option, + /// The recorder the on-arm turns on. `IW4L_PERF` is the Perfetto session; + /// `IW4L_BENCH` is the in-process recorder that feeds `make bench`, whose + /// cost is a different question with a different answer. + var: Recorder, +} + +/// Which recorder is being measured. A closed set rather than a free-form +/// variable name: a typo would otherwise run both arms identically and report +/// its own noise as the overhead of something. +#[derive(Clone, Copy, PartialEq, Eq)] +enum Recorder { + Perf, + Bench, +} + +impl Recorder { + const fn env(self) -> &'static str { + match self { + Self::Perf => "IW4L_PERF", + Self::Bench => "IW4L_BENCH", + } + } + + /// Whether an on-arm of this recorder leaves a `trace.pftrace` behind. + /// Only the Perfetto session writes one; the bench recorder writes a report + /// and a manifest, and counting traces would expect a file it never makes. + const fn writes_trace(self) -> bool { + matches!(self, Self::Perf) + } } struct Pair { @@ -41,6 +70,7 @@ fn parse(root: &Path, args: Vec) -> Result { let mut zone = "mp_boneyard".to_owned(); let mut commands = None; let mut focus = None; + let mut var = Recorder::Perf; let mut args = args.into_iter(); while let Some(flag) = args.next() { let value = args @@ -62,6 +92,17 @@ fn parse(root: &Path, args: Vec) -> Result { "--zone" => zone = value, "--cmds" => commands = Some(value), "--focus" => focus = Some(value), + "--var" => { + var = match value.as_str() { + "IW4L_PERF" => Recorder::Perf, + "IW4L_BENCH" => Recorder::Bench, + other => { + return Err(format!( + "unknown --var {other}: expected IW4L_PERF or IW4L_BENCH" + )); + } + } + } _ => return Err(format!("unknown flag: {flag}\n{}", usage())), } } @@ -91,11 +132,12 @@ fn parse(root: &Path, args: Vec) -> Result { zone, commands, focus, + var, }) } fn usage() -> String { - "usage: cargo xtask perf-overhead --pairs N --warmup-pairs N --bin PATH [--workdir PATH] --zone ZONE --cmds SCRIPT [--focus SELECTOR]" + "usage: cargo xtask perf-overhead --pairs N --warmup-pairs N --bin PATH [--workdir PATH] --zone ZONE --cmds SCRIPT [--focus SELECTOR] [--var IW4L_PERF|IW4L_BENCH]" .to_owned() } @@ -107,7 +149,7 @@ fn run_inner(root: &Path, config: Result) -> Result<(), String> if let Some(focus) = &config.focus { println!("comparison: focus={focus} / no-focus (IW4L_PERF=1 in both arms)"); } else { - println!("comparison: IW4L_PERF on / off"); + println!("comparison: {} on / off", config.var.env()); } println!( "design: {} warmup pair(s), {} measured AB/BA pair(s)", @@ -180,16 +222,18 @@ fn run_once(config: &Config, enabled: bool) -> Result { .args(["map", &config.zone, "--cmds", &config.commands]) .stdout(Stdio::piped()) .stderr(Stdio::piped()); + // Both recorders are cleared first: whichever one the caller inherited + // would otherwise sit in the off-arm and be measured as no overhead at all. command.env_remove("IW4L_PERF_FOCUS"); + command.env_remove("IW4L_PERF"); + command.env_remove("IW4L_BENCH"); if let Some(focus) = &config.focus { command.env("IW4L_PERF", "1"); if enabled { command.env("IW4L_PERF_FOCUS", focus); } } else if enabled { - command.env("IW4L_PERF", "1"); - } else { - command.env_remove("IW4L_PERF"); + command.env(config.var.env(), "1"); } let started = Instant::now(); let output = command @@ -207,7 +251,7 @@ fn run_once(config: &Config, enabled: bool) -> Result { } let after = trace_runs(&config.workdir)?; let added = after.difference(&before).count(); - let expected = usize::from(config.focus.is_some() || enabled); + let expected = usize::from(config.focus.is_some() || (enabled && config.var.writes_trace())); if added != expected { return Err(format!( "{} run created {added} trace(s), expected {expected}; do not benchmark alongside another recorder",