diff --git a/beacon_node/beacon_chain/src/beacon_chain.rs b/beacon_node/beacon_chain/src/beacon_chain.rs index ec4379b9cd..30479795e5 100644 --- a/beacon_node/beacon_chain/src/beacon_chain.rs +++ b/beacon_node/beacon_chain/src/beacon_chain.rs @@ -24,7 +24,8 @@ use crate::shuffling_cache::{BlockShufflingIds, ShufflingCache}; use crate::snapshot_cache::SnapshotCache; use crate::timeout_rw_lock::TimeoutRwLock; use crate::validator_monitor::{ - ValidatorMonitor, HISTORIC_EPOCHS as VALIDATOR_MONITOR_HISTORIC_EPOCHS, + get_block_delay_ms, timestamp_now, ValidatorMonitor, + HISTORIC_EPOCHS as VALIDATOR_MONITOR_HISTORIC_EPOCHS, }; use crate::validator_pubkey_cache::ValidatorPubkeyCache; use crate::BeaconForkChoiceStore; @@ -1712,6 +1713,15 @@ impl BeaconChain { // This prevents inconsistency between the two at the expense of concurrency. drop(fork_choice); + // Log metrics to track the delay between when the block was made and when we imported it. + // + // We're declaring the block "imported" at this point, since fork choice and the DB know + // about it. + metrics::observe_duration( + &metrics::BEACON_BLOCK_IMPORTED_SLOT_START_DELAY_TIME, + get_block_delay_ms(timestamp_now(), &signed_block.message, &self.slot_clock), + ); + let parent_root = block.parent_root; let slot = block.slot; diff --git a/beacon_node/beacon_chain/src/metrics.rs b/beacon_node/beacon_chain/src/metrics.rs index 029c27da20..f70a11dcb0 100644 --- a/beacon_node/beacon_chain/src/metrics.rs +++ b/beacon_node/beacon_chain/src/metrics.rs @@ -570,6 +570,13 @@ lazy_static! { &["src", "validator"] ); + /* + * Block Delay Metrics + */ + pub static ref BEACON_BLOCK_IMPORTED_SLOT_START_DELAY_TIME: Result = try_create_histogram( + "beacon_block_imported_slot_start_delay_time", + "Duration between the start of the blocks slot and the current time.", + ); } /// Scrape the `beacon_chain` for metrics that are not constantly updated (e.g., the present slot, diff --git a/beacon_node/beacon_chain/src/validator_monitor.rs b/beacon_node/beacon_chain/src/validator_monitor.rs index 5cb37fa881..ec906ed199 100644 --- a/beacon_node/beacon_chain/src/validator_monitor.rs +++ b/beacon_node/beacon_chain/src/validator_monitor.rs @@ -367,18 +367,6 @@ impl ValidatorMonitor { } } - /// Returns the delay between the start of `block.slot` and `seen_timestamp`. - fn get_block_delay_ms( - seen_timestamp: Duration, - block: &BeaconBlock, - slot_clock: &S, - ) -> Duration { - slot_clock - .start_of(block.slot) - .and_then(|slot_start| seen_timestamp.checked_sub(slot_start)) - .unwrap_or_else(|| Duration::from_secs(0)) - } - /// Process a block received on gossip. pub fn register_gossip_block( &self, @@ -410,7 +398,7 @@ impl ValidatorMonitor { slot_clock: &S, ) { if let Some(id) = self.get_validator_id(block.proposer_index) { - let delay = Self::get_block_delay_ms(seen_timestamp, block, slot_clock); + let delay = get_block_delay_ms(seen_timestamp, block, slot_clock); metrics::inc_counter_vec(&metrics::VALIDATOR_MONITOR_BEACON_BLOCK_TOTAL, &[src, id]); metrics::observe_timer_vec( @@ -951,3 +939,15 @@ pub fn timestamp_now() -> Duration { fn u64_to_i64(n: impl Into) -> i64 { i64::try_from(n.into()).unwrap_or(i64::max_value()) } + +/// Returns the delay between the start of `block.slot` and `seen_timestamp`. +pub fn get_block_delay_ms( + seen_timestamp: Duration, + block: &BeaconBlock, + slot_clock: &S, +) -> Duration { + slot_clock + .start_of(block.slot) + .and_then(|slot_start| seen_timestamp.checked_sub(slot_start)) + .unwrap_or_else(|| Duration::from_secs(0)) +} diff --git a/beacon_node/network/src/beacon_processor/worker/gossip_methods.rs b/beacon_node/network/src/beacon_processor/worker/gossip_methods.rs index ee226a9f6a..443aa0265e 100644 --- a/beacon_node/network/src/beacon_processor/worker/gossip_methods.rs +++ b/beacon_node/network/src/beacon_processor/worker/gossip_methods.rs @@ -3,12 +3,13 @@ use crate::{metrics, service::NetworkMessage, sync::SyncMessage}; use beacon_chain::{ attestation_verification::{Error as AttnError, SignatureVerifiedAttestation}, observed_operations::ObservationOutcome, + validator_monitor::get_block_delay_ms, BeaconChainError, BeaconChainTypes, BlockError, ForkChoiceError, }; use eth2_libp2p::{MessageAcceptance, MessageId, PeerAction, PeerId, ReportSource}; use slog::{debug, error, info, trace, warn}; use ssz::Encode; -use std::time::Duration; +use std::time::{Duration, SystemTime, UNIX_EPOCH}; use types::{ Attestation, AttesterSlashing, Hash256, ProposerSlashing, SignedAggregateAndProof, SignedBeaconBlock, SignedVoluntaryExit, SubnetId, @@ -237,6 +238,12 @@ impl Worker { block: SignedBeaconBlock, seen_duration: Duration, ) { + // Log metrics to track delay from other nodes on the network. + metrics::observe_duration( + &metrics::BEACON_BLOCK_GOSSIP_SLOT_START_DELAY_TIME, + get_block_delay_ms(seen_duration, &block.message, &self.chain.slot_clock), + ); + let verified_block = match self.chain.verify_block_for_gossip(block) { Ok(verified_block) => { info!( @@ -246,6 +253,19 @@ impl Worker { "hash" => %verified_block.block_root ); self.propagate_validation_result(message_id, peer_id, MessageAcceptance::Accept); + + // Log metrics to keep track of propagation delay times. + if let Some(duration) = SystemTime::now() + .duration_since(UNIX_EPOCH) + .ok() + .and_then(|now| now.checked_sub(seen_duration)) + { + metrics::observe_duration( + &metrics::BEACON_BLOCK_GOSSIP_PROPAGATION_VERIFICATION_DELAY_TIME, + duration, + ); + } + verified_block } Err(BlockError::ParentUnknown(block)) => { diff --git a/beacon_node/network/src/metrics.rs b/beacon_node/network/src/metrics.rs index b046ccbfb1..11f04ff860 100644 --- a/beacon_node/network/src/metrics.rs +++ b/beacon_node/network/src/metrics.rs @@ -351,6 +351,17 @@ lazy_static! { &["range_type"] ); + /* + * Block Delay Metrics + */ + pub static ref BEACON_BLOCK_GOSSIP_PROPAGATION_VERIFICATION_DELAY_TIME: Result = try_create_histogram( + "beacon_block_gossip_propagation_verification_delay_time", + "Duration between when the block is received and when it is verified for propagation.", + ); + pub static ref BEACON_BLOCK_GOSSIP_SLOT_START_DELAY_TIME: Result = try_create_histogram( + "beacon_block_gossip_slot_start_delay_time", + "Duration between when the block is received and the start of the slot it belongs to.", + ); } pub fn register_attestation_error(error: &AttnError) { diff --git a/common/lighthouse_metrics/src/lib.rs b/common/lighthouse_metrics/src/lib.rs index 7f5bcf5e9c..b8f8601716 100644 --- a/common/lighthouse_metrics/src/lib.rs +++ b/common/lighthouse_metrics/src/lib.rs @@ -252,14 +252,8 @@ pub fn start_timer(histogram: &Result) -> Option { /// Starts a timer on `vec` with the given `name`. pub fn observe_timer_vec(vec: &Result, name: &[&str], duration: Duration) { - // This conversion was taken from here: - // - // https://docs.rs/prometheus/0.5.0/src/prometheus/histogram.rs.html#550-555 - let nanos = f64::from(duration.subsec_nanos()) / 1e9; - let secs = duration.as_secs() as f64 + nanos; - if let Some(h) = get_histogram(vec, name) { - h.observe(secs) + h.observe(duration_to_f64(duration)) } } @@ -330,3 +324,17 @@ pub fn observe(histogram: &Result, value: f64) { histogram.observe(value); } } + +pub fn observe_duration(histogram: &Result, duration: Duration) { + if let Ok(histogram) = histogram { + histogram.observe(duration_to_f64(duration)) + } +} + +fn duration_to_f64(duration: Duration) -> f64 { + // This conversion was taken from here: + // + // https://docs.rs/prometheus/0.5.0/src/prometheus/histogram.rs.html#550-555 + let nanos = f64::from(duration.subsec_nanos()) / 1e9; + duration.as_secs() as f64 + nanos +}