feat: impl custom timer to track latency. add metrics for bundler pro… (

#910)

crates/builder/src/bundle_proposer.rs

@@ -25,6 +25,8 @@ use async_trait::async_trait;
 use futures::future;
 use futures_util::TryFutureExt;
 use linked_hash_map::LinkedHashMap;
+use metrics::Histogram;
+use metrics_derive::Metrics;
 #[cfg(test)]
 use mockall::automock;
 use rundler_provider::{
@@ -43,7 +45,7 @@ use rundler_types::{
     Timestamp, UserOperation, UserOperationVariant, UserOpsPerAggregator, ValidationRevert,
     BUNDLE_BYTE_OVERHEAD, TIME_RANGE_BUFFER, USER_OP_OFFSET_WORD_SIZE,
 };
-use rundler_utils::{emit::WithEntryPoint, math};
+use rundler_utils::{emit::WithEntryPoint, guard_timer::CustomTimerGuard, math};
 use tokio::{sync::broadcast, try_join};
 use tracing::{debug, error, info, warn};
 
@@ -141,6 +143,7 @@ pub(crate) struct BundleProposerImpl<EP, BP> {
     bundle_providers: BP,
     event_sender: broadcast::Sender<WithEntryPoint<BuilderEvent>>,
     condition_not_met_notified: bool,
+    metric: BuilderProposerMetric,
 }
 
 #[derive(Debug)]
@@ -183,6 +186,7 @@ where
         required_fees: Option<GasFees>,
         is_replacement: bool,
     ) -> BundleProposerResult<Bundle<Self::UO>> {
+        let _bundler_build_timer = CustomTimerGuard::new(self.metric.bundle_build_ms.clone());
         let (ops, (block_hash, _), (bundle_fees, base_fee)) = try_join!(
             self.get_ops_from_pool(),
             self.ep_providers
@@ -195,8 +199,6 @@ where
             return Err(BundleProposerError::NoOperationsInitially);
         }
 
-        debug!("Starting bundle proposal with {} ops", ops.len());
-
         // (0) Determine fees required for ops to be included in a bundle
         // if replacing, just require bundle fees increase chances of unsticking
         let required_op_fees = if is_replacement {
@@ -226,7 +228,6 @@ where
         } else {
             None
         };
-
         // (1) Filter out ops that don't pay enough to be included
         let fee_futs = ops
             .into_iter()
@@ -269,8 +270,10 @@ where
         let ops_with_simulations_future = future::join_all(simulation_futures);
         let balances_by_paymaster_future =
             self.get_balances_by_paymaster(all_paymaster_addresses, block_hash);
+
         let (ops_with_simulations, balances_by_paymaster) =
             tokio::join!(ops_with_simulations_future, balances_by_paymaster_future);
+
         let balances_by_paymaster = balances_by_paymaster?;
         let ops_with_simulations = ops_with_simulations
             .into_iter()
@@ -302,7 +305,6 @@ where
                 for op in context.iter_ops_with_simulations() {
                     expected_storage.merge(&op.simulation.expected_storage)?;
                 }
-
                 return Ok(Bundle {
                     ops_per_aggregator: context.to_ops_per_aggregator(),
                     gas_estimate,
@@ -314,6 +316,7 @@ where
             }
             info!("Bundle gas estimation failed. Retrying after removing rejected op(s).");
         }
+
         Ok(Bundle {
             rejected_ops: context.rejected_ops.iter().map(|po| po.0.clone()).collect(),
             entity_updates: context.entity_updates.into_values().collect(),
@@ -323,6 +326,15 @@ where
     }
 }
 
+#[derive(Metrics)]
+#[metrics(scope = "builder_proposer")]
+struct BuilderProposerMetric {
+    #[metric(describe = "the distribution of end to end bundle build time.")]
+    bundle_build_ms: Histogram,
+    #[metric(describe = "the distribution of op simulation time of a bundle.")]
+    op_simulation_ms: Histogram,
+}
+
 impl<EP, BP> BundleProposerImpl<EP, BP>
 where
     EP: ProvidersWithEntryPointT,
@@ -343,6 +355,7 @@ where
             settings,
             event_sender,
             condition_not_met_notified: false,
+            metric: BuilderProposerMetric::default(),
         }
     }
 
