diff --git a/beacon_node/beacon_chain/src/beacon_chain.rs b/beacon_node/beacon_chain/src/beacon_chain.rs index 0595d53c072..19ee3d116c1 100644 --- a/beacon_node/beacon_chain/src/beacon_chain.rs +++ b/beacon_node/beacon_chain/src/beacon_chain.rs @@ -3088,14 +3088,21 @@ impl BeaconChain { notify_execution_layer, )?; publish_fn()?; + + // Record the time it took to complete consensus verification. + if let Some(timestamp) = self.slot_clock.now_duration() { + self.block_times_cache + .write() + .set_time_consensus_verified(block_root, block_slot, timestamp) + } + 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, - ) + + // Record the *additional* time it took to wait for execution layer verification. + if let Some(timestamp) = self.slot_clock.now_duration() { + self.block_times_cache + .write() + .set_time_executed(block_root, block_slot, timestamp) } match executed_block { diff --git a/beacon_node/beacon_chain/src/block_times_cache.rs b/beacon_node/beacon_chain/src/block_times_cache.rs index db547a1186c..3b75046f3a4 100644 --- a/beacon_node/beacon_chain/src/block_times_cache.rs +++ b/beacon_node/beacon_chain/src/block_times_cache.rs @@ -19,7 +19,9 @@ type BlockRoot = Hash256; pub struct Timestamps { pub observed: Option, pub all_blobs_observed: Option, - pub execution_time: Option, + pub consensus_verified: Option, + pub started_execution: Option, + pub executed: Option, pub attestable: Option, pub imported: Option, pub set_as_head: Option, @@ -32,7 +34,9 @@ pub struct BlockDelays { pub observed: Option, /// 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. + /// The time it took to complete consensus verification of the block. + pub consensus_verification_time: Option, + /// The time it took to complete execution verification of the block. pub execution_time: Option, /// The delay from the start of the slot before the block became available /// @@ -58,13 +62,16 @@ impl BlockDelays { let all_blobs_observed = times .all_blobs_observed .and_then(|all_blobs_observed| all_blobs_observed.checked_sub(slot_start_time)); + let consensus_verification_time = times + .consensus_verified + .and_then(|consensus_verified| consensus_verified.checked_sub(times.observed?)); let execution_time = times - .execution_time - .and_then(|execution_time| execution_time.checked_sub(times.observed?)); + .executed + .and_then(|executed| executed.checked_sub(times.started_execution?)); // Duration since UNIX epoch at which block became available. - let available_time = times.execution_time.map(|execution_time| { - std::cmp::max(execution_time, times.all_blobs_observed.unwrap_or_default()) - }); + let available_time = times + .executed + .map(|executed| std::cmp::max(executed, times.all_blobs_observed.unwrap_or_default())); // 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)); @@ -80,6 +87,7 @@ impl BlockDelays { BlockDelays { observed, all_blobs_observed, + consensus_verification_time, execution_time, available: available_delay, attestable, @@ -155,6 +163,9 @@ impl BlockTimesCache { slot: Slot, timestamp: Duration, ) { + // Unlike other functions in this file, we update the blob observed time only if it is + // *greater* than existing blob observation times. This allows us to know the observation + // time of the last blob to arrive. let block_times = self .cache .entry(block_root) @@ -168,48 +179,89 @@ impl BlockTimesCache { } } - pub fn set_execution_time(&mut self, block_root: BlockRoot, slot: Slot, timestamp: Duration) { + /// Set the timestamp for `field` if that timestamp is less than any previously known value. + /// + /// If no previous value is known for the field, then the supplied timestamp will always be + /// stored. + pub fn set_time_if_less( + &mut self, + block_root: BlockRoot, + slot: Slot, + field: impl Fn(&mut Timestamps) -> &mut Option, + 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); + let existing_timestamp = field(&mut block_times.timestamps); + if existing_timestamp.map_or(true, |prev| timestamp < prev) { + *existing_timestamp = Some(timestamp); } } + pub fn set_time_consensus_verified( + &mut self, + block_root: BlockRoot, + slot: Slot, + timestamp: Duration, + ) { + self.set_time_if_less( + block_root, + slot, + |timestamps| &mut timestamps.consensus_verified, + timestamp, + ) + } + + pub fn set_time_executed(&mut self, block_root: BlockRoot, slot: Slot, timestamp: Duration) { + self.set_time_if_less( + block_root, + slot, + |timestamps| &mut timestamps.executed, + timestamp, + ) + } + + pub fn set_time_started_execution( + &mut self, + block_root: BlockRoot, + slot: Slot, + timestamp: Duration, + ) { + self.set_time_if_less( + block_root, + slot, + |timestamps| &mut timestamps.started_execution, + 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); - } + self.set_time_if_less( + block_root, + slot, + |timestamps| &mut timestamps.attestable, + timestamp, + ) } pub fn set_time_imported(&mut self, block_root: BlockRoot, slot: Slot, timestamp: Duration) { - let block_times = self - .cache - .entry(block_root) - .or_insert_with(|| BlockTimesCacheValue::new(slot)); - block_times.timestamps.imported = Some(timestamp); + self.set_time_if_less( + block_root, + slot, + |timestamps| &mut timestamps.imported, + timestamp, + ) } pub fn set_time_set_as_head(&mut self, block_root: BlockRoot, slot: Slot, timestamp: Duration) { - let block_times = self - .cache - .entry(block_root) - .or_insert_with(|| BlockTimesCacheValue::new(slot)); - block_times.timestamps.set_as_head = Some(timestamp); + self.set_time_if_less( + block_root, + slot, + |timestamps| &mut timestamps.set_as_head, + timestamp, + ) } pub fn get_block_delays( diff --git a/beacon_node/beacon_chain/src/block_verification.rs b/beacon_node/beacon_chain/src/block_verification.rs index 33605c6b1de..d906518ff5a 100644 --- a/beacon_node/beacon_chain/src/block_verification.rs +++ b/beacon_node/beacon_chain/src/block_verification.rs @@ -1344,6 +1344,13 @@ impl ExecutionPendingBlock { // The specification declares that this should be run *inside* `per_block_processing`, // however we run it here to keep `per_block_processing` pure (i.e., no calls to external // servers). + if let Some(started_execution) = chain.slot_clock.now_duration() { + chain.block_times_cache.write().set_time_started_execution( + block_root, + block.slot(), + started_execution, + ); + } let payload_verification_status = payload_notifier.notify_new_payload().await?; // If the payload did not validate or invalidate the block, check to see if this block is diff --git a/beacon_node/beacon_chain/src/canonical_head.rs b/beacon_node/beacon_chain/src/canonical_head.rs index a84cfab298d..84e1544451c 100644 --- a/beacon_node/beacon_chain/src/canonical_head.rs +++ b/beacon_node/beacon_chain/src/canonical_head.rs @@ -1385,6 +1385,15 @@ fn observe_head_block_delays( .as_millis() as i64, ); + // The time it took to check the validity within Lighthouse + metrics::set_gauge( + &metrics::BEACON_BLOCK_DELAY_CONSENSUS_VERIFICATION_TIME, + block_delays + .consensus_verification_time + .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, @@ -1447,6 +1456,7 @@ fn observe_head_block_delays( "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), + "consensus_time_ms" => format_delay(&block_delays.consensus_verification_time), "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), @@ -1463,6 +1473,7 @@ fn observe_head_block_delays( "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), + "consensus_time_ms" => format_delay(&block_delays.consensus_verification_time), "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), diff --git a/beacon_node/beacon_chain/src/metrics.rs b/beacon_node/beacon_chain/src/metrics.rs index be8f46f7d1b..064b2b199ff 100644 --- a/beacon_node/beacon_chain/src/metrics.rs +++ b/beacon_node/beacon_chain/src/metrics.rs @@ -857,6 +857,11 @@ lazy_static! { "Duration between the start of the block's slot and the time the block was observed.", ); + pub static ref BEACON_BLOCK_DELAY_CONSENSUS_VERIFICATION_TIME: Result = try_create_int_gauge( + "beacon_block_delay_consensus_verification_time", + "The time taken to verify the block within Lighthouse", + ); + 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.",