From 3f57fc8cc9718440b16805480dc5156b1421463c Mon Sep 17 00:00:00 2001 From: Danno Ferrin Date: Fri, 9 Feb 2024 05:14:37 -0700 Subject: [PATCH] feat: Enhance block import log line (#6095) Signed-off-by: Danno Ferrin --- bin/reth/src/commands/node/events.rs | 91 ++++++++++++++++----- crates/consensus/beacon/src/engine/event.rs | 8 +- crates/consensus/beacon/src/engine/mod.rs | 4 +- 3 files changed, 76 insertions(+), 27 deletions(-) diff --git a/bin/reth/src/commands/node/events.rs b/bin/reth/src/commands/node/events.rs index c0f38f93a..e83c7772e 100644 --- a/bin/reth/src/commands/node/events.rs +++ b/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 { current_stage: Option, /// The latest block reached by either pipeline or consensus engine. latest_block: Option, + /// The time of the latest block seen by the pipeline + latest_block_time: Option, + /// Hash of the head block last set by fork choice update + head_block_hash: Option, + /// Hash of the safe block last set by fork choice update + safe_block_hash: Option, + /// Hash of finalized block last set by fork choice update + finalized_block_hash: Option, } impl NodeState { fn new(db: DB, network: Option, latest_block: Option) -> 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,19 +173,40 @@ impl NodeState { BeaconConsensusEngineEvent::ForkchoiceUpdated(state, status) => { let ForkchoiceState { head_block_hash, safe_block_hash, finalized_block_hash } = state; - info!( - ?head_block_hash, - ?safe_block_hash, - ?finalized_block_hash, - ?status, - "Forkchoice updated" - ); + 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, + ?finalized_block_hash, + ?status, + "Forkchoice updated" + ); + } + 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) => { - info!(number=block.number, hash=?block.hash(), "Block added to canonical chain"); + 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,13 +396,19 @@ where ); } } else if let Some(latest_block) = this.state.latest_block { - info!( - target: "reth::cli", - connected_peers = this.state.num_connected_peers(), - %freelist, - %latest_block, - "Status" - ); + 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(), + %freelist, + %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())) - ) + ); } } diff --git a/crates/consensus/beacon/src/engine/event.rs b/crates/consensus/beacon/src/engine/event.rs index 548d0797f..bf986c8ab 100644 --- a/crates/consensus/beacon/src/engine/event.rs +++ b/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), - /// A canonical chain was committed. + /// A block was added to the canonical chain, and the elapsed time validating the block + CanonicalBlockAdded(Arc, Duration), + /// A canonical chain was committed, and the elapsed time committing the data CanonicalChainCommitted(Box, Duration), /// A block was added to the fork chain. ForkBlockAdded(Arc), diff --git a/crates/consensus/beacon/src/engine/mod.rs b/crates/consensus/beacon/src/engine/mod.rs index 66deffee9..042202551 100644 --- a/crates/consensus/beacon/src/engine/mod.rs +++ b/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) };