crates/nornir-bench/src/progress.rs
//! Benchmark progress logging — name every bench unit as it runs.
//!
//! When `nornir` (or a child repo's `examples/nornir-bench.rs`) drives the
//! registry, each bencher gets a `bench: …` line *before* it starts and
//! another when it finishes, so an operator can see **which** benchmark is
//! running rather than staring at a silent terminal for minutes.
//!
//! Two sinks, both cheap and non-fatal:
//! 1. a **stderr line** with a stable `bench:` prefix (always on, greppable),
//! 2. an appended line in **`$NORNIR_VIZ_ACTIONLOG`** when that env var is set
//! — the very file the viz's action-log overlay tails (see
//! `viz::action_log`). Writing it here lets a running bench be watched live
//! in the viz without the bench module taking any dependency on `viz`.
//!
//! The action-log file line format is mirrored verbatim from
//! `nornir::viz::action_log` so the same parser/overlay renders it:
//! `HH:MM:SS.mmm <seq> [<TAG>] <detail>`. Bench lines use the tag `BENCH`.
//! `seq` is a per-process counter (the overlay only needs monotonicity within
//! one writer); when the viz process writes its own actions it keeps its own
//! sequence — the two never need to agree because each line stands alone.
use std::io::Write;
use std::sync::atomic::{AtomicU64, Ordering};
use std::time::Duration;
/// The stable grep prefix for every bench-progress line on stderr.
pub const PREFIX: &str = "bench:";
/// The action-log kind tag bench lines carry in `$NORNIR_VIZ_ACTIONLOG`.
/// Matches the `[TAG]` slot the viz overlay colour-codes on.
pub const ACTIONLOG_TAG: &str = "BENCH";
/// Per-process monotonic sequence for the action-log `seq` column.
static SEQ: AtomicU64 = AtomicU64::new(0);
/// `mt` (multi-core) or `st` (single-core / `_st` pass) — the mode label in a
/// progress line, so the two passes are distinguishable in the trail.
pub fn mode_label(single_core: bool) -> &'static str {
if single_core {
"st"
} else {
"mt"
}
}
/// Format the "starting" line body (without the `bench:` prefix), e.g.
/// `znippy.compress (mt) starting…`. Kept pure for unit testing.
pub fn starting_line(id: &str, single_core: bool) -> String {
format!("{id} ({}) starting…", mode_label(single_core))
}
/// Format the "done" line body (without the `bench:` prefix), e.g.
/// `znippy.compress (mt) → 1234 ops/s (0.42s)`. `summary` is a short
/// already-rendered metric blurb (may be empty). Kept pure for unit testing.
pub fn done_line(id: &str, single_core: bool, summary: &str, elapsed: Duration) -> String {
let arrow = if summary.is_empty() {
String::new()
} else {
format!(" → {summary}")
};
format!(
"{id} ({}){arrow} ({:.2}s)",
mode_label(single_core),
elapsed.as_secs_f64()
)
}
/// Format a telemetry suffix for a progress "done" line, so a long bench's CPU
/// footprint is visible in the trail. Empty when `n_cores` is 0 (no sampler
/// data, e.g. non-Linux).
///
/// `proc_cores` — the bench's OWN peak occupancy (task-clock ÷ wall) — leads,
/// because it is the only one of the two that is about the bench. `host-busy`
/// follows as ambient context, explicitly labelled: it counts every process on
/// the box, so on a loaded machine it reads N/N no matter what the bench does.
/// Printing it unlabelled as "cores-busy" is how a strictly serial arm came to
/// be read as 32/32-core parallel. `proc_cores == None` (unmeasurable) prints
/// `?` rather than a number nobody measured.
pub fn telem_suffix(proc_cores: Option<f64>, busy: u32, n_cores: u32) -> String {
if n_cores == 0 {
String::new()
} else {
match proc_cores {
Some(p) => format!(" [cores {p:.2}/{n_cores} · host-busy {busy}/{n_cores}]"),
None => format!(" [cores ?/{n_cores} · host-busy {busy}/{n_cores}]"),
}
}
}
/// Like [`done_line`] but appends the [`telem_suffix`] telemetry suffix.
pub fn done_line_with_telem(
id: &str,
single_core: bool,
summary: &str,
elapsed: Duration,
proc_cores: Option<f64>,
busy: u32,
n_cores: u32,
) -> String {
format!(
"{}{}",
done_line(id, single_core, summary, elapsed),
telem_suffix(proc_cores, busy, n_cores)
)
}
/// Format the "failed" line body (without the `bench:` prefix).
pub fn failed_line(id: &str, single_core: bool, err: &str, elapsed: Duration) -> String {
format!(
"{id} ({}) ✗ failed: {err} ({:.2}s)",
mode_label(single_core),
elapsed.as_secs_f64()
)
}
/// Emit one progress line: `bench: <body>` on stderr, and — when
/// `$NORNIR_VIZ_ACTIONLOG` is set — an action-log-format line appended to that
/// file so the viz overlay/tailer sees it live. Both sinks are best-effort;
/// a missing env var or an unwritable file is silently ignored (stderr already
/// carried it).
pub fn emit(body: &str) {
eprintln!("{PREFIX} {body}");
append_to_actionlog(body);
}
/// Append `body` to `$NORNIR_VIZ_ACTIONLOG` in the exact line format the viz
/// action-log writer uses, so the existing overlay/parser renders it unchanged.
/// No-op (and never panics) when the env var is unset or the file can't be
/// opened/written.
fn append_to_actionlog(body: &str) {
let Some(path) = std::env::var_os("NORNIR_VIZ_ACTIONLOG") else {
return;
};
if path.is_empty() {
return;
}
// Append (do NOT truncate): the viz owns truncation at launch; the bencher
// is a second writer to the same trail.
let mut f = match std::fs::OpenOptions::new().create(true).append(true).open(&path) {
Ok(f) => f,
Err(_) => return,
};
let seq = SEQ.fetch_add(1, Ordering::Relaxed) + 1;
let stamp = now_stamp();
// Mirror viz::action_log's `writeln!(f, "{stamp} {seq:>5} [{TAG}] {detail}")`.
let _ = writeln!(f, "{stamp} {seq:>5} [{ACTIONLOG_TAG}] {PREFIX} {body}");
let _ = f.flush();
}
/// `HH:MM:SS.mmm` local-time stamp — identical formatting to
/// `nornir::viz::action_log` so a mixed trail is uniform.
fn now_stamp() -> String {
chrono::Local::now().format("%H:%M:%S%.3f").to_string()
}
#[cfg(test)]
mod tests {
use super::*;
#[test]
fn mode_labels() {
assert_eq!(mode_label(false), "mt");
assert_eq!(mode_label(true), "st");
}
#[test]
fn starting_line_names_suite_and_mode() {
assert_eq!(
starting_line("znippy.compress", false),
"znippy.compress (mt) starting…"
);
assert_eq!(
starting_line("znippy.compress", true),
"znippy.compress (st) starting…"
);
}
#[test]
fn done_line_includes_summary_and_elapsed() {
let line = done_line("holger.ops", false, "1234 ops/s", Duration::from_millis(420));
assert_eq!(line, "holger.ops (mt) → 1234 ops/s (0.42s)");
// Empty summary drops the arrow but keeps id/mode/elapsed.
let bare = done_line("x.y", true, "", Duration::from_secs(1));
assert_eq!(bare, "x.y (st) (1.00s)");
}
#[test]
fn telem_suffix_and_done_line() {
assert_eq!(telem_suffix(Some(2.75), 3, 8), " [cores 2.75/8 · host-busy 3/8]");
// No core data → no suffix.
assert_eq!(telem_suffix(Some(1.0), 0, 0), "");
// Unmeasurable process CPU prints `?`, never a fabricated number.
assert_eq!(telem_suffix(None, 3, 8), " [cores ?/8 · host-busy 3/8]");
// The line the operator reads must NOT let the host's ambient load
// masquerade as the bench's parallelism: a serial arm on a saturated
// box shows `cores 0.56` next to `host-busy 8/8`.
let line = done_line_with_telem(
"z.c",
false,
"100 MB/s",
Duration::from_millis(500),
Some(0.56),
8,
8,
);
assert_eq!(line, "z.c (mt) → 100 MB/s (0.50s) [cores 0.56/8 · host-busy 8/8]");
}
#[test]
fn failed_line_carries_error() {
let line = failed_line("a.b", false, "boom", Duration::from_millis(50));
assert_eq!(line, "a.b (mt) ✗ failed: boom (0.05s)");
}
#[test]
fn actionlog_append_matches_viz_format() {
let _g = crate::serial_guard(); // global env NORNIR_VIZ_ACTIONLOG — serialize
// Point the bencher at a temp action-log and assert the appended line
// parses the way viz::action_log's writer/overlay expects:
// `HH:MM:SS.mmm <seq> [BENCH] bench: <body>`.
// Process-unique so a concurrent `cargo test` run (a parallel checkout)
// never appends interleaved lines into the file we read back.
let path = std::env::temp_dir()
.join(format!("nornir_bench_progress_test_{}.log", std::process::id()));
let _ = std::fs::remove_file(&path);
// SAFETY: single-threaded test; restored below.
unsafe { std::env::set_var("NORNIR_VIZ_ACTIONLOG", &path) };
emit("demo.case (mt) starting…");
unsafe { std::env::remove_var("NORNIR_VIZ_ACTIONLOG") };
let contents = std::fs::read_to_string(&path).unwrap();
// Assert AT LEAST ONE well-formed line carries our body. A concurrent
// bench::api emit() (which does not take serial_guard) can append its own
// line during our env-var window, so we can't assume the first body-match
// is the well-formed one — require a single line that matches BOTH the
// `stamp seq ` head shape and the `[TAG] prefix body` tail shape.
let ok = contents.lines().any(|line| {
let mut parts = line.splitn(2, |c: char| c == '[');
let head = parts.next().unwrap_or(""); // "HH:MM:SS.mmm 1 "
let tail = parts.next().unwrap_or(""); // "BENCH] bench: demo.case ..."
head.split_whitespace().count() == 2
&& tail.starts_with("BENCH] bench: demo.case (mt) starting…")
});
assert!(ok, "no well-formed BENCH line in: {contents:?}");
let _ = std::fs::remove_file(&path);
}
}