Load tracing and iteration benchmarks

bin/stress-test/Cargo.toml

@@ -29,5 +29,11 @@ rand             = { workspace = true }
 rayon            = { workspace = true }
 tokio            = { workspace = true }
 
+[features]
+# Renders spans as a timing tree on stdout, showing the per-phase breakdown of e.g. the
+# `load-state` benchmark. Opt-in because feature unification would otherwise switch the log
+# format of every binary in a workspace-wide build.
+tracing-forest = ["miden-node-utils/tracing-forest"]
+
 [dev-dependencies]
 tempfile = { workspace = true }

bin/stress-test/README.md

@@ -107,13 +107,35 @@ Latency measurements represent pure store processing time without network overhe
 
 #### load-state
 
+Measures full store startup (`State::load`) against the seeded data directory. `--load-iterations` (default 3) repeats
+the load; the first iteration may pay RocksDB WAL recovery and a cold OS page cache, while later iterations measure a
+clean warm restart.
+
 ```text
-State loaded in 42.959271667s
-Database contains 99961 accounts and 99960 nullifiers
+Iteration 0: state loaded in 38.623292ms
+Iteration 1: state loaded in 20.376417ms
+Iteration 2: state loaded in 17.526916ms
+...
+Database contains 52 accounts and 50 nullifiers
 ```
 
-Account tree loading (~21.3s) and nullifier tree loading (~21.5s) were the primary bottlenecks; MMR loading and database
-connection were negligible (<3ms each).
+Build with `--features tracing-forest` to render the per-phase breakdown of each load as a timing tree, including the
+RocksDB opens (`open_tree_storage`, `open_forest_storage`):
+
+```text
+INFO     load [ 36.1ms | 0.00% / 100.00% ]
+INFO     ┕━ load_with_database_options [ 36.1ms | 0.00% / 100.00% ]
+INFO        ┝━ load_with_pool_size [ 8.47ms | 23.48% ]
+INFO        ┝━ load_mmr [ 1.27ms | 3.52% ]
+INFO        ┝━ open_tree_storage [ 10.3ms | 28.68% ] path: "accounttree"
+INFO        ┝━ load_account_tree [ 2.19ms | 6.08% ]
+INFO        ┝━ open_tree_storage [ 6.38ms | 17.70% ] path: "nullifiertree"
+INFO        ┝━ load_nullifier_tree [ 822µs | 2.28% ]
+INFO        ┝━ verify_tree_consistency [ 68.0µs | 0.19% ]
+INFO        ┝━ open_forest_storage [ 5.98ms | 16.60% ] path: "accountstateforest"
+INFO        ┝━ load_account_state_forest [ 74.4µs | 0.21% ] block.number: 2
+INFO        ┕━ verify_account_state_forest_consistency [ 458µs | 1.27% ]
+```
 
 #### sync-notes
 

bin/stress-test/src/main.rs

@@ -148,7 +148,12 @@ pub enum Endpoint {
     #[command(name = "sync-chain-mmr")]
     SyncChainMmr,
     #[command(name = "load-state")]
-    LoadState,
+    LoadState {
+        /// Number of times to load the state. The first iteration may pay `RocksDB` WAL recovery
+        /// and a cold OS page cache; later iterations measure a clean warm restart.
+        #[arg(long, value_name = "LOAD_ITERATIONS", default_value = "3")]
+        load_iterations: NonZeroUsize,
+    },
     #[command(name = "get-account")]
     GetAccount {
         /// Storage slot name to request with all entries.
@@ -228,8 +233,8 @@ async fn main() {
             Endpoint::SyncChainMmr => {
                 bench_sync_chain_mmr(data_directory, iterations, concurrency).await;
             },
-            Endpoint::LoadState => {
-                load_state(&data_directory).await;
+            Endpoint::LoadState { load_iterations } => {
+                load_state(&data_directory, load_iterations.get()).await;
             },
             Endpoint::GetAccount { storage_map_slot } => {
                 bench_get_account(data_directory, iterations, concurrency, storage_map_slot).await;

bin/stress-test/src/store/mod.rs

@@ -696,12 +696,25 @@ fn transaction_record_to_proto(
 // LOAD STATE
 // ================================================================================================
 
-pub async fn load_state(data_directory: &Path) {
-    let start = Instant::now();
-    // The writer is never started: this bench only measures load time, and dropping the un-started
-    // state releases the tree storage the writer owns.
-    let _loaded = State::load(data_directory, StorageOptions::default()).await.unwrap();
-    let elapsed = start.elapsed();
+pub async fn load_state(data_directory: &Path, iterations: usize) {
+    let mut durations = Vec::with_capacity(iterations);
+    for iteration in 0..iterations {
+        let start = Instant::now();
+        // The writer is never started: this bench only measures load time, and dropping the
+        // un-started state releases the tree storage the writer owns.
+        let loaded = State::load(data_directory, StorageOptions::default()).await.unwrap();
+        let elapsed = start.elapsed();
+        drop(loaded);
+
+        // The first iteration may pay RocksDB WAL recovery and a cold OS page cache; later
+        // iterations measure a clean warm restart.
+        println!("Iteration {iteration}: state loaded in {elapsed:?}");
+        durations.push(elapsed);
+    }
+
+    if durations.len() > 1 {
+        print_summary(&durations);
+    }
 
     // Get database path and run SQL commands to count records
     let data_directory =
@@ -727,6 +740,5 @@ pub async fn load_state(data_directory: &Path) {
             |output| String::from_utf8_lossy(&output.stdout).trim().to_string(),
         );
 
-    println!("State loaded in {elapsed:?}");
     println!("Database contains {account_count} accounts and {nullifier_count} nullifiers");
 }

crates/store/src/state/loader.rs

@@ -270,6 +270,13 @@ impl TreeStorageLoader for MemoryStorage {
 #[cfg(feature = "rocksdb")]
 impl TreeStorageLoader for RocksDbStorage {
     type Config = RocksDbOptions;
+    // Opening RocksDB replays unflushed WAL segments and fills the table cache, which can take
+    // seconds; the span makes this cost visible in startup traces.
+    #[miden_instrument(
+        target = COMPONENT,
+        name = "open_tree_storage",
+        fields(path = domain),
+    )]
     fn create(
         data_dir: &Path,
         storage_options: &Self::Config,
@@ -424,6 +431,13 @@ impl AccountForestLoader for ForestInMemoryBackend {
 impl AccountForestLoader for ForestPersistentBackend {
     type Config = RocksDbOptions;
 
+    // Opening RocksDB replays unflushed WAL segments and fills the table cache, which can take
+    // seconds; the span makes this cost visible in startup traces.
+    #[miden_instrument(
+        target = COMPONENT,
+        name = "open_forest_storage",
+        fields(path = domain),
+    )]
     fn create(
         data_dir: &Path,
         storage_options: &Self::Config,