diff --git a/ffi/src/handle.rs b/ffi/src/handle.rs index 8bc3902c29..77b5362d75 100644 --- a/ffi/src/handle.rs +++ b/ffi/src/handle.rs @@ -10,7 +10,7 @@ use firewood::{ use crate::{BorrowedBytes, CView, CreateProposalResult, KeyValuePair, arc_cache::ArcCache}; use crate::revision::{GetRevisionResult, RevisionHandle}; -use metrics::counter; +use firewood_storage::firewood_counter; /// Arguments for creating or opening a database. These are passed to [`fwd_open_db`] /// @@ -176,11 +176,16 @@ impl DatabaseHandle { self.create_proposal_handle(values.as_ref())?; let root_hash = handle.commit_proposal(|commit_time| { - counter!("firewood.ffi.commit_ms").increment(commit_time.as_millis()); + firewood_counter!( + "firewood.ffi.commit_ms", + "FFI commit timing in milliseconds" + ) + .increment(commit_time.as_millis()); })?; - counter!("firewood.ffi.batch_ms").increment(start_time.elapsed().as_millis()); - counter!("firewood.ffi.batch").increment(1); + firewood_counter!("firewood.ffi.batch_ms", "FFI batch timing in milliseconds") + .increment(start_time.elapsed().as_millis()); + firewood_counter!("firewood.ffi.batch", "Number of FFI batch operations").increment(1); Ok(root_hash) } @@ -208,9 +213,17 @@ impl DatabaseHandle { })?; if cache_miss { - counter!("firewood.ffi.cached_view.miss").increment(1); + firewood_counter!( + "firewood.ffi.cached_view.miss", + "Number of FFI cached view misses" + ) + .increment(1); } else { - counter!("firewood.ffi.cached_view.hit").increment(1); + firewood_counter!( + "firewood.ffi.cached_view.hit", + "Number of FFI cached view hits" + ) + .increment(1); } Ok(view) diff --git a/ffi/src/lib.rs b/ffi/src/lib.rs index 2577451ce8..62d3c03baa 100644 --- a/ffi/src/lib.rs +++ b/ffi/src/lib.rs @@ -32,6 +32,8 @@ mod proposal; mod revision; mod value; +use firewood_storage::firewood_counter; + use firewood::v2::api::DbView; pub use crate::handle::*; @@ -527,8 +529,13 @@ pub unsafe extern "C" fn fwd_commit_proposal( ) -> HashResult { invoke_with_handle(proposal, move |proposal| { proposal.commit_proposal(|commit_time| { - metrics::counter!("firewood.ffi.commit_ms").increment(commit_time.as_millis()); - metrics::counter!("firewood.ffi.commit").increment(1); + firewood_counter!( + "firewood.ffi.commit_ms", + "FFI commit timing in milliseconds" + ) + .increment(commit_time.as_millis()); + firewood_counter!("firewood.ffi.commit", "Number of FFI commit operations") + .increment(1); }) }) } diff --git a/ffi/src/proofs/range.rs b/ffi/src/proofs/range.rs index 6033257601..7f8f488bc9 100644 --- a/ffi/src/proofs/range.rs +++ b/ffi/src/proofs/range.rs @@ -13,6 +13,7 @@ use crate::{ BorrowedBytes, DatabaseHandle, HashResult, Maybe, NextKeyRangeResult, RangeProofResult, ValueResult, VoidResult, }; +use firewood_storage::firewood_counter; /// A key range represented by a start key and an optional end key. pub type KeyRange = (Box<[u8]>, Option>); @@ -224,8 +225,12 @@ impl<'db> RangeProofContext<'db> { }; let metrics_cb = |commit_time: coarsetime::Duration| { - metrics::counter!("firewood.ffi.commit_ms").increment(commit_time.as_millis()); - metrics::counter!("firewood.ffi.merge").increment(1); + firewood_counter!( + "firewood.ffi.commit_ms", + "FFI commit timing in milliseconds" + ) + .increment(commit_time.as_millis()); + firewood_counter!("firewood.ffi.merge", "Number of FFI merge operations").increment(1); }; let result = proposal_handle.commit_proposal(metrics_cb); diff --git a/ffi/src/proposal.rs b/ffi/src/proposal.rs index 6f6267f8e9..a51727ad60 100644 --- a/ffi/src/proposal.rs +++ b/ffi/src/proposal.rs @@ -4,7 +4,7 @@ use firewood::v2::api::{self, DbView, HashKey, IntoBatchIter, Proposal as _}; use crate::{IteratorHandle, iterator::CreateIteratorResult}; -use metrics::counter; +use firewood_storage::firewood_counter; /// An opaque wrapper around a Proposal that also retains a reference to the /// database handle it was created from. @@ -125,8 +125,12 @@ impl<'db> CreateProposalResult<'db> { let start_time = coarsetime::Instant::now(); let proposal = f()?; let propose_time = start_time.elapsed(); - counter!("firewood.ffi.propose_ms").increment(propose_time.as_millis()); - counter!("firewood.ffi.propose").increment(1); + firewood_counter!( + "firewood.ffi.propose_ms", + "FFI propose timing in milliseconds" + ) + .increment(propose_time.as_millis()); + firewood_counter!("firewood.ffi.propose", "Number of FFI propose operations").increment(1); let hash_key = proposal.root_hash()?; diff --git a/firewood/src/db.rs b/firewood/src/db.rs index 0416591ca7..afa5a2cb37 100644 --- a/firewood/src/db.rs +++ b/firewood/src/db.rs @@ -20,9 +20,8 @@ use crate::v2::api::{ use crate::manager::{ConfigManager, RevisionManager, RevisionManagerConfig}; use firewood_storage::{ CheckOpt, CheckerReport, Committed, FileBacked, FileIoError, HashedNodeReader, - ImmutableProposal, NodeStore, Parentable, ReadableStorage, TrieReader, + ImmutableProposal, NodeStore, Parentable, ReadableStorage, TrieReader, firewood_counter, }; -use metrics::{counter, describe_counter}; use std::io::Write; use std::num::NonZeroUsize; use std::path::Path; @@ -168,9 +167,8 @@ impl Db { /// Create a new database instance. pub fn new>(db_dir: P, cfg: DbConfig) -> Result { let metrics = Arc::new(DbMetrics { - proposals: counter!("firewood.proposals"), + proposals: firewood_counter!("firewood.proposals", "Number of proposals created"), }); - describe_counter!("firewood.proposals", "Number of proposals created"); let config_manager = ConfigManager::builder() .create(cfg.create_if_missing) .truncate(cfg.truncate) @@ -385,6 +383,13 @@ impl<'db> api::Proposal for Proposal<'db> { impl Proposal<'_> { #[crate::metrics("firewood.proposal.create", "database proposal creation")] fn create_proposal(&self, batch: impl IntoBatchIter) -> Result { + // Proposal created based on another proposal + firewood_storage::firewood_counter!( + "firewood.proposals.based_on_proposal", + "Number of proposals created with a proposal parent" + ) + .increment(1); + self.db.propose_with_parent(batch, &self.nodestore) } diff --git a/firewood/src/manager.rs b/firewood/src/manager.rs index 5e8eaebdab..54835b35ca 100644 --- a/firewood/src/manager.rs +++ b/firewood/src/manager.rs @@ -18,7 +18,6 @@ use std::path::PathBuf; use std::sync::{Arc, OnceLock}; use firewood_storage::logger::{trace, warn}; -use metrics::gauge; use rayon::{ThreadPool, ThreadPoolBuilder}; use typed_builder::TypedBuilder; @@ -29,7 +28,7 @@ use crate::v2::api::{ArcDynDbView, HashKey, OptionalHashKeyExt}; pub use firewood_storage::CacheReadStrategy; use firewood_storage::{ BranchNode, Committed, FileBacked, FileIoError, HashedNodeReader, ImmutableProposal, NodeStore, - TrieHash, + TrieHash, firewood_counter, firewood_gauge, }; const DB_FILE_NAME: &str = "firewood.db"; @@ -249,16 +248,45 @@ impl RevisionManager { // This guarantee is there because we have a `&mut self` reference to the manager, so // the compiler guarantees we are the only one using this manager. match Arc::try_unwrap(oldest) { - Ok(oldest) => oldest.reap_deleted(&mut committed)?, + Ok(oldest) => { + oldest.reap_deleted(&mut committed)?; + firewood_counter!( + "firewood.revisions.reaped", + "Number of revisions removed from memory", + "mode" => "without_rootstore" + ) + .increment(1); + } Err(original) => { warn!("Oldest revision could not be reaped; still referenced"); + firewood_counter!( + "firewood.revisions.reaping_failed", + "Reaping attempts that failed due to outstanding references" + ) + .increment(1); self.in_memory_revisions.write().push_front(original); break; } } + } else { + // RootStore is enabled: drop only in-memory handle and keep history on disk + firewood_counter!( + "firewood.revisions.reaped", + "Number of revisions removed from memory", + "mode" => "with_rootstore" + ) + .increment(1); } - gauge!("firewood.active_revisions").set(self.in_memory_revisions.read().len() as f64); - gauge!("firewood.max_revisions").set(self.max_revisions as f64); + firewood_gauge!( + "firewood.active_revisions", + "Current number of active revisions in memory" + ) + .set(self.in_memory_revisions.read().len() as f64); + firewood_gauge!( + "firewood.max_revisions", + "Maximum number of revisions configured" + ) + .set(self.max_revisions as f64); } // 3. Persist to disk. @@ -289,10 +317,30 @@ impl RevisionManager { // 6. Proposal Cleanup // Free proposal that is being committed as well as any proposals no longer - // referenced by anyone else. - self.proposals - .lock() - .retain(|p| !Arc::ptr_eq(&proposal, p) && Arc::strong_count(p) > 1); + // referenced by anyone else. Track how many were discarded (dropped without commit). + { + let mut lock = self.proposals.lock(); + let discarded = lock + .iter() + .filter(|p| !Arc::ptr_eq(&proposal, p) && Arc::strong_count(p) <= 1) + .count(); + if discarded > 0 { + firewood_counter!( + "firewood.proposals.discarded", + "Number of proposals dropped without commit" + ) + .increment(discarded as u64); + } + + lock.retain(|p| !Arc::ptr_eq(&proposal, p) && Arc::strong_count(p) > 1); + + // Update outstanding proposals gauge after cleanup + firewood_gauge!( + "firewood.proposals.outstanding", + "Current number of outstanding proposals" + ) + .set(lock.len() as f64); + } // then reparent any proposals that have this proposal as a parent for p in &*self.proposals.lock() { @@ -331,7 +379,14 @@ impl RevisionManager { } pub fn add_proposal(&self, proposal: ProposedRevision) { - self.proposals.lock().push(proposal); + let mut lock = self.proposals.lock(); + lock.push(proposal); + // Update outstanding proposals gauge when adding + firewood_gauge!( + "firewood.proposals.outstanding", + "Current number of outstanding proposals" + ) + .set(lock.len() as f64); } /// Retrieve a committed revision by its root hash. @@ -341,6 +396,12 @@ impl RevisionManager { pub fn revision(&self, root_hash: HashKey) -> Result { // 1. Check the in-memory revision manager. if let Some(revision) = self.by_hash.read().get(&root_hash).cloned() { + firewood_counter!( + "firewood.revisions.historical_queries", + "Historical revision queries by source", + "source" => "memory" + ) + .increment(1); return Ok(revision); } @@ -358,6 +419,13 @@ impl RevisionManager { provided: root_hash.clone(), })?; + firewood_counter!( + "firewood.revisions.historical_queries", + "Historical revision queries by source", + "source" => "rootstore" + ) + .increment(1); + Ok(revision) } diff --git a/firewood/src/merkle/mod.rs b/firewood/src/merkle/mod.rs index f1f486e95b..2cbe5c894d 100644 --- a/firewood/src/merkle/mod.rs +++ b/firewood/src/merkle/mod.rs @@ -17,9 +17,8 @@ use firewood_storage::{ BranchNode, Child, Children, FileIoError, HashType, HashedNodeReader, ImmutableProposal, IntoHashType, LeafNode, MaybePersistedNode, MutableProposal, NibblesIterator, Node, NodeStore, Parentable, Path, PathComponent, ReadableStorage, SharedNode, TrieHash, TrieReader, - ValueDigest, + ValueDigest, firewood_counter, }; -use metrics::counter; use std::collections::HashSet; use std::fmt::Debug; use std::io::Error; @@ -659,7 +658,7 @@ impl Merkle> { (None, None) => { // 1. The node is at `key` node.update_value(value); - counter!("firewood.insert", "merkle" => "update").increment(1); + firewood_counter!("firewood.insert", "Number of merkle insert operations", "merkle" => "update").increment(1); Ok(node) } (None, Some((child_index, partial_path))) => { @@ -680,7 +679,7 @@ impl Merkle> { // Shorten the node's partial path since it has a new parent. node.update_partial_path(partial_path); branch.children[child_index] = Some(Child::Node(node)); - counter!("firewood.insert", "merkle"=>"above").increment(1); + firewood_counter!("firewood.insert", "Number of merkle insert operations", "merkle"=>"above").increment(1); Ok(Node::Branch(Box::new(branch))) } @@ -702,7 +701,7 @@ impl Merkle> { partial_path, }); branch.children[child_index] = Some(Child::Node(new_leaf)); - counter!("firewood.insert", "merkle"=>"below").increment(1); + firewood_counter!("firewood.insert", "Number of merkle insert operations", "merkle"=>"below").increment(1); return Ok(node); }; let child = self.read_for_update(child)?; @@ -725,7 +724,7 @@ impl Merkle> { branch.children[child_index] = Some(Child::Node(new_leaf)); - counter!("firewood.insert", "merkle"=>"split").increment(1); + firewood_counter!("firewood.insert", "Number of merkle insert operations", "merkle"=>"split").increment(1); Ok(Node::Branch(Box::new(branch))) } } @@ -755,7 +754,7 @@ impl Merkle> { }); branch.children[key_index] = Some(Child::Node(new_leaf)); - counter!("firewood.insert", "merkle" => "split").increment(1); + firewood_counter!("firewood.insert", "Number of merkle insert operations", "merkle" => "split").increment(1); Ok(Node::Branch(Box::new(branch))) } } @@ -781,7 +780,7 @@ impl Merkle> { let root = self.nodestore.root_mut(); let Some(root_node) = std::mem::take(root) else { // The trie is empty. There is nothing to remove. - counter!("firewood.remove", "prefix" => "false", "result" => "nonexistent") + firewood_counter!("firewood.remove", "Number of merkle remove operations", "prefix" => "false", "result" => "nonexistent") .increment(1); return Ok(None); }; @@ -789,9 +788,9 @@ impl Merkle> { let (root_node, removed_value) = self.remove_helper(root_node, &key)?; *self.nodestore.root_mut() = root_node; if removed_value.is_some() { - counter!("firewood.remove", "prefix" => "false", "result" => "success").increment(1); + firewood_counter!("firewood.remove", "Number of merkle remove operations", "prefix" => "false", "result" => "success").increment(1); } else { - counter!("firewood.remove", "prefix" => "false", "result" => "nonexistent") + firewood_counter!("firewood.remove", "Number of merkle remove operations", "prefix" => "false", "result" => "nonexistent") .increment(1); } Ok(removed_value) @@ -880,13 +879,13 @@ impl Merkle> { let root = self.nodestore.root_mut(); let Some(root_node) = std::mem::take(root) else { // The trie is empty. There is nothing to remove. - counter!("firewood.remove", "prefix" => "true", "result" => "nonexistent").increment(1); + firewood_counter!("firewood.remove", "Number of merkle remove operations", "prefix" => "true", "result" => "nonexistent").increment(1); return Ok(0); }; let mut deleted = 0; let root_node = self.remove_prefix_helper(root_node, &prefix, &mut deleted)?; - counter!("firewood.remove", "prefix" => "true", "result" => "success") + firewood_counter!("firewood.remove", "Number of merkle remove operations", "prefix" => "true", "result" => "success") .increment(deleted as u64); *self.nodestore.root_mut() = root_node; Ok(deleted) diff --git a/storage/src/lib.rs b/storage/src/lib.rs index 8012d267e7..fb5ea17665 100644 --- a/storage/src/lib.rs +++ b/storage/src/lib.rs @@ -43,6 +43,8 @@ pub mod logger; #[macro_use] /// Macros module for defining macros used in the storage module pub mod macros; +#[cfg(test)] +mod macros_test; // re-export these so callers don't need to know where they are pub use checker::{CheckOpt, CheckerReport, DBStats, FreeListsStats, TrieStats}; pub use hashednode::{Hashable, Preimage, ValueDigest, hash_node, hash_preimage}; diff --git a/storage/src/linear/filebacked.rs b/storage/src/linear/filebacked.rs index 2fb49774bc..fdd4e7e2b0 100644 --- a/storage/src/linear/filebacked.rs +++ b/storage/src/linear/filebacked.rs @@ -26,8 +26,8 @@ use std::num::NonZero; use std::os::unix::fs::FileExt; use std::path::PathBuf; +use crate::firewood_counter; use lru::LruCache; -use metrics::counter; use crate::{CacheReadStrategy, LinearAddress, MaybePersistedNode, SharedNode}; @@ -104,7 +104,8 @@ impl FileBacked { impl ReadableStorage for FileBacked { fn stream_from(&self, addr: u64) -> Result { - counter!("firewood.read_node", "from" => "file").increment(1); + firewood_counter!("firewood.read_node", "Number of node reads", "from" => "file") + .increment(1); Ok(PredictiveReader::new(self, addr)) } @@ -119,7 +120,7 @@ impl ReadableStorage for FileBacked { fn read_cached_node(&self, addr: LinearAddress, mode: &'static str) -> Option { let mut guard = self.cache.lock(); let cached = guard.get(&addr).cloned(); - counter!("firewood.cache.node", "mode" => mode, "type" => if cached.is_some() { "hit" } else { "miss" }) + firewood_counter!("firewood.cache.node", "Number of node cache operations", "mode" => mode, "type" => if cached.is_some() { "hit" } else { "miss" }) .increment(1); cached } @@ -127,7 +128,7 @@ impl ReadableStorage for FileBacked { fn free_list_cache(&self, addr: LinearAddress) -> Option> { let mut guard = self.free_list_cache.lock(); let cached = guard.pop(&addr); - counter!("firewood.cache.freelist", "type" => if cached.is_some() { "hit" } else { "miss" }).increment(1); + firewood_counter!("firewood.cache.freelist", "Number of freelist cache operations", "type" => if cached.is_some() { "hit" } else { "miss" }).increment(1); cached } @@ -237,8 +238,9 @@ impl<'a> PredictiveReader<'a> { impl Drop for PredictiveReader<'_> { fn drop(&mut self) { let elapsed = self.started.elapsed(); - counter!("firewood.io.read_ms").increment(elapsed.as_millis()); - counter!("firewood.io.read").increment(1); + firewood_counter!("firewood.io.read_ms", "IO read timing in milliseconds") + .increment(elapsed.as_millis()); + firewood_counter!("firewood.io.read", "Number of IO read operations").increment(1); } } diff --git a/storage/src/linear/memory.rs b/storage/src/linear/memory.rs index feaf7499db..4e496a0d2c 100644 --- a/storage/src/linear/memory.rs +++ b/storage/src/linear/memory.rs @@ -11,7 +11,7 @@ )] use super::{FileIoError, OffsetReader, ReadableStorage, WritableStorage}; -use metrics::counter; +use crate::firewood_counter; use parking_lot::Mutex; use std::io::Cursor; @@ -45,7 +45,8 @@ impl WritableStorage for MemStore { impl ReadableStorage for MemStore { fn stream_from(&self, addr: u64) -> Result { - counter!("firewood.read_node", "from" => "memory").increment(1); + firewood_counter!("firewood.read_node", "Number of node reads", "from" => "memory") + .increment(1); let bytes = self .bytes .lock() diff --git a/storage/src/macros.rs b/storage/src/macros.rs index 1188fb70fa..996f0aec90 100644 --- a/storage/src/macros.rs +++ b/storage/src/macros.rs @@ -43,14 +43,14 @@ macro_rules! firewood_counter { /// `firewood_gauge!("metric_name", "description")` /// `firewood_gauge!("metric_name", "description", "label" => "value")` /// -/// Call `.increment(val)` or `.decrement(val)` on the result as appropriate. +/// Call `.set(val)`, `.increment(val)`, or `.decrement(val)` on the result as appropriate. macro_rules! firewood_gauge { // With labels ($name:expr, $desc:expr, $($labels:tt)+) => { { static ONCE: std::sync::Once = std::sync::Once::new(); ONCE.call_once(|| { - metrics::describe_counter!($name, $desc); + metrics::describe_gauge!($name, $desc); }); metrics::gauge!($name, $($labels)+) } @@ -60,7 +60,7 @@ macro_rules! firewood_gauge { { static ONCE: std::sync::Once = std::sync::Once::new(); ONCE.call_once(|| { - metrics::describe_counter!($name, $desc); + metrics::describe_gauge!($name, $desc); }); metrics::gauge!($name) } diff --git a/storage/src/macros_test.rs b/storage/src/macros_test.rs new file mode 100644 index 0000000000..7237defe9e --- /dev/null +++ b/storage/src/macros_test.rs @@ -0,0 +1,46 @@ +// Copyright (C) 2023, Ava Labs, Inc. All rights reserved. +// See the file LICENSE.md for licensing terms. + +#[cfg(test)] +mod tests { + use crate::{firewood_counter, firewood_gauge}; + + #[test] + fn test_firewood_counter_macro() { + // Test counter without labels + let counter = firewood_counter!("test.counter.simple", "A simple test counter"); + counter.increment(1); + + // Test counter with labels + let counter_with_labels = + firewood_counter!("test.counter.labeled", "A labeled test counter", "env" => "test"); + counter_with_labels.increment(5); + } + + #[test] + fn test_firewood_gauge_macro() { + // Test gauge without labels + let gauge = firewood_gauge!("test.gauge.simple", "A simple test gauge"); + gauge.set(42.0); + gauge.increment(10.0); + gauge.decrement(5.0); + + // Test gauge with labels + let gauge_with_labels = + firewood_gauge!("test.gauge.labeled", "A labeled test gauge", "env" => "test"); + gauge_with_labels.set(100.0); + } + + #[test] + fn test_macro_description_registration() { + // Verify that calling the macro multiple times doesn't panic + // (the static ONCE guard should ensure describe_* is only called once) + for i in 0..10 { + let counter = firewood_counter!("test.counter.multi", "Multi-call test counter"); + counter.increment(1); + + let gauge = firewood_gauge!("test.gauge.multi", "Multi-call test gauge"); + gauge.set(f64::from(i)); + } + } +} diff --git a/storage/src/nodestore/mod.rs b/storage/src/nodestore/mod.rs index 249ac785c1..63cc6825ca 100644 --- a/storage/src/nodestore/mod.rs +++ b/storage/src/nodestore/mod.rs @@ -44,6 +44,7 @@ pub(crate) mod header; pub(crate) mod persist; pub(crate) mod primitives; +use crate::firewood_counter; use crate::linear::OffsetReader; use crate::logger::trace; use crate::node::branch::ReadSerializable as _; @@ -479,6 +480,12 @@ impl ImmutableProposal { && Arc::ptr_eq(parent, committing) { *guard = NodeStoreParent::Committed(committing.root_hash()); + // Track reparenting events + firewood_counter!( + "firewood.proposals.reparented", + "Number of proposals reparented to committed parent" + ) + .increment(1); } } }