From 06f4986d1aab3fcccdb060edc19c8cce5646c3a9 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1s=20Gr=C3=BCner?= <47506558+MegaRedHand@users.noreply.github.com> Date: Wed, 15 Jul 2026 15:28:41 -0300 Subject: [PATCH 1/3] fix(metrics): discard block-processing time for duplicate blocks lean_fork_choice_block_processing_time_seconds is sampled by a TimingGuard created at the top of on_block_core, before the idempotent duplicate-block check returns early. A duplicate does no block processing, so it recorded a near-zero sample that skewed the histogram low (duplicates are common during range sync). Add TimingGuard::discard() to cancel a measurement before the guard drops, and call it on the duplicate-block early return. The block hashing stays inside the timed span since it is real work; only the sample for the no-op duplicate is dropped. Other early returns (validation rejections) still record, as they represent real processing time. --- crates/blockchain/src/store.rs | 9 +++-- crates/common/metrics/src/timing.rs | 53 ++++++++++++++++++++++++++++- 2 files changed, 59 insertions(+), 3 deletions(-) diff --git a/crates/blockchain/src/store.rs b/crates/blockchain/src/store.rs index 8ec2bc64..0fb04d5c 100644 --- a/crates/blockchain/src/store.rs +++ b/crates/blockchain/src/store.rs @@ -569,18 +569,23 @@ fn on_block_core( signed_block: SignedBlock, verify: bool, ) -> Result<(), StoreError> { - let _timing = metrics::time_fork_choice_block_processing(); + let mut timing = metrics::time_fork_choice_block_processing(); let block_start = std::time::Instant::now(); let block = &signed_block.message; let block_root = block.hash_tree_root(); let slot = block.slot; - // Skip duplicate blocks (idempotent operation) + // Skip duplicate blocks (idempotent operation). The block hashing above is + // real work and stays inside the timed span, but a duplicate does no block + // processing, so discard the sample instead of recording a near-zero + // duration that would skew `lean_fork_choice_block_processing_time_seconds` + // low (duplicates are common during range sync). if store .has_state(&block_root) .expect("DB read should succeed") { + timing.discard(); return Ok(()); } diff --git a/crates/common/metrics/src/timing.rs b/crates/common/metrics/src/timing.rs index a3baa941..4d67bf7a 100644 --- a/crates/common/metrics/src/timing.rs +++ b/crates/common/metrics/src/timing.rs @@ -5,9 +5,15 @@ use std::time::Instant; use crate::Histogram; /// A guard that records elapsed time to a histogram when dropped. +/// +/// The measurement can be cancelled with [`TimingGuard::discard`] before the +/// guard drops, for a timed path that turns out to be a no-op whose duration +/// would only skew the histogram (e.g. an idempotent early return). pub struct TimingGuard { histogram: &'static Histogram, start: Instant, + /// When `true`, [`Drop`] does not record the elapsed time. + disarmed: bool, } impl TimingGuard { @@ -15,12 +21,57 @@ impl TimingGuard { Self { histogram, start: Instant::now(), + disarmed: false, } } + + /// Discard the measurement so no sample is recorded when the guard drops. + /// + /// Use when the timed work should not contribute a sample, such as a + /// duplicate/idempotent request that returns early: the elapsed time is + /// real but recording it would skew the histogram toward near-zero. + pub fn discard(&mut self) { + self.disarmed = true; + } } impl Drop for TimingGuard { fn drop(&mut self) { - self.histogram.observe(self.start.elapsed().as_secs_f64()); + if !self.disarmed { + self.histogram.observe(self.start.elapsed().as_secs_f64()); + } + } +} + +#[cfg(test)] +mod tests { + use prometheus::{Histogram, HistogramOpts}; + + use super::TimingGuard; + + /// Build a histogram that is not registered with any registry — enough to + /// observe samples and read `get_sample_count` without global state. + fn unregistered_histogram() -> &'static Histogram { + let opts = HistogramOpts::new("test_timing_guard", "test-only histogram"); + let histogram = Histogram::with_opts(opts).expect("valid histogram opts"); + Box::leak(Box::new(histogram)) + } + + #[test] + fn records_a_sample_on_drop() { + let histogram = unregistered_histogram(); + assert_eq!(histogram.get_sample_count(), 0); + drop(TimingGuard::new(histogram)); + assert_eq!(histogram.get_sample_count(), 1); + } + + #[test] + fn discard_suppresses_the_sample() { + let histogram = unregistered_histogram(); + { + let mut guard = TimingGuard::new(histogram); + guard.discard(); + } + assert_eq!(histogram.get_sample_count(), 0); } } From 0aaef9555eda86f367c868adfa75728522242413 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1s=20Gr=C3=BCner?= <47506558+MegaRedHand@users.noreply.github.com> Date: Wed, 15 Jul 2026 15:49:33 -0300 Subject: [PATCH 2/3] chore: simplify comment --- crates/blockchain/src/store.rs | 6 +----- 1 file changed, 1 insertion(+), 5 deletions(-) diff --git a/crates/blockchain/src/store.rs b/crates/blockchain/src/store.rs index 0fb04d5c..fbc0510c 100644 --- a/crates/blockchain/src/store.rs +++ b/crates/blockchain/src/store.rs @@ -576,11 +576,7 @@ fn on_block_core( let block_root = block.hash_tree_root(); let slot = block.slot; - // Skip duplicate blocks (idempotent operation). The block hashing above is - // real work and stays inside the timed span, but a duplicate does no block - // processing, so discard the sample instead of recording a near-zero - // duration that would skew `lean_fork_choice_block_processing_time_seconds` - // low (duplicates are common during range sync). + // Skip duplicate blocks (idempotent operation) if store .has_state(&block_root) .expect("DB read should succeed") From 2ce5658a214b5ae7f26c647369e3c1fd48d46ab6 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Tom=C3=A1s=20Gr=C3=BCner?= <47506558+MegaRedHand@users.noreply.github.com> Date: Thu, 16 Jul 2026 11:43:47 -0300 Subject: [PATCH 3/3] refactor(metrics): consume the guard in TimingGuard::discard Change discard from a `&mut self` disarmed-flag defusal to a consuming `discard(self)` that deconstructs the guard via `ManuallyDrop`, inhibiting the recording `Drop` without `mem::forget` or `unsafe`. Drop the timing unit tests. --- crates/blockchain/src/store.rs | 2 +- crates/common/metrics/src/timing.rs | 60 ++++++++--------------------- 2 files changed, 16 insertions(+), 46 deletions(-) diff --git a/crates/blockchain/src/store.rs b/crates/blockchain/src/store.rs index fbc0510c..8a439263 100644 --- a/crates/blockchain/src/store.rs +++ b/crates/blockchain/src/store.rs @@ -569,7 +569,7 @@ fn on_block_core( signed_block: SignedBlock, verify: bool, ) -> Result<(), StoreError> { - let mut timing = metrics::time_fork_choice_block_processing(); + let timing = metrics::time_fork_choice_block_processing(); let block_start = std::time::Instant::now(); let block = &signed_block.message; diff --git a/crates/common/metrics/src/timing.rs b/crates/common/metrics/src/timing.rs index 4d67bf7a..964716af 100644 --- a/crates/common/metrics/src/timing.rs +++ b/crates/common/metrics/src/timing.rs @@ -6,14 +6,13 @@ use crate::Histogram; /// A guard that records elapsed time to a histogram when dropped. /// -/// The measurement can be cancelled with [`TimingGuard::discard`] before the -/// guard drops, for a timed path that turns out to be a no-op whose duration -/// would only skew the histogram (e.g. an idempotent early return). +/// The measurement can be cancelled with [`TimingGuard::discard`], which +/// consumes the guard without recording a sample, for a timed path that turns +/// out to be a no-op whose duration would only skew the histogram (e.g. an +/// idempotent early return). pub struct TimingGuard { histogram: &'static Histogram, start: Instant, - /// When `true`, [`Drop`] does not record the elapsed time. - disarmed: bool, } impl TimingGuard { @@ -21,57 +20,28 @@ impl TimingGuard { Self { histogram, start: Instant::now(), - disarmed: false, } } - /// Discard the measurement so no sample is recorded when the guard drops. + /// Consume the guard without recording a sample. /// /// Use when the timed work should not contribute a sample, such as a /// duplicate/idempotent request that returns early: the elapsed time is /// real but recording it would skew the histogram toward near-zero. - pub fn discard(&mut self) { - self.disarmed = true; + /// + /// `TimingGuard` implements [`Drop`], so its fields cannot be moved out to + /// destructure it directly. Wrapping in [`std::mem::ManuallyDrop`] inhibits + /// the recording `Drop`; the fields are `Copy`, so they are then read out + /// and their copies dropped here, leaving nothing to record. + pub fn discard(self) { + let guard = std::mem::ManuallyDrop::new(self); + let _histogram = guard.histogram; + let _start = guard.start; } } impl Drop for TimingGuard { fn drop(&mut self) { - if !self.disarmed { - self.histogram.observe(self.start.elapsed().as_secs_f64()); - } - } -} - -#[cfg(test)] -mod tests { - use prometheus::{Histogram, HistogramOpts}; - - use super::TimingGuard; - - /// Build a histogram that is not registered with any registry — enough to - /// observe samples and read `get_sample_count` without global state. - fn unregistered_histogram() -> &'static Histogram { - let opts = HistogramOpts::new("test_timing_guard", "test-only histogram"); - let histogram = Histogram::with_opts(opts).expect("valid histogram opts"); - Box::leak(Box::new(histogram)) - } - - #[test] - fn records_a_sample_on_drop() { - let histogram = unregistered_histogram(); - assert_eq!(histogram.get_sample_count(), 0); - drop(TimingGuard::new(histogram)); - assert_eq!(histogram.get_sample_count(), 1); - } - - #[test] - fn discard_suppresses_the_sample() { - let histogram = unregistered_histogram(); - { - let mut guard = TimingGuard::new(histogram); - guard.discard(); - } - assert_eq!(histogram.get_sample_count(), 0); + self.histogram.observe(self.start.elapsed().as_secs_f64()); } }