From 77fea620ce583752b8d277e467455d348fe21e2d Mon Sep 17 00:00:00 2001 From: Michael Sproul Date: Tue, 2 Apr 2024 17:15:14 +1100 Subject: [PATCH 1/8] Add timing for block availability --- beacon_node/beacon_chain/src/beacon_chain.rs | 31 ++++-- .../beacon_chain/src/block_times_cache.rs | 50 ++++++++- .../beacon_chain/src/block_verification.rs | 3 +- .../beacon_chain/src/canonical_head.rs | 27 ++++- .../src/data_availability_checker.rs | 40 ++++++- .../src/data_availability_checker/error.rs | 4 +- .../overflow_lru_cache.rs | 100 +++++++++++++----- beacon_node/execution_layer/src/lib.rs | 24 +++-- 8 files changed, 223 insertions(+), 56 deletions(-) diff --git a/beacon_node/beacon_chain/src/beacon_chain.rs b/beacon_node/beacon_chain/src/beacon_chain.rs index deeda491dca..5fb5fe39573 100644 --- a/beacon_node/beacon_chain/src/beacon_chain.rs +++ b/beacon_node/beacon_chain/src/beacon_chain.rs @@ -2955,7 +2955,7 @@ impl BeaconChain { } /// Wraps `process_block` in logic to cache the block's commitments in the processing cache - /// and evict if the block was imported or erred. + /// and evict if the block was imported or errored. pub async fn process_block_with_early_caching>( self: &Arc, block_root: Hash256, @@ -2998,22 +2998,20 @@ impl BeaconChain { // Increment the Prometheus counter for block processing requests. metrics::inc_counter(&metrics::BLOCK_PROCESSING_REQUESTS); + let block_slot = unverified_block.block().slot(); + // Set observed time if not already set. Usually this should be set by gossip or RPC, // but just in case we set it again here (useful for tests). - if let (Some(seen_timestamp), Some(current_slot)) = - (self.slot_clock.now_duration(), self.slot_clock.now()) - { + if let Some(seen_timestamp) = self.slot_clock.now_duration() { self.block_times_cache.write().set_time_observed( block_root, - current_slot, + block_slot, seen_timestamp, None, None, ); } - let block_slot = unverified_block.block().slot(); - // A small closure to group the verification and import errors. let chain = self.clone(); let import_block = async move { @@ -3090,8 +3088,8 @@ impl BeaconChain { } } - /// Accepts a fully-verified block and awaits on it's payload verification handle to - /// get a fully `ExecutedBlock` + /// Accepts a fully-verified block and awaits on its payload verification handle to + /// get a fully `ExecutedBlock`. /// /// An error is returned if the verification handle couldn't be awaited. pub async fn into_executed_block( @@ -3256,6 +3254,13 @@ impl BeaconChain { consensus_context, } = import_data; + // Record the time at which this block became available. + self.block_times_cache.write().set_time_available( + block_root, + block.slot(), + block.available_timestamp(), + ); + // import let chain = self.clone(); let block_root = self @@ -3398,6 +3403,14 @@ impl BeaconChain { "Early attester cache insert failed"; "error" => ?e ); + } else { + let attestable_timestamp = + self.slot_clock.now_duration().unwrap_or_default(); + self.block_times_cache.write().set_time_attestable( + block_root, + signed_block.slot(), + attestable_timestamp, + ) } } else { warn!( diff --git a/beacon_node/beacon_chain/src/block_times_cache.rs b/beacon_node/beacon_chain/src/block_times_cache.rs index c5293bcb0ee..84da2c2b807 100644 --- a/beacon_node/beacon_chain/src/block_times_cache.rs +++ b/beacon_node/beacon_chain/src/block_times_cache.rs @@ -18,6 +18,8 @@ type BlockRoot = Hash256; #[derive(Clone, Default)] pub struct Timestamps { pub observed: Option, + pub available: Option, + pub attestable: Option, pub imported: Option, pub set_as_head: Option, } @@ -25,8 +27,18 @@ pub struct Timestamps { // Helps arrange delay data so it is more relevant to metrics. #[derive(Debug, Default)] pub struct BlockDelays { + /// Time after start of slot. pub observed: Option, + /// Time after `observable`. + pub available: Option, + /// Time after `available`. + pub attestable: Option, + /// ALSO time after `available`. + /// + /// We need to use `available` again rather than `attestable` to handle the case where the block + /// does not get added to the early-attester cache. pub imported: Option, + /// Time after `imported`. pub set_as_head: Option, } @@ -35,14 +47,22 @@ impl BlockDelays { let observed = times .observed .and_then(|observed_time| observed_time.checked_sub(slot_start_time)); + let available = times + .available + .and_then(|available_time| available_time.checked_sub(times.observed?)); + let attestable = times + .attestable + .and_then(|attestable_time| attestable_time.checked_sub(times.available?)); let imported = times .imported - .and_then(|imported_time| imported_time.checked_sub(times.observed?)); + .and_then(|imported_time| imported_time.checked_sub(times.available?)); let set_as_head = times .set_as_head .and_then(|set_as_head_time| set_as_head_time.checked_sub(times.imported?)); BlockDelays { observed, + available, + attestable, imported, set_as_head, } @@ -109,6 +129,34 @@ impl BlockTimesCache { } } + pub fn set_time_available(&mut self, block_root: BlockRoot, slot: Slot, timestamp: Duration) { + let block_times = self + .cache + .entry(block_root) + .or_insert_with(|| BlockTimesCacheValue::new(slot)); + if block_times + .timestamps + .available + .map_or(true, |prev| timestamp < prev) + { + block_times.timestamps.available = Some(timestamp); + } + } + + pub fn set_time_attestable(&mut self, block_root: BlockRoot, slot: Slot, timestamp: Duration) { + let block_times = self + .cache + .entry(block_root) + .or_insert_with(|| BlockTimesCacheValue::new(slot)); + if block_times + .timestamps + .attestable + .map_or(true, |prev| timestamp < prev) + { + block_times.timestamps.attestable = Some(timestamp); + } + } + pub fn set_time_imported(&mut self, block_root: BlockRoot, slot: Slot, timestamp: Duration) { let block_times = self .cache diff --git a/beacon_node/beacon_chain/src/block_verification.rs b/beacon_node/beacon_chain/src/block_verification.rs index ecfd04ed00f..7c70338491d 100644 --- a/beacon_node/beacon_chain/src/block_verification.rs +++ b/beacon_node/beacon_chain/src/block_verification.rs @@ -666,8 +666,7 @@ type PayloadVerificationHandle = /// - Parent is known /// - Signatures /// - State root check -/// - Per block processing -/// - Blobs sidecar has been validated if present +/// - Block processing /// /// Note: a `ExecutionPendingBlock` is not _forever_ valid to be imported, it may later become invalid /// due to finality or some other event. A `ExecutionPendingBlock` should be imported into the diff --git a/beacon_node/beacon_chain/src/canonical_head.rs b/beacon_node/beacon_chain/src/canonical_head.rs index ced4eda05cf..1a1790dfe34 100644 --- a/beacon_node/beacon_chain/src/canonical_head.rs +++ b/beacon_node/beacon_chain/src/canonical_head.rs @@ -1437,6 +1437,9 @@ fn observe_head_block_delays( // If the block was enshrined as head too late for attestations to be created for it, // log a debug warning and increment a metric. + let format_delay = |delay: &Option| { + delay.map_or("unknown".to_string(), |d| format!("{}", d.as_millis())) + }; if late_head { metrics::inc_counter(&metrics::BEACON_BLOCK_HEAD_SLOT_START_DELAY_EXCEEDED_TOTAL); debug!( @@ -1445,10 +1448,26 @@ fn observe_head_block_delays( "block_root" => ?head_block_root, "proposer_index" => head_block_proposer_index, "slot" => head_block_slot, - "block_delay" => ?block_delay_total, - "observed_delay" => ?block_delays.observed, - "imported_delay" => ?block_delays.imported, - "set_as_head_delay" => ?block_delays.set_as_head, + "block_delay_ms" => block_delay_total.as_millis(), + "observed_delay_ms" => format_delay(&block_delays.observed), + "available_delay_ms" => format_delay(&block_delays.available), + "attestable_delay_ms" => format_delay(&block_delays.attestable), + "imported_delay_ms" => format_delay(&block_delays.imported), + "set_as_head_delay_ms" => format_delay(&block_delays.set_as_head), + ); + } else { + debug!( + log, + "On-time head block"; + "block_root" => ?head_block_root, + "proposer_index" => head_block_proposer_index, + "slot" => head_block_slot, + "block_delay_ms" => block_delay_total.as_millis(), + "observed_delay_ms" => format_delay(&block_delays.observed), + "available_delay_ms" => format_delay(&block_delays.available), + "attestable_delay_ms" => format_delay(&block_delays.attestable), + "imported_delay_ms" => format_delay(&block_delays.imported), + "set_as_head_delay_ms" => format_delay(&block_delays.set_as_head), ); } } diff --git a/beacon_node/beacon_chain/src/data_availability_checker.rs b/beacon_node/beacon_chain/src/data_availability_checker.rs index 7d8af48c782..e2517c07295 100644 --- a/beacon_node/beacon_chain/src/data_availability_checker.rs +++ b/beacon_node/beacon_chain/src/data_availability_checker.rs @@ -19,6 +19,7 @@ use std::fmt; use std::fmt::Debug; use std::num::NonZeroUsize; use std::sync::Arc; +use std::time::Duration; use task_executor::TaskExecutor; use types::beacon_block_body::KzgCommitmentOpts; use types::blob_sidecar::{BlobIdentifier, BlobSidecar, FixedBlobSidecarList}; @@ -213,7 +214,7 @@ impl DataAvailabilityChecker { .map_err(AvailabilityCheckError::Kzg)?; self.availability_cache - .put_kzg_verified_blobs(block_root, verified_blobs) + .put_kzg_verified_blobs(block_root, verified_blobs, &self.slot_clock) } /// Check if we've cached other blobs for this block. If it completes a set and we also @@ -225,8 +226,11 @@ impl DataAvailabilityChecker { &self, gossip_blob: GossipVerifiedBlob, ) -> Result, AvailabilityCheckError> { - self.availability_cache - .put_kzg_verified_blobs(gossip_blob.block_root(), vec![gossip_blob.into_inner()]) + self.availability_cache.put_kzg_verified_blobs( + gossip_blob.block_root(), + vec![gossip_blob.into_inner()], + &self.slot_clock, + ) } /// Check if we have all the blobs for a block. Returns `Availability` which has information @@ -236,7 +240,7 @@ impl DataAvailabilityChecker { executed_block: AvailabilityPendingExecutedBlock, ) -> Result, AvailabilityCheckError> { self.availability_cache - .put_pending_executed_block(executed_block) + .put_pending_executed_block(executed_block, &self.slot_clock) } /// Verifies kzg commitments for an RpcBlock, returns a `MaybeAvailableBlock` that may @@ -254,10 +258,15 @@ impl DataAvailabilityChecker { if self.blobs_required_for_block(&block) { Ok(MaybeAvailableBlock::AvailabilityPending { block_root, block }) } else { + let available_timestamp = self + .slot_clock + .now_duration() + .ok_or(AvailabilityCheckError::SlotClockError)?; Ok(MaybeAvailableBlock::Available(AvailableBlock { block_root, block, blobs: None, + available_timestamp, })) } } @@ -273,10 +282,15 @@ impl DataAvailabilityChecker { } else { None }; + let available_timestamp = self + .slot_clock + .now_duration() + .ok_or(AvailabilityCheckError::SlotClockError)?; Ok(MaybeAvailableBlock::Available(AvailableBlock { block_root, block, blobs: verified_blobs, + available_timestamp, })) } } @@ -318,10 +332,15 @@ impl DataAvailabilityChecker { if self.blobs_required_for_block(&block) { results.push(MaybeAvailableBlock::AvailabilityPending { block_root, block }) } else { + let available_timestamp = self + .slot_clock + .now_duration() + .ok_or(AvailabilityCheckError::SlotClockError)?; results.push(MaybeAvailableBlock::Available(AvailableBlock { block_root, block, blobs: None, + available_timestamp, })) } } @@ -332,10 +351,15 @@ impl DataAvailabilityChecker { None }; // already verified kzg for all blobs + let available_timestamp = self + .slot_clock + .now_duration() + .ok_or(AvailabilityCheckError::SlotClockError)?; results.push(MaybeAvailableBlock::Available(AvailableBlock { block_root, block, blobs: verified_blobs, + available_timestamp, })) } } @@ -543,6 +567,8 @@ pub struct AvailableBlock { block_root: Hash256, block: Arc>, blobs: Option>, + /// Timestamp at which this block first became available (UNIX timestamp, time since 1970). + available_timestamp: Duration, } impl AvailableBlock { @@ -555,6 +581,7 @@ impl AvailableBlock { block_root, block, blobs, + available_timestamp: Duration::from_millis(0), } } @@ -569,6 +596,10 @@ impl AvailableBlock { self.blobs.as_ref() } + pub fn available_timestamp(&self) -> Duration { + self.available_timestamp + } + pub fn deconstruct( self, ) -> ( @@ -580,6 +611,7 @@ impl AvailableBlock { block_root, block, blobs, + available_timestamp: _, } = self; (block_root, block, blobs) } diff --git a/beacon_node/beacon_chain/src/data_availability_checker/error.rs b/beacon_node/beacon_chain/src/data_availability_checker/error.rs index 0804fe3b9ab..6c524786bfa 100644 --- a/beacon_node/beacon_chain/src/data_availability_checker/error.rs +++ b/beacon_node/beacon_chain/src/data_availability_checker/error.rs @@ -19,6 +19,7 @@ pub enum Error { ParentStateMissing(Hash256), BlockReplayError(state_processing::BlockReplayError), RebuildingStateCaches(BeaconStateError), + SlotClockError, } pub enum ErrorCategory { @@ -39,7 +40,8 @@ impl Error { | Error::Unexpected | Error::ParentStateMissing(_) | Error::BlockReplayError(_) - | Error::RebuildingStateCaches(_) => ErrorCategory::Internal, + | Error::RebuildingStateCaches(_) + | Error::SlotClockError => ErrorCategory::Internal, Error::Kzg(_) | Error::BlobIndexInvalid(_) | Error::KzgCommitmentMismatch { .. } diff --git a/beacon_node/beacon_chain/src/data_availability_checker/overflow_lru_cache.rs b/beacon_node/beacon_chain/src/data_availability_checker/overflow_lru_cache.rs index b0afcc5e676..7274adb15d9 100644 --- a/beacon_node/beacon_chain/src/data_availability_checker/overflow_lru_cache.rs +++ b/beacon_node/beacon_chain/src/data_availability_checker/overflow_lru_cache.rs @@ -39,6 +39,7 @@ use crate::store::{DBColumn, KeyValueStore}; use crate::BeaconChainTypes; use lru::LruCache; use parking_lot::{Mutex, RwLock, RwLockUpgradableReadGuard}; +use slot_clock::SlotClock; use ssz::{Decode, Encode}; use ssz_derive::{Decode, Encode}; use ssz_types::{FixedVector, VariableList}; @@ -73,12 +74,24 @@ impl PendingComponents { /// /// WARNING: This function can potentially take a lot of time if the state needs to be /// reconstructed from disk. Ensure you are not holding any write locks while calling this. - pub fn make_available(self, recover: R) -> Result, AvailabilityCheckError> + pub fn make_available( + self, + recover: R, + slot_clock: &Clock, + ) -> Result, AvailabilityCheckError> where R: FnOnce( DietAvailabilityPendingExecutedBlock, ) -> Result, AvailabilityCheckError>, + Clock: SlotClock, { + // Record the availability timestamp as soon as the block components are all available. We + // are mostly interested in how long availability takes from a network point-of-view, not + // how long availability processing takes. + let available_timestamp = slot_clock + .now_duration() + .ok_or(AvailabilityCheckError::SlotClockError)?; + let Self { block_root, verified_blobs, @@ -112,6 +125,7 @@ impl PendingComponents { block_root, block, blobs: Some(verified_blobs), + available_timestamp, }; Ok(Availability::Available(Box::new( AvailableExecutedBlock::new(available_block, import_data, payload_verification_outcome), @@ -429,6 +443,7 @@ impl OverflowLRUCache { &self, block_root: Hash256, kzg_verified_blobs: I, + slot_clock: &T::SlotClock, ) -> Result, AvailabilityCheckError> { let mut fixed_blobs = FixedVector::default(); @@ -451,9 +466,10 @@ impl OverflowLRUCache { if pending_components.is_available() { // No need to hold the write lock anymore drop(write_lock); - pending_components.make_available(|diet_block| { - self.state_cache.recover_pending_executed_block(diet_block) - }) + pending_components.make_available( + |diet_block| self.state_cache.recover_pending_executed_block(diet_block), + slot_clock, + ) } else { write_lock.put_pending_components( block_root, @@ -469,6 +485,7 @@ impl OverflowLRUCache { pub fn put_pending_executed_block( &self, executed_block: AvailabilityPendingExecutedBlock, + slot_clock: &T::SlotClock, ) -> Result, AvailabilityCheckError> { let mut write_lock = self.critical.write(); let block_root = executed_block.import_data.block_root; @@ -490,9 +507,10 @@ impl OverflowLRUCache { if pending_components.is_available() { // No need to hold the write lock anymore drop(write_lock); - pending_components.make_available(|diet_block| { - self.state_cache.recover_pending_executed_block(diet_block) - }) + pending_components.make_available( + |diet_block| self.state_cache.recover_pending_executed_block(diet_block), + slot_clock, + ) } else { write_lock.put_pending_components( block_root, @@ -1030,7 +1048,7 @@ mod test { "cache should be empty" ); let availability = cache - .put_pending_executed_block(pending_block) + .put_pending_executed_block(pending_block, &harness.chain.slot_clock) .expect("should put block"); if blobs_expected == 0 { assert!( @@ -1062,7 +1080,7 @@ mod test { for (blob_index, gossip_blob) in blobs.into_iter().enumerate() { kzg_verified_blobs.push(gossip_blob.into_inner()); let availability = cache - .put_kzg_verified_blobs(root, kzg_verified_blobs.clone()) + .put_kzg_verified_blobs(root, kzg_verified_blobs.clone(), &harness.chain.slot_clock) .expect("should put blob"); if blob_index == blobs_expected - 1 { assert!(matches!(availability, Availability::Available(_))); @@ -1088,7 +1106,7 @@ mod test { for gossip_blob in blobs { kzg_verified_blobs.push(gossip_blob.into_inner()); let availability = cache - .put_kzg_verified_blobs(root, kzg_verified_blobs.clone()) + .put_kzg_verified_blobs(root, kzg_verified_blobs.clone(), &harness.chain.slot_clock) .expect("should put blob"); assert_eq!( availability, @@ -1098,7 +1116,7 @@ mod test { assert_eq!(cache.critical.read().in_memory.len(), 1); } let availability = cache - .put_pending_executed_block(pending_block) + .put_pending_executed_block(pending_block, &harness.chain.slot_clock) .expect("should put block"); assert!( matches!(availability, Availability::Available(_)), @@ -1135,7 +1153,10 @@ mod test { for i in 0..capacity { cache - .put_pending_executed_block(pending_blocks.pop_front().expect("should have block")) + .put_pending_executed_block( + pending_blocks.pop_front().expect("should have block"), + &harness.chain.slot_clock, + ) .expect("should put block"); assert_eq!(cache.critical.read().in_memory.len(), i + 1); } @@ -1161,7 +1182,10 @@ mod test { ); cache - .put_pending_executed_block(pending_blocks.pop_front().expect("should have block")) + .put_pending_executed_block( + pending_blocks.pop_front().expect("should have block"), + &harness.chain.slot_clock, + ) .expect("should put block"); assert_eq!( cache.critical.read().in_memory.len(), @@ -1216,7 +1240,11 @@ mod test { for (blob_index, gossip_blob) in blobs_0.into_iter().enumerate() { kzg_verified_blobs.push(gossip_blob.into_inner()); let availability = cache - .put_kzg_verified_blobs(roots[0], kzg_verified_blobs.clone()) + .put_kzg_verified_blobs( + roots[0], + kzg_verified_blobs.clone(), + &harness.chain.slot_clock, + ) .expect("should put blob"); if blob_index == expected_blobs - 1 { assert!(matches!(availability, Availability::Available(_))); @@ -1296,14 +1324,18 @@ mod test { let block_first = (rand::random::() % 2) == 0; if block_first { let availability = cache - .put_pending_executed_block(pending_block) + .put_pending_executed_block(pending_block, &harness.chain.slot_clock) .expect("should put block"); assert!( matches!(availability, Availability::MissingComponents(_)), "should have pending blobs" ); let availability = cache - .put_kzg_verified_blobs(block_root, kzg_verified_blobs) + .put_kzg_verified_blobs( + block_root, + kzg_verified_blobs, + &harness.chain.slot_clock, + ) .expect("should put blob"); assert!( matches!(availability, Availability::MissingComponents(_)), @@ -1312,7 +1344,11 @@ mod test { ); } else { let availability = cache - .put_kzg_verified_blobs(block_root, kzg_verified_blobs) + .put_kzg_verified_blobs( + block_root, + kzg_verified_blobs, + &harness.chain.slot_clock, + ) .expect("should put blob"); let root = pending_block.block.as_block().canonical_root(); assert_eq!( @@ -1321,7 +1357,7 @@ mod test { "should be pending block" ); let availability = cache - .put_pending_executed_block(pending_block) + .put_pending_executed_block(pending_block, &harness.chain.slot_clock) .expect("should put block"); assert!( matches!(availability, Availability::MissingComponents(_)), @@ -1330,7 +1366,7 @@ mod test { } } else { let availability = cache - .put_pending_executed_block(pending_block) + .put_pending_executed_block(pending_block, &harness.chain.slot_clock) .expect("should put block"); assert!( matches!(availability, Availability::MissingComponents(_)), @@ -1428,14 +1464,18 @@ mod test { let block_first = (rand::random::() % 2) == 0; if block_first { let availability = cache - .put_pending_executed_block(pending_block) + .put_pending_executed_block(pending_block, &harness.chain.slot_clock) .expect("should put block"); assert!( matches!(availability, Availability::MissingComponents(_)), "should have pending blobs" ); let availability = cache - .put_kzg_verified_blobs(block_root, kzg_verified_blobs) + .put_kzg_verified_blobs( + block_root, + kzg_verified_blobs, + &harness.chain.slot_clock, + ) .expect("should put blob"); assert!( matches!(availability, Availability::MissingComponents(_)), @@ -1444,7 +1484,11 @@ mod test { ); } else { let availability = cache - .put_kzg_verified_blobs(block_root, kzg_verified_blobs) + .put_kzg_verified_blobs( + block_root, + kzg_verified_blobs, + &harness.chain.slot_clock, + ) .expect("should put blob"); let root = pending_block.block.as_block().canonical_root(); assert_eq!( @@ -1453,7 +1497,7 @@ mod test { "should be pending block" ); let availability = cache - .put_pending_executed_block(pending_block) + .put_pending_executed_block(pending_block, &harness.chain.slot_clock) .expect("should put block"); assert!( matches!(availability, Availability::MissingComponents(_)), @@ -1462,7 +1506,7 @@ mod test { } } else { let availability = cache - .put_pending_executed_block(pending_block) + .put_pending_executed_block(pending_block, &harness.chain.slot_clock) .expect("should put block"); assert!( matches!(availability, Availability::MissingComponents(_)), @@ -1538,7 +1582,11 @@ mod test { for (i, gossip_blob) in blobs.into_iter().enumerate() { kzg_verified_blobs.push(gossip_blob.into_inner()); let availability = recovered_cache - .put_kzg_verified_blobs(root, kzg_verified_blobs.clone()) + .put_kzg_verified_blobs( + root, + kzg_verified_blobs.clone(), + &harness.chain.slot_clock, + ) .expect("should put blob"); if i == additional_blobs - 1 { assert!(matches!(availability, Availability::Available(_))) @@ -1598,7 +1646,7 @@ mod test { // put the block in the cache let availability = cache - .put_pending_executed_block(pending_block) + .put_pending_executed_block(pending_block, &harness.chain.slot_clock) .expect("should put block"); // grab the diet block from the cache for later testing diff --git a/beacon_node/execution_layer/src/lib.rs b/beacon_node/execution_layer/src/lib.rs index 69b84adbb8f..2204b554dc5 100644 --- a/beacon_node/execution_layer/src/lib.rs +++ b/beacon_node/execution_layer/src/lib.rs @@ -24,7 +24,7 @@ use payload_status::process_payload_status; pub use payload_status::PayloadStatus; use sensitive_url::SensitiveUrl; use serde::{Deserialize, Serialize}; -use slog::{crit, debug, error, info, trace, warn, Logger}; +use slog::{crit, debug, error, info, warn, Logger}; use slot_clock::SlotClock; use std::collections::HashMap; use std::fmt; @@ -1330,15 +1330,11 @@ impl ExecutionLayer { &metrics::EXECUTION_LAYER_REQUEST_TIMES, &[metrics::NEW_PAYLOAD], ); + let timer = std::time::Instant::now(); + let block_number = new_payload_request.block_number(); let block_hash = new_payload_request.block_hash(); - trace!( - self.log(), - "Issuing engine_newPayload"; - "parent_hash" => ?new_payload_request.parent_hash(), - "block_hash" => ?block_hash, - "block_number" => ?new_payload_request.block_number(), - ); + let parent_hash = new_payload_request.parent_hash(); let result = self .engine() @@ -1346,9 +1342,19 @@ impl ExecutionLayer { .await; if let Ok(status) = &result { + let status_str = <&'static str>::from(status.status); metrics::inc_counter_vec( &metrics::EXECUTION_LAYER_PAYLOAD_STATUS, - &["new_payload", status.status.into()], + &["new_payload", status_str], + ); + debug!( + self.log(), + "Processed engine_newPayload"; + "status" => status_str, + "parent_hash" => ?parent_hash, + "block_hash" => ?block_hash, + "block_number" => block_number, + "response_time_ms" => timer.elapsed().as_millis() ); } *self.inner.last_new_payload_errored.write().await = result.is_err(); From 83eff835b86f1d04394e58ecfe86a1dbfbf1f1e5 Mon Sep 17 00:00:00 2001 From: Age Manning Date: Thu, 4 Apr 2024 16:23:11 +1100 Subject: [PATCH 2/8] Attestation metrics analysis --- beacon_node/beacon_chain/src/beacon_chain.rs | 9 +++--- beacon_node/beacon_chain/src/metrics.rs | 4 +-- beacon_node/network/src/metrics.rs | 27 ++++++++++-------- .../gossip_methods.rs | 28 +++++++++++++------ 4 files changed, 41 insertions(+), 27 deletions(-) diff --git a/beacon_node/beacon_chain/src/beacon_chain.rs b/beacon_node/beacon_chain/src/beacon_chain.rs index 5fb5fe39573..c0410eb5620 100644 --- a/beacon_node/beacon_chain/src/beacon_chain.rs +++ b/beacon_node/beacon_chain/src/beacon_chain.rs @@ -3002,6 +3002,7 @@ impl BeaconChain { // Set observed time if not already set. Usually this should be set by gossip or RPC, // but just in case we set it again here (useful for tests). + #[cfg(test)] if let Some(seen_timestamp) = self.slot_clock.now_duration() { self.block_times_cache.write().set_time_observed( block_root, @@ -3022,6 +3023,7 @@ impl BeaconChain { )?; publish_fn()?; let executed_block = chain.into_executed_block(execution_pending).await?; + match executed_block { ExecutedBlock::Available(block) => { self.import_available_block(Box::new(block)).await @@ -3222,10 +3224,6 @@ impl BeaconChain { ) -> Result> { match availability { Availability::Available(block) => { - // This is the time since start of the slot where all the components of the block have become available - let delay = - get_slot_delay_ms(timestamp_now(), block.block.slot(), &self.slot_clock); - metrics::observe_duration(&metrics::BLOCK_AVAILABILITY_DELAY, delay); // Block is fully available, import into fork choice self.import_available_block(block).await } @@ -3254,6 +3252,9 @@ impl BeaconChain { consensus_context, } = import_data; + // This is the time since start of the slot where all the components of the block have become available + let delay = get_slot_delay_ms(timestamp_now(), block.slot(), &self.slot_clock); + metrics::set_gauge(&metrics::BLOCK_AVAILABILITY_DELAY, delay.as_millis() as i64); // Record the time at which this block became available. self.block_times_cache.write().set_time_available( block_root, diff --git a/beacon_node/beacon_chain/src/metrics.rs b/beacon_node/beacon_chain/src/metrics.rs index abac2c80e7f..d7e1d673f23 100644 --- a/beacon_node/beacon_chain/src/metrics.rs +++ b/beacon_node/beacon_chain/src/metrics.rs @@ -1122,11 +1122,9 @@ lazy_static! { /* * Availability related metrics */ - pub static ref BLOCK_AVAILABILITY_DELAY: Result = try_create_histogram_with_buckets( + pub static ref BLOCK_AVAILABILITY_DELAY: Result = try_create_int_gauge( "block_availability_delay", "Duration between start of the slot and the time at which all components of the block are available.", - // Create a custom bucket list for greater granularity in block delay - Ok(vec![0.1, 0.2, 0.3,0.4,0.5,0.75,1.0,1.25,1.5,1.75,2.0,2.5,3.0,3.5,4.0,5.0,6.0,7.0,8.0,9.0,10.0,15.0,20.0]) ); diff --git a/beacon_node/network/src/metrics.rs b/beacon_node/network/src/metrics.rs index 0509ed1ea7d..d08bccb7791 100644 --- a/beacon_node/network/src/metrics.rs +++ b/beacon_node/network/src/metrics.rs @@ -248,12 +248,6 @@ lazy_static! { /* * Block Delay Metrics */ - pub static ref BEACON_BLOCK_GOSSIP_PROPAGATION_VERIFICATION_DELAY_TIME: Result = try_create_histogram_with_buckets( - "beacon_block_gossip_propagation_verification_delay_time", - "Duration between when the block is received and when it is verified for propagation.", - // [0.001, 0.002, 0.005, 0.01, 0.02, 0.05, 0.1, 0.2, 0.5] - decimal_buckets(-3,-1) - ); pub static ref BEACON_BLOCK_GOSSIP_SLOT_START_DELAY_TIME: Result = try_create_histogram_with_buckets( "beacon_block_gossip_slot_start_delay_time", "Duration between when the block is received and the start of the slot it belongs to.", @@ -264,6 +258,15 @@ lazy_static! { //decimal_buckets(-1,2) ); + pub static ref BEACON_BLOCK_LAST_GOSSIP_VERIFICATION_TIME: Result = try_create_int_gauge( + "beacon_block_last_gossip_delay", + "Keeps track of the time delay from the start of the slot to the point we propagate the block" + ); + pub static ref BEACON_BLOCK_LAST_FULL_VERIFICATION_TIME: Result = try_create_int_gauge( + "beacon_block_last_full_verification_delay", + "The time it takes to verify a beacon block." + ); + pub static ref BEACON_BLOCK_LAST_DELAY: Result = try_create_int_gauge( "beacon_block_last_delay", "Keeps track of the last block's delay from the start of the slot" @@ -277,11 +280,13 @@ lazy_static! { /* * Blob Delay Metrics */ - pub static ref BEACON_BLOB_GOSSIP_PROPAGATION_VERIFICATION_DELAY_TIME: Result = try_create_histogram_with_buckets( - "beacon_blob_gossip_propagation_verification_delay_time", - "Duration between when the blob is received over gossip and when it is verified for propagation.", - // [0.001, 0.002, 0.005, 0.01, 0.02, 0.05, 0.1, 0.2, 0.5] - decimal_buckets(-3,-1) + pub static ref BEACON_BLOB_LAST_GOSSIP_VERIFICATION_TIME: Result = try_create_int_gauge( + "beacon_blob_last_gossip_delay", + "Keeps track of the time delay from the start of the slot to the point we propagate the blob" + ); + pub static ref BEACON_BLOB_LAST_FULL_VERIFICATION_TIME: Result = try_create_int_gauge( + "beacon_blob_last_full_verification_delay", + "The time it takes to verify a beacon blob" ); pub static ref BEACON_BLOB_GOSSIP_SLOT_START_DELAY_TIME: Result = try_create_histogram_with_buckets( "beacon_blob_gossip_slot_start_delay_time", diff --git a/beacon_node/network/src/network_beacon_processor/gossip_methods.rs b/beacon_node/network/src/network_beacon_processor/gossip_methods.rs index 0fda52244ec..15613c39111 100644 --- a/beacon_node/network/src/network_beacon_processor/gossip_methods.rs +++ b/beacon_node/network/src/network_beacon_processor/gossip_methods.rs @@ -27,7 +27,7 @@ use std::fs; use std::io::Write; use std::path::PathBuf; use std::sync::Arc; -use std::time::{Duration, SystemTime, UNIX_EPOCH}; +use std::time::{Duration, Instant, SystemTime, UNIX_EPOCH}; use store::hot_cold_store::HotColdDBError; use tokio::sync::mpsc; use types::{ @@ -654,9 +654,9 @@ impl NetworkBeaconProcessor { .ok() .and_then(|now| now.checked_sub(seen_duration)) { - metrics::observe_duration( - &metrics::BEACON_BLOB_GOSSIP_PROPAGATION_VERIFICATION_DELAY_TIME, - duration, + metrics::set_gauge( + &metrics::BEACON_BLOB_LAST_GOSSIP_VERIFICATION_TIME, + duration.as_millis() as i64, ); } self.process_gossip_verified_blob(peer_id, gossip_verified_blob, seen_duration) @@ -747,9 +747,9 @@ impl NetworkBeaconProcessor { self: &Arc, peer_id: PeerId, verified_blob: GossipVerifiedBlob, - // This value is not used presently, but it might come in handy for debugging. _seen_duration: Duration, ) { + let processing_start_time = Instant::now(); let block_root = verified_blob.block_root(); let blob_slot = verified_blob.slot(); let blob_index = verified_blob.id().index; @@ -764,6 +764,11 @@ impl NetworkBeaconProcessor { "block_root" => %block_root ); self.chain.recompute_head_at_current_slot().await; + + metrics::set_gauge( + &metrics::BEACON_BLOB_LAST_FULL_VERIFICATION_TIME, + processing_start_time.elapsed().as_millis() as i64, + ); } Ok(AvailabilityProcessingStatus::MissingComponents(slot, block_root)) => { trace!( @@ -923,9 +928,9 @@ impl NetworkBeaconProcessor { .ok() .and_then(|now| now.checked_sub(seen_duration)) { - metrics::observe_duration( - &metrics::BEACON_BLOCK_GOSSIP_PROPAGATION_VERIFICATION_DELAY_TIME, - duration, + metrics::set_gauge( + &metrics::BEACON_BLOCK_LAST_GOSSIP_VERIFICATION_TIME, + duration.as_millis() as i64, ); } @@ -1130,9 +1135,9 @@ impl NetworkBeaconProcessor { verified_block: GossipVerifiedBlock, reprocess_tx: mpsc::Sender, invalid_block_storage: InvalidBlockStorage, - // This value is not used presently, but it might come in handy for debugging. _seen_duration: Duration, ) { + let processing_start_time = Instant::now(); let block = verified_block.block.block_cloned(); let block_root = verified_block.block_root; @@ -1168,6 +1173,11 @@ impl NetworkBeaconProcessor { ); self.chain.recompute_head_at_current_slot().await; + + metrics::set_gauge( + &metrics::BEACON_BLOCK_LAST_FULL_VERIFICATION_TIME, + processing_start_time.elapsed().as_millis() as i64, + ); } Ok(AvailabilityProcessingStatus::MissingComponents(slot, block_root)) => { trace!( From d7191c5dff883e28802f8c3df0543e13f3031187 Mon Sep 17 00:00:00 2001 From: Age Manning Date: Thu, 4 Apr 2024 16:38:59 +1100 Subject: [PATCH 3/8] Prettier printing --- beacon_node/beacon_chain/src/canonical_head.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/beacon_node/beacon_chain/src/canonical_head.rs b/beacon_node/beacon_chain/src/canonical_head.rs index 1a1790dfe34..7e099c4a0ce 100644 --- a/beacon_node/beacon_chain/src/canonical_head.rs +++ b/beacon_node/beacon_chain/src/canonical_head.rs @@ -1438,7 +1438,7 @@ fn observe_head_block_delays( // If the block was enshrined as head too late for attestations to be created for it, // log a debug warning and increment a metric. let format_delay = |delay: &Option| { - delay.map_or("unknown".to_string(), |d| format!("{}", d.as_millis())) + delay.map_or("unknown".to_string(), |d| format!("{:?}", d)) }; if late_head { metrics::inc_counter(&metrics::BEACON_BLOCK_HEAD_SLOT_START_DELAY_EXCEEDED_TOTAL); From 15fef3b0b7dad4373297ff19688c77c7cc72a2ad Mon Sep 17 00:00:00 2001 From: Age Manning Date: Wed, 17 Apr 2024 15:47:52 +1000 Subject: [PATCH 4/8] Add some metrics and timings to track late blocks --- beacon_node/beacon_chain/src/beacon_chain.rs | 37 ++++--- .../beacon_chain/src/block_times_cache.rs | 56 +++++++++- .../beacon_chain/src/canonical_head.rs | 102 ++++++++++++++---- beacon_node/beacon_chain/src/metrics.rs | 68 +++++++----- beacon_node/network/src/metrics.rs | 54 ++++------ .../gossip_methods.rs | 23 ++-- 6 files changed, 224 insertions(+), 116 deletions(-) diff --git a/beacon_node/beacon_chain/src/beacon_chain.rs b/beacon_node/beacon_chain/src/beacon_chain.rs index c0410eb5620..2927d0871bb 100644 --- a/beacon_node/beacon_chain/src/beacon_chain.rs +++ b/beacon_node/beacon_chain/src/beacon_chain.rs @@ -2889,6 +2889,15 @@ impl BeaconChain { return Err(BlockError::BlockIsAlreadyKnown(blob.block_root())); } + // Record the delay for receiving this blob + if let Some(seen_timestamp) = self.slot_clock.now_duration() { + self.block_times_cache.write().set_time_blob_observed( + block_root, + blob.slot(), + seen_timestamp, + ); + } + if let Some(event_handler) = self.event_handler.as_ref() { if event_handler.has_blob_sidecar_subscribers() { event_handler.register(EventKind::BlobSidecar(SseBlobSidecar::from_blob_sidecar( @@ -2899,6 +2908,7 @@ impl BeaconChain { self.data_availability_checker .notify_gossip_blob(block_root, &blob); + let r = self.check_gossip_blob_availability_and_import(blob).await; self.remove_notified(&block_root, r) } @@ -3023,6 +3033,14 @@ impl BeaconChain { )?; publish_fn()?; let executed_block = chain.into_executed_block(execution_pending).await?; + // Record the time it took to ask the execution layer. + if let Some(seen_timestamp) = self.slot_clock.now_duration() { + self.block_times_cache.write().set_execution_time( + block_root, + block_slot, + seen_timestamp, + ) + } match executed_block { ExecutedBlock::Available(block) => { @@ -3901,25 +3919,6 @@ impl BeaconChain { ); } - // Do not store metrics if the block was > 4 slots old, this helps prevent noise during - // sync. - if block_delay_total < self.slot_clock.slot_duration() * 4 { - // Observe the delay between when we observed the block and when we imported it. - let block_delays = self.block_times_cache.read().get_block_delays( - block_root, - self.slot_clock - .start_of(current_slot) - .unwrap_or_else(|| Duration::from_secs(0)), - ); - - metrics::observe_duration( - &metrics::BEACON_BLOCK_IMPORTED_OBSERVED_DELAY_TIME, - block_delays - .imported - .unwrap_or_else(|| Duration::from_secs(0)), - ); - } - if let Some(event_handler) = self.event_handler.as_ref() { if event_handler.has_block_subscribers() { event_handler.register(EventKind::Block(SseBlock { diff --git a/beacon_node/beacon_chain/src/block_times_cache.rs b/beacon_node/beacon_chain/src/block_times_cache.rs index 84da2c2b807..2cbade89969 100644 --- a/beacon_node/beacon_chain/src/block_times_cache.rs +++ b/beacon_node/beacon_chain/src/block_times_cache.rs @@ -18,6 +18,8 @@ type BlockRoot = Hash256; #[derive(Clone, Default)] pub struct Timestamps { pub observed: Option, + pub all_blobs_observed: Option, + pub execution_time: Option, pub available: Option, pub attestable: Option, pub imported: Option, @@ -27,12 +29,17 @@ pub struct Timestamps { // Helps arrange delay data so it is more relevant to metrics. #[derive(Debug, Default)] pub struct BlockDelays { - /// Time after start of slot. + /// Time after start of slot we saw the block. pub observed: Option, - /// Time after `observable`. + /// The time after the start of the slot we saw all blobs. + pub all_blobs_observed: Option, + /// The time it took to get verification from the EL for the block. + pub execution_time: Option, + /// Time after max(`observed + execution_time`, `all_blobs_observed`) the block became available. pub available: Option, /// Time after `available`. pub attestable: Option, + /// Time /// ALSO time after `available`. /// /// We need to use `available` again rather than `attestable` to handle the case where the block @@ -47,12 +54,18 @@ impl BlockDelays { let observed = times .observed .and_then(|observed_time| observed_time.checked_sub(slot_start_time)); + let all_blobs_observed = times + .all_blobs_observed + .and_then(|all_blobs_observed| all_blobs_observed.checked_sub(slot_start_time)); + let execution_time = times + .execution_time + .and_then(|execution_time| execution_time.checked_sub(times.observed?)); let available = times .available - .and_then(|available_time| available_time.checked_sub(times.observed?)); + .and_then(|available_time| available_time.checked_sub(slot_start_time)); let attestable = times .attestable - .and_then(|attestable_time| attestable_time.checked_sub(times.available?)); + .and_then(|attestable_time| attestable_time.checked_sub(slot_start_time)); let imported = times .imported .and_then(|imported_time| imported_time.checked_sub(times.available?)); @@ -61,6 +74,8 @@ impl BlockDelays { .and_then(|set_as_head_time| set_as_head_time.checked_sub(times.imported?)); BlockDelays { observed, + all_blobs_observed, + execution_time, available, attestable, imported, @@ -129,6 +144,39 @@ impl BlockTimesCache { } } + pub fn set_time_blob_observed( + &mut self, + block_root: BlockRoot, + slot: Slot, + timestamp: Duration, + ) { + let block_times = self + .cache + .entry(block_root) + .or_insert_with(|| BlockTimesCacheValue::new(slot)); + if block_times + .timestamps + .all_blobs_observed + .map_or(true, |prev| timestamp > prev) + { + block_times.timestamps.all_blobs_observed = Some(timestamp); + } + } + + pub fn set_execution_time(&mut self, block_root: BlockRoot, slot: Slot, timestamp: Duration) { + let block_times = self + .cache + .entry(block_root) + .or_insert_with(|| BlockTimesCacheValue::new(slot)); + if block_times + .timestamps + .execution_time + .map_or(true, |prev| timestamp < prev) + { + block_times.timestamps.execution_time = Some(timestamp); + } + } + pub fn set_time_available(&mut self, block_root: BlockRoot, slot: Slot, timestamp: Duration) { let block_times = self .cache diff --git a/beacon_node/beacon_chain/src/canonical_head.rs b/beacon_node/beacon_chain/src/canonical_head.rs index 7e099c4a0ce..462880009f7 100644 --- a/beacon_node/beacon_chain/src/canonical_head.rs +++ b/beacon_node/beacon_chain/src/canonical_head.rs @@ -1405,12 +1405,6 @@ fn observe_head_block_delays( // Do not store metrics if the block was > 4 slots old, this helps prevent noise during // sync. if !block_from_sync { - // Observe the total block delay. This is the delay between the time the slot started - // and when the block was set as head. - metrics::observe_duration( - &metrics::BEACON_BLOCK_HEAD_SLOT_START_DELAY_TIME, - block_delay_total, - ); // Observe the delay between when we imported the block and when we set the block as // head. @@ -1421,39 +1415,105 @@ fn observe_head_block_delays( .unwrap_or_else(|| Duration::from_secs(0)), ); - metrics::observe_duration( - &metrics::BEACON_BLOCK_OBSERVED_SLOT_START_DELAY_TIME, + // Update all the metrics + + // Convention here is to use "Time" to indicate the duration of the event and "Delay" + // to indicate the time since the start of the slot. + // + // Observe the total block delay. This is the delay between the time the slot started + // and when the block was set as head. + metrics::set_gauge( + &metrics::BEACON_BLOCK_DELAY_TOTAL, + block_delay_total.as_millis() as i64, + ); + + // The time at which the beacon block was first observed to be processed + metrics::set_gauge( + &metrics::BEACON_BLOCK_DELAY_OBSERVED_SLOT_START, block_delays .observed - .unwrap_or_else(|| Duration::from_secs(0)), + .unwrap_or_else(|| Duration::from_secs(0)) + .as_millis() as i64, ); - metrics::observe_duration( - &metrics::BEACON_BLOCK_HEAD_IMPORTED_DELAY_TIME, + // The time from the start of the slot when all blobs have been observed. Technically this + // is the time we last saw a blob related to this block/slot. + metrics::set_gauge( + &metrics::BEACON_BLOB_DELAY_ALL_OBSERVED_SLOT_START, + block_delays + .all_blobs_observed + .unwrap_or_else(|| Duration::from_secs(0)) + .as_millis() as i64, + ); + + // The time it took to check the validity with the EL + metrics::set_gauge( + &metrics::BEACON_BLOCK_DELAY_EXECUTION_TIME, + block_delays + .execution_time + .unwrap_or_else(|| Duration::from_secs(0)) + .as_millis() as i64, + ); + + // The time the block became available after the start of the slot. Available here means + // that all the blobs have arrived and the block has been verified by the execution layer. + metrics::set_gauge( + &metrics::BEACON_BLOCK_DELAY_AVAILABLE_SLOT_START, + block_delays + .available + .unwrap_or_else(|| Duration::from_secs(0)) + .as_millis() as i64, + ); + + + // The time the block became attestable after the start of the slot. + metrics::set_gauge( + &metrics::BEACON_BLOCK_DELAY_ATTESTABLE_SLOT_START, + block_delays + .attestable + .unwrap_or_else(|| Duration::from_secs(0)) + .as_millis() as i64, + ); + + // The time the block was imported since becoming available. + metrics::set_gauge( + &metrics::BEACON_BLOCK_DELAY_IMPORTED_TIME, + block_delays + .imported + .unwrap_or_else(|| Duration::from_secs(0)) + .as_millis() as i64, + ); + + // The time the block was imported and setting it as head + metrics::set_gauge( + &metrics::BEACON_BLOCK_DELAY_HEAD_IMPORTED_TIME, block_delays .set_as_head - .unwrap_or_else(|| Duration::from_secs(0)), + .unwrap_or_else(|| Duration::from_secs(0)) + .as_millis() as i64, ); // If the block was enshrined as head too late for attestations to be created for it, // log a debug warning and increment a metric. let format_delay = |delay: &Option| { - delay.map_or("unknown".to_string(), |d| format!("{:?}", d)) + delay.map_or("unknown".to_string(), |d| format!("{}", d.as_millis())) }; if late_head { - metrics::inc_counter(&metrics::BEACON_BLOCK_HEAD_SLOT_START_DELAY_EXCEEDED_TOTAL); + metrics::inc_counter(&metrics::BEACON_BLOCK_DELAY_HEAD_SLOT_START_EXCEEDED_TOTAL); debug!( log, "Delayed head block"; "block_root" => ?head_block_root, "proposer_index" => head_block_proposer_index, "slot" => head_block_slot, - "block_delay_ms" => block_delay_total.as_millis(), + "total_delay_ms" => block_delay_total.as_millis(), "observed_delay_ms" => format_delay(&block_delays.observed), + "blob_delay_ms" => format_delay(&block_delays.all_blobs_observed), + "execution_time_ms" => format_delay(&block_delays.execution_time), "available_delay_ms" => format_delay(&block_delays.available), "attestable_delay_ms" => format_delay(&block_delays.attestable), - "imported_delay_ms" => format_delay(&block_delays.imported), - "set_as_head_delay_ms" => format_delay(&block_delays.set_as_head), + "imported_time_ms" => format_delay(&block_delays.imported), + "set_as_head_time_ms" => format_delay(&block_delays.set_as_head), ); } else { debug!( @@ -1462,12 +1522,14 @@ fn observe_head_block_delays( "block_root" => ?head_block_root, "proposer_index" => head_block_proposer_index, "slot" => head_block_slot, - "block_delay_ms" => block_delay_total.as_millis(), + "total_delay_ms" => block_delay_total.as_millis(), "observed_delay_ms" => format_delay(&block_delays.observed), + "blob_delay_ms" => format_delay(&block_delays.all_blobs_observed), + "execution_time_ms" => format_delay(&block_delays.execution_time), "available_delay_ms" => format_delay(&block_delays.available), "attestable_delay_ms" => format_delay(&block_delays.attestable), - "imported_delay_ms" => format_delay(&block_delays.imported), - "set_as_head_delay_ms" => format_delay(&block_delays.set_as_head), + "imported_time_ms" => format_delay(&block_delays.imported), + "set_as_head_time_ms" => format_delay(&block_delays.set_as_head), ); } } diff --git a/beacon_node/beacon_chain/src/metrics.rs b/beacon_node/beacon_chain/src/metrics.rs index d7e1d673f23..34cca5ee682 100644 --- a/beacon_node/beacon_chain/src/metrics.rs +++ b/beacon_node/beacon_chain/src/metrics.rs @@ -839,37 +839,55 @@ lazy_static! { "Number of attester slashings seen", &["src", "validator"] ); +} + +// Prevent recursion limit +lazy_static! { /* * Block Delay Metrics */ - pub static ref BEACON_BLOCK_OBSERVED_SLOT_START_DELAY_TIME: Result = try_create_histogram_with_buckets( - "beacon_block_observed_slot_start_delay_time", - "Duration between the start of the block's slot and the time the block was observed.", - // [0.1, 0.2, 0.5, 1, 2, 5, 10, 20, 50] - decimal_buckets(-1,2) - ); - pub static ref BEACON_BLOCK_IMPORTED_OBSERVED_DELAY_TIME: Result = try_create_histogram_with_buckets( - "beacon_block_imported_observed_delay_time", - "Duration between the time the block was observed and the time when it was imported.", - // [0.01, 0.02, 0.05, 0.1, 0.2, 0.5, 1, 2, 5] - decimal_buckets(-2,0) - ); - pub static ref BEACON_BLOCK_HEAD_IMPORTED_DELAY_TIME: Result = try_create_histogram_with_buckets( - "beacon_block_head_imported_delay_time", - "Duration between the time the block was imported and the time when it was set as head.", - // [0.01, 0.02, 0.05, 0.1, 0.2, 0.5, 1, 2, 5] - decimal_buckets(-2,-1) - ); - pub static ref BEACON_BLOCK_HEAD_SLOT_START_DELAY_TIME: Result = try_create_histogram_with_buckets( - "beacon_block_head_slot_start_delay_time", + pub static ref BEACON_BLOCK_DELAY_TOTAL: Result = try_create_int_gauge( + "beacon_block_delay_total", "Duration between the start of the block's slot and the time when it was set as head.", - // [0.1, 0.2, 0.5, 1, 2, 5, 10, 20, 50] - decimal_buckets(-1,2) ); - pub static ref BEACON_BLOCK_HEAD_SLOT_START_DELAY_EXCEEDED_TOTAL: Result = try_create_int_counter( - "beacon_block_head_slot_start_delay_exceeded_total", - "Triggered when the duration between the start of the block's slot and the current time \ + + pub static ref BEACON_BLOCK_DELAY_OBSERVED_SLOT_START: Result = try_create_int_gauge( + "beacon_block_delay_observed_slot_start", + "Duration between the start of the block's slot and the time the block was observed.", + ); + + pub static ref BEACON_BLOB_DELAY_ALL_OBSERVED_SLOT_START: Result = try_create_int_gauge( + "beacon_blob_delay_all_observed_slot_start", + "Duration between the start of the block's slot and the time the block was observed.", + ); + + pub static ref BEACON_BLOCK_DELAY_EXECUTION_TIME: Result = try_create_int_gauge( + "beacon_block_delay_execution_time", + "The duration in verifying the block with the execution layer.", + ); + + pub static ref BEACON_BLOCK_DELAY_AVAILABLE_SLOT_START: Result = try_create_int_gauge( + "beacon_block_delay_available_slot_start", + "Duration between the time that block became available and the start of the slot.", + ); + pub static ref BEACON_BLOCK_DELAY_ATTESTABLE_SLOT_START: Result = try_create_int_gauge( + "beacon_block_delay_attestable_slot_start", + "Duration between the time that block became attestable and the start of the slot.", + ); + + pub static ref BEACON_BLOCK_DELAY_IMPORTED_TIME: Result = try_create_int_gauge( + "beacon_block_delay_imported_time", + "Duration between the time the block became available and the time when it was imported.", + ); + + pub static ref BEACON_BLOCK_DELAY_HEAD_IMPORTED_TIME: Result = try_create_int_gauge( + "beacon_block_delay_head_imported_time", + "Duration between the time that block was imported and the time when it was set as head.", + ); + pub static ref BEACON_BLOCK_DELAY_HEAD_SLOT_START_EXCEEDED_TOTAL: Result = try_create_int_counter( + "beacon_block_delay_head_slot_start_exceeded_total", + "A counter that is triggered when the duration between the start of the block's slot and the current time \ will result in failed attestations.", ); diff --git a/beacon_node/network/src/metrics.rs b/beacon_node/network/src/metrics.rs index d08bccb7791..368e1e662b0 100644 --- a/beacon_node/network/src/metrics.rs +++ b/beacon_node/network/src/metrics.rs @@ -248,55 +248,41 @@ lazy_static! { /* * Block Delay Metrics */ - pub static ref BEACON_BLOCK_GOSSIP_SLOT_START_DELAY_TIME: Result = try_create_histogram_with_buckets( - "beacon_block_gossip_slot_start_delay_time", - "Duration between when the block is received and the start of the slot it belongs to.", - // Create a custom bucket list for greater granularity in block delay - Ok(vec![0.1, 0.2, 0.3,0.4,0.5,0.75,1.0,1.25,1.5,1.75,2.0,2.5,3.0,3.5,4.0,5.0,6.0,7.0,8.0,9.0,10.0,15.0,20.0]) - // NOTE: Previous values, which we may want to switch back to. - // [0.1, 0.2, 0.5, 1, 2, 5, 10, 20, 50] - //decimal_buckets(-1,2) - + pub static ref BEACON_BLOCK_DELAY_GOSSIP: Result = try_create_int_gauge( + "beacon_block_delay_gossip", + "The first time we see this block from gossip as a delay from the start of the slot" ); - pub static ref BEACON_BLOCK_LAST_GOSSIP_VERIFICATION_TIME: Result = try_create_int_gauge( - "beacon_block_last_gossip_delay", + pub static ref BEACON_BLOCK_DELAY_GOSSIP_VERIFICATION: Result = try_create_int_gauge( + "beacon_block_delay_gossip_verification", "Keeps track of the time delay from the start of the slot to the point we propagate the block" ); - pub static ref BEACON_BLOCK_LAST_FULL_VERIFICATION_TIME: Result = try_create_int_gauge( - "beacon_block_last_full_verification_delay", + pub static ref BEACON_BLOCK_DELAY_FULL_VERIFICATION: Result = try_create_int_gauge( + "beacon_block_delay_full_verification", "The time it takes to verify a beacon block." ); - pub static ref BEACON_BLOCK_LAST_DELAY: Result = try_create_int_gauge( - "beacon_block_last_delay", - "Keeps track of the last block's delay from the start of the slot" - ); - - pub static ref BEACON_BLOCK_GOSSIP_ARRIVED_LATE_TOTAL: Result = try_create_int_counter( - "beacon_block_gossip_arrived_late_total", + pub static ref BEACON_BLOCK_DELAY_GOSSIP_ARRIVED_LATE_TOTAL: Result = try_create_int_counter( + "beacon_block_delay_gossip_arrived_late_total", "Count of times when a gossip block arrived from the network later than the attestation deadline.", ); /* * Blob Delay Metrics */ - pub static ref BEACON_BLOB_LAST_GOSSIP_VERIFICATION_TIME: Result = try_create_int_gauge( - "beacon_blob_last_gossip_delay", + pub static ref BEACON_BLOB_DELAY_GOSSIP: Result = try_create_int_gauge( + "beacon_blob_delay_gossip_last_delay", + "The first time we see this blob as a delay from the start of the slot" + ); + + pub static ref BEACON_BLOB_DELAY_GOSSIP_VERIFICATION: Result = try_create_int_gauge( + "beacon_blob_delay_gossip_verification", "Keeps track of the time delay from the start of the slot to the point we propagate the blob" ); - pub static ref BEACON_BLOB_LAST_FULL_VERIFICATION_TIME: Result = try_create_int_gauge( + pub static ref BEACON_BLOB_DELAY_FULL_VERIFICATION: Result = try_create_int_gauge( "beacon_blob_last_full_verification_delay", "The time it takes to verify a beacon blob" ); - pub static ref BEACON_BLOB_GOSSIP_SLOT_START_DELAY_TIME: Result = try_create_histogram_with_buckets( - "beacon_blob_gossip_slot_start_delay_time", - "Duration between when the blob is received over gossip and the start of the slot it belongs to.", - // Create a custom bucket list for greater granularity in block delay - Ok(vec![0.1, 0.2, 0.3,0.4,0.5,0.75,1.0,1.25,1.5,1.75,2.0,2.5,3.0,3.5,4.0,5.0,6.0,7.0,8.0,9.0,10.0,15.0,20.0]) - // NOTE: Previous values, which we may want to switch back to. - // [0.1, 0.2, 0.5, 1, 2, 5, 10, 20, 50] - //decimal_buckets(-1,2) - ); + pub static ref BEACON_BLOB_RPC_SLOT_START_DELAY_TIME: Result = try_create_histogram_with_buckets( "beacon_blob_rpc_slot_start_delay_time", "Duration between when a blob is received over rpc and the start of the slot it belongs to.", @@ -307,10 +293,6 @@ lazy_static! { //decimal_buckets(-1,2) ); - pub static ref BEACON_BLOB_LAST_DELAY: Result = try_create_int_gauge( - "beacon_blob_last_delay", - "Keeps track of the last blob's delay from the start of the slot" - ); pub static ref BEACON_BLOB_GOSSIP_ARRIVED_LATE_TOTAL: Result = try_create_int_counter( "beacon_blob_gossip_arrived_late_total", diff --git a/beacon_node/network/src/network_beacon_processor/gossip_methods.rs b/beacon_node/network/src/network_beacon_processor/gossip_methods.rs index 15613c39111..d7e2e5a8185 100644 --- a/beacon_node/network/src/network_beacon_processor/gossip_methods.rs +++ b/beacon_node/network/src/network_beacon_processor/gossip_methods.rs @@ -615,8 +615,10 @@ impl NetworkBeaconProcessor { let commitment = blob_sidecar.kzg_commitment; let delay = get_slot_delay_ms(seen_duration, slot, &self.chain.slot_clock); // Log metrics to track delay from other nodes on the network. - metrics::observe_duration(&metrics::BEACON_BLOB_GOSSIP_SLOT_START_DELAY_TIME, delay); - metrics::set_gauge(&metrics::BEACON_BLOB_LAST_DELAY, delay.as_millis() as i64); + metrics::set_gauge( + &metrics::BEACON_BLOB_DELAY_GOSSIP, + delay.as_millis() as i64, + ); match self .chain .verify_blob_sidecar_for_gossip(blob_sidecar, blob_index) @@ -655,7 +657,7 @@ impl NetworkBeaconProcessor { .and_then(|now| now.checked_sub(seen_duration)) { metrics::set_gauge( - &metrics::BEACON_BLOB_LAST_GOSSIP_VERIFICATION_TIME, + &metrics::BEACON_BLOB_DELAY_GOSSIP_VERIFICATION, duration.as_millis() as i64, ); } @@ -766,7 +768,7 @@ impl NetworkBeaconProcessor { self.chain.recompute_head_at_current_slot().await; metrics::set_gauge( - &metrics::BEACON_BLOB_LAST_FULL_VERIFICATION_TIME, + &metrics::BEACON_BLOB_DELAY_FULL_VERIFICATION, processing_start_time.elapsed().as_millis() as i64, ); } @@ -870,12 +872,9 @@ impl NetworkBeaconProcessor { let block_delay = get_block_delay_ms(seen_duration, block.message(), &self.chain.slot_clock); // Log metrics to track delay from other nodes on the network. - metrics::observe_duration( - &metrics::BEACON_BLOCK_GOSSIP_SLOT_START_DELAY_TIME, - block_delay, - ); + metrics::set_gauge( - &metrics::BEACON_BLOCK_LAST_DELAY, + &metrics::BEACON_BLOCK_DELAY_GOSSIP, block_delay.as_millis() as i64, ); @@ -903,7 +902,7 @@ impl NetworkBeaconProcessor { let verified_block = match verification_result { Ok(verified_block) => { if block_delay >= self.chain.slot_clock.unagg_attestation_production_delay() { - metrics::inc_counter(&metrics::BEACON_BLOCK_GOSSIP_ARRIVED_LATE_TOTAL); + metrics::inc_counter(&metrics::BEACON_BLOCK_DELAY_GOSSIP_ARRIVED_LATE_TOTAL); debug!( self.log, "Gossip block arrived late"; @@ -929,7 +928,7 @@ impl NetworkBeaconProcessor { .and_then(|now| now.checked_sub(seen_duration)) { metrics::set_gauge( - &metrics::BEACON_BLOCK_LAST_GOSSIP_VERIFICATION_TIME, + &metrics::BEACON_BLOCK_DELAY_GOSSIP_VERIFICATION, duration.as_millis() as i64, ); } @@ -1175,7 +1174,7 @@ impl NetworkBeaconProcessor { self.chain.recompute_head_at_current_slot().await; metrics::set_gauge( - &metrics::BEACON_BLOCK_LAST_FULL_VERIFICATION_TIME, + &metrics::BEACON_BLOCK_DELAY_FULL_VERIFICATION, processing_start_time.elapsed().as_millis() as i64, ); } From 32b072ec049436a6dea9146dfbb2cf96af160d41 Mon Sep 17 00:00:00 2001 From: Age Manning Date: Mon, 22 Apr 2024 09:41:36 +1000 Subject: [PATCH 5/8] fmt --- beacon_node/beacon_chain/src/canonical_head.rs | 2 -- .../src/data_availability_checker/overflow_lru_cache.rs | 6 +++++- .../network/src/network_beacon_processor/gossip_methods.rs | 5 +---- 3 files changed, 6 insertions(+), 7 deletions(-) diff --git a/beacon_node/beacon_chain/src/canonical_head.rs b/beacon_node/beacon_chain/src/canonical_head.rs index 462880009f7..734575d2c0d 100644 --- a/beacon_node/beacon_chain/src/canonical_head.rs +++ b/beacon_node/beacon_chain/src/canonical_head.rs @@ -1405,7 +1405,6 @@ fn observe_head_block_delays( // Do not store metrics if the block was > 4 slots old, this helps prevent noise during // sync. if !block_from_sync { - // Observe the delay between when we imported the block and when we set the block as // head. let block_delays = block_times_cache.get_block_delays( @@ -1465,7 +1464,6 @@ fn observe_head_block_delays( .as_millis() as i64, ); - // The time the block became attestable after the start of the slot. metrics::set_gauge( &metrics::BEACON_BLOCK_DELAY_ATTESTABLE_SLOT_START, diff --git a/beacon_node/beacon_chain/src/data_availability_checker/overflow_lru_cache.rs b/beacon_node/beacon_chain/src/data_availability_checker/overflow_lru_cache.rs index 561026ef5c5..16ee4f98111 100644 --- a/beacon_node/beacon_chain/src/data_availability_checker/overflow_lru_cache.rs +++ b/beacon_node/beacon_chain/src/data_availability_checker/overflow_lru_cache.rs @@ -193,7 +193,11 @@ impl PendingComponents { /// /// WARNING: This function can potentially take a lot of time if the state needs to be /// reconstructed from disk. Ensure you are not holding any write locks while calling this. - pub fn make_available(self, recover: R, slot_clock: &Clock) -> Result, AvailabilityCheckError> + pub fn make_available( + self, + recover: R, + slot_clock: &Clock, + ) -> Result, AvailabilityCheckError> where R: FnOnce( DietAvailabilityPendingExecutedBlock, diff --git a/beacon_node/network/src/network_beacon_processor/gossip_methods.rs b/beacon_node/network/src/network_beacon_processor/gossip_methods.rs index 6557f7be2db..7b8826bd853 100644 --- a/beacon_node/network/src/network_beacon_processor/gossip_methods.rs +++ b/beacon_node/network/src/network_beacon_processor/gossip_methods.rs @@ -615,10 +615,7 @@ impl NetworkBeaconProcessor { let commitment = blob_sidecar.kzg_commitment; let delay = get_slot_delay_ms(seen_duration, slot, &self.chain.slot_clock); // Log metrics to track delay from other nodes on the network. - metrics::set_gauge( - &metrics::BEACON_BLOB_DELAY_GOSSIP, - delay.as_millis() as i64, - ); + metrics::set_gauge(&metrics::BEACON_BLOB_DELAY_GOSSIP, delay.as_millis() as i64); match self .chain .verify_blob_sidecar_for_gossip(blob_sidecar, blob_index) From d21a7f15aefaf0f73ab76d9e52183f768360df17 Mon Sep 17 00:00:00 2001 From: Michael Sproul Date: Mon, 22 Apr 2024 10:59:59 +1000 Subject: [PATCH 6/8] Small tweaks --- beacon_node/beacon_chain/src/beacon_chain.rs | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/beacon_node/beacon_chain/src/beacon_chain.rs b/beacon_node/beacon_chain/src/beacon_chain.rs index 1cf8a4a0bdc..103933071c8 100644 --- a/beacon_node/beacon_chain/src/beacon_chain.rs +++ b/beacon_node/beacon_chain/src/beacon_chain.rs @@ -3011,7 +3011,6 @@ impl BeaconChain { // Set observed time if not already set. Usually this should be set by gossip or RPC, // but just in case we set it again here (useful for tests). - #[cfg(test)] if let Some(seen_timestamp) = self.slot_clock.now_duration() { self.block_times_cache.write().set_time_observed( block_root, @@ -3270,8 +3269,10 @@ impl BeaconChain { } = import_data; // This is the time since start of the slot where all the components of the block have become available - let delay = get_slot_delay_ms(timestamp_now(), block.slot(), &self.slot_clock); - metrics::set_gauge(&metrics::BLOCK_AVAILABILITY_DELAY, delay.as_millis() as i64); + metrics::set_gauge( + &metrics::BLOCK_AVAILABILITY_DELAY, + block.available_timestamp().as_millis() as i64, + ); // Record the time at which this block became available. self.block_times_cache.write().set_time_available( block_root, From 73cb98281da07440795d6659ef291be8d4d47e9a Mon Sep 17 00:00:00 2001 From: Michael Sproul Date: Mon, 22 Apr 2024 13:25:15 +1000 Subject: [PATCH 7/8] Try pushing blob timing down into verification --- beacon_node/beacon_chain/src/beacon_chain.rs | 28 ++--- .../beacon_chain/src/blob_verification.rs | 42 +++++-- .../beacon_chain/src/block_times_cache.rs | 37 +++--- .../src/data_availability_checker.rs | 55 ++++----- .../overflow_lru_cache.rs | 107 ++++++------------ 5 files changed, 112 insertions(+), 157 deletions(-) diff --git a/beacon_node/beacon_chain/src/beacon_chain.rs b/beacon_node/beacon_chain/src/beacon_chain.rs index 103933071c8..c59c5e8ed10 100644 --- a/beacon_node/beacon_chain/src/beacon_chain.rs +++ b/beacon_node/beacon_chain/src/beacon_chain.rs @@ -2891,15 +2891,6 @@ impl BeaconChain { return Err(BlockError::BlockIsAlreadyKnown(blob.block_root())); } - // Record the delay for receiving this blob - if let Some(seen_timestamp) = self.slot_clock.now_duration() { - self.block_times_cache.write().set_time_blob_observed( - block_root, - blob.slot(), - seen_timestamp, - ); - } - if let Some(event_handler) = self.event_handler.as_ref() { if event_handler.has_blob_sidecar_subscribers() { event_handler.register(EventKind::BlobSidecar(SseBlobSidecar::from_blob_sidecar( @@ -3268,17 +3259,14 @@ impl BeaconChain { consensus_context, } = import_data; - // This is the time since start of the slot where all the components of the block have become available - metrics::set_gauge( - &metrics::BLOCK_AVAILABILITY_DELAY, - block.available_timestamp().as_millis() as i64, - ); - // Record the time at which this block became available. - self.block_times_cache.write().set_time_available( - block_root, - block.slot(), - block.available_timestamp(), - ); + // Record the time at which this block's blobs became available. + if let Some(blobs_available) = block.blobs_available_timestamp() { + self.block_times_cache.write().set_time_blob_observed( + block_root, + block.slot(), + blobs_available, + ); + } // import let chain = self.clone(); diff --git a/beacon_node/beacon_chain/src/blob_verification.rs b/beacon_node/beacon_chain/src/blob_verification.rs index 1fb61702006..a1ae260d930 100644 --- a/beacon_node/beacon_chain/src/blob_verification.rs +++ b/beacon_node/beacon_chain/src/blob_verification.rs @@ -14,6 +14,7 @@ use merkle_proof::MerkleTreeError; use slog::{debug, warn}; use ssz_derive::{Decode, Encode}; use ssz_types::VariableList; +use std::time::Duration; use tree_hash::TreeHash; use types::blob_sidecar::BlobIdentifier; use types::{ @@ -214,7 +215,10 @@ impl GossipVerifiedBlob { pub fn __assumed_valid(blob: Arc>) -> Self { Self { block_root: blob.block_root(), - blob: KzgVerifiedBlob { blob }, + blob: KzgVerifiedBlob { + blob, + seen_timestamp: Duration::from_secs(0), + }, } } pub fn id(&self) -> BlobIdentifier { @@ -260,6 +264,8 @@ impl GossipVerifiedBlob { #[ssz(struct_behaviour = "transparent")] pub struct KzgVerifiedBlob { blob: Arc>, + #[ssz(skip_serializing, skip_deserializing)] + seen_timestamp: Duration, } impl PartialOrd for KzgVerifiedBlob { @@ -275,8 +281,12 @@ impl Ord for KzgVerifiedBlob { } impl KzgVerifiedBlob { - pub fn new(blob: Arc>, kzg: &Kzg) -> Result { - verify_kzg_for_blob(blob, kzg) + pub fn new( + blob: Arc>, + kzg: &Kzg, + seen_timestamp: Duration, + ) -> Result { + verify_kzg_for_blob(blob, kzg, seen_timestamp) } pub fn to_blob(self) -> Arc> { self.blob @@ -294,12 +304,18 @@ impl KzgVerifiedBlob { pub fn blob_index(&self) -> u64 { self.blob.index } + pub fn seen_timestamp(&self) -> Duration { + self.seen_timestamp + } /// Construct a `KzgVerifiedBlob` that is assumed to be valid. /// /// This should ONLY be used for testing. #[cfg(test)] pub fn __assumed_valid(blob: Arc>) -> Self { - Self { blob } + Self { + blob, + seen_timestamp: Duration::from_secs(0), + } } } @@ -309,9 +325,13 @@ impl KzgVerifiedBlob { pub fn verify_kzg_for_blob( blob: Arc>, kzg: &Kzg, + seen_timestamp: Duration, ) -> Result, KzgError> { validate_blob::(kzg, &blob.blob, blob.kzg_commitment, blob.kzg_proof)?; - Ok(KzgVerifiedBlob { blob }) + Ok(KzgVerifiedBlob { + blob, + seen_timestamp, + }) } pub struct KzgVerifiedBlobList { @@ -322,13 +342,17 @@ impl KzgVerifiedBlobList { pub fn new>>>( blob_list: I, kzg: &Kzg, + seen_timestamp: Duration, ) -> Result { let blobs = blob_list.into_iter().collect::>(); verify_kzg_for_blob_list(blobs.iter(), kzg)?; Ok(Self { verified_blobs: blobs .into_iter() - .map(|blob| KzgVerifiedBlob { blob }) + .map(|blob| KzgVerifiedBlob { + blob, + seen_timestamp, + }) .collect(), }) } @@ -374,6 +398,8 @@ pub fn validate_blob_sidecar_for_gossip( let blob_epoch = blob_slot.epoch(T::EthSpec::slots_per_epoch()); let signed_block_header = &blob_sidecar.signed_block_header; + let seen_timestamp = chain.slot_clock.now_duration().unwrap_or_default(); + // This condition is not possible if we have received the blob from the network // since we only subscribe to `MaxBlobsPerBlock` subnets over gossip network. // We include this check only for completeness. @@ -641,8 +667,8 @@ pub fn validate_blob_sidecar_for_gossip( .kzg .as_ref() .ok_or(GossipBlobError::KzgNotInitialized)?; - let kzg_verified_blob = - KzgVerifiedBlob::new(blob_sidecar, kzg).map_err(GossipBlobError::KzgError)?; + let kzg_verified_blob = KzgVerifiedBlob::new(blob_sidecar, kzg, seen_timestamp) + .map_err(GossipBlobError::KzgError)?; Ok(GossipVerifiedBlob { block_root, diff --git a/beacon_node/beacon_chain/src/block_times_cache.rs b/beacon_node/beacon_chain/src/block_times_cache.rs index 2cbade89969..9d9c403ffaf 100644 --- a/beacon_node/beacon_chain/src/block_times_cache.rs +++ b/beacon_node/beacon_chain/src/block_times_cache.rs @@ -20,7 +20,6 @@ pub struct Timestamps { pub observed: Option, pub all_blobs_observed: Option, pub execution_time: Option, - pub available: Option, pub attestable: Option, pub imported: Option, pub set_as_head: Option, @@ -35,7 +34,9 @@ pub struct BlockDelays { pub all_blobs_observed: Option, /// The time it took to get verification from the EL for the block. pub execution_time: Option, - /// Time after max(`observed + execution_time`, `all_blobs_observed`) the block became available. + /// The delay from the start of the slot before the block became available + /// + /// Equal to max(`observed + execution_time`, `all_blobs_observed`). pub available: Option, /// Time after `available`. pub attestable: Option, @@ -60,15 +61,23 @@ impl BlockDelays { let execution_time = times .execution_time .and_then(|execution_time| execution_time.checked_sub(times.observed?)); - let available = times - .available - .and_then(|available_time| available_time.checked_sub(slot_start_time)); + // Duration since UNIX epoch at which block became available. + let available_time = times.execution_time.and_then(|execution_time| { + if let Some(all_blobs_observed) = times.all_blobs_observed { + Some(std::cmp::max(execution_time, all_blobs_observed)) + } else { + Some(execution_time) + } + }); + // Duration from the start of the slot until the block became available. + let available_delay = + available_time.and_then(|available_time| available_time.checked_sub(slot_start_time)); let attestable = times .attestable .and_then(|attestable_time| attestable_time.checked_sub(slot_start_time)); let imported = times .imported - .and_then(|imported_time| imported_time.checked_sub(times.available?)); + .and_then(|imported_time| imported_time.checked_sub(available_time?)); let set_as_head = times .set_as_head .and_then(|set_as_head_time| set_as_head_time.checked_sub(times.imported?)); @@ -76,7 +85,7 @@ impl BlockDelays { observed, all_blobs_observed, execution_time, - available, + available: available_delay, attestable, imported, set_as_head, @@ -177,20 +186,6 @@ impl BlockTimesCache { } } - pub fn set_time_available(&mut self, block_root: BlockRoot, slot: Slot, timestamp: Duration) { - let block_times = self - .cache - .entry(block_root) - .or_insert_with(|| BlockTimesCacheValue::new(slot)); - if block_times - .timestamps - .available - .map_or(true, |prev| timestamp < prev) - { - block_times.timestamps.available = Some(timestamp); - } - } - pub fn set_time_attestable(&mut self, block_root: BlockRoot, slot: Slot, timestamp: Duration) { let block_times = self .cache diff --git a/beacon_node/beacon_chain/src/data_availability_checker.rs b/beacon_node/beacon_chain/src/data_availability_checker.rs index 360b7507cc2..dd0d97b1dae 100644 --- a/beacon_node/beacon_chain/src/data_availability_checker.rs +++ b/beacon_node/beacon_chain/src/data_availability_checker.rs @@ -177,11 +177,17 @@ impl DataAvailabilityChecker { return Err(AvailabilityCheckError::KzgNotInitialized); }; - let verified_blobs = KzgVerifiedBlobList::new(Vec::from(blobs).into_iter().flatten(), kzg) - .map_err(AvailabilityCheckError::Kzg)?; + let seen_timestamp = self + .slot_clock + .now_duration() + .ok_or(AvailabilityCheckError::SlotClockError)?; + + let verified_blobs = + KzgVerifiedBlobList::new(Vec::from(blobs).into_iter().flatten(), kzg, seen_timestamp) + .map_err(AvailabilityCheckError::Kzg)?; self.availability_cache - .put_kzg_verified_blobs(block_root, verified_blobs, &self.slot_clock) + .put_kzg_verified_blobs(block_root, verified_blobs) } /// Check if we've cached other blobs for this block. If it completes a set and we also @@ -193,11 +199,8 @@ impl DataAvailabilityChecker { &self, gossip_blob: GossipVerifiedBlob, ) -> Result, AvailabilityCheckError> { - self.availability_cache.put_kzg_verified_blobs( - gossip_blob.block_root(), - vec![gossip_blob.into_inner()], - &self.slot_clock, - ) + self.availability_cache + .put_kzg_verified_blobs(gossip_blob.block_root(), vec![gossip_blob.into_inner()]) } /// Check if we have all the blobs for a block. Returns `Availability` which has information @@ -207,7 +210,7 @@ impl DataAvailabilityChecker { executed_block: AvailabilityPendingExecutedBlock, ) -> Result, AvailabilityCheckError> { self.availability_cache - .put_pending_executed_block(executed_block, &self.slot_clock) + .put_pending_executed_block(executed_block) } /// Verifies kzg commitments for an RpcBlock, returns a `MaybeAvailableBlock` that may @@ -225,15 +228,11 @@ impl DataAvailabilityChecker { if self.blobs_required_for_block(&block) { Ok(MaybeAvailableBlock::AvailabilityPending { block_root, block }) } else { - let available_timestamp = self - .slot_clock - .now_duration() - .ok_or(AvailabilityCheckError::SlotClockError)?; Ok(MaybeAvailableBlock::Available(AvailableBlock { block_root, block, blobs: None, - available_timestamp, + blobs_available_timestamp: None, })) } } @@ -249,15 +248,11 @@ impl DataAvailabilityChecker { } else { None }; - let available_timestamp = self - .slot_clock - .now_duration() - .ok_or(AvailabilityCheckError::SlotClockError)?; Ok(MaybeAvailableBlock::Available(AvailableBlock { block_root, block, blobs: verified_blobs, - available_timestamp, + blobs_available_timestamp: None, })) } } @@ -299,15 +294,11 @@ impl DataAvailabilityChecker { if self.blobs_required_for_block(&block) { results.push(MaybeAvailableBlock::AvailabilityPending { block_root, block }) } else { - let available_timestamp = self - .slot_clock - .now_duration() - .ok_or(AvailabilityCheckError::SlotClockError)?; results.push(MaybeAvailableBlock::Available(AvailableBlock { block_root, block, blobs: None, - available_timestamp, + blobs_available_timestamp: None, })) } } @@ -318,15 +309,11 @@ impl DataAvailabilityChecker { None }; // already verified kzg for all blobs - let available_timestamp = self - .slot_clock - .now_duration() - .ok_or(AvailabilityCheckError::SlotClockError)?; results.push(MaybeAvailableBlock::Available(AvailableBlock { block_root, block, blobs: verified_blobs, - available_timestamp, + blobs_available_timestamp: None, })) } } @@ -487,7 +474,7 @@ pub struct AvailableBlock { block: Arc>, blobs: Option>, /// Timestamp at which this block first became available (UNIX timestamp, time since 1970). - available_timestamp: Duration, + blobs_available_timestamp: Option, } impl AvailableBlock { @@ -500,7 +487,7 @@ impl AvailableBlock { block_root, block, blobs, - available_timestamp: Duration::from_millis(0), + blobs_available_timestamp: None, } } @@ -515,8 +502,8 @@ impl AvailableBlock { self.blobs.as_ref() } - pub fn available_timestamp(&self) -> Duration { - self.available_timestamp + pub fn blobs_available_timestamp(&self) -> Option { + self.blobs_available_timestamp } pub fn deconstruct( @@ -530,7 +517,7 @@ impl AvailableBlock { block_root, block, blobs, - available_timestamp: _, + blobs_available_timestamp: _, } = self; (block_root, block, blobs) } diff --git a/beacon_node/beacon_chain/src/data_availability_checker/overflow_lru_cache.rs b/beacon_node/beacon_chain/src/data_availability_checker/overflow_lru_cache.rs index 16ee4f98111..f4c1bc308c0 100644 --- a/beacon_node/beacon_chain/src/data_availability_checker/overflow_lru_cache.rs +++ b/beacon_node/beacon_chain/src/data_availability_checker/overflow_lru_cache.rs @@ -38,7 +38,6 @@ use crate::store::{DBColumn, KeyValueStore}; use crate::BeaconChainTypes; use lru::LruCache; use parking_lot::{Mutex, RwLock, RwLockUpgradableReadGuard}; -use slot_clock::SlotClock; use ssz::{Decode, Encode}; use ssz_derive::{Decode, Encode}; use ssz_types::{FixedVector, VariableList}; @@ -193,30 +192,24 @@ impl PendingComponents { /// /// WARNING: This function can potentially take a lot of time if the state needs to be /// reconstructed from disk. Ensure you are not holding any write locks while calling this. - pub fn make_available( - self, - recover: R, - slot_clock: &Clock, - ) -> Result, AvailabilityCheckError> + pub fn make_available(self, recover: R) -> Result, AvailabilityCheckError> where R: FnOnce( DietAvailabilityPendingExecutedBlock, ) -> Result, AvailabilityCheckError>, - Clock: SlotClock, { - // Record the availability timestamp as soon as the block components are all available. We - // are mostly interested in how long availability takes from a network point-of-view, not - // how long availability processing takes. - let available_timestamp = slot_clock - .now_duration() - .ok_or(AvailabilityCheckError::SlotClockError)?; - let Self { block_root, verified_blobs, executed_block, } = self; + let blobs_available_timestamp = verified_blobs + .iter() + .flatten() + .map(|blob| blob.seen_timestamp()) + .max(); + let Some(diet_executed_block) = executed_block else { return Err(AvailabilityCheckError::Unexpected); }; @@ -244,7 +237,7 @@ impl PendingComponents { block_root, block, blobs: Some(verified_blobs), - available_timestamp, + blobs_available_timestamp, }; Ok(Availability::Available(Box::new( AvailableExecutedBlock::new(available_block, import_data, payload_verification_outcome), @@ -588,7 +581,6 @@ impl OverflowLRUCache { &self, block_root: Hash256, kzg_verified_blobs: I, - slot_clock: &T::SlotClock, ) -> Result, AvailabilityCheckError> { let mut fixed_blobs = FixedVector::default(); @@ -611,10 +603,9 @@ impl OverflowLRUCache { if pending_components.is_available() { // No need to hold the write lock anymore drop(write_lock); - pending_components.make_available( - |diet_block| self.state_cache.recover_pending_executed_block(diet_block), - slot_clock, - ) + pending_components.make_available(|diet_block| { + self.state_cache.recover_pending_executed_block(diet_block) + }) } else { write_lock.put_pending_components( block_root, @@ -630,7 +621,6 @@ impl OverflowLRUCache { pub fn put_pending_executed_block( &self, executed_block: AvailabilityPendingExecutedBlock, - slot_clock: &T::SlotClock, ) -> Result, AvailabilityCheckError> { let mut write_lock = self.critical.write(); let block_root = executed_block.import_data.block_root; @@ -652,10 +642,9 @@ impl OverflowLRUCache { if pending_components.is_available() { // No need to hold the write lock anymore drop(write_lock); - pending_components.make_available( - |diet_block| self.state_cache.recover_pending_executed_block(diet_block), - slot_clock, - ) + pending_components.make_available(|diet_block| { + self.state_cache.recover_pending_executed_block(diet_block) + }) } else { write_lock.put_pending_components( block_root, @@ -1193,7 +1182,7 @@ mod test { "cache should be empty" ); let availability = cache - .put_pending_executed_block(pending_block, &harness.chain.slot_clock) + .put_pending_executed_block(pending_block) .expect("should put block"); if blobs_expected == 0 { assert!( @@ -1225,7 +1214,7 @@ mod test { for (blob_index, gossip_blob) in blobs.into_iter().enumerate() { kzg_verified_blobs.push(gossip_blob.into_inner()); let availability = cache - .put_kzg_verified_blobs(root, kzg_verified_blobs.clone(), &harness.chain.slot_clock) + .put_kzg_verified_blobs(root, kzg_verified_blobs.clone()) .expect("should put blob"); if blob_index == blobs_expected - 1 { assert!(matches!(availability, Availability::Available(_))); @@ -1251,7 +1240,7 @@ mod test { for gossip_blob in blobs { kzg_verified_blobs.push(gossip_blob.into_inner()); let availability = cache - .put_kzg_verified_blobs(root, kzg_verified_blobs.clone(), &harness.chain.slot_clock) + .put_kzg_verified_blobs(root, kzg_verified_blobs.clone()) .expect("should put blob"); assert_eq!( availability, @@ -1261,7 +1250,7 @@ mod test { assert_eq!(cache.critical.read().in_memory.len(), 1); } let availability = cache - .put_pending_executed_block(pending_block, &harness.chain.slot_clock) + .put_pending_executed_block(pending_block) .expect("should put block"); assert!( matches!(availability, Availability::Available(_)), @@ -1298,10 +1287,7 @@ mod test { for i in 0..capacity { cache - .put_pending_executed_block( - pending_blocks.pop_front().expect("should have block"), - &harness.chain.slot_clock, - ) + .put_pending_executed_block(pending_blocks.pop_front().expect("should have block")) .expect("should put block"); assert_eq!(cache.critical.read().in_memory.len(), i + 1); } @@ -1327,10 +1313,7 @@ mod test { ); cache - .put_pending_executed_block( - pending_blocks.pop_front().expect("should have block"), - &harness.chain.slot_clock, - ) + .put_pending_executed_block(pending_blocks.pop_front().expect("should have block")) .expect("should put block"); assert_eq!( cache.critical.read().in_memory.len(), @@ -1385,11 +1368,7 @@ mod test { for (blob_index, gossip_blob) in blobs_0.into_iter().enumerate() { kzg_verified_blobs.push(gossip_blob.into_inner()); let availability = cache - .put_kzg_verified_blobs( - roots[0], - kzg_verified_blobs.clone(), - &harness.chain.slot_clock, - ) + .put_kzg_verified_blobs(roots[0], kzg_verified_blobs.clone()) .expect("should put blob"); if blob_index == expected_blobs - 1 { assert!(matches!(availability, Availability::Available(_))); @@ -1469,18 +1448,14 @@ mod test { let block_first = (rand::random::() % 2) == 0; if block_first { let availability = cache - .put_pending_executed_block(pending_block, &harness.chain.slot_clock) + .put_pending_executed_block(pending_block) .expect("should put block"); assert!( matches!(availability, Availability::MissingComponents(_)), "should have pending blobs" ); let availability = cache - .put_kzg_verified_blobs( - block_root, - kzg_verified_blobs, - &harness.chain.slot_clock, - ) + .put_kzg_verified_blobs(block_root, kzg_verified_blobs) .expect("should put blob"); assert!( matches!(availability, Availability::MissingComponents(_)), @@ -1489,11 +1464,7 @@ mod test { ); } else { let availability = cache - .put_kzg_verified_blobs( - block_root, - kzg_verified_blobs, - &harness.chain.slot_clock, - ) + .put_kzg_verified_blobs(block_root, kzg_verified_blobs) .expect("should put blob"); let root = pending_block.block.as_block().canonical_root(); assert_eq!( @@ -1502,7 +1473,7 @@ mod test { "should be pending block" ); let availability = cache - .put_pending_executed_block(pending_block, &harness.chain.slot_clock) + .put_pending_executed_block(pending_block) .expect("should put block"); assert!( matches!(availability, Availability::MissingComponents(_)), @@ -1511,7 +1482,7 @@ mod test { } } else { let availability = cache - .put_pending_executed_block(pending_block, &harness.chain.slot_clock) + .put_pending_executed_block(pending_block) .expect("should put block"); assert!( matches!(availability, Availability::MissingComponents(_)), @@ -1609,18 +1580,14 @@ mod test { let block_first = (rand::random::() % 2) == 0; if block_first { let availability = cache - .put_pending_executed_block(pending_block, &harness.chain.slot_clock) + .put_pending_executed_block(pending_block) .expect("should put block"); assert!( matches!(availability, Availability::MissingComponents(_)), "should have pending blobs" ); let availability = cache - .put_kzg_verified_blobs( - block_root, - kzg_verified_blobs, - &harness.chain.slot_clock, - ) + .put_kzg_verified_blobs(block_root, kzg_verified_blobs) .expect("should put blob"); assert!( matches!(availability, Availability::MissingComponents(_)), @@ -1629,11 +1596,7 @@ mod test { ); } else { let availability = cache - .put_kzg_verified_blobs( - block_root, - kzg_verified_blobs, - &harness.chain.slot_clock, - ) + .put_kzg_verified_blobs(block_root, kzg_verified_blobs) .expect("should put blob"); let root = pending_block.block.as_block().canonical_root(); assert_eq!( @@ -1642,7 +1605,7 @@ mod test { "should be pending block" ); let availability = cache - .put_pending_executed_block(pending_block, &harness.chain.slot_clock) + .put_pending_executed_block(pending_block) .expect("should put block"); assert!( matches!(availability, Availability::MissingComponents(_)), @@ -1651,7 +1614,7 @@ mod test { } } else { let availability = cache - .put_pending_executed_block(pending_block, &harness.chain.slot_clock) + .put_pending_executed_block(pending_block) .expect("should put block"); assert!( matches!(availability, Availability::MissingComponents(_)), @@ -1727,11 +1690,7 @@ mod test { for (i, gossip_blob) in blobs.into_iter().enumerate() { kzg_verified_blobs.push(gossip_blob.into_inner()); let availability = recovered_cache - .put_kzg_verified_blobs( - root, - kzg_verified_blobs.clone(), - &harness.chain.slot_clock, - ) + .put_kzg_verified_blobs(root, kzg_verified_blobs.clone()) .expect("should put blob"); if i == additional_blobs - 1 { assert!(matches!(availability, Availability::Available(_))) @@ -1791,7 +1750,7 @@ mod test { // put the block in the cache let availability = cache - .put_pending_executed_block(pending_block, &harness.chain.slot_clock) + .put_pending_executed_block(pending_block) .expect("should put block"); // grab the diet block from the cache for later testing From 958bac4c3711dcbe5c5f2edbf10e18e228b5e1cc Mon Sep 17 00:00:00 2001 From: Michael Sproul Date: Tue, 23 Apr 2024 15:38:40 +1000 Subject: [PATCH 8/8] Simplify for clippy --- beacon_node/beacon_chain/src/block_times_cache.rs | 8 ++------ 1 file changed, 2 insertions(+), 6 deletions(-) diff --git a/beacon_node/beacon_chain/src/block_times_cache.rs b/beacon_node/beacon_chain/src/block_times_cache.rs index 9d9c403ffaf..db547a1186c 100644 --- a/beacon_node/beacon_chain/src/block_times_cache.rs +++ b/beacon_node/beacon_chain/src/block_times_cache.rs @@ -62,12 +62,8 @@ impl BlockDelays { .execution_time .and_then(|execution_time| execution_time.checked_sub(times.observed?)); // Duration since UNIX epoch at which block became available. - let available_time = times.execution_time.and_then(|execution_time| { - if let Some(all_blobs_observed) = times.all_blobs_observed { - Some(std::cmp::max(execution_time, all_blobs_observed)) - } else { - Some(execution_time) - } + let available_time = times.execution_time.map(|execution_time| { + std::cmp::max(execution_time, times.all_blobs_observed.unwrap_or_default()) }); // Duration from the start of the slot until the block became available. let available_delay =