benchmark delays by path

3 files changed, 28 insertions, 0 deletions

diff --git a/src/simtest/bench.rs b/src/simtest/bench.rs
index 290fd7c..09cd82c 100644
--- a/src/simtest/bench.rs
+++ b/src/simtest/bench.rs
@@ -240,6 +240,8 @@ impl Totals {
             relay.carrying_bloom_bytes += stats.relay.carrying_bloom_bytes;
             relay.nothing_new_change_bytes += stats.relay.nothing_new_change_bytes;
             relay.nothing_new_bloom_bytes += stats.relay.nothing_new_bloom_bytes;
+            relay.off_tree += stats.relay.off_tree;
+            relay.off_tree_ms += stats.relay.off_tree_ms;
             for (_, peer_state) in node.peers_snapshot().await {
                 totals.incidents.add(&peer_state.lock().await.incidents);
             }
@@ -575,6 +577,17 @@ fn report(
         within(0.5),
         within(0.99),
     );
+    let off_tree = r1.off_tree - r0.off_tree;
+    let along = propagation.count.saturating_sub(off_tree);
+    let _ = writeln!(
+        out,
+        "    of those, along writers' trees: {along} (mean {} ms); not: {off_tree} (mean {} ms)",
+        propagation
+            .sum_ms
+            .saturating_sub(r1.off_tree_ms - r0.off_tree_ms)
+            / along.max(1),
+        (r1.off_tree_ms - r0.off_tree_ms) / off_tree.max(1),
+    );
     // Where the late arrivals were: the nodes that had any, the most first.
     let mut late: Vec<(&str, u64, u64)> = during
         .0
diff --git a/src/swarm/stats.rs b/src/swarm/stats.rs
index 905e668..74076a4 100644
--- a/src/swarm/stats.rs
+++ b/src/swarm/stats.rs
@@ -129,6 +129,10 @@ pub(crate) struct Relay {
     pub(crate) carrying_bloom_bytes: u64,
     pub(crate) nothing_new_change_bytes: u64,
     pub(crate) nothing_new_bloom_bytes: u64,
+    /// Changes from elsewhere that came not along a writer's tree (pulled, with an
+    /// answer, sent again), and their delays summed (as `Propagation`).
+    pub(crate) off_tree: u64,
+    pub(crate) off_tree_ms: u64,
 }
 
 /// When the initial sync finished, and what it took.
@@ -248,6 +252,14 @@ impl NodeStats {
         inner.relay.nothing_new_bloom_bytes += sizes.1 as u64;
     }
 
+    /// Changes from elsewhere were applied, `delays_ms` after they were committed, that
+    /// came not along a writer's tree.
+    pub(crate) fn off_tree(&self, delays_ms: &[i64]) {
+        let mut inner = self.lock();
+        inner.relay.off_tree += delays_ms.len() as u64;
+        inner.relay.off_tree_ms += delays_ms.iter().map(|ms| ms.max(&0)).sum::<i64>() as u64;
+    }
+
     /// A sync message carrying changes arrived; `sizes`: of its changes and blooms.
     pub(crate) fn carrying(&self, sizes: (usize, usize)) {
         let mut inner = self.lock();
diff --git a/src/swarm/sync.rs b/src/swarm/sync.rs
index 04d06de..4bb6ba5 100644
--- a/src/swarm/sync.rs
+++ b/src/swarm/sync.rs
@@ -469,6 +469,9 @@ pub(crate) async fn handle_sync(
                         .into_iter()
                         .map(|time| now_ms - time)
                         .collect();
+                if writer.is_none() {
+                    stats.off_tree(&delays);
+                }
                 stats.propagated(delays);
             }