feat: adding additional fine grained spans

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<Self, Self::Error> {
+        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::<Result<Vec<_>, _>>()?;
 
+        info!(
+            decoded_tx_count = transactions.len(),
+            "decoded payload attributes"
+        );
+
         Ok(Self {
             ethereum_attributes,
             transactions,
@@ -166,3 +181,49 @@ impl PayloadAttributesBuilder<EvolveEnginePayloadAttributes>
         }
     }
 }
+
+#[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"
+        );
+    }
+}

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<SealedBlock<ev_primitives::Block>, 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(),

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.

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<Self::Attributes, Self::BuiltPayload>,
     ) -> Result<BuildOutcome<Self::BuiltPayload>, 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<Self::Attributes, HeaderForPayload<Self::BuiltPayload>>,
     ) -> Result<Self::BuiltPayload, PayloadBuilderError> {
+        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::<EvPooledTransaction>::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"
+        );
+    }
 }

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);
+    }
+}

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: <Self as TransactionValidator>::Transaction,
     ) -> TransactionValidationOutcome<Self::Transaction> {
-        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<Box<dyn AccountInfoReader + Send>> = 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);