add late arrivals benchmark

1 files changed, 49 insertions, 3 deletions

diff --git a/src/simtest/bench.rs b/src/simtest/bench.rs
index a263e64..acf91bf 100644
--- a/src/simtest/bench.rs
+++ b/src/simtest/bench.rs
@@ -167,14 +167,20 @@ async fn bench_propagation() {
 
 /// What all nodes have sent, counted, and their relay counters and propagation delays
 /// summed: at one moment.
-#[derive(Clone, Copy)]
+#[derive(Clone)]
 struct Totals {
     at: Instant,
     sent: ByKind,
     relay: Relay,
     propagation: Propagation,
+    /// Per node, by name: its arrivals, their delays summed, and those later than
+    /// `LATE_MS`.
+    by_node: Vec<(String, u64, u64, u64)>,
 }
 
+/// Arrivals later than this are late (`report`): the propagation buckets above it.
+const LATE_MS: u64 = 500;
+
 impl Totals {
     fn of(nodes: &[AppState]) -> Self {
         let mut totals = Self {
@@ -182,6 +188,7 @@ impl Totals {
             sent: ByKind::default(),
             relay: Relay::default(),
             propagation: Propagation::default(),
+            by_node: Vec::new(),
         };
         for node in nodes {
             let sent = node.traffic.total().sent;
@@ -210,6 +217,20 @@ impl Totals {
             }
             propagation.count += stats.propagation.count;
             propagation.sum_ms += stats.propagation.sum_ms;
+            let late: u64 = stats
+                .propagation
+                .buckets()
+                .filter(|(bound, _)| bound.is_none_or(|bound| bound > LATE_MS))
+                .map(|(_, count)| count)
+                .sum();
+            totals.by_node.push((
+                node.alias
+                    .clone()
+                    .unwrap_or_else(|| node.local_id().to_owned()),
+                stats.propagation.count,
+                stats.propagation.sum_ms,
+                late,
+            ));
         }
         totals
     }
@@ -310,7 +331,7 @@ async fn run(seed: u64, scenario: &'static Scenario) -> String {
         }
     }
     let n = halves.len();
-    let quiet = (halves[n.saturating_sub(3)], halves[n - 1]);
+    let quiet = (halves[n.saturating_sub(3)].clone(), halves[n - 1].clone());
 
     let _ = writeln!(
         out,
@@ -340,7 +361,7 @@ async fn run(seed: u64, scenario: &'static Scenario) -> String {
         report(
             &mut out,
             workload,
-            quiet,
+            quiet.clone(),
             (start, Totals::of(&nodes)),
             converged,
         );
@@ -438,4 +459,29 @@ fn report(
         within(0.5),
         within(0.99),
     );
+    // Where the late arrivals were: the nodes that had any, the most first.
+    let mut late: Vec<(&str, u64, u64)> = during
+        .0
+        .by_node
+        .iter()
+        .zip(&during.1.by_node)
+        .map(|((name, c0, s0, l0), (_, c1, s1, l1))| {
+            (name.as_str(), l1 - l0, (s1 - s0) / (c1 - c0).max(1))
+        })
+        .filter(|(_, late, _)| *late > 0)
+        .collect();
+    late.sort_by_key(|(_, late, _)| std::cmp::Reverse(*late));
+    if !late.is_empty() {
+        let listed: Vec<String> = late
+            .iter()
+            .take(5)
+            .map(|(name, late, mean)| format!("{name} {late} (mean {mean} ms)"))
+            .collect();
+        let _ = writeln!(
+            out,
+            "    later than {LATE_MS} ms: {}{}",
+            listed.join(", "),
+            if late.len() > 5 { ", …" } else { "" }
+        );
+    }
 }