diff --git a/driver/src/cli/native/diff.rs b/driver/src/cli/native/diff.rs index a83516d..1eb6e65 100644 --- a/driver/src/cli/native/diff.rs +++ b/driver/src/cli/native/diff.rs @@ -14,12 +14,17 @@ use serde::Deserialize; use crate::cli::{Exit, Failure, failed, gate}; use crate::client::{ConnArgs, Db}; use crate::native::session::STAGE_TABLE; -use crate::native::{Session, plan, probe, refusal, schema}; +use crate::native::{Refusal, Session, plan, probe, record, refusal, schema}; use crate::stats::{Clock, Monotonic}; /// How often the progress line comes out. const PROGRESS_INTERVAL: Duration = Duration::from_secs(1); +/// How long `--record` waits for the simulation statements' own rows to +/// reach `system.query_log`, and how often it looks. +const QUERY_LOG_TIMEOUT: Duration = Duration::from_secs(30); +const QUERY_LOG_POLL: Duration = Duration::from_millis(250); + #[derive(Args)] #[command( about = "Run the simulation against the reference emulator's own state rows", @@ -42,6 +47,12 @@ A tic native_state marks unresolved or unimplemented is checked before any field is, since a tic the statement could not produce exactly is not one to compare. +--record appends one JSON line to PATH with what the run found: the first +refused tic, the first field that differs, the last tic compared, what each +simulation statement's analysis took, the tic time's median and 95th +percentile, the commit, the server version and the CPU model. A run that +fails writes nothing. + Exit codes: 0 the two agree over TICS tics, 1 the run failed, 3 a tic refused or the two diverged." )] @@ -57,6 +68,16 @@ pub struct DiffCmd { /// Also list every field that ever differs #[arg(long)] pub summary: bool, + /// Append what the run found to this file as one JSON line + #[arg(long, value_name = "PATH")] + pub record: Option, +} + +/// What the field comparison found. +struct Compared { + /// Tics both sides hold, up to the last one the run fed. + tics: u64, + first: Option, } /// One row of `parity::first_divergence`. @@ -108,25 +129,47 @@ pub(crate) async fn run(cmd: &DiffCmd) -> Result { let session = Session::open(&cmd.conn, database, Some((&stage1, &stage2)), None) .await .map_err(|err| failed(format!("opening the simulation: {err}")))?; + let query_ids = [ + session.sim_query_id().to_owned(), + session.sim2_query_id().to_owned(), + ]; let ran = simulate(&session, cmd.tics).await; let closed = session.close().await; - match (ran, closed) { - (Ok(()), Ok(())) => {} + let elapsed = match (ran, closed) { + (Ok(elapsed), Ok(())) => elapsed, (_, Err(err)) => return Err(failed(format!("the simulation statement failed: {err}"))), (Err(failure), Ok(())) => return Err(failure), - } + }; // A refused tic is checked before the fields are, because a tic the // statement itself could not produce is not one to compare field by // field against the probe. - if let Some(refusal) = refusal::first(&db, database, cmd.tics) + let refused = refusal::first(&db, database, cmd.tics) .await - .map_err(|err| failed(format!("reading whether a tic refused: {err}")))? - { - return Err(gate(refusal.to_string())); + .map_err(|err| failed(format!("reading whether a tic refused: {err}")))?; + let compared = match refused { + Some(_) => None, + None => Some(compare(cmd, &db).await?), + }; + + if let Some(path) = &cmd.record { + let found = found( + cmd, + &db, + &query_ids, + &elapsed, + refused.as_ref(), + compared.as_ref(), + ) + .await?; + record::append(path, &found).map_err(|err| failed(err.to_string()))?; } - report(cmd, &db).await + match (refused, compared) { + (Some(refusal), _) => Err(gate(refusal.to_string())), + (None, Some(compared)) => report(compared), + (None, None) => unreachable!("a run that did not refuse is compared"), + } } /// Empties `native_state` and `native_stage` and writes the level's first @@ -168,18 +211,21 @@ fn timeout(tic: u32) -> Duration { } } -/// Runs tic 1 to `tics`, one row at a time, as an interactive run does. -async fn simulate(session: &Session, tics: u32) -> Result<(), Failure> { +/// Runs tic 1 to `tics`, one row at a time, as an interactive run does, +/// and returns what each tic took. +async fn simulate(session: &Session, tics: u32) -> Result, Failure> { let clock = Monotonic::new(); let mut last = Duration::ZERO; + let mut elapsed = Vec::with_capacity(tics as usize); for tic in 1..=tics { session .feed_sim(tic, tick::source::DEMO, 0, 0, 0) .map_err(|err| failed(format!("feeding tic {tic}: {err}")))?; - session + let ran = session .wait_sim(tic, timeout(tic)) .await .map_err(|err| failed(err.to_string()))?; + elapsed.push(ran.elapsed); let now = clock.elapsed(); if now.saturating_sub(last) >= PROGRESS_INTERVAL { last = now; @@ -190,7 +236,7 @@ async fn simulate(session: &Session, tics: u32) -> Result<(), Failure> { ); } } - Ok(()) + Ok(elapsed) } /// How many tics the comparison actually covers: the ones the run produced @@ -212,7 +258,7 @@ async fn compared(cmd: &DiffCmd, db: &Db) -> Result { } /// The comparison itself, which is one query per question. -async fn report(cmd: &DiffCmd, db: &Db) -> Result { +async fn compare(cmd: &DiffCmd, db: &Db) -> Result { let database = &cmd.conn.database; let compared = compared(cmd, db).await?; if compared == 0 { @@ -240,16 +286,122 @@ async fn report(cmd: &DiffCmd, db: &Db) -> Result { .fetch_all(&parity::first_divergence(database)) .await .map_err(|err| failed(format!("reading the first divergence: {err}")))?; - let Some(first) = first.first() else { - println!("no divergence: every field agrees over the {compared} tics both sides hold"); + Ok(Compared { + tics: compared, + first: first.into_iter().next(), + }) +} + +/// Prints what the comparison found and turns it into the exit code. +fn report(compared: Compared) -> Result { + let Some(first) = compared.first else { + println!( + "no divergence: every field agrees over the {} tics both sides hold", + compared.tics + ); return Ok(Exit::Ok); }; Err(gate(format!( - "tic {} {} slot {} {}: {} against the probe's {}", - first.tic, first.kind, first.slot, first.field, first.ours, first.theirs + "tic {} {}: {} against the probe's {}", + first.tic, + first.location(), + first.ours, + first.theirs ))) } +impl Divergence { + /// The row and the field, as `mobj slot 1 m_momx`. + fn location(&self) -> String { + format!("{} slot {} {}", self.kind, self.slot, self.field) + } +} + +/// The line `--record` appends for this run. +/// +/// The analysis times are read from `system.query_log` by the two +/// simulation statements' own query ids, after the session has closed them. +async fn found( + cmd: &DiffCmd, + db: &Db, + query_ids: &[String; 2], + elapsed: &[Duration], + refused: Option<&Refusal>, + compared: Option<&Compared>, +) -> Result { + let clickhouse = db + .fetch_one::("SELECT version()") + .await + .map_err(|err| failed(format!("reading the server version: {err}")))?; + let [stage1, stage2] = analysis(db, query_ids).await?; + let divergence = compared.and_then(|compared| compared.first.as_ref()); + // The first tic pays for both statements' analysis, which is recorded + // on its own. + let mut warm: Vec = elapsed.iter().skip(1).copied().collect(); + warm.sort_unstable(); + let tic_ms = + |fraction| (!warm.is_empty()).then(|| super::millis(super::percentile(&warm, fraction))); + Ok(record::Record { + commit: record::commit().unwrap_or_default(), + clickhouse: Some(clickhouse), + runner_cpu: record::cpu_model(), + first_refused_tic: refused.map(|refusal| refusal.tic), + first_refused_bits: refused.map(|refusal| refusal.reason.clone()), + first_divergent_tic: divergence.map(|first| first.tic), + first_divergent_field: divergence.map(Divergence::location), + compared_through: compared.map(|_| cmd.tics), + compared_tics: compared.map(|compared| compared.tics), + stage1_analysis_s: Some(stage1), + stage2_analysis_s: Some(stage2), + tic_ms_p50: tic_ms(0.50), + tic_ms_p95: tic_ms(0.95), + tics: Some(cmd.tics), + run_id: record::run_id(), + error: None, + }) +} + +/// `QueryAnalysisMicroseconds` of each of `query_ids`, in seconds. +/// +/// The server logs a statement's finish after it has answered the close, +/// so the log is flushed and read again until both rows are there or +/// [`QUERY_LOG_TIMEOUT`] has passed. +async fn analysis(db: &Db, query_ids: &[String; 2]) -> Result<[f64; 2], Failure> { + let sql = format!( + "SELECT query_id, toUInt64(ProfileEvents['QueryAnalysisMicroseconds']) \ + FROM system.query_log \ + WHERE type = 'QueryFinish' AND query_id IN ('{}', '{}')", + query_ids[0], query_ids[1] + ); + let clock = Monotonic::new(); + loop { + db.run("SYSTEM FLUSH LOGS") + .await + .map_err(|err| failed(format!("flushing system.query_log: {err}")))?; + let rows: Vec<(String, u64)> = db + .fetch_all(&sql) + .await + .map_err(|err| failed(format!("reading system.query_log: {err}")))?; + let seconds = |id: &String| { + rows.iter() + .find(|(query_id, _)| query_id == id) + .map(|(_, micros)| *micros as f64 / 1e6) + }; + match (seconds(&query_ids[0]), seconds(&query_ids[1])) { + (Some(stage1), Some(stage2)) => return Ok([stage1, stage2]), + _ if clock.elapsed() >= QUERY_LOG_TIMEOUT => { + return Err(failed(format!( + "system.query_log holds no finished row for the simulation \ + statements {} and {} after {QUERY_LOG_TIMEOUT:?}, so their \ + analysis time is unknown", + query_ids[0], query_ids[1] + ))); + } + _ => tokio::time::sleep(QUERY_LOG_POLL).await, + } + } +} + #[cfg(test)] mod tests { use super::*; @@ -274,6 +426,9 @@ mod tests { assert_eq!(cmd.tics, 100); assert_eq!(cmd.probe, PathBuf::from("p.tsv")); assert!(!cmd.summary); + assert_eq!(cmd.record, None); + let cmd = parsed(&["100", "--probe", "p.tsv", "--record", "r.jsonl"]); + assert_eq!(cmd.record, Some(PathBuf::from("r.jsonl"))); } /// The comparison needs a tic to compare, and running none of them and diff --git a/driver/src/native/mod.rs b/driver/src/native/mod.rs index 99dbc93..3f19854 100644 --- a/driver/src/native/mod.rs +++ b/driver/src/native/mod.rs @@ -11,7 +11,8 @@ //! the screen wipe's schedule, and [`schedule`] reads back which frames a //! run renders and what each one draws from. [`refusal`] reads back the //! tic a run stopped at, where `unresolved` or `unimplemented` said one -//! could not be produced exactly. [`schema`] stands between a database an +//! could not be produced exactly. [`record`] writes what a differential +//! run found as one JSON line. [`schema`] stands between a database an //! older binary loaded and one this binary's own statements can read: a //! load without `--fresh` refuses a column that moved, and //! [`Session::open`] refuses a database whose schema hash is not this @@ -24,6 +25,7 @@ pub mod melt; pub mod pace; pub mod plan; pub mod probe; +pub mod record; pub mod refusal; pub mod schedule; pub mod schema; diff --git a/driver/src/native/record.rs b/driver/src/native/record.rs new file mode 100644 index 0000000..db64c2d --- /dev/null +++ b/driver/src/native/record.rs @@ -0,0 +1,214 @@ +//! What one differential run found, as one JSON line. +//! +//! `clickdoom native diff --record` appends a [`Record`] to a file, one +//! line per run. A line carries where the simulation stops matching the +//! reference emulator and what the run cost, together with the commit, +//! the server and the machine that measured it. + +use std::io::Write; +use std::path::{Path, PathBuf}; + +use serde::{Deserialize, Serialize}; + +/// One differential run. +/// +/// Every field but `commit` may be absent: a line the nightly writes for a +/// commit that did not build or run carries `error` and nothing measured. +#[derive(Serialize, Deserialize, Clone, Debug, Default, PartialEq)] +#[serde(default)] +pub struct Record { + /// The commit the run was built from, as `git rev-parse HEAD` printed it. + pub commit: String, + /// `SELECT version()` on the server the run used. + pub clickhouse: Option, + /// The CPU model of the machine the driver ran on. + pub runner_cpu: Option, + /// The first tic `native_state` marks unresolved or unimplemented. + pub first_refused_tic: Option, + /// The column that tic set and the bits it named, as + /// `unresolved: CHASE_STUCK`. + pub first_refused_bits: Option, + /// The first tic a field differs on. Absent when the fields agree or + /// when nothing was compared, which `compared_through` tells apart. + pub first_divergent_tic: Option, + /// That field, as `mobj slot 1 m_momx`. + pub first_divergent_field: Option, + /// The last tic the field comparison covered. Absent when the run + /// stopped at a refusal before comparing. + pub compared_through: Option, + /// How many tics the comparison covered: the ones both sides hold. + pub compared_tics: Option, + /// `QueryAnalysisMicroseconds` of the simulation's first statement. + pub stage1_analysis_s: Option, + /// The same for its second statement. + pub stage2_analysis_s: Option, + /// The median tic, from its row being sent to its state row being + /// readable, over every tic but the first, which pays for the analysis. + pub tic_ms_p50: Option, + /// The 95th percentile of the same. + pub tic_ms_p95: Option, + /// Tics the run fed. + pub tics: Option, + /// `GITHUB_RUN_ID`, when the run is a GitHub Actions job. + pub run_id: Option, + /// Why the run produced nothing, for a line the nightly writes itself. + pub error: Option, +} + +/// Anything that stops a record from being written or read. +#[derive(Debug, thiserror::Error)] +pub enum Error { + #[error("writing {path}: {source}")] + Write { + path: PathBuf, + #[source] + source: std::io::Error, + }, + #[error("reading {path}: {source}")] + Read { + path: PathBuf, + #[source] + source: std::io::Error, + }, + #[error("{path} line {line}: {source}")] + Parse { + path: PathBuf, + line: usize, + #[source] + source: serde_json::Error, + }, +} + +/// Appends `record` to `path` as one line, creating the file and its +/// directory if they are missing. +pub fn append(path: &Path, record: &Record) -> Result<(), Error> { + let write = |source| Error::Write { + path: path.to_owned(), + source, + }; + if let Some(parent) = path.parent().filter(|p| !p.as_os_str().is_empty()) { + std::fs::create_dir_all(parent).map_err(write)?; + } + let line = serde_json::to_string(record).expect("a record serializes"); + let mut file = std::fs::OpenOptions::new() + .create(true) + .append(true) + .open(path) + .map_err(write)?; + writeln!(file, "{line}").map_err(write) +} + +/// Every record in `path`, in file order. Blank lines are skipped. +pub fn read(path: &Path) -> Result, Error> { + let text = std::fs::read_to_string(path).map_err(|source| Error::Read { + path: path.to_owned(), + source, + })?; + parse(path, &text) +} + +fn parse(path: &Path, text: &str) -> Result, Error> { + text.lines() + .enumerate() + .filter(|(_, line)| !line.trim().is_empty()) + .map(|(at, line)| { + serde_json::from_str(line).map_err(|source| Error::Parse { + path: path.to_owned(), + line: at + 1, + source, + }) + }) + .collect() +} + +/// `git rev-parse HEAD` in the working directory, or `None` outside a +/// checkout. +pub fn commit() -> Option { + let output = std::process::Command::new("git") + .args(["rev-parse", "HEAD"]) + .output() + .ok() + .filter(|output| output.status.success())?; + let sha = String::from_utf8(output.stdout).ok()?; + Some(sha.trim().to_owned()).filter(|sha| !sha.is_empty()) +} + +/// The CPU model this process runs on: `/proc/cpuinfo`'s `model name` on +/// Linux, `machdep.cpu.brand_string` on macOS, `None` elsewhere. +pub fn cpu_model() -> Option { + let model = match std::env::consts::OS { + "linux" => std::fs::read_to_string("/proc/cpuinfo") + .ok() + .and_then(|info| cpuinfo_model(&info)), + "macos" => std::process::Command::new("sysctl") + .args(["-n", "machdep.cpu.brand_string"]) + .output() + .ok() + .filter(|output| output.status.success()) + .and_then(|output| String::from_utf8(output.stdout).ok()), + _ => None, + }?; + Some(model.trim().to_owned()).filter(|model| !model.is_empty()) +} + +fn cpuinfo_model(info: &str) -> Option { + info.lines() + .find_map(|line| line.strip_prefix("model name")) + .and_then(|rest| rest.split_once(':')) + .map(|(_, model)| model.trim().to_owned()) +} + +/// `GITHUB_RUN_ID`, when it is set and not empty. +pub fn run_id() -> Option { + std::env::var("GITHUB_RUN_ID") + .ok() + .filter(|id| !id.is_empty()) +} + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn a_record_round_trips_through_its_line() { + let record = Record { + commit: "abc".into(), + first_refused_tic: Some(275), + first_refused_bits: Some("unresolved: CHASE_STUCK".into()), + stage1_analysis_s: Some(40.5), + ..Record::default() + }; + let line = serde_json::to_string(&record).unwrap(); + assert!(line.contains("\"first_divergent_tic\":null"), "{line}"); + let back = parse(Path::new("t"), &format!("{line}\n\n{line}\n")).unwrap(); + assert_eq!(back, vec![record.clone(), record]); + } + + /// The nightly writes an error line with the commit and the reason + /// alone, and it has to read back. + #[test] + fn a_line_carrying_only_the_commit_and_an_error_parses() { + let back = parse(Path::new("t"), r#"{"commit":"abc","error":"build failed"}"#).unwrap(); + assert_eq!(back[0].commit, "abc"); + assert_eq!(back[0].error.as_deref(), Some("build failed")); + assert_eq!(back[0].first_refused_tic, None); + } + + #[test] + fn a_bad_line_is_named_by_its_number() { + let err = parse(Path::new("h.jsonl"), "{\"commit\":\"a\"}\nnot json\n").unwrap_err(); + assert!(err.to_string().starts_with("h.jsonl line 2:"), "{err}"); + } + + #[test] + fn the_cpu_model_is_the_first_model_name_line() { + let info = "processor\t: 0\nvendor_id\t: AuthenticAMD\n\ + model name\t: AMD EPYC 7763 64-Core Processor\n\ + processor\t: 1\nmodel name\t: other\n"; + assert_eq!( + cpuinfo_model(info).as_deref(), + Some("AMD EPYC 7763 64-Core Processor") + ); + assert_eq!(cpuinfo_model("processor\t: 0\n"), None); + } +} diff --git a/driver/tests/native_diff_live.rs b/driver/tests/native_diff_live.rs index 37dc5e0..d06059f 100644 --- a/driver/tests/native_diff_live.rs +++ b/driver/tests/native_diff_live.rs @@ -7,7 +7,9 @@ //! * the probe rows land in `probe_state` and not in `native_state`, //! because the two are the sides of the comparison; //! * a tic `native_state` marks unresolved stops the run there, before -//! any field is compared. +//! any field is compared; +//! * `--record` appends one line per run that says which of these the run +//! found, with the analysis and tic times it measured. //! //! Needs a reachable ClickHouse (`CLICKHOUSE_HOST`/`CLICKHOUSE_HTTP_PORT`/ //! `CLICKHOUSE_PASSWORD`, defaulting to `localhost:8123`) and the committed @@ -18,6 +20,8 @@ use std::path::{Path, PathBuf}; use std::process::Command; +use clickdoom_driver::native::record::{self, Record}; + mod support; use support::{committed_fixture, conn_args, repo_root}; @@ -72,10 +76,35 @@ async fn a_differential_run_reports_the_first_field_that_differs() { // Over the tics the fixture records and the simulation reproduces, the // two sides agree. + let recorded = record_path(&database); + let recorded_arg = recorded.to_str().expect("a path"); let tics = FIRST_RECORDED_TIC.to_string(); - let (code, printed) = clickdoom(&database, &["native", "diff", &tics, "--probe", probe]); + let (code, printed) = clickdoom( + &database, + &[ + "native", + "diff", + &tics, + "--probe", + probe, + "--record", + recorded_arg, + ], + ); assert_eq!(code, 0, "{printed}"); assert!(printed.contains("no divergence"), "{printed}"); + let lines = record::read(&recorded).expect("the record is written"); + assert_eq!(lines.len(), 1, "{lines:?}"); + let agreed = &lines[0]; + assert_measured(agreed, FIRST_RECORDED_TIC); + assert_eq!( + agreed.compared_through, + Some(FIRST_RECORDED_TIC), + "{agreed:?}" + ); + assert!(agreed.compared_tics.is_some_and(|t| t > 0), "{agreed:?}"); + assert_eq!(agreed.first_refused_tic, None, "{agreed:?}"); + assert_eq!(agreed.first_divergent_tic, None, "{agreed:?}"); // A probe that differs from the simulation on one field is reported on // the tic and the field, with exit 3. The fixture is copied with one @@ -85,7 +114,15 @@ async fn a_differential_run_reports_the_first_field_that_differs() { let moved_probe = moved.to_str().expect("a path"); let (code, printed) = clickdoom( &database, - &["native", "diff", &tics, "--probe", moved_probe], + &[ + "native", + "diff", + &tics, + "--probe", + moved_probe, + "--record", + recorded_arg, + ], ); assert_eq!(code, 3, "{printed}"); assert!( @@ -94,6 +131,23 @@ async fn a_differential_run_reports_the_first_field_that_differs() { ); assert!(printed.contains("leveltime"), "{printed}"); assert!(printed.contains("against the probe's"), "{printed}"); + let lines = record::read(&recorded).expect("the record is written"); + assert_eq!(lines.len(), 2, "one line per run: {lines:?}"); + let diverged = &lines[1]; + assert_measured(diverged, FIRST_RECORDED_TIC); + assert_eq!( + diverged.first_divergent_tic, + Some(FIRST_RECORDED_TIC), + "{diverged:?}" + ); + assert!( + diverged + .first_divergent_field + .as_deref() + .is_some_and(|field| field.ends_with(" leveltime")), + "{diverged:?}" + ); + std::fs::remove_file(&recorded).ok(); // The two sides are two tables. A diff that copied the probe into // native_state would compare the run against itself and always agree. @@ -143,8 +197,20 @@ async fn a_tic_that_refuses_stops_before_the_field_comparison() { let fixture = committed_fixture(); let probe = fixture.to_str().expect("a path"); - let tics = (FIRST_REFUSED_TIC + 8).to_string(); - let (code, printed) = clickdoom(&database, &["native", "diff", &tics, "--probe", probe]); + let recorded = record_path(&database); + let tics = FIRST_REFUSED_TIC + 8; + let (code, printed) = clickdoom( + &database, + &[ + "native", + "diff", + &tics.to_string(), + "--probe", + probe, + "--record", + recorded.to_str().expect("a path"), + ], + ); assert_eq!(code, 3, "{printed}"); assert!( printed.contains(&format!("tic {FIRST_REFUSED_TIC} unresolved")), @@ -154,6 +220,27 @@ async fn a_tic_that_refuses_stops_before_the_field_comparison() { !printed.contains("no divergence") && !printed.contains("against the probe's"), "a refused tic is reported before any field is compared: {printed}" ); + let lines = record::read(&recorded).expect("the record is written"); + std::fs::remove_file(&recorded).ok(); + assert_eq!(lines.len(), 1, "{lines:?}"); + let refused = &lines[0]; + assert_measured(refused, tics); + assert_eq!( + refused.first_refused_tic, + Some(FIRST_REFUSED_TIC), + "{refused:?}" + ); + assert!( + refused + .first_refused_bits + .as_deref() + .is_some_and(|bits| bits.starts_with("unresolved: ")), + "{refused:?}" + ); + assert_eq!( + refused.compared_through, None, + "a refused run compares nothing: {refused:?}" + ); conn_args("default") .connect() @@ -162,6 +249,29 @@ async fn a_tic_that_refuses_stops_before_the_field_comparison() { .expect("the database is dropped"); } +/// Where a test's `--record` lines go, named after its database. +fn record_path(database: &str) -> PathBuf { + let path = std::env::temp_dir().join(format!("{database}.jsonl")); + std::fs::remove_file(&path).ok(); + path +} + +/// The fields every recorded run carries, whatever it found. +fn assert_measured(line: &Record, tics: u32) { + assert_eq!(line.commit.len(), 40, "{line:?}"); + assert!(line.clickhouse.is_some(), "{line:?}"); + assert!(line.runner_cpu.is_some(), "{line:?}"); + assert_eq!(line.tics, Some(tics), "{line:?}"); + for analysis in [line.stage1_analysis_s, line.stage2_analysis_s] { + assert!(analysis.is_some_and(|s| s > 0.0), "{line:?}"); + } + let (Some(p50), Some(p95)) = (line.tic_ms_p50, line.tic_ms_p95) else { + panic!("the tic times are missing: {line:?}"); + }; + assert!(p50 > 0.0 && p95 >= p50, "{line:?}"); + assert_eq!(line.error, None, "{line:?}"); +} + /// A copy of `fixture` with `column` moved by one on every row of /// `gametic`, written beside the temporary files, so a differential has one /// field to report. Every row, because the melt commits several frames in