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