Merge pull request #38 from lambdaclass/add-timers

Add timers to benchmark feature

replay/src/benchmark.rs

@@ -1,3 +1,5 @@
+use std::time::Instant;
+
 use blockifier::{
     context::BlockContext,
     state::{cached_state::CachedState, state_api::StateReader},
@@ -11,7 +13,7 @@ use starknet_api::{
     hash::StarkFelt,
     transaction::{Transaction as SNTransaction, TransactionHash},
 };
-use tracing::{error, info};
+use tracing::{error, info, info_span};
 
 pub type BlockCachedData = (
     CachedState<OptionalStateReader<RpcStateReader>>,
@@ -77,23 +79,37 @@ pub fn fetch_block_range_data(
 pub fn execute_block_range(block_range_data: &mut Vec<BlockCachedData>) {
     for (state, block_context, transactions) in block_range_data {
         // For each block
+        let _block_span = info_span!(
+            "block execution",
+            block_number = block_context.block_info().block_number.0,
+        )
+        .entered();
+        info!("starting block execution");
 
         // The transactional state is used to execute a transaction while discarding state changes applied to it.
         let mut transactional_state = CachedState::create_transactional(state);
 
         for (transaction_hash, transaction) in transactions {
             // Execute each transaction
+            let _tx_span = info_span!(
+                "tx execution",
+                transaction_hash = transaction_hash.to_string(),
+            )
+            .entered();
+            info!("starting tx execution");
+
+            let pre_execution_instant = Instant::now();
             let result = execute_tx_with_blockifier(
                 &mut transactional_state,
                 block_context.clone(),
                 transaction.to_owned(),
                 transaction_hash.to_owned(),
             );
+            let execution_time = pre_execution_instant.elapsed();
 
             match result {
                 Ok(info) => {
                     info!(
-                        transaction_hash = transaction_hash.to_string(),
                         succeeded = info.revert_error.is_none(),
                         "tx execution status"
                     )
@@ -103,6 +119,8 @@ pub fn execute_block_range(block_range_data: &mut Vec<BlockCachedData>) {
                     "tx execution failed"
                 ),
             }
+
+            info!(time = ?execution_time, "finished tx execution");
         }
     }
 }

replay/src/main.rs

@@ -117,24 +117,29 @@ fn main() {
             let block_end = BlockNumber(block_end);
             let chain = parse_network(&chain);
 
-            info!("fetching block range data");
-            let mut block_range_data = fetch_block_range_data(block_start, block_end, chain);
+            let mut block_range_data = {
+                let _caching_span = info_span!("caching block range").entered();
 
-            // We must execute the block range once first to ensure that all data required by blockifier is chached
-            info!("filling up execution cache");
-            execute_block_range(&mut block_range_data);
+                info!("fetching block range data");
+                let mut block_range_data = fetch_block_range_data(block_start, block_end, chain);
 
-            // Benchmark run should make no api requests as all data is cached
-            // To ensure this, we disable the inner StateReader
-            for (cached_state, ..) in &mut block_range_data {
-                cached_state.state.disable();
-            }
+                // We must execute the block range once first to ensure that all data required by blockifier is chached
+                info!("filling up execution cache");
+                execute_block_range(&mut block_range_data);
+
+                // Benchmark run should make no api requests as all data is cached
+                // To ensure this, we disable the inner StateReader
+                for (cached_state, ..) in &mut block_range_data {
+                    cached_state.state.disable();
+                }
+
+                block_range_data
+            };
 
             {
+                let _benchmark_span = info_span!("benchmarking block range").entered();
                 let before_execution = Instant::now();
 
-                info!("replaying with cached state");
-
                 for _ in 0..number_of_runs {
                     execute_block_range(&mut block_range_data);
                 }
@@ -238,15 +243,20 @@ fn get_transaction_hashes(network: &str, block_number: u64) -> Result<Vec<String
 fn set_global_subscriber() {
     let default_directive = Directive::from_str("replay=info").expect("should be valid");
 
-    tracing_subscriber::fmt()
+    let subscriber = tracing_subscriber::fmt()
         .with_env_filter({
             EnvFilter::builder()
                 .with_default_directive(default_directive)
                 .from_env_lossy()
         })
-        .pretty()
         .with_file(false)
-        .with_line_number(false)
-        .finish()
-        .init();
+        .with_line_number(false);
+
+    #[cfg(feature = "benchmark")]
+    let subscriber = subscriber.json();
+
+    #[cfg(not(feature = "benchmark"))]
+    let subscriber = subscriber.pretty();
+
+    subscriber.finish().init();
 }