From 204867b11138c065e39d05c4681e2d2e8675049f Mon Sep 17 00:00:00 2001 From: sergerad Date: Tue, 11 Aug 2026 12:23:22 +1200 Subject: [PATCH] Load tracing and iteration benchmarks --- bin/stress-test/Cargo.toml | 6 ++++++ bin/stress-test/README.md | 30 ++++++++++++++++++++++++++---- bin/stress-test/src/main.rs | 11 ++++++++--- bin/stress-test/src/store/mod.rs | 26 +++++++++++++++++++------- crates/store/src/state/loader.rs | 14 ++++++++++++++ 5 files changed, 73 insertions(+), 14 deletions(-) diff --git a/bin/stress-test/Cargo.toml b/bin/stress-test/Cargo.toml index eb82ce982e..36128cc4ed 100644 --- a/bin/stress-test/Cargo.toml +++ b/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 } diff --git a/bin/stress-test/README.md b/bin/stress-test/README.md index d2908f154e..3e102e4b24 100644 --- a/bin/stress-test/README.md +++ b/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 diff --git a/bin/stress-test/src/main.rs b/bin/stress-test/src/main.rs index fe9e5770d4..734213aca6 100644 --- a/bin/stress-test/src/main.rs +++ b/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; diff --git a/bin/stress-test/src/store/mod.rs b/bin/stress-test/src/store/mod.rs index c8c0789684..01cf4c54b1 100644 --- a/bin/stress-test/src/store/mod.rs +++ b/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"); } diff --git a/crates/store/src/state/loader.rs b/crates/store/src/state/loader.rs index a2cdd45de4..7f5cb49c63 100644 --- a/crates/store/src/state/loader.rs +++ b/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,