Measure consensus verification time (#6089)

* Measure consensus verification time

* Track execution time properly

beacon_node/beacon_chain/src/beacon_chain.rs

@@ -3088,14 +3088,21 @@ impl<T: BeaconChainTypes> BeaconChain<T> {
                 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 {

beacon_node/beacon_chain/src/block_times_cache.rs

@@ -19,7 +19,9 @@ type BlockRoot = Hash256;
 pub struct Timestamps {
     pub observed: Option<Duration>,
     pub all_blobs_observed: Option<Duration>,
-    pub execution_time: Option<Duration>,
+    pub consensus_verified: Option<Duration>,
+    pub started_execution: Option<Duration>,
+    pub executed: Option<Duration>,
     pub attestable: Option<Duration>,
     pub imported: Option<Duration>,
     pub set_as_head: Option<Duration>,
@@ -32,7 +34,9 @@ pub struct BlockDelays {
     pub observed: Option<Duration>,
     /// The time after the start of the slot we saw all blobs.
     pub all_blobs_observed: Option<Duration>,
-    /// 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<Duration>,
+    /// The time it took to complete execution verification of the block.
     pub execution_time: Option<Duration>,
     /// 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<Duration>,
+        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(

beacon_node/beacon_chain/src/block_verification.rs

@@ -1344,6 +1344,13 @@ impl<T: BeaconChainTypes> ExecutionPendingBlock<T> {
             // 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

beacon_node/beacon_chain/src/canonical_head.rs

@@ -1385,6 +1385,15 @@ fn observe_head_block_delays<E: EthSpec, S: SlotClock>(
                 .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<E: EthSpec, S: SlotClock>(
                 "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<E: EthSpec, S: SlotClock>(
                 "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),

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<IntGauge> = 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<IntGauge> = try_create_int_gauge(
         "beacon_block_delay_execution_time",
         "The duration in verifying the block with the execution layer.",