mirror of
https://github.com/vladtrc/iw4L
synced 2026-10-25 18:05:19 -04:00
Package what each run measured, and decode the match's audio once.
`make bench` printed two reports and left nothing behind but a text file, so a number could be compared with another number from the same afternoon and not much else. It now prints three and writes the run's own directory: `report.txt`, `manifest.json` and `summary.json` beside the `trace.pftrace`. Section [3/3] is the counters — the render stages, the GPU passes, and the per-frame work census. A counter nobody sampled prints MISS rather than `0.00`, and the counters and spans this build declares but this run never reached are named at the end, so a hole in the instrumentation cannot read as a fact about the workload. GPU passes overlap and resolve late, so they are never summed. `manifest.json` says what produced the number: the revision, the dirty flag, the toolchain, the profile cargo actually built under, the locked `bevy` and `wgpu`, the adapter and whether its device can time a pass, the window, the pools, the env toggles and the cache state. The build half is baked in at compile time, because asking `git` at runtime names the tree the process is standing in rather than the build. A fact nobody could read is `null`, never a plausible default. Reading that report, `preparing match audio` was the largest stage of every load — one row holding one number, which cannot tell a thousand cheap byte loops from five hundred external processes. It is the second. Section [1/3] now splits the stage by the decoder each clip took, in worker time, and counts what each one prepared, failed, held and left resident. The T5 XWMA decode goes through the artifact cache under `xwma_pcm`, keyed on every input the decode reads, so a clip is decoded once per machine rather than once per launch. A cold load still had to pay the first time: 515 `ffmpeg` processes, 18.9 s of worker time, almost none of it decoding. A worker now takes the jobs already queued and answers up to 64 clips through one process — every clip its own input and its own output, nothing concatenated — which is 1.3 s for the same bytes. Failure stays per clip: a batch `ffmpeg` refuses is re-asked one clip at a time, leaving the bad clip as the only failure. `make bench-overhead` can point at either recorder, `VAR=IW4L_PERF` or `VAR=IW4L_BENCH`; they are separate costs and each needs its own pairs. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
This commit is contained in:
vtroc
Generated
+1
@@ -1812,6 +1812,7 @@ dependencies = [
|
||||
"render",
|
||||
"render_frontend",
|
||||
"replay",
|
||||
"serde_json",
|
||||
"session",
|
||||
"sim",
|
||||
"ui",
|
||||
|
||||
@@ -97,10 +97,12 @@ play: require-games
|
||||
@test -n "$(ARGS)" || { echo "usage: make play <demoname> e.g. make play demo0000"; exit 1; }
|
||||
cd $(ROOT) && $(CARGO) run $(PROFILE_ARG) -p launcher -- play $(ARGS) $(ZONE_ARG) $(CMDS_ARG)
|
||||
|
||||
# The bench. One process, two independent reports written at exit: where the
|
||||
# map load spent its time, and where a gameplay frame spends its time by span.
|
||||
# Both are in-process — no trace file and no Trace Processor — and both land in
|
||||
# iw4l-artifacts/bench/<stamp>.txt as well as on stdout.
|
||||
# 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/<stamp>.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 <demo> play iw4l-artifacts/demos/<demo>.iw4ldemo, then quit"
|
||||
@echo " ZONE= overrides header"
|
||||
@echo " CMDS='wait world; wait 5s; quit' mid-play"
|
||||
@echo "make bench <demo> the bench: map-load breakdown + frame time by span,"
|
||||
@echo " printed at exit and written to iw4l-artifacts/bench/"
|
||||
@echo "make bench <demo> 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"
|
||||
|
||||
@@ -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<i32>, stderr: String },
|
||||
Process {
|
||||
status: Option<i32>,
|
||||
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<Vec<u8>, 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<Result<Vec<u8>, XwmaDecodeError>> {
|
||||
let key_at = Instant::now();
|
||||
let keys: Vec<String> = 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<Option<Result<Vec<u8>, 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<u8>)> = 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<u8>)],
|
||||
clips: &[XwmaClip<'_>],
|
||||
) -> Vec<(usize, Result<Vec<u8>, XwmaDecodeError>)> {
|
||||
let alone =
|
||||
|(i, xwma): &(usize, Vec<u8>)| (*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<u8> {
|
||||
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<Vec<u8>> {
|
||||
if bytes.len() < XWMA_CACHE_HEADER || &bytes[..8] != XWMA_CACHE_MAGIC {
|
||||
return None;
|
||||
}
|
||||
let word = |at: usize| -> Option<u32> {
|
||||
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<Vec<u8>> {
|
||||
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<PathBuf, XwmaDecodeError> {
|
||||
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<u8>)],
|
||||
clips: &[XwmaClip<'_>],
|
||||
) -> Result<Vec<Result<Vec<u8>, 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<u8>)],
|
||||
clips: &[XwmaClip<'_>],
|
||||
) -> Result<Vec<Result<Vec<u8>, 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<Vec<u8>, 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");
|
||||
}
|
||||
}
|
||||
|
||||
@@ -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,
|
||||
|
||||
+297
-22
@@ -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<SoundCatalog>,
|
||||
tx: Sender<ClipKey>,
|
||||
tx: Sender<ClipJob>,
|
||||
queued: HashSet<ClipKey>,
|
||||
outcomes: Arc<Mutex<HashMap<ClipKey, Result<PreparedPcm, ClipError>>>>,
|
||||
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::<ClipKey>();
|
||||
let (tx, rx) = channel::<ClipJob>();
|
||||
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::<f32>()) 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<Result<PreparedPcm, ClipError>> {
|
||||
let mut out: Vec<Option<Result<PreparedPcm, ClipError>>> = 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<assets::XwmaClip<'_>> = 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<PreparedPcm, ClipError> {
|
||||
) -> (ClipPath, Result<PreparedPcm, ClipError>) {
|
||||
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<ClipPath> {
|
||||
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<PreparedPcm, ClipErr
|
||||
} else {
|
||||
return Err(ClipError::Decode);
|
||||
};
|
||||
pcm_from_bytes(bits, bytes, sound.channels(), sound.rate)
|
||||
}
|
||||
|
||||
/// Encoded samples as the mixer wants them: interleaved `f32`, a whole number
|
||||
/// of frames, and never empty — a clip with no samples is a failed decode and
|
||||
/// not a silent clip.
|
||||
fn pcm_from_bytes(
|
||||
bits: i32,
|
||||
bytes: &[u8],
|
||||
channels: i32,
|
||||
rate: u32,
|
||||
) -> Result<PreparedPcm, ClipError> {
|
||||
let mut samples: Vec<f32> = 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<PreparedPcm, ClipErr
|
||||
.collect(),
|
||||
_ => 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),
|
||||
})
|
||||
}
|
||||
|
||||
|
||||
@@ -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::{
|
||||
|
||||
@@ -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"
|
||||
|
||||
@@ -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 `<target>/<profile>/build/<crate>-<hash>/
|
||||
/// 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<String> {
|
||||
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 `<target>/<profile>/build/<crate>-<hash>/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<String>) {
|
||||
// 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<String> {
|
||||
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<String> {
|
||||
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<String> {
|
||||
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<String> {
|
||||
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}")
|
||||
}
|
||||
@@ -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<String>) {
|
||||
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<String>) {
|
||||
let tabled: Vec<Counter> = 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<String>,
|
||||
) {
|
||||
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<String>) {
|
||||
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<String>) {
|
||||
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<String>) {
|
||||
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<f64>) -> String {
|
||||
value.map_or_else(|| "—".to_owned(), |value| format!("{value:.2}"))
|
||||
}
|
||||
@@ -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<RuntimeFacts> = 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>, 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<Res<RenderAdapterInfo>>,
|
||||
device: Option<Res<RenderDevice>>,
|
||||
windows: Query<&Window, With<PrimaryWindow>>,
|
||||
) {
|
||||
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
|
||||
}
|
||||
@@ -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<String>) {
|
||||
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<String>) {
|
||||
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<String>) {
|
||||
@@ -80,11 +86,13 @@ fn tree(stats: &[SpanStats], wall: &SpanStats, out: &mut Vec<String>) {
|
||||
&[
|
||||
("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<String>) {
|
||||
" `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<Span>) -> 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<String>) {
|
||||
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<String>) {
|
||||
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<String>) {
|
||||
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<String>) {
|
||||
|
||||
@@ -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<Instant>, out: &mut Vec<String>) {
|
||||
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<String>) {
|
||||
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<String>) {
|
||||
}
|
||||
}
|
||||
|
||||
/// 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<String>) {
|
||||
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<String>) {
|
||||
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<String>) {
|
||||
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<String>) {
|
||||
}
|
||||
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)
|
||||
|
||||
@@ -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<String>,
|
||||
pub(crate) demo: Option<String>,
|
||||
pub(crate) role: Option<String>,
|
||||
/// Adapter name, backend, device type and driver, as wgpu reported them.
|
||||
pub(crate) adapter: Option<AdapterFacts>,
|
||||
pub(crate) window: Option<WindowFacts>,
|
||||
pub(crate) present_mode: Option<String>,
|
||||
/// 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<bool>,
|
||||
}
|
||||
|
||||
#[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::<Vec<_>>(),
|
||||
"workload": {
|
||||
"zone": facts.zone,
|
||||
"demo": facts.demo,
|
||||
"role": facts.role,
|
||||
"command_line": std::env::args().collect::<Vec<_>>(),
|
||||
},
|
||||
"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<String> {
|
||||
std::fs::read_to_string("/proc/sys/kernel/osrelease")
|
||||
.ok()
|
||||
.map(|value| value.trim().to_owned())
|
||||
}
|
||||
|
||||
#[cfg(not(target_os = "linux"))]
|
||||
fn kernel() -> Option<String> {
|
||||
None
|
||||
}
|
||||
|
||||
#[cfg(target_os = "linux")]
|
||||
fn cpu_model() -> Option<String> {
|
||||
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<String> {
|
||||
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()))
|
||||
}
|
||||
@@ -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/<stamp>.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/<stamp>.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<PathBuf>) {
|
||||
let mut lines = Vec::new();
|
||||
heading("<none>", trace.as_deref(), &mut lines);
|
||||
lines.push(
|
||||
"[1/2] MAP LOAD: MISS — this run loaded no map, so there was nothing to time."
|
||||
"[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<PathBuf>) {
|
||||
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<PathBuf, String> {
|
||||
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/<stamp>.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<String> {
|
||||
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 {
|
||||
|
||||
@@ -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::<Vec<_>>(),
|
||||
"spans_never_sampled": perf::stats::spans_never_sampled()
|
||||
.into_iter()
|
||||
.map(|span| span.name())
|
||||
.collect::<Vec<_>>(),
|
||||
},
|
||||
})
|
||||
}
|
||||
|
||||
/// 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::<Vec<_>>(),
|
||||
"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::<Vec<_>>(),
|
||||
"counters": perf::stats::counter_snapshot(phase)
|
||||
.iter()
|
||||
.map(|row| counter(row, frames))
|
||||
.collect::<Vec<_>>(),
|
||||
})
|
||||
}
|
||||
|
||||
fn span(row: &SpanStats, frames: Option<u64>) -> 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<u64>) -> 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<f64> {
|
||||
(frames > 0).then(|| value / frames as f64)
|
||||
}
|
||||
@@ -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<String>) {
|
||||
let mut widths: Vec<usize> = self
|
||||
.headers
|
||||
|
||||
@@ -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/<id>/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;
|
||||
|
||||
@@ -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<bool>) {
|
||||
/// 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<bool>, mut allocations: Local<Option<u64>>) {
|
||||
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;
|
||||
}
|
||||
|
||||
@@ -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,
|
||||
|
||||
@@ -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::{
|
||||
|
||||
+13
-1
@@ -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};
|
||||
|
||||
@@ -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<Result<(PathBuf, String), String>> = 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<PathBuf, String> {
|
||||
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<String> {
|
||||
slot().as_ref().ok().map(|(_, id)| id.clone())
|
||||
}
|
||||
@@ -68,9 +68,7 @@ pub fn start(metadata: RunMetadata) -> Result<Option<PathBuf>, 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()
|
||||
|
||||
+184
-3
@@ -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<Span>) {
|
||||
}
|
||||
}
|
||||
|
||||
/// 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<SpanStats> {
|
||||
.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<f64> {
|
||||
(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<f64> {
|
||||
(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<CounterStats> {
|
||||
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> {
|
||||
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> {
|
||||
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<Span> {
|
||||
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 [
|
||||
|
||||
@@ -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<TrackEventTrack>; 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<TrackEventTrack>; 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) {
|
||||
|
||||
@@ -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);
|
||||
}
|
||||
}
|
||||
|
||||
@@ -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,
|
||||
}
|
||||
|
||||
@@ -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"
|
||||
));
|
||||
|
||||
@@ -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);
|
||||
}
|
||||
|
||||
@@ -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<ExactColourSubmitCensus>,
|
||||
slot: Option<Res<crate::diag::render_frame_diag::SharedRenderStagesSlot>>,
|
||||
) {
|
||||
if !perf::enabled() {
|
||||
if !perf::recording() {
|
||||
return;
|
||||
}
|
||||
|
||||
|
||||
+36
-35
@@ -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/<stamp>.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/<zone>.png`; eyeball it for geometry
|
||||
that never arrived. A demo gets one too: the overlay comes down as soon as the
|
||||
first recorded snapshot is presented, so the capture settles during the load.
|
||||
**[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/<zone>.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.
|
||||
|
||||
+1
-1
@@ -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" |
|
||||
|
||||
+8
-7
@@ -40,10 +40,11 @@ half-installed resources. Commit publishes it, boots the sim, writes
|
||||
|
||||
## Cache, and poking it: `iw4l-artifacts/cache/<kind>/<key>`, 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`.
|
||||
|
||||
@@ -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
|
||||
|
||||
@@ -13,6 +13,35 @@ struct Config {
|
||||
zone: String,
|
||||
commands: String,
|
||||
focus: Option<String>,
|
||||
/// 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<String>) -> Result<Config, String> {
|
||||
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<String>) -> Result<Config, String> {
|
||||
"--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<String>) -> Result<Config, String> {
|
||||
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<Config, String>) -> 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<f64, String> {
|
||||
.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<f64, String> {
|
||||
}
|
||||
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",
|
||||
|
||||
Reference in New Issue
Block a user