Add timing for block availability

beacon_node/beacon_chain/src/beacon_chain.rs

@@ -2955,7 +2955,7 @@ impl<T: BeaconChainTypes> BeaconChain<T> {
     }
 
     /// 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<B: IntoExecutionPendingBlock<T>>(
         self: &Arc<Self>,
         block_root: Hash256,
@@ -2998,22 +2998,20 @@ impl<T: BeaconChainTypes> BeaconChain<T> {
         // 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<T: BeaconChainTypes> BeaconChain<T> {
         }
     }
 
-    /// 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<T: BeaconChainTypes> BeaconChain<T> {
             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<T: BeaconChainTypes> BeaconChain<T> {
                                 "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!(

beacon_node/beacon_chain/src/block_times_cache.rs

@@ -18,15 +18,27 @@ type BlockRoot = Hash256;
 #[derive(Clone, Default)]
 pub struct Timestamps {
     pub observed: Option<Duration>,
+    pub available: Option<Duration>,
+    pub attestable: Option<Duration>,
     pub imported: Option<Duration>,
     pub set_as_head: Option<Duration>,
 }
 
 // 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<Duration>,
+    /// Time after `observable`.
+    pub available: Option<Duration>,
+    /// Time after `available`.
+    pub attestable: Option<Duration>,
+    /// 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<Duration>,
+    /// Time after `imported`.
     pub set_as_head: Option<Duration>,
 }
 
@@ -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

beacon_node/beacon_chain/src/block_verification.rs

@@ -666,8 +666,7 @@ type PayloadVerificationHandle<E> =
 /// - 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

beacon_node/beacon_chain/src/canonical_head.rs

@@ -1437,6 +1437,9 @@ fn observe_head_block_delays<E: EthSpec, S: SlotClock>(
 
         // 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<Duration>| {
+            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<E: EthSpec, S: SlotClock>(
                 "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),
             );
         }
     }

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<T: BeaconChainTypes> DataAvailabilityChecker<T> {
             .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<T: BeaconChainTypes> DataAvailabilityChecker<T> {
         &self,
         gossip_blob: GossipVerifiedBlob<T>,
     ) -> Result<Availability<T::EthSpec>, 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<T: BeaconChainTypes> DataAvailabilityChecker<T> {
         executed_block: AvailabilityPendingExecutedBlock<T::EthSpec>,
     ) -> Result<Availability<T::EthSpec>, 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<T: BeaconChainTypes> DataAvailabilityChecker<T> {
                 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<T: BeaconChainTypes> DataAvailabilityChecker<T> {
                 } 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<T: BeaconChainTypes> DataAvailabilityChecker<T> {
                     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<T: BeaconChainTypes> DataAvailabilityChecker<T> {
                         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<E: EthSpec> {
     block_root: Hash256,
     block: Arc<SignedBeaconBlock<E>>,
     blobs: Option<BlobSidecarList<E>>,
+    /// Timestamp at which this block first became available (UNIX timestamp, time since 1970).
+    available_timestamp: Duration,
 }
 
 impl<E: EthSpec> AvailableBlock<E> {
@@ -555,6 +581,7 @@ impl<E: EthSpec> AvailableBlock<E> {
             block_root,
             block,
             blobs,
+            available_timestamp: Duration::from_millis(0),
         }
     }
 
@@ -569,6 +596,10 @@ impl<E: EthSpec> AvailableBlock<E> {
         self.blobs.as_ref()
     }
 
+    pub fn available_timestamp(&self) -> Duration {
+        self.available_timestamp
+    }
+
     pub fn deconstruct(
         self,
     ) -> (
@@ -580,6 +611,7 @@ impl<E: EthSpec> AvailableBlock<E> {
             block_root,
             block,
             blobs,
+            available_timestamp: _,
         } = self;
         (block_root, block, blobs)
     }

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 { .. }