diff --git a/ledger/store/Cargo.toml b/ledger/store/Cargo.toml index 395c8fca7a..9011a7672e 100644 --- a/ledger/store/Cargo.toml +++ b/ledger/store/Cargo.toml @@ -60,6 +60,9 @@ workspace = true [dependencies.snarkvm-ledger-puzzle] workspace = true +[dependencies.snarkvm-metrics] +workspace = true + [dependencies.snarkvm-synthesizer-program] workspace = true diff --git a/ledger/store/src/helpers/memory/internal/map.rs b/ledger/store/src/helpers/memory/internal/map.rs index 9d68b5b729..04d75b84e9 100644 --- a/ledger/store/src/helpers/memory/internal/map.rs +++ b/ledger/store/src/helpers/memory/internal/map.rs @@ -100,7 +100,16 @@ impl< } // Otherwise, insert the key-value pair directly into the map. false => { - self.map.write().insert(bincode::serialize(&key)?, value); + let serialized_key = bincode::serialize(&key)?; + let start = std::time::Instant::now(); + self.map.write().insert(serialized_key, value); + let duration = start.elapsed().as_secs_f64(); + snarkvm_metrics::histogram_label( + snarkvm_metrics::database::WRITE_DURATION, + "map_type", + "memory".to_string(), + duration, + ); } } @@ -119,7 +128,16 @@ impl< } // Otherwise, remove the key-value pair directly from the map. false => { - self.map.write().remove(&bincode::serialize(&key)?); + let serialized_key = bincode::serialize(&key)?; + let start = std::time::Instant::now(); + self.map.write().remove(&serialized_key); + let duration = start.elapsed().as_secs_f64(); + snarkvm_metrics::histogram_label( + snarkvm_metrics::database::DELETE_DURATION, + "map_type", + "memory".to_string(), + duration, + ); } } @@ -217,12 +235,24 @@ impl< .collect::>>()?; // Perform all the queued operations. + let start = std::time::Instant::now(); for (key, value) in prepared_operations { match value { - Some(value) => locked_map.insert(key, value), - None => locked_map.remove(&key), + Some(value) => { + locked_map.insert(key, value); + } + None => { + locked_map.remove(&key); + } }; } + let duration = start.elapsed().as_secs_f64(); + snarkvm_metrics::histogram_label( + snarkvm_metrics::database::WRITE_DURATION, + "map_type", + "memory_batch".to_string(), + duration, + ); } // Clear the checkpoint stack. @@ -315,7 +345,17 @@ impl< K: Borrow, Q: PartialEq + Eq + Hash + Serialize + ?Sized, { - Ok(self.map.read().get(&bincode::serialize(key)?).cloned().map(Cow::Owned)) + let serialized_key = bincode::serialize(key)?; + let start = std::time::Instant::now(); + let result = self.map.read().get(&serialized_key).cloned(); + let duration = start.elapsed().as_secs_f64(); + snarkvm_metrics::histogram_label( + snarkvm_metrics::database::READ_DURATION, + "map_type", + "memory".to_string(), + duration, + ); + Ok(result.map(Cow::Owned)) } /// diff --git a/ledger/store/src/helpers/rocksdb/internal/map.rs b/ledger/store/src/helpers/rocksdb/internal/map.rs index dcab5d7406..4c97191aae 100644 --- a/ledger/store/src/helpers/rocksdb/internal/map.rs +++ b/ledger/store/src/helpers/rocksdb/internal/map.rs @@ -53,6 +53,33 @@ impl InnerData let checkpoint = rocksdb::checkpoint::Checkpoint::new(&self.database)?; checkpoint.create_checkpoint(path).map_err(|e| e.into_string()) } + + /// Returns a human-readable map type label for metrics based on the context. + fn map_type_label(&self) -> &'static str { + // Extract the map_id from context (bytes 2-4 contain the u16 map_id) + if self.context.len() >= 4 { + let map_id_bytes = [self.context[2], self.context[3]]; + let map_id = u16::from_le_bytes(map_id_bytes); + + // Map the ID ranges to categories based on DataID enum ordering + match map_id { + 0..=1 => "bft", + 2..=18 => "block", + 19..=21 => "committee", + 22..=29 => "deployment", + 30..=32 => "execution", + 33..=34 => "fee", + 35..=42 => "input", + 43..=51 => "output", + 52 => "transaction", + 53..=57 => "transition", + 58..=59 => "program", + _ => "unknown", + } + } else { + "unknown" + } + } } impl< @@ -76,7 +103,16 @@ impl< // Prepare the prefixed key and serialized value. let raw_key = self.create_prefixed_key(&key)?; let raw_value = bincode::serialize(&value)?; + let map_type = self.map_type_label(); + let start = std::time::Instant::now(); self.database.put(raw_key, raw_value)?; + let duration = start.elapsed().as_secs_f64(); + snarkvm_metrics::histogram_label( + snarkvm_metrics::database::WRITE_DURATION, + "map_type", + map_type.to_string(), + duration, + ); } } @@ -97,7 +133,16 @@ impl< false => { // Prepare the prefixed key. let raw_key = self.create_prefixed_key(key)?; + let map_type = self.map_type_label(); + let start = std::time::Instant::now(); self.database.delete(raw_key)?; + let duration = start.elapsed().as_secs_f64(); + snarkvm_metrics::histogram_label( + snarkvm_metrics::database::DELETE_DURATION, + "map_type", + map_type.to_string(), + duration, + ); } } @@ -236,7 +281,15 @@ impl< // Empty the collection of pending operations. let batch = mem::take(&mut *self.database.atomic_batch.lock()); // Execute all the operations atomically. + let start = std::time::Instant::now(); self.database.rocksdb.write(batch)?; + let duration = start.elapsed().as_secs_f64(); + snarkvm_metrics::histogram_label( + snarkvm_metrics::database::WRITE_DURATION, + "map_type", + "batch".to_string(), + duration, + ); // Ensure that the database atomic batch is empty. assert!(self.database.atomic_batch.lock().is_empty()); } @@ -543,10 +596,17 @@ impl DataMap Ok(Some(data)), - None => Ok(None), - } + let map_type = self.map_type_label(); + let start = std::time::Instant::now(); + let result = self.database.get_pinned_opt(&raw_key, &self.database.default_readopts)?; + let duration = start.elapsed().as_secs_f64(); + snarkvm_metrics::histogram_label( + snarkvm_metrics::database::READ_DURATION, + "map_type", + map_type.to_string(), + duration, + ); + Ok(result) } } @@ -560,9 +620,7 @@ impl fmt::Debu mod tests { use super::*; use crate::{ - FinalizeMode, - atomic_batch_scope, - atomic_finalize, + FinalizeMode, atomic_batch_scope, atomic_finalize, helpers::rocksdb::{MapID, TestMap}, }; use console::{ diff --git a/metrics/src/lib.rs b/metrics/src/lib.rs index be1fe65e3a..24496930f0 100644 --- a/metrics/src/lib.rs +++ b/metrics/src/lib.rs @@ -16,16 +16,26 @@ #![forbid(unsafe_code)] const GAUGE_NAMES: [&str; 1] = [committee::TOTAL_STAKE]; +const HISTOGRAM_NAMES: [&str; 3] = [database::READ_DURATION, database::WRITE_DURATION, database::DELETE_DURATION]; pub mod committee { pub const TOTAL_STAKE: &str = "snarkvm_ledger_committee_total_stake"; } +pub mod database { + pub const READ_DURATION: &str = "snarkvm_database_read_duration_seconds"; + pub const WRITE_DURATION: &str = "snarkvm_database_write_duration_seconds"; + pub const DELETE_DURATION: &str = "snarkvm_database_delete_duration_seconds"; +} + /// Registers all snarkVM metrics. pub fn register_metrics() { for name in GAUGE_NAMES { register_gauge(name); } + for name in HISTOGRAM_NAMES { + register_histogram(name); + } } /******** Counter ********/ @@ -103,3 +113,15 @@ pub fn histogram>(name: &'static str, value: V) { pub fn histogram_label>(name: &'static str, label_key: &'static str, label_value: String, value: V) { ::metrics::histogram!(name, label_key => label_value).record(value.into()); } + +/// Times a database operation and records the duration with the given map type label. +pub fn time_database_operation(metric_name: &'static str, map_type: &str, operation: F) -> R +where + F: FnOnce() -> R, +{ + let start = std::time::Instant::now(); + let result = operation(); + let duration = start.elapsed().as_secs_f64(); + histogram_label(metric_name, "map_type", map_type.to_string(), duration); + result +}