feat: Enhance block import log line (#6095)

Signed-off-by: Danno Ferrin <danno.ferrin@gmail.com>

bin/reth/src/commands/node/events.rs

@@ -1,13 +1,14 @@
 //! Support for handling events emitted by node components.
 
-use crate::commands::node::cl_events::ConsensusLayerHealthEvent;
+use crate::{commands::node::cl_events::ConsensusLayerHealthEvent, primitives::B256};
 use futures::Stream;
-use reth_beacon_consensus::BeaconConsensusEngineEvent;
+use reth_beacon_consensus::{BeaconConsensusEngineEvent, ForkchoiceStatus};
 use reth_db::{database::Database, database_metrics::DatabaseMetadata};
 use reth_interfaces::consensus::ForkchoiceState;
 use reth_network::{NetworkEvent, NetworkHandle};
 use reth_network_api::PeersInfo;
 use reth_primitives::{
+    constants,
     stage::{EntitiesCheckpoint, StageCheckpoint, StageId},
     BlockNumber,
 };
@@ -18,7 +19,7 @@ use std::{
     future::Future,
     pin::Pin,
     task::{Context, Poll},
-    time::{Duration, Instant},
+    time::{Duration, Instant, SystemTime, UNIX_EPOCH},
 };
 use tokio::time::Interval;
 use tracing::{info, warn};
@@ -38,11 +39,28 @@ struct NodeState<DB> {
     current_stage: Option<CurrentStage>,
     /// The latest block reached by either pipeline or consensus engine.
     latest_block: Option<BlockNumber>,
+    /// The time of the latest block seen by the pipeline
+    latest_block_time: Option<u64>,
+    /// Hash of the head block last set by fork choice update
+    head_block_hash: Option<B256>,
+    /// Hash of the safe block last set by fork choice update
+    safe_block_hash: Option<B256>,
+    /// Hash of finalized block last set by fork choice update
+    finalized_block_hash: Option<B256>,
 }
 
 impl<DB> NodeState<DB> {
     fn new(db: DB, network: Option<NetworkHandle>, latest_block: Option<BlockNumber>) -> Self {
-        Self { db, network, current_stage: None, latest_block }
+        Self {
+            db,
+            network,
+            current_stage: None,
+            latest_block,
+            latest_block_time: None,
+            head_block_hash: None,
+            safe_block_hash: None,
+            finalized_block_hash: None,
+        }
     }
 
     fn num_connected_peers(&self) -> usize {
@@ -155,6 +173,10 @@ impl<DB> NodeState<DB> {
             BeaconConsensusEngineEvent::ForkchoiceUpdated(state, status) => {
                 let ForkchoiceState { head_block_hash, safe_block_hash, finalized_block_hash } =
                     state;
+                if status != ForkchoiceStatus::Valid ||
+                    (self.safe_block_hash != Some(safe_block_hash) &&
+                        self.finalized_block_hash != Some(finalized_block_hash))
+                {
                     info!(
                         ?head_block_hash,
                         ?safe_block_hash,
@@ -163,11 +185,28 @@ impl<DB> NodeState<DB> {
                         "Forkchoice updated"
                     );
                 }
-            BeaconConsensusEngineEvent::CanonicalBlockAdded(block) => {
-                info!(number=block.number, hash=?block.hash(), "Block added to canonical chain");
+                self.head_block_hash = Some(head_block_hash);
+                self.safe_block_hash = Some(safe_block_hash);
+                self.finalized_block_hash = Some(finalized_block_hash);
+            }
+            BeaconConsensusEngineEvent::CanonicalBlockAdded(block, elapsed) => {
+                info!(
+                    number=block.number,
+                    hash=?block.hash(),
+                    peers=self.num_connected_peers(),
+                    txs=block.body.len(),
+                    mgas=%format!("{:.3}", block.header.gas_used as f64 / constants::MGAS_TO_GAS as f64),
+                    full=%format!("{:.1}%", block.header.gas_used as f64 * 100.0 / block.header.gas_limit as f64),
+                    base_fee=%format!("{:.2}gwei", block.header.base_fee_per_gas.unwrap_or(0) as f64 / constants::GWEI_TO_WEI as f64),
+                    blobs=block.header.blob_gas_used.unwrap_or(0) / constants::eip4844::DATA_GAS_PER_BLOB,
+                    excess_blobs=block.header.excess_blob_gas.unwrap_or(0) / constants::eip4844::DATA_GAS_PER_BLOB,
+                    ?elapsed,
+                    "Block added to canonical chain"
+                );
             }
             BeaconConsensusEngineEvent::CanonicalChainCommitted(head, elapsed) => {
                 self.latest_block = Some(head.number);
+                self.latest_block_time = Some(head.timestamp);
 
                 info!(number=head.number, hash=?head.hash(), ?elapsed, "Canonical chain committed");
             }
@@ -357,6 +396,11 @@ where
                     );
                 }
             } else if let Some(latest_block) = this.state.latest_block {
+                let now =
+                    SystemTime::now().duration_since(UNIX_EPOCH).unwrap_or_default().as_secs();
+                if now - this.state.latest_block_time.unwrap_or(0) > 60 {
+                    // Once we start receiving consensus nodes, don't emit status unless stalled for
+                    // 1 minute
                     info!(
                         target: "reth::cli",
                         connected_peers = this.state.num_connected_peers(),
@@ -364,6 +408,7 @@ where
                         %latest_block,
                         "Status"
                     );
+                }
             } else {
                 info!(
                     target: "reth::cli",
@@ -415,7 +460,9 @@ struct Eta {
 impl Eta {
     /// Update the ETA given the checkpoint, if possible.
     fn update(&mut self, checkpoint: StageCheckpoint) {
-        let Some(current) = checkpoint.entities() else { return };
+        let Some(current) = checkpoint.entities() else {
+            return;
+        };
 
         if let Some(last_checkpoint_time) = &self.last_checkpoint_time {
             let processed_since_last = current.processed - self.last_checkpoint.processed;
@@ -456,7 +503,7 @@ impl Display for Eta {
                     f,
                     "{}",
                     humantime::format_duration(Duration::from_secs(remaining.as_secs()))
-                )
+                );
             }
         }
 

crates/consensus/beacon/src/engine/event.rs

@@ -6,11 +6,11 @@ use std::{sync::Arc, time::Duration};
 /// Events emitted by [crate::BeaconConsensusEngine].
 #[derive(Clone, Debug)]
 pub enum BeaconConsensusEngineEvent {
-    /// The fork choice state was updated.
+    /// The fork choice state was updated, and the current fork choice status
     ForkchoiceUpdated(ForkchoiceState, ForkchoiceStatus),
-    /// A block was added to the canonical chain.
-    CanonicalBlockAdded(Arc<SealedBlock>),
-    /// A canonical chain was committed.
+    /// A block was added to the canonical chain, and the elapsed time validating the block
+    CanonicalBlockAdded(Arc<SealedBlock>, Duration),
+    /// A canonical chain was committed, and the elapsed time committing the data
     CanonicalChainCommitted(Box<SealedHeader>, Duration),
     /// A block was added to the fork chain.
     ForkBlockAdded(Arc<SealedBlock>),

crates/consensus/beacon/src/engine/mod.rs

@@ -1271,16 +1271,18 @@ where
         debug_assert!(self.sync.is_pipeline_idle(), "pipeline must be idle");
 
         let block_hash = block.hash();
+        let start = Instant::now();
         let status = self
             .blockchain
             .insert_block_without_senders(block.clone(), BlockValidationKind::Exhaustive)?;
+        let elapsed = start.elapsed();
         let mut latest_valid_hash = None;
         let block = Arc::new(block);
         let status = match status {
             InsertPayloadOk::Inserted(BlockStatus::Valid(attachment)) => {
                 latest_valid_hash = Some(block_hash);
                 let event = if attachment.is_canonical() {
-                    BeaconConsensusEngineEvent::CanonicalBlockAdded(block)
+                    BeaconConsensusEngineEvent::CanonicalBlockAdded(block, elapsed)
                 } else {
                     BeaconConsensusEngineEvent::ForkBlockAdded(block)
                 };