@@ -459,6 +472,8 @@ where
         op: PoolOperation,
         block_hash: B256,
     ) -> Option<(PoolOperation, Result<SimulationResult, SimulationError>)> {
+        let _timer_guard =
+            rundler_utils::guard_timer::CustomTimerGuard::new(self.metric.op_simulation_ms.clone());
         let op_hash = self.op_hash(&op.uo);
 
         // Simulate

crates/builder/src/bundle_sender.rs

@@ -18,7 +18,7 @@ use anyhow::{bail, Context};
 use async_trait::async_trait;
 use futures::Stream;
 use futures_util::StreamExt;
-use metrics::Counter;
+use metrics::{Counter, Histogram};
 use metrics_derive::Metrics;
 #[cfg(test)]
 use mockall::automock;
@@ -517,6 +517,9 @@ where
         fee_increase_count: u64,
     ) -> anyhow::Result<SendBundleAttemptResult> {
         let (nonce, required_fees) = state.transaction_tracker.get_nonce_and_required_fees()?;
+        let _timer_guard = rundler_utils::guard_timer::CustomTimerGuard::new(
+            self.metrics.bundle_build_time_ms.clone(),
+        );
 
         let bundle = match self
             .proposer
@@ -1196,6 +1199,8 @@ struct BuilderMetric {
     cancellation_txns_failed: Counter,
     #[metric(describe = "the count of state machine errors.")]
     state_machine_errors: Counter,
+    #[metric(describe = "the timespan a bundle is build.")]
+    bundle_build_time_ms: Histogram,
 }
 
 impl BuilderMetric {

crates/utils/Cargo.toml

@@ -13,6 +13,7 @@ anyhow.workspace = true
 derive_more = "0.99.18"
 futures.workspace = true
 itertools.workspace = true
+metrics.workspace = true
 rand.workspace = true
 schnellru = "0.2.1"
 tokio.workspace = true

crates/utils/src/guard_timer.rs

@@ -0,0 +1,48 @@
+// This file is part of Rundler.
+//
+// Rundler is free software: you can redistribute it and/or modify it under the
+// terms of the GNU Lesser General Public License as published by the Free Software
+// Foundation, either version 3 of the License, or (at your option) any later version.
+//
+// Rundler is distributed in the hope that it will be useful, but WITHOUT ANY WARRANTY;
+// without even the implied warranty of MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.
+// See the GNU General Public License for more details.
+//
+// You should have received a copy of the GNU General Public License along with Rundler.
+// If not, see https://www.gnu.org/licenses/.
+
+//! Utilities for track scoped method timer.
+
+use std::time::Instant;
+
+use metrics::Histogram;
+
+/// A customized guard to measure duration and record to metric.
+///
+/// exmaple usage:
+/// ```
+/// fn bala() {
+///   let _timer = CustomTimerGuard::new(metric);
+///   ...
+/// } // _timer will automatically dropped and record the duration.
+/// ```
+pub struct CustomTimerGuard {
+    timer: Instant,
+    metric: Histogram,
+}
+
+impl CustomTimerGuard {
+    /// initialzie instance.
+    pub fn new(metric: Histogram) -> Self {
+        Self {
+            timer: Instant::now(),
+            metric,
+        }
+    }
+}
+
+impl Drop for CustomTimerGuard {
+    fn drop(&mut self) {
+        self.metric.record(self.timer.elapsed().as_millis() as f64);
+    }
+}

crates/utils/src/lib.rs

@@ -23,6 +23,7 @@
 pub mod cache;
 pub mod emit;
 pub mod eth;
+pub mod guard_timer;
 pub mod log;
 pub mod math;
 pub mod retry;