feat: add granular prewarm metrics (#14282)

crates/engine/tree/src/tree/metrics.rs

@@ -16,6 +16,8 @@ pub(crate) struct EngineApiMetrics {
     pub(crate) block_validation: BlockValidationMetrics,
     /// A copy of legacy blockchain tree metrics, to be replaced when we replace the old tree
     pub(crate) tree: TreeMetrics,
+    /// Metrics for transaction prewarming threads
+    pub(crate) prewarm: PrewarmThreadMetrics,
 }
 
 /// Metrics for the entire blockchain tree
@@ -69,8 +71,6 @@ pub(crate) struct BlockValidationMetrics {
     pub(crate) state_root_duration: Gauge,
     /// Trie input computation duration
     pub(crate) trie_input_duration: Gauge,
-    /// Prewarm spawn duration
-    pub(crate) prewarm_spawn_duration: Gauge,
     /// Cache saving duration
     pub(crate) cache_saving_duration: Gauge,
     /// State root config creation duration
@@ -87,6 +87,26 @@ impl BlockValidationMetrics {
     }
 }
 
+/// Metrics for prewarming threads
+#[derive(Metrics, Clone)]
+#[metrics(scope = "sync.prewarm")]
+pub(crate) struct PrewarmThreadMetrics {
+    /// Prewarm thread spawn duration
+    pub(crate) spawn_duration: Gauge,
+    /// A histogram of the prewarm thread spawn duration
+    pub(crate) spawn_duration_histogram: Histogram,
+    /// The number of transactions in the block
+    pub(crate) transactions: Gauge,
+    /// A histogram of the number of transactions in the block
+    pub(crate) transactions_histogram: Histogram,
+    /// A histogram of total runtime durations for prewarm threads
+    pub(crate) total_runtime: Histogram,
+    /// A histogram of execution durations for prewarm threads
+    pub(crate) execution_duration: Histogram,
+    /// A histogram for total prefetch targets in prewarm threads
+    pub(crate) prefetch_storage_targets: Histogram,
+}
+
 /// Metrics for the blockchain tree block buffer
 #[derive(Metrics)]
 #[metrics(scope = "blockchain_tree.block_buffer")]

crates/engine/tree/src/tree/mod.rs

@@ -20,6 +20,7 @@ use alloy_rpc_types_engine::{
 };
 use cached_state::{ProviderCaches, SavedCache};
 use error::{InsertBlockError, InsertBlockErrorKind, InsertBlockFatalError};
+use metrics::PrewarmThreadMetrics;
 use persistence_state::CurrentPersistenceAction;
 use reth_chain_state::{
     CanonicalInMemoryState, ExecutedBlock, ExecutedBlockWithTrieUpdates,
@@ -2485,6 +2486,7 @@ where
         if self.config.use_caching_and_prewarming() {
             debug!(target: "engine::tree", "Spawning prewarm threads");
             let prewarm_start = Instant::now();
+            let prewarm_metrics = self.metrics.prewarm.clone();
 
             // Prewarm transactions
             for (tx_idx, tx) in block.transactions_recovered().enumerate() {
@@ -2499,16 +2501,21 @@ where
                     state_root_sender,
                     cancel_execution.clone(),
                     prewarm_task_lock.clone(),
+                    prewarm_metrics.clone(),
                 )?;
                 let elapsed = start.elapsed();
                 debug!(target: "engine::tree", ?tx_idx, elapsed = ?elapsed, "Spawned transaction prewarm");
             }
 
+            prewarm_metrics.transactions.set(block.transaction_count() as f64);
+            prewarm_metrics.transactions_histogram.record(block.transaction_count() as f64);
+
             drop(state_root_sender);
             let elapsed = prewarm_start.elapsed();
             debug!(target: "engine::tree", ?elapsed, "Done spawning prewarm threads");
 
-            self.metrics.block_validation.prewarm_spawn_duration.set(elapsed.as_secs_f64());
+            self.metrics.prewarm.spawn_duration.set(elapsed);
+            self.metrics.prewarm.spawn_duration_histogram.record(elapsed);
         }
         trace!(target: "engine::tree", block=?block_num_hash, "Executing block");
 
@@ -2711,6 +2718,7 @@ where
         state_root_sender: Option<Sender<StateRootMessage>>,
         cancel_execution: ManualCancel,
         task_finished: Arc<RwLock<()>>,
+        metrics: PrewarmThreadMetrics,
     ) -> Result<(), InsertBlockErrorKind> {
         // Get the builder once, outside the thread
         let Some(state_provider_builder) = self.state_provider_builder(block.parent_hash())? else {
@@ -2723,6 +2731,7 @@ where
 
         // spawn task executing the individual tx
         self.thread_pool.spawn(move || {
+            let thread_start = Instant::now();
             let in_progress = task_finished.read().unwrap();
 
             // Create the state provider inside the thread
@@ -2755,13 +2764,15 @@ where
                 return
             }
 
+            let execution_start = Instant::now();
             let ResultAndState { state, .. } = match evm.transact(tx_env) {
                 Ok(res) => res,
                 Err(err) => {
                     trace!(target: "engine::tree", %err, tx_hash=%tx.tx_hash(), sender=%tx.signer(), "Error when executing prewarm transaction");
                     return
                 }
             };
+            metrics.execution_duration.record(execution_start.elapsed());
 
             // execution no longer in progress, so we can drop the lock
             drop(in_progress);
@@ -2795,15 +2806,20 @@ where
                 targets.insert(keccak256(addr), storage_set);
             }
 
+            let storage_targets = targets.values().map(|slots| slots.len()).sum::<usize>();
             debug!(
                 target: "engine::tree",
                 tx_hash = ?tx.tx_hash(),
                 targets = targets.len(),
-                storage_targets = targets.values().map(|slots| slots.len()).sum::<usize>(),
+                storage_targets,
                 "Prefetching proofs for a transaction"
             );
+            metrics.prefetch_storage_targets.record(storage_targets as f64);
 
             let _ = state_root_sender.send(StateRootMessage::PrefetchProofs(targets));
+
+            // record final metrics
+            metrics.total_runtime.record(thread_start.elapsed());
         });
 
         Ok(())