From 88c46a1cf8ac6ee09e5b615361d09263b05ca23d Mon Sep 17 00:00:00 2001 From: Nathan Herald Date: Mon, 24 Aug 2026 19:44:55 +0200 Subject: [PATCH] sync: time each peer's reconcile separately The per-phase counters from #68 say the peer step is 90.8 percent of a sync pass on Silber, and that it is CPU rather than blocking. They cannot say whether both peers cost the same. That distinction decides the fix. In the window I measured, droppy was relay-routed and hetz was direct, in the same pass. If one of those dominates, the answer is about the path. If they cost the same, the answer is about the manifest, which is the same 31,000 entries either way. The aggregate counter hides exactly that. So each peer's reconcile is timed and logged to the validation log: peer, microseconds, and whether it failed. EMITTED BEFORE THE OUTCOME IS MATCHED, DELIBERATELY. Putting this inside the Ok arm would have hidden every failing peer, and a peer that times out or retries on a relay is precisely the expensive case being hunted. A diagnostic that only fires on success fails open and reports a healthy picture of an unhealthy one. A LOG LINE RATHER THAN A COUNTER, WHICH IS THE OPPOSITE OF #68. Peers are dynamic, so per-peer counters would put an unbounded set of keys on the control wire. This question is also a one-off: once we know whether the path matters, the line has served. The volume is proportionate at about 4.6 lines a minute against the roughly 15 that log already writes. `VALIDATION_LOG_TARGET` becomes `pub(crate)` instead of being retyped in a second place. Two copies of a literal drift apart. NO NEW TEST, AND I WILL NOT PRETEND OTHERWISE. This emits a diagnostic and changes no behaviour. The 237 lib and 12 bin tests are the control that it changed nothing. A test asserting a log line fires would need a subscriber-capture harness and would mirror the change rather than check it. Verified on macOS 15 arm64. Linux is CI's. Agent: Silber.fabric --- src/daemon.rs | 4 +++- src/sync/engine.rs | 23 ++++++++++++++++++++--- 2 files changed, 23 insertions(+), 4 deletions(-) diff --git a/src/daemon.rs b/src/daemon.rs index 2201d77..8be7750 100644 --- a/src/daemon.rs +++ b/src/daemon.rs @@ -96,7 +96,9 @@ const PEER_HEALTH_ATTEMPTS_BEFORE_RECYCLE: usize = 3; /// peer, so a genuinely-down peer does not cause recovery thrash. const PEER_HEALTH_RECOVER_INITIAL_BACKOFF: Duration = Duration::from_secs(30); const PEER_HEALTH_RECOVER_MAX_BACKOFF: Duration = Duration::from_secs(10 * 60); -const VALIDATION_LOG_TARGET: &str = "fabric::validation"; +/// The validation log target. `pub(crate)` because `sync::engine` writes to the +/// same log and a second copy of the literal is a string that drifts. +pub(crate) const VALIDATION_LOG_TARGET: &str = "fabric::validation"; /// What a backoff record is about. /// diff --git a/src/sync/engine.rs b/src/sync/engine.rs index 2e1e176..2d7ebd2 100644 --- a/src/sync/engine.rs +++ b/src/sync/engine.rs @@ -27,6 +27,8 @@ use std::{ }; use anyhow::{Context, Result}; + +use crate::daemon::VALIDATION_LOG_TARGET; use iroh::EndpointAddr; use serde::{Deserialize, Serialize}; use tokio::sync::{Mutex, OwnedMutexGuard, RwLock, mpsc}; @@ -868,11 +870,26 @@ impl SyncEngine { if self.cancel.is_cancelled() { break; } - match self + let peer_started = Instant::now(); + let outcome = self .transport .reconcile(peer.clone(), name.to_string(), entry.node.clone()) - .await - { + .await; + // Per peer, every pass, whether or not it changed anything. The + // aggregate reconcile counter says the peer step is 91% of a pass; + // it cannot say whether both peers cost the same. A relay-routed + // peer and a direct one in the same window are the case that + // matters, and the aggregate hides it. + tracing::debug!( + target: VALIDATION_LOG_TARGET, + event = "reconcile_peer", + sync = name, + peer = peer.id, + micros = peer_started.elapsed().as_micros() as u64, + failed = outcome.is_err(), + "per-peer reconcile cost" + ); + match outcome { Ok(stats) => { if !stats.is_noop() { tracing::debug!(sync = name, peer = peer.id, ?stats, "sync reconciled");