nornir 0.4.12 - Docs.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
//! [`crate::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 `[cores-busy C/N]` 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). `busy` is the peak cores-busy count.
pub fn telem_suffix(busy: u32, n_cores: u32) -> String {
    if n_cores == 0 {
        String::new()
    } else {
        format!(" [cores-busy {busy}/{n_cores}]")
    }
}

/// Like [`done_line`] but appends a `[cores-busy C/N]` telemetry suffix.
pub fn done_line_with_telem(
    id: &str,
    single_core: bool,
    summary: &str,
    elapsed: Duration,
    busy: u32,
    n_cores: u32,
) -> String {
    format!("{}{}", done_line(id, single_core, summary, elapsed), telem_suffix(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
/// [`crate::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(3, 8), " [cores-busy 3/8]");
        // No core data → no suffix.
        assert_eq!(telem_suffix(0, 0), "");
        let line =
            done_line_with_telem("z.c", false, "100 MB/s", Duration::from_millis(500), 4, 8);
        assert_eq!(line, "z.c (mt) → 100 MB/s (0.50s) [cores-busy 4/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() {
        // 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>`.
        let path = std::env::temp_dir().join("nornir_bench_progress_test.log");
        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();
        let line = contents.lines().last().unwrap();
        // stamp seq [TAG] prefix body...
        let mut parts = line.splitn(2, |c: char| c == '[');
        let head = parts.next().unwrap(); // "HH:MM:SS.mmm   1 "
        let tail = parts.next().unwrap(); // "BENCH] bench: demo.case (mt) starting…"
        assert!(head.split_whitespace().count() == 2, "head: {head:?}");
        assert!(tail.starts_with("BENCH] bench: demo.case (mt) starting…"), "tail: {tail:?}");
        let _ = std::fs::remove_file(&path);
    }
}