diff --git a/crates/node/src/attributes.rs b/crates/node/src/attributes.rs index 30531b6..06bbd86 100644 --- a/crates/node/src/attributes.rs +++ b/crates/node/src/attributes.rs @@ -13,6 +13,9 @@ use reth_payload_primitives::PayloadAttributesBuilder; use reth_primitives_traits::SealedHeader; use serde::{Deserialize, Serialize}; +use crate::tracing_ext::RecordDurationOnDrop; +use tracing::{info, instrument}; + use crate::error::EvolveEngineError; use ev_primitives::TransactionSigned; @@ -68,11 +71,18 @@ impl PayloadBuilderAttributes for EvolveEnginePayloadBuilderAttributes { type RpcPayloadAttributes = EvolveEnginePayloadAttributes; type Error = EvolveEngineError; + #[instrument(skip(parent, attributes, _version), fields( + parent_hash = %parent, + raw_tx_count = attributes.transactions.as_ref().map_or(0, |t| t.len()), + gas_limit = ?attributes.gas_limit, + duration_ms = tracing::field::Empty, + ))] fn try_new( parent: B256, attributes: EvolveEnginePayloadAttributes, _version: u8, ) -> Result { + let _duration = RecordDurationOnDrop::new(); let ethereum_attributes = EthPayloadBuilderAttributes::new(parent, attributes.inner); // Decode transactions from bytes if provided. @@ -86,6 +96,11 @@ impl PayloadBuilderAttributes for EvolveEnginePayloadBuilderAttributes { }) .collect::, _>>()?; + info!( + decoded_tx_count = transactions.len(), + "decoded payload attributes" + ); + Ok(Self { ethereum_attributes, transactions, @@ -166,3 +181,49 @@ impl PayloadAttributesBuilder } } } + +#[cfg(test)] +mod tests { + use super::*; + use crate::test_utils::SpanCollector; + + #[test] + fn try_new_span_has_expected_fields() { + let collector = SpanCollector::new(); + let _guard = collector.as_default(); + + let parent = B256::random(); + let attrs = EvolveEnginePayloadAttributes { + inner: RpcPayloadAttributes { + timestamp: 1710338136, + prev_randao: B256::random(), + suggested_fee_recipient: Address::random(), + withdrawals: Some(vec![]), + parent_beacon_block_root: Some(B256::ZERO), + }, + transactions: Some(vec![]), + gas_limit: Some(30_000_000), + }; + + // we only care that the span was created with the right fields. + let _ = EvolveEnginePayloadBuilderAttributes::try_new(parent, attrs, 3); + + let span = collector + .find_span("try_new") + .expect("try_new span should be recorded"); + + assert!( + span.has_field("parent_hash"), + "span missing parent_hash field" + ); + assert!( + span.has_field("raw_tx_count"), + "span missing raw_tx_count field" + ); + assert!(span.has_field("gas_limit"), "span missing gas_limit field"); + assert!( + span.has_field("duration_ms"), + "span missing duration_ms field" + ); + } +} diff --git a/crates/node/src/builder.rs b/crates/node/src/builder.rs index e25257a..139e5f6 100644 --- a/crates/node/src/builder.rs +++ b/crates/node/src/builder.rs @@ -1,4 +1,6 @@ -use crate::{config::EvolvePayloadBuilderConfig, executor::EvEvmConfig}; +use crate::{ + config::EvolvePayloadBuilderConfig, executor::EvEvmConfig, tracing_ext::RecordDurationOnDrop, +}; use alloy_consensus::transaction::{Transaction, TxHashRef}; use alloy_primitives::Address; use ev_revm::EvTxEvmFactory; @@ -72,7 +74,7 @@ where &self, attributes: EvolvePayloadAttributes, ) -> Result, PayloadBuilderError> { - let _start = std::time::Instant::now(); + let _duration = RecordDurationOnDrop::new(); // Validate attributes attributes @@ -185,8 +187,6 @@ where let sealed_block = block.sealed_block().clone(); - tracing::Span::current().record("duration_ms", _start.elapsed().as_millis() as u64); - info!( block_number = sealed_block.number, block_hash = ?sealed_block.hash(), diff --git a/crates/node/src/lib.rs b/crates/node/src/lib.rs index aee43b8..3007acd 100644 --- a/crates/node/src/lib.rs +++ b/crates/node/src/lib.rs @@ -29,6 +29,8 @@ pub mod payload_service; pub mod payload_types; /// RPC wiring for EvTxEnvelope support. pub mod rpc; +/// Drop guard for recording `duration_ms` on tracing spans. +pub(crate) mod tracing_ext; /// Transaction pool wiring and validation. pub mod txpool; /// Payload validator integration. diff --git a/crates/node/src/payload_service.rs b/crates/node/src/payload_service.rs index dc2e8de..09e6186 100644 --- a/crates/node/src/payload_service.rs +++ b/crates/node/src/payload_service.rs @@ -1,5 +1,6 @@ use std::sync::Arc; +use crate::tracing_ext::RecordDurationOnDrop; use alloy_primitives::{Address, U256}; use evolve_ev_reth::EvolvePayloadAttributes; use eyre::WrapErr; @@ -145,7 +146,7 @@ where &self, args: BuildArguments, ) -> Result, PayloadBuilderError> { - let _start = std::time::Instant::now(); + let _duration = RecordDurationOnDrop::new(); let BuildArguments { cached_reads: _, config, @@ -233,24 +234,27 @@ where None, // No blob sidecar for evolve. ); - tracing::Span::current().record("duration_ms", _start.elapsed().as_millis() as u64); - Ok(BuildOutcome::Better { payload: built_payload, cached_reads: CachedReads::default(), }) } + #[instrument(skip(self, config), fields( + payload_id = %config.attributes.payload_id(), + duration_ms = tracing::field::Empty, + ))] fn build_empty_payload( &self, config: PayloadConfig>, ) -> Result { + let _duration = RecordDurationOnDrop::new(); let PayloadConfig { parent_header, attributes, } = config; - info!("Evolve engine payload builder: building empty payload"); + info!("building empty payload"); // Create empty evolve attributes (no transactions). // If no gas_limit provided, default to the parent header's gas limit (genesis for first block). @@ -416,4 +420,87 @@ mod tests { "span missing duration_ms field" ); } + + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn build_empty_payload_span_has_expected_fields() { + let collector = SpanCollector::new(); + let _guard = collector.as_default(); + + let genesis: alloy_genesis::Genesis = + serde_json::from_str(include_str!("../../tests/assets/genesis.json")) + .expect("valid genesis"); + let chain_spec = Arc::new( + ChainSpecBuilder::default() + .chain(reth_chainspec::Chain::from_id(1234)) + .genesis(genesis) + .cancun_activated() + .build(), + ); + + let provider = MockEthProvider::default(); + let genesis_hash = B256::from_slice( + &hex::decode("2b8bbb1ea1e04f9c9809b4b278a8687806edc061a356c7dbc491930d8e922503") + .unwrap(), + ); + let genesis_state_root = B256::from_slice( + &hex::decode("05e9954443da80d86f2104e56ffdfd98fe21988730684360104865b3dc8191b4") + .unwrap(), + ); + + let genesis_header = Header { + state_root: genesis_state_root, + number: 0, + gas_limit: 30_000_000, + timestamp: 1710338135, + base_fee_per_gas: Some(0), + excess_blob_gas: Some(0), + blob_gas_used: Some(0), + parent_beacon_block_root: Some(B256::ZERO), + ..Default::default() + }; + provider.add_header(genesis_hash, genesis_header.clone()); + + let config = EvolvePayloadBuilderConfig::from_chain_spec(chain_spec.as_ref()).unwrap(); + let evm_config = EvolveEvmConfig::new(chain_spec); + let evolve_builder = Arc::new(EvolvePayloadBuilder::new( + Arc::new(provider), + evm_config, + config.clone(), + )); + + let engine_builder = EvolveEnginePayloadBuilder { + evolve_builder, + config, + pool: NoopTransactionPool::::new(), + }; + + let rpc_attrs = RpcPayloadAttributes { + timestamp: 1710338136, + prev_randao: B256::random(), + suggested_fee_recipient: Address::random(), + withdrawals: Some(vec![]), + parent_beacon_block_root: Some(B256::ZERO), + }; + let eth_attrs = EthPayloadBuilderAttributes::new(genesis_hash, rpc_attrs); + let builder_attrs = EvolveEnginePayloadBuilderAttributes::from(eth_attrs); + + let sealed_parent = SealedHeader::new(genesis_header, genesis_hash); + let payload_config = PayloadConfig::new(Arc::new(sealed_parent), builder_attrs); + + // we only care that the span was created with the right fields. + let _ = engine_builder.build_empty_payload(payload_config); + + let span = collector + .find_span("build_empty_payload") + .expect("build_empty_payload span should be recorded"); + + assert!( + span.has_field("payload_id"), + "span missing payload_id field" + ); + assert!( + span.has_field("duration_ms"), + "span missing duration_ms field" + ); + } } diff --git a/crates/node/src/tracing_ext.rs b/crates/node/src/tracing_ext.rs new file mode 100644 index 0000000..9290b45 --- /dev/null +++ b/crates/node/src/tracing_ext.rs @@ -0,0 +1,15 @@ +/// records `duration_ms` on the current tracing span when dropped, +/// ensuring duration is captured even on early-return error paths. +pub(crate) struct RecordDurationOnDrop(std::time::Instant); + +impl RecordDurationOnDrop { + pub(crate) fn new() -> Self { + Self(std::time::Instant::now()) + } +} + +impl Drop for RecordDurationOnDrop { + fn drop(&mut self) { + tracing::Span::current().record("duration_ms", self.0.elapsed().as_millis() as u64); + } +} diff --git a/crates/node/src/txpool.rs b/crates/node/src/txpool.rs index 7d7eeb6..c9ebb45 100644 --- a/crates/node/src/txpool.rs +++ b/crates/node/src/txpool.rs @@ -1,5 +1,6 @@ use std::sync::Arc; +use crate::tracing_ext::RecordDurationOnDrop; use alloy_consensus::{ constants::EIP1559_TX_TYPE_ID, transaction::{Recovered, TxHashRef}, @@ -410,6 +411,11 @@ where /// Validates an `EvNode` transaction. Returns an optional override balance /// for sponsored transactions (the sponsor's balance), so the pool uses /// the sponsor's balance for pending/queued ordering instead of the executor's. + #[instrument(skip(self, pooled, sender_balance, state), fields( + tx_hash = %pooled.hash(), + is_evnode = matches!(pooled.transaction().inner(), EvTxEnvelope::EvNode(_)), + duration_ms = tracing::field::Empty, + ))] fn validate_evnode( &self, pooled: &EvPooledTransaction, @@ -419,6 +425,7 @@ where where Client: StateProviderFactory, { + let _duration = RecordDurationOnDrop::new(); // Unified deploy allowlist check (covers both Ethereum and EvNode txs). if let Some(settings) = &self.deploy_allowlist { let is_top_level_create = match pooled.transaction().inner() { @@ -502,7 +509,7 @@ where origin: TransactionOrigin, transaction: ::Transaction, ) -> TransactionValidationOutcome { - let _start = std::time::Instant::now(); + let _duration = RecordDurationOnDrop::new(); let mut state = None; let outcome = self .inner @@ -532,7 +539,6 @@ where other => other, }; - tracing::Span::current().record("duration_ms", _start.elapsed().as_millis() as u64); result } } @@ -904,6 +910,39 @@ mod tests { } } + #[test] + fn validate_evnode_span_has_expected_fields() { + use crate::test_utils::SpanCollector; + + let collector = SpanCollector::new(); + let _guard = collector.as_default(); + + let validator = create_test_validator(None); + + let gas_limit = 21_000u64; + let max_fee_per_gas = 1_000_000_000u128; + let signed_tx = create_non_sponsored_evnode_tx(gas_limit, max_fee_per_gas); + + let signer = Address::random(); + let pooled = create_pooled_tx(signed_tx, signer); + + let sender_balance = *pooled.cost() + U256::from(1); + let mut state: Option> = None; + + let _ = validator.validate_evnode(&pooled, sender_balance, &mut state); + + let span = collector + .find_span("validate_evnode") + .expect("validate_evnode span should be recorded"); + + assert!(span.has_field("tx_hash"), "span missing tx_hash field"); + assert!(span.has_field("is_evnode"), "span missing is_evnode field"); + assert!( + span.has_field("duration_ms"), + "span missing duration_ms field" + ); + } + #[test] fn evnode_create_allowed_when_allowlist_is_none() { let validator = create_test_validator(None); diff --git a/crates/node/src/validator.rs b/crates/node/src/validator.rs index c0bdf55..807f1c1 100644 --- a/crates/node/src/validator.rs +++ b/crates/node/src/validator.rs @@ -2,6 +2,7 @@ use std::sync::Arc; +use crate::tracing_ext::RecordDurationOnDrop; use alloy_consensus::Header; use alloy_eips::Decodable2718; use alloy_rpc_types::engine::ExecutionData; @@ -20,7 +21,7 @@ use reth_ethereum::{ }; use reth_ethereum_payload_builder::EthereumExecutionPayloadValidator; use reth_primitives_traits::{Block as _, RecoveredBlock, SealedBlock}; -use tracing::{debug, info, instrument}; +use tracing::{debug, info, instrument, Span}; use crate::{attributes::EvolveEnginePayloadAttributes, node::EvolveEngineTypes}; @@ -67,13 +68,11 @@ impl PayloadValidator for EvolveEngineValidator { &self, payload: ExecutionData, ) -> Result, NewPayloadError> { - let _start = std::time::Instant::now(); + let _duration = RecordDurationOnDrop::new(); // Use inner validator but with custom evolve handling. match self.inner.ensure_well_formed_payload(payload.clone()) { Ok(sealed_block) => { - let span = tracing::Span::current(); - span.record("block_hash", tracing::field::display(sealed_block.hash())); - span.record("duration_ms", _start.elapsed().as_millis() as u64); + Span::current().record("block_hash", tracing::field::display(sealed_block.hash())); info!("payload validation succeeded"); let ev_block = convert_sealed_block(sealed_block); ev_block @@ -100,9 +99,7 @@ impl PayloadValidator for EvolveEngineValidator { info!(error = ?err, "bypassing validation error for ev-reth"); // For evolve, we trust the payload builder - parse the block with EvNode support. let ev_block = parse_evolve_payload(payload)?; - let span = tracing::Span::current(); - span.record("block_hash", tracing::field::display(ev_block.hash())); - span.record("duration_ms", _start.elapsed().as_millis() as u64); + Span::current().record("block_hash", tracing::field::display(ev_block.hash())); ev_block .try_recover() .map_err(|e| NewPayloadError::Other(e.into())) @@ -133,9 +130,15 @@ fn convert_sealed_block( } /// Parses an execution payload containing `EvNode` transactions. +#[instrument(skip(payload), fields( + tx_count = payload.payload.transactions().len(), + block_number = payload.payload.block_number(), + duration_ms = tracing::field::Empty, +))] fn parse_evolve_payload( payload: ExecutionData, ) -> Result, NewPayloadError> { + let _duration = RecordDurationOnDrop::new(); let ExecutionData { payload, sidecar } = payload; // Parse transactions using EvTxEnvelope which supports both Ethereum and EvNode types. @@ -184,7 +187,8 @@ fn parse_evolve_payload( }; let block = EvBlock::new(header, body); - Ok(block.seal_slow()) + let sealed = block.seal_slow(); + Ok(sealed) } impl EngineApiValidator for EvolveEngineValidator { @@ -396,4 +400,64 @@ mod tests { "Should not match BlockHash error" ); } + + #[test] + fn parse_evolve_payload_span_has_expected_fields() { + use crate::test_utils::SpanCollector; + use alloy_primitives::{Address, Bloom, Bytes, B256, U256}; + use alloy_rpc_types::engine::{ + ExecutionData, ExecutionPayload, ExecutionPayloadSidecar, ExecutionPayloadV1, + ExecutionPayloadV2, ExecutionPayloadV3, + }; + + let collector = SpanCollector::new(); + let _guard = collector.as_default(); + + let v1 = ExecutionPayloadV1 { + parent_hash: B256::ZERO, + fee_recipient: Address::ZERO, + state_root: B256::ZERO, + receipts_root: B256::ZERO, + logs_bloom: Bloom::ZERO, + prev_randao: B256::ZERO, + block_number: 1, + gas_limit: 30_000_000, + gas_used: 0, + timestamp: 1710338136, + extra_data: Bytes::default(), + base_fee_per_gas: U256::ZERO, + block_hash: B256::ZERO, + transactions: vec![], + }; + let v2 = ExecutionPayloadV2 { + payload_inner: v1, + withdrawals: vec![], + }; + let v3 = ExecutionPayloadV3 { + payload_inner: v2, + blob_gas_used: 0, + excess_blob_gas: 0, + }; + + let payload = ExecutionPayload::V3(v3); + let sidecar = ExecutionPayloadSidecar::default(); + let execution_data = ExecutionData::new(payload, sidecar); + + // we only care that the span was created with the right fields. + let _ = parse_evolve_payload(execution_data); + + let span = collector + .find_span("parse_evolve_payload") + .expect("parse_evolve_payload span should be recorded"); + + assert!(span.has_field("tx_count"), "span missing tx_count field"); + assert!( + span.has_field("block_number"), + "span missing block_number field" + ); + assert!( + span.has_field("duration_ms"), + "span missing duration_ms field" + ); + } }