hop delays

4 files changed, 128 insertions, 2 deletions

diff --git a/src/swarm/hop.rs b/src/swarm/hop.rs
new file mode 100644
index 0000000..4cd413f
--- /dev/null
+++ b/src/swarm/hop.rs
@@ -0,0 +1,102 @@
+//! How long sync messages take from a peer to us, per hop: from the peer's clock when it
+//! generated one (`SyncEnvelope::sent`) to ours when we start handling it, the peer's
+//! clock offset taken off (`Transport::clock_offset`, from PING and PONG). So the
+//! transport, the network and the queues at both ends, which a PING's round trip leaves
+//! out (PINGs don't wait behind sync messages).
+//!
+//! The offset is known to within half a round trip only, so a single figure is too;
+//! but that error is the same for every message from a peer while the offset stands, so
+//! how the delay changes over time is exact: a link getting worse shows whatever the
+//! offset. Hence the means of the last `MINUTES` minutes besides all since start, and
+//! half the round trip to compare with (`api::peers`).
+
+use std::collections::VecDeque;
+
+use tokio::time::{Duration, Instant};
+
+use crate::swarm::stats::Propagation;
+
+/// The minutes whose means are kept.
+pub(crate) const MINUTES: usize = 15;
+const MINUTE: Duration = Duration::from_secs(60);
+
+/// A peer's hop delays (`PeerState::hop_delays`).
+#[derive(Debug, Default, Clone)]
+pub(crate) struct HopDelays {
+    /// All since we started, in buckets.
+    pub(crate) all: Propagation,
+    /// The minutes with messages, oldest first: when each began, how many, their sum.
+    minutes: VecDeque<(Instant, u64, i64)>,
+}
+
+impl HopDelays {
+    /// A message that took `delay_ms` (negative where the offset's error exceeds it).
+    pub(crate) fn record(&mut self, delay_ms: i64, now: Instant) {
+        self.all.record(delay_ms);
+        match self.minutes.back_mut() {
+            Some((began, count, sum)) if now.saturating_duration_since(*began) < MINUTE => {
+                *count += 1;
+                *sum += delay_ms;
+            }
+            _ => self.minutes.push_back((now, 1, delay_ms)),
+        }
+        while self.minutes.front().is_some_and(|(began, _, _)| {
+            now.saturating_duration_since(*began) >= MINUTE * MINUTES as u32
+        }) {
+            self.minutes.pop_front();
+        }
+    }
+
+    /// The mean of each of the last `MINUTES` minutes, oldest first, None for one without
+    /// messages; the last is the current one.
+    pub(crate) fn by_minute(&self, now: Instant) -> Vec<Option<i64>> {
+        let mut means = vec![None; MINUTES];
+        for (began, count, sum) in &self.minutes {
+            let ago = (now.saturating_duration_since(*began).as_secs() / 60) as usize;
+            if ago < MINUTES {
+                means[MINUTES - 1 - ago] = Some(sum / (*count).max(1) as i64);
+            }
+        }
+        means
+    }
+}
+
+/// How long a sync message `sent` by a peer (its clock) took to come, as `arrived` (ours),
+/// with the peer's clock `offset_ms` ahead of ours.
+pub(crate) fn delay_ms(
+    sent: crate::clock::UnixMillis,
+    arrived: crate::clock::UnixMillis,
+    offset_ms: i64,
+) -> i64 {
+    arrived.as_u64() as i64 - sent.as_u64() as i64 + offset_ms
+}
+
+#[cfg(test)]
+mod tests {
+    use super::*;
+    use crate::clock::UnixMillis;
+
+    /// Sent at 1000 by a clock 300 ahead (700 by ours), arrived at 750: 50 ms.
+    #[test]
+    fn the_offset_is_taken_off() {
+        assert_eq!(delay_ms(UnixMillis(1000), UnixMillis(750), 300), 50);
+    }
+
+    /// Each minute's mean, oldest first; minutes past `MINUTES` forgotten.
+    #[test]
+    fn means_by_minute() {
+        let start = Instant::now();
+        let mut delays = HopDelays::default();
+        delays.record(10, start);
+        delays.record(30, start + Duration::from_secs(10));
+        delays.record(100, start + MINUTE * 2);
+        let now = start + MINUTE * 2 + Duration::from_secs(1);
+        let means = delays.by_minute(now);
+        assert_eq!(means[MINUTES - 1], Some(100));
+        assert_eq!(means[MINUTES - 2], None);
+        assert_eq!(means[MINUTES - 3], Some(20));
+        assert_eq!(delays.all.count, 3);
+        delays.record(5, start + MINUTE * (MINUTES as u32 + 1));
+        assert_eq!(delays.minutes.len(), 2, "the first minute is forgotten");
+    }
+}
diff --git a/src/swarm/mod.rs b/src/swarm/mod.rs
index 985e968..071f00e 100644
--- a/src/swarm/mod.rs
+++ b/src/swarm/mod.rs
@@ -6,6 +6,7 @@ pub(crate) mod blob;
 pub(crate) mod bootstrap;
 pub(crate) mod changes;
 pub(crate) mod document_file;
