starknet_committer: add storage benchmark timing in commit_block

Author: TzahiTaub

crates/starknet_committer/src/block_committer/commit.rs

@@ -13,6 +13,7 @@ use crate::block_committer::input::{
     Input,
     StateDiff,
 };
+use crate::block_committer::timing_util::{Action, TimeMeasurement};
 use crate::forest::filled_forest::FilledForest;
 use crate::forest::original_skeleton_forest::{ForestSortedIndices, OriginalSkeletonForest};
 use crate::forest::updated_skeleton_forest::UpdatedSkeletonForest;
@@ -25,6 +26,7 @@ type BlockCommitmentResult<T> = Result<T, BlockCommitmentError>;
 pub async fn commit_block<S: Storage>(
     input: Input<ConfigImpl>,
     storage: &mut S,
+    #[cfg(feature = "benchmark")] time_measurement: &mut TimeMeasurement,
 ) -> BlockCommitmentResult<FilledForest> {
     let (mut storage_tries_indices, mut contracts_trie_indices, mut classes_trie_indices) =
         get_all_modified_indices(&input.state_diff);
@@ -38,6 +40,9 @@ pub async fn commit_block<S: Storage>(
     };
     let actual_storage_updates = input.state_diff.actual_storage_updates();
     let actual_classes_updates = input.state_diff.actual_classes_updates();
+    // Reads - fetch_nodes.
+    #[cfg(feature = "benchmark")]
+    time_measurement.start_measurement(Action::Read);
     let (mut original_forest, original_contracts_trie_leaves) = OriginalSkeletonForest::create(
         storage,
         input.contracts_trie_root_hash,
@@ -47,6 +52,9 @@ pub async fn commit_block<S: Storage>(
         &forest_sorted_indices,
         &input.config,
     )?;
+    let n_read_facts = original_forest.storage_tries.values().map(|trie| trie.nodes.len()).sum();
+    #[cfg(feature = "benchmark")]
+    time_measurement.stop_measurement(Some(n_read_facts), Action::Read);
     info!("Original skeleton forest created successfully.");
 
     if input.config.warn_on_trivial_modifications() {
@@ -57,6 +65,9 @@ pub async fn commit_block<S: Storage>(
         );
     }
 
+    // Compute the new topology.
+    #[cfg(feature = "benchmark")]
+    time_measurement.start_measurement(Action::Compute);
     let updated_forest = UpdatedSkeletonForest::create(
         &mut original_forest,
         &input.state_diff.skeleton_classes_updates(),
@@ -67,6 +78,7 @@ pub async fn commit_block<S: Storage>(
     )?;
     info!("Updated skeleton forest created successfully.");
 
+    // Compute the new hashes.
     let filled_forest = FilledForest::create::<TreeHashFunctionImpl>(
         updated_forest,
         actual_storage_updates,
@@ -76,6 +88,8 @@ pub async fn commit_block<S: Storage>(
         &input.state_diff.address_to_nonce,
     )
     .await?;
+    #[cfg(feature = "benchmark")]
+    time_measurement.stop_measurement(None, Action::Compute);
     info!("Filled forest created successfully.");
 
     Ok(filled_forest)

crates/starknet_committer/src/block_committer/timing_util.rs

@@ -3,50 +3,103 @@ use std::time::Instant;
 
 use csv::Writer;
 use tracing::info;
+
+use crate::block_committer::input::{ConfigImpl, Input};
+
+pub type InputImpl = Input<ConfigImpl>;
+
+#[derive(Debug, PartialEq, Eq)]
+pub enum Action {
+    Total,
+    Read,
+    Compute,
+    Write,
+}
+
 pub struct TimeMeasurement {
-    timer: Option<Instant>,
-    total_time: u128,             // Total duration of all blocks (milliseconds).
-    per_fact_durations: Vec<u64>, // Average duration (microseconds) per new fact in a block.
-    n_facts: Vec<usize>,
-    block_durations: Vec<u64>, // Duration of a block (milliseconds).
-    facts_in_db: Vec<usize>,   // Number of facts in the DB prior to the current block.
-    total_facts: usize,
+    pub block_timer: Option<Instant>,
+    pub read_timer: Option<Instant>,
+    pub compute_timer: Option<Instant>,
+    pub writer_timer: Option<Instant>,
+    pub total_time: u64, // Total duration of all blocks (milliseconds).
+    pub n_new_facts: Vec<usize>,
+    pub n_read_facts: Vec<usize>,
+    pub block_durations: Vec<u64>, // Duration of a block (milliseconds).
+    pub read_durations: Vec<u64>,  // Duration of a read (milliseconds).
+    pub compute_durations: Vec<u64>, // Duration of a compute (milliseconds).
+    pub write_durations: Vec<u64>, // Duration of a write (milliseconds).
+    pub facts_in_db: Vec<usize>,   // Number of facts in the DB prior to the current block.
+pub block_number: usize,
+    pub total_facts: usize,
 }
 
 impl TimeMeasurement {
-    pub fn new(n_iterations: usize) -> Self {
+    pub fn new(size: usize) -> Self {
         Self {
-            timer: None,
+block_timer: None,
+            read_timer: None,
+            compute_timer: None,
+            writer_timer: None,
             total_time: 0,
-            per_fact_durations: Vec::with_capacity(n_iterations),
-            n_facts: Vec::with_capacity(n_iterations),
-            block_durations: Vec::with_capacity(n_iterations),
-            facts_in_db: Vec::with_capacity(n_iterations),
+            n_new_facts: Vec::with_capacity(size),
+            n_read_facts: Vec::with_capacity(size),
+            read_durations: Vec::with_capacity(size),
+            compute_durations: Vec::with_capacity(size),
+            write_durations: Vec::with_capacity(size),
+            block_durations: Vec::with_capacity(size),
+            facts_in_db: Vec::with_capacity(size),
+            block_number: 0,
             total_facts: 0,
         }
     }
 
-    pub fn start_measurement(&mut self) {
-        self.timer = Some(Instant::now());
+    fn get_mut_timer(&mut self, action: &Action) -> &mut Option<Instant> {
+        match action {
+            Action::Total => &mut self.block_timer,
+            Action::Read => &mut self.read_timer,
+            Action::Compute => &mut self.compute_timer,
+            Action::Write => &mut self.writer_timer,
+        }
     }
 
-    pub fn stop_measurement(&mut self, facts_count: usize) {
-        let duration =
-            self.timer.expect("stop_measurement called before start_measurement").elapsed();
+    pub fn start_measurement(&mut self, action: Action) {
+        *self.get_mut_timer(&action) = Some(Instant::now());
+    }
+
+    /// Stop the measurement for the given action and add the duration to the corresponding vector.
+    /// facts_count is either the number of facts read from the DB for Read action, or the number of
+    /// new facts written to the DB for the Total action.
+    pub fn stop_measurement(&mut self, facts_count: Option<usize>, action: Action) {
+        let duration = self
+            .get_mut_timer(&action)
+            .expect("stop_measurement called before start_measurement")
+            .elapsed();
         info!(
             "Time elapsed for iteration {}: {} milliseconds",
             self.n_results(),
             duration.as_millis()
         );
-        let millis = duration.as_millis();
+        let millis: u64 = duration.as_millis().try_into().unwrap();
+        match action {
+            Action::Total => {
+                self.block_durations.push(millis);
         self.total_time += millis;
-        #[allow(clippy::as_conversions)]
-        self.per_fact_durations
-            .push(duration.div_f32(facts_count as f32).as_micros().try_into().unwrap());
-        self.block_durations.push(millis.try_into().unwrap());
-        self.n_facts.push(facts_count);
+                self.n_new_facts.push(facts_count.unwrap());
         self.facts_in_db.push(self.total_facts);
-        self.total_facts += facts_count;
+                self.total_facts += facts_count.unwrap();
+                self.block_number += 1;
+            }
+            Action::Read => {
+                self.read_durations.push(millis);
+                self.n_read_facts.push(facts_count.unwrap());
+            }
+            Action::Compute => {
+                self.compute_durations.push(millis);
+            }
+            Action::Write => {
+                self.write_durations.push(millis);
+            }
+        }
     }
 
     pub fn n_results(&self) -> usize {
@@ -72,7 +125,7 @@ impl TimeMeasurement {
             let sum: u64 =
                 self.block_durations[window_start..window_start + window_size].iter().sum();
             let sum_of_facts: usize =
-                self.n_facts[window_start..window_start + window_size].iter().sum();
+                self.n_new_facts[window_start..window_start + window_size].iter().sum();
             #[allow(clippy::as_conversions)]
             averages.push(1000.0 * sum as f64 / sum_of_facts as f64);
         }
@@ -116,26 +169,26 @@ impl TimeMeasurement {
         let mut wtr = Writer::from_writer(file);
         wtr.write_record([
             "block_number",
-            "n_facts",
-            "facts_in_db",
-            "time_per_fact_micros",
+            "n_new_facts",
+            "n_read_facts",
+            "initial_facts_in_db",
             "block_duration_millis",
+            "read_duration_millis",
+            "compute_duration_millis",
+            "write_duration_millis",
         ])
         .expect("Failed to write CSV header.");
-        for (i, (((&per_fact, &n_facts), &duration), &facts_in_db)) in self
-            .per_fact_durations
-            .iter()
-            .zip(self.n_facts.iter())
-            .zip(self.block_durations.iter())
-            .zip(self.facts_in_db.iter())
-            .enumerate()
-        {
+        let n_results = self.n_results();
+        for i in 0..n_results {
             wtr.write_record(&[
-                i.to_string(),
-                n_facts.to_string(),
-                facts_in_db.to_string(),
-                per_fact.to_string(),
-                duration.to_string(),
+                (self.block_number - n_results + i).to_string(),
+                self.n_new_facts[i].to_string(),
+                self.n_read_facts[i].to_string(),
+                self.facts_in_db[i].to_string(),
+                self.block_durations[i].to_string(),
+                self.read_durations[i].to_string(),
+                self.compute_durations[i].to_string(),
+                self.write_durations[i].to_string(),
             ])
             .expect("Failed to write CSV record.");
         }

crates/starknet_committer_cli/src/commands.rs

@@ -3,7 +3,7 @@ use rand::SeedableRng;
 use starknet_committer::block_committer::commit::commit_block;
 use starknet_committer::block_committer::input::{ConfigImpl, Input};
 use starknet_committer::block_committer::state_diff_generator::generate_random_state_diff;
-use starknet_committer::block_committer::timing_util::TimeMeasurement;
+use starknet_committer::block_committer::timing_util::{Action, TimeMeasurement};
 use starknet_patricia::hash::hash_trait::HashOutput;
 use starknet_patricia_storage::map_storage::MapStorage;
 use tracing::info;
@@ -30,13 +30,15 @@ pub async fn run_storage_benchmark(seed: u64, n_iterations: usize, output_dir: &
             config: ConfigImpl::default(),
         };
 
-        time_measurement.start_measurement();
-        let filled_forest =
-            commit_block(input, &mut storage).await.expect("Failed to commit the given block.");
-        // TODO(Tzahi): measure the computation above and the fact writing below separately.
+        time_measurement.start_measurement(Action::Total);
+        let filled_forest = commit_block(input, &mut storage, &mut time_measurement)
+            .await
+            .expect("Failed to commit the given block.");
+        time_measurement.start_measurement(Action::Write);
         let n_new_facts = filled_forest.write_to_storage(&mut storage);
+        time_measurement.stop_measurement(None, Action::Write);
 
-        time_measurement.stop_measurement(n_new_facts);
+        time_measurement.stop_measurement(Some(n_new_facts), Action::Total);
 
         contracts_trie_root_hash = filled_forest.get_contract_root_hash();
         classes_trie_root_hash = filled_forest.get_compiled_class_root_hash();