From 499390c40690dd1f46c2944b6e6f4f695076c146 Mon Sep 17 00:00:00 2001 From: Marcus Kainth Date: Fri, 25 Sep 2026 14:00:19 +0100 Subject: [PATCH] driver: record what a differential run found `clickdoom native diff --record PATH` appends one JSON line per run: the commit, the server version, the CPU model, the first refused tic and the bits it named, the first divergent tic and field, the last tic compared and how many both sides held, each simulation statement's QueryAnalysisMicroseconds, the median and 95th percentile tic time, the tic count and GITHUB_RUN_ID when it is set. A nightly job appends these lines per main commit and compares each one with the one before it, so the line has to say which of refusal, divergence and agreement the run found, with nulls where the run could not tell: a run that stopped at a refusal compared nothing, and its compared_through is null. The analysis times come from system.query_log, keyed by the query ids the session already gives both statements. The server writes a statement's QueryFinish row after it has answered the close, so a single flush can miss it; the read flushes and polls for up to 30 s. The first tic is left out of the tic percentiles because it pays for the analysis, which is recorded on its own. The comparison is split from the printing so the record and the exit code read the same result. What the command prints and its exit codes are unchanged. --- driver/src/cli/native/diff.rs | 191 ++++++++++++++++++++++++--- driver/src/native/mod.rs | 4 +- driver/src/native/record.rs | 214 +++++++++++++++++++++++++++++++ driver/tests/native_diff_live.rs | 120 ++++++++++++++++- 4 files changed, 505 insertions(+), 24 deletions(-) create mode 100644 driver/src/native/record.rs diff --git a/driver/src/cli/native/diff.rs b/driver/src/cli/native/diff.rs index a83516dc..1eb6e658 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 99dbc939..3f198540 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 00000000..db64c2d2 --- /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 37dc5e09..d06059f6 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