+pub(crate) mod hop;
 pub(crate) mod links;
 pub(crate) mod members;
 pub(crate) mod pair;
diff --git a/src/swarm/stats.rs b/src/swarm/stats.rs
index 74076a4..de63962 100644
--- a/src/swarm/stats.rs
+++ b/src/swarm/stats.rs
@@ -59,7 +59,7 @@ pub(crate) struct Propagation {
 }
 
 impl Propagation {
-    fn record(&mut self, delay_ms: i64) {
+    pub(crate) fn record(&mut self, delay_ms: i64) {
         if delay_ms < 0 {
             self.ahead += 1;
         }
@@ -73,6 +73,20 @@ impl Propagation {
         self.sum_ms += delay_ms;
     }
 
+    /// The bound of the bucket by which `quantile` of the delays came: None if beyond
+    /// the last bound, or none came.
+    pub(crate) fn within(&self, quantile: f64) -> Option<u64> {
+        let wanted = (self.count as f64 * quantile).ceil() as u64;
+        let mut seen = 0;
+        for (bound, count) in self.buckets() {
+            seen += count;
+            if seen >= wanted && seen > 0 {
+                return bound;
+            }
+        }
+        None
+    }
+
     /// Each bucket's upper bound (None for the last) and count.
     pub(crate) fn buckets(&self) -> impl Iterator<Item = (Option<u64>, u64)> + '_ {
         PROPAGATION_BUCKETS_MS
diff --git a/src/swarm/sync.rs b/src/swarm/sync.rs
index 4bb6ba5..a9d98b0 100644
--- a/src/swarm/sync.rs
+++ b/src/swarm/sync.rs
@@ -140,6 +140,7 @@ async fn deliver_sync_to_peer(state: &AppState, peer: &str) -> Result<()> {
         let delta_threshold = state.blobs.delta_threshold_for(rate, failed);
 
         let stats = Arc::clone(&state.stats);
+        let clock = Arc::clone(&state.clock);
         // The session the message comes from, for its send's outcome.
         let (session, generated) = tokio::task::spawn_blocking(
             move || -> (u64, Result<Option<transport::EncodedMessage>>) {
@@ -205,6 +206,7 @@ async fn deliver_sync_to_peer(state: &AppState, peer: &str) -> Result<()> {
                     ready,
                     writer,
                     delivered,
+                    sent: clock.now_millis(),
                 };
                 let encoded = transport
                     .encode(&peer_owned, &ParsedMessage::Sync(envelope))
@@ -318,11 +320,18 @@ pub(crate) async fn handle_sync(
     debug!(peer = %peer, "Processing sync envelope");
     // This message is counted already (`transport::traffic`).
     let arrived = (Instant::now(), SyncBytes::of(&state.traffic, peer));
+    // How long it took to come, where we know the peer's clock (`swarm::hop`).
+    let hop_delay = state.transport.clock_offset(peer).map(|offset| {
+        crate::swarm::hop::delay_ms(envelope.sent, state.clock.now_millis(), offset.offset_ms)
+    });
 
     let peer_state_mutex = state.get_or_create_peer_state(peer).await;
 
     let needs_hello = {
-        let peer_state = peer_state_mutex.lock().await;
+        let mut peer_state = peer_state_mutex.lock().await;
+        if let Some(delay_ms) = hop_delay {
+            peer_state.hop_delays.record(delay_ms, arrived.0);
+        }
 
         match &peer_state.standing {
             Standing::Stranger | Standing::Admitted => {