diff --git a/client/api/src/client.rs b/client/api/src/client.rs index 78a70bd5ea49c..65952ce787bb2 100644 --- a/client/api/src/client.rs +++ b/client/api/src/client.rs @@ -121,6 +121,10 @@ pub struct IoInfo { pub reads: u64, /// Average size of the transaction. pub average_transaction_size: u64, + /// State reads (keys) + pub state_reads: u64, + /// State reads (keys) from cache. + pub state_reads_cache: u64, } /// Usage statistics for running client instance. @@ -139,13 +143,15 @@ pub struct UsageInfo { impl fmt::Display for UsageInfo { fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { write!(f, - "caches: ({} state, {} db overlay), i/o: ({} tx, {} write, {} read, {} tx size)", + "caches: ({} state, {} db overlay), i/o: ({} tx, {} write, {} read, {} avg tx, {}/{} key cache reads/total)", self.memory.state_cache, self.memory.database_cache, self.io.transactions, self.io.bytes_written, self.io.bytes_read, self.io.average_transaction_size, + self.io.state_reads_cache, + self.io.state_reads, ) } } diff --git a/client/db/src/lib.rs b/client/db/src/lib.rs index 3a7f090e604eb..06d0dc18ffa36 100644 --- a/client/db/src/lib.rs +++ b/client/db/src/lib.rs @@ -33,6 +33,7 @@ mod children; mod cache; mod storage_cache; mod utils; +mod stats; use std::sync::Arc; use std::path::PathBuf; @@ -63,13 +64,14 @@ use sp_runtime::traits::{ use sc_executor::RuntimeInfo; use sp_state_machine::{ DBValue, ChangesTrieTransaction, ChangesTrieCacheAction, ChangesTrieBuildCache, - backend::Backend as StateBackend, + backend::Backend as StateBackend, UsageInfo as StateUsageInfo, }; use crate::utils::{Meta, db_err, meta_keys, read_db, read_meta}; use sc_client::leaves::{LeafSet, FinalizationDisplaced}; use sc_state_db::StateDb; use sp_blockchain::{CachedHeaderMetadata, HeaderMetadata, HeaderMetadataCache}; use crate::storage_cache::{CachingState, SharedCache, new_shared_cache}; +use crate::stats::StateUsageStats; use log::{trace, debug, warn}; pub use sc_state_db::PruningMode; @@ -895,7 +897,8 @@ pub struct Backend { shared_cache: SharedCache, import_lock: RwLock<()>, is_archive: bool, - io_stats: FrozenForDuration, + io_stats: FrozenForDuration<(kvdb::IoStats, StateUsageInfo)>, + state_usage: StateUsageStats, } impl Backend { @@ -963,7 +966,8 @@ impl Backend { ), import_lock: Default::default(), is_archive: is_archive_pruning, - io_stats: FrozenForDuration::new(std::time::Duration::from_secs(1), kvdb::IoStats::empty()), + io_stats: FrozenForDuration::new(std::time::Duration::from_secs(1), (kvdb::IoStats::empty(), StateUsageInfo::empty())), + state_usage: StateUsageStats::new(), }) } @@ -1257,13 +1261,23 @@ impl Backend { let finalized = if operation.commit_state { let mut changeset: sc_state_db::ChangeSet> = sc_state_db::ChangeSet::default(); + let mut ops: u64 = 0; + let mut bytes: u64 = 0; for (key, (val, rc)) in operation.db_updates.drain() { if rc > 0 { + ops += 1; + bytes += key.len() as u64 + val.len() as u64; + changeset.inserted.push((key, val.to_vec())); } else if rc < 0 { + ops += 1; + bytes += key.len() as u64; + changeset.deleted.push(key); } } + self.state_usage.tally_writes(ops, bytes); + let number_u64 = number.saturated_into::(); let commit = self.storage.state_db.insert_block(&hash, number_u64, &pending_block.header.parent_hash(), changeset) .map_err(|e: sc_state_db::Error| sp_blockchain::Error::from(format!("State database error: {:?}", e)))?; @@ -1495,6 +1509,9 @@ impl sc_client_api::backend::Backend for Backend { fn commit_operation(&self, operation: Self::BlockImportOperation) -> ClientResult<()> { + let usage = operation.old_state.usage_info(); + self.state_usage.merge_sm(usage); + match self.try_commit_operation(operation) { Ok(_) => { self.storage.state_db.apply_pending(); @@ -1548,8 +1565,14 @@ impl sc_client_api::backend::Backend for Backend { Some(self.offchain_storage.clone()) } + fn usage_info(&self) -> Option { - let io_stats = self.io_stats.take_or_else(|| self.storage.db.io_stats(kvdb::IoStatsKind::SincePrevious)); + let (io_stats, state_stats) = self.io_stats.take_or_else(|| + ( + self.storage.db.io_stats(kvdb::IoStatsKind::SincePrevious), + self.state_usage.take(), + ) + ); let database_cache = parity_util_mem::malloc_size(&*self.storage.db); let state_cache = (*&self.shared_cache).lock().used_storage_cache_size(); @@ -1565,6 +1588,8 @@ impl sc_client_api::backend::Backend for Backend { writes: io_stats.writes, reads: io_stats.reads, average_transaction_size: io_stats.avg_transaction_size() as u64, + state_reads: state_stats.reads.ops, + state_reads_cache: state_stats.cache_reads.ops, }, }) } diff --git a/client/db/src/light.rs b/client/db/src/light.rs index 7a79885fad35f..d9620093f5876 100644 --- a/client/db/src/light.rs +++ b/client/db/src/light.rs @@ -576,6 +576,9 @@ impl LightBlockchainStorage for LightStorage writes: io_stats.writes, reads: io_stats.reads, average_transaction_size: io_stats.avg_transaction_size() as u64, + // Light client does not track those + state_reads: 0, + state_reads_cache: 0, } }) } diff --git a/client/db/src/stats.rs b/client/db/src/stats.rs new file mode 100644 index 0000000000000..805a0f498f7fc --- /dev/null +++ b/client/db/src/stats.rs @@ -0,0 +1,102 @@ +// Copyright 2017-2020 Parity Technologies (UK) Ltd. +// This file is part of Substrate. + +// Substrate is free software: you can redistribute it and/or modify +// it under the terms of the GNU General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. + +// Substrate is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU General Public License for more details. + +// You should have received a copy of the GNU General Public License +// along with Substrate. If not, see . + +//! Database usage statistics + +use std::sync::atomic::{AtomicU64, Ordering as AtomicOrdering}; + +/// Accumulated usage statistics for state queries. +pub struct StateUsageStats { + started: std::time::Instant, + reads: AtomicU64, + bytes_read: AtomicU64, + writes: AtomicU64, + bytes_written: AtomicU64, + reads_cache: AtomicU64, + bytes_read_cache: AtomicU64, +} + +impl StateUsageStats { + /// New empty usage stats. + pub fn new() -> Self { + Self { + started: std::time::Instant::now(), + reads: 0.into(), + bytes_read: 0.into(), + writes: 0.into(), + bytes_written: 0.into(), + reads_cache: 0.into(), + bytes_read_cache: 0.into(), + } + } + + /// Tally one read operation, of some length. + pub fn tally_read(&self, data_bytes: u64, cache: bool) { + self.reads.fetch_add(1, AtomicOrdering::Relaxed); + self.bytes_read.fetch_add(data_bytes, AtomicOrdering::Relaxed); + if cache { + self.reads_cache.fetch_add(1, AtomicOrdering::Relaxed); + self.bytes_read_cache.fetch_add(data_bytes, AtomicOrdering::Relaxed); + } + } + + /// Tally one key read. + pub fn tally_key_read(&self, key: &[u8], val: Option<&Vec>, cache: bool) { + self.tally_read(key.len() as u64 + val.as_ref().map(|x| x.len() as u64).unwrap_or(0), cache); + } + + /// Tally one child key read. + pub fn tally_child_key_read(&self, key: &(Vec, Vec), val: Option>, cache: bool) -> Option> { + self.tally_read(key.0.len() as u64 + key.1.len() as u64 + val.as_ref().map(|x| x.len() as u64).unwrap_or(0), cache); + val + } + + /// Tally some write operations, including their byte count. + pub fn tally_writes(&self, ops: u64, data_bytes: u64) { + self.writes.fetch_add(ops, AtomicOrdering::Relaxed); + self.bytes_written.fetch_add(data_bytes, AtomicOrdering::Relaxed); + } + + /// Merge state machine usage info. + pub fn merge_sm(&self, info: sp_state_machine::UsageInfo) { + self.reads.fetch_add(info.reads.ops, AtomicOrdering::Relaxed); + self.bytes_read.fetch_add(info.reads.bytes, AtomicOrdering::Relaxed); + self.writes.fetch_add(info.writes.ops, AtomicOrdering::Relaxed); + self.bytes_written.fetch_add(info.writes.bytes, AtomicOrdering::Relaxed); + self.reads_cache.fetch_add(info.cache_reads.ops, AtomicOrdering::Relaxed); + self.bytes_read_cache.fetch_add(info.cache_reads.bytes, AtomicOrdering::Relaxed); + } + + pub fn take(&self) -> sp_state_machine::UsageInfo { + use sp_state_machine::UsageUnit; + + fn unit(ops: &AtomicU64, bytes: &AtomicU64) -> UsageUnit { + UsageUnit { ops: ops.swap(0, AtomicOrdering::Relaxed), bytes: bytes.swap(0, AtomicOrdering::Relaxed) } + } + + sp_state_machine::UsageInfo { + reads: unit(&self.reads, &self.bytes_read), + writes: unit(&self.writes, &self.bytes_written), + cache_reads: unit(&self.reads_cache, &self.bytes_read_cache), + // TODO: Proper tracking state of memory footprint here requires + // imposing `MallocSizeOf` requirement on half of the codebase, + // so it is an open question how to do it better + memory: 0, + started: self.started, + span: self.started.elapsed(), + } + } +} diff --git a/client/db/src/storage_cache.rs b/client/db/src/storage_cache.rs index 1921dcc7af7ce..4f7e906a0ae28 100644 --- a/client/db/src/storage_cache.rs +++ b/client/db/src/storage_cache.rs @@ -28,6 +28,7 @@ use sp_state_machine::{backend::Backend as StateBackend, TrieBackend}; use log::trace; use sc_client_api::backend::{StorageCollection, ChildStorageCollection}; use std::hash::Hash as StdHash; +use crate::stats::StateUsageStats; const STATE_CACHE_BLOCKS: usize = 12; @@ -296,6 +297,8 @@ pub struct CacheChanges { /// in `sync_cache` along with the change overlay. /// For non-canonical clones local cache and changes are dropped. pub struct CachingState>, B: BlockT> { + /// Usage statistics + usage: StateUsageStats, /// Backing state. state: S, /// Cache data. @@ -421,6 +424,7 @@ impl>, B: BlockT> CachingState { /// Create a new instance wrapping generic State and shared cache. pub fn new(state: S, shared_cache: SharedCache, parent_hash: Option) -> Self { CachingState { + usage: StateUsageStats::new(), state, cache: CacheChanges { shared_cache, @@ -495,18 +499,22 @@ impl>, B: BlockT> StateBackend> for Ca // Note that local cache makes that lru is not refreshed if let Some(entry) = local_cache.storage.get(key).cloned() { trace!("Found in local cache: {:?}", HexDisplay::from(&key)); + self.usage.tally_key_read(key, entry.as_ref(), true); + return Ok(entry) } let mut cache = self.cache.shared_cache.lock(); if Self::is_allowed(Some(key), None, &self.cache.parent_hash, &cache.modifications) { if let Some(entry) = cache.lru_storage.get(key).map(|a| a.clone()) { trace!("Found in shared cache: {:?}", HexDisplay::from(&key)); + self.usage.tally_key_read(key, entry.as_ref(), true); return Ok(entry) } } trace!("Cache miss: {:?}", HexDisplay::from(&key)); let value = self.state.storage(key)?; RwLockUpgradableReadGuard::upgrade(local_cache).storage.insert(key.to_vec(), value.clone()); + self.usage.tally_key_read(key, value.as_ref(), false); Ok(value) } @@ -539,17 +547,25 @@ impl>, B: BlockT> StateBackend> for Ca let local_cache = self.cache.local_cache.upgradable_read(); if let Some(entry) = local_cache.child_storage.get(&key).cloned() { trace!("Found in local cache: {:?}", key); - return Ok(entry) + return Ok( + self.usage.tally_child_key_read(&key, entry, true) + ) } let mut cache = self.cache.shared_cache.lock(); if Self::is_allowed(None, Some(&key), &self.cache.parent_hash, &cache.modifications) { if let Some(entry) = cache.lru_child_storage.get(&key).map(|a| a.clone()) { trace!("Found in shared cache: {:?}", key); - return Ok(entry) + return Ok( + self.usage.tally_child_key_read(&key, entry, true) + ) } } trace!("Cache miss: {:?}", key); let value = self.state.child_storage(storage_key, child_info, &key.1[..])?; + + // just pass it through the usage counter + let value = self.usage.tally_child_key_read(&key, value, false); + RwLockUpgradableReadGuard::upgrade(local_cache).child_storage.insert(key, value.clone()); Ok(value) } @@ -646,6 +662,10 @@ impl>, B: BlockT> StateBackend> for Ca fn as_trie_backend(&mut self) -> Option<&TrieBackend>> { self.state.as_trie_backend() } + + fn usage_info(&self) -> sp_state_machine::UsageInfo { + self.usage.take() + } } #[cfg(test)] diff --git a/primitives/state-machine/src/backend.rs b/primitives/state-machine/src/backend.rs index d542dab8ad2bd..75733d68b3ffa 100644 --- a/primitives/state-machine/src/backend.rs +++ b/primitives/state-machine/src/backend.rs @@ -18,11 +18,16 @@ use log::warn; use hash_db::Hasher; -use crate::trie_backend::TrieBackend; -use crate::trie_backend_essence::TrieBackendStorage; -use sp_trie::{TrieMut, MemoryDB, trie_types::TrieDBMut}; use codec::Encode; + use sp_core::storage::{ChildInfo, OwnedChildInfo}; +use sp_trie::{TrieMut, MemoryDB, trie_types::TrieDBMut}; + +use crate::{ + trie_backend::TrieBackend, + trie_backend_essence::TrieBackendStorage, + UsageInfo, +}; /// A state backend is used to read state data and can have changes committed /// to it. @@ -200,6 +205,14 @@ pub trait Backend: std::fmt::Debug { txs.consolidate(parent_txs); (root, txs) } + + /// Query backend usage statistics (i/o, memory) + /// + /// Not all implementations are expected to be able to do this. In the + /// case when thay don't, empty statistics is returned. + fn usage_info(&self) -> UsageInfo { + UsageInfo::empty() + } } impl<'a, T: Backend, H: Hasher> Backend for &'a T { @@ -284,7 +297,11 @@ impl<'a, T: Backend, H: Hasher> Backend for &'a T { fn for_key_values_with_prefix(&self, prefix: &[u8], f: F) { (*self).for_key_values_with_prefix(prefix, f); } -} + + fn usage_info(&self) -> UsageInfo { + (*self).usage_info() + } + } /// Trait that allows consolidate two transactions together. pub trait Consolidate { diff --git a/primitives/state-machine/src/lib.rs b/primitives/state-machine/src/lib.rs index f89bc0631ffd5..c8329178c6c4d 100644 --- a/primitives/state-machine/src/lib.rs +++ b/primitives/state-machine/src/lib.rs @@ -40,6 +40,7 @@ mod overlayed_changes; mod proving_backend; mod trie_backend; mod trie_backend_essence; +mod stats; pub use sp_trie::{trie_types::{Layout, TrieDBMut}, TrieMut, DBValue, MemoryDB}; pub use testing::TestExternalities; @@ -68,6 +69,7 @@ pub use trie_backend_essence::{TrieBackendStorage, Storage}; pub use trie_backend::TrieBackend; pub use error::{Error, ExecutionError}; pub use in_memory_backend::InMemory as InMemoryBackend; +pub use stats::{UsageInfo, UsageUnit}; type CallResult = Result, E>; diff --git a/primitives/state-machine/src/stats.rs b/primitives/state-machine/src/stats.rs new file mode 100644 index 0000000000000..38286be545af5 --- /dev/null +++ b/primitives/state-machine/src/stats.rs @@ -0,0 +1,62 @@ +// Copyright 2017-2020 Parity Technologies (UK) Ltd. +// This file is part of Substrate. + +// Substrate is free software: you can redistribute it and/or modify +// it under the terms of the GNU General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. + +// Substrate is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU General Public License for more details. + +// You should have received a copy of the GNU General Public License +// along with Substrate. If not, see . + +//! Usage statistics for state db + +use std::time::{Instant, Duration}; + +/// Measured count of operations and total bytes. +#[derive(Clone, Debug, Default)] +pub struct UsageUnit { + /// Number of operations. + pub ops: u64, + /// Number of bytes. + pub bytes: u64, +} + +/// Usage statistics for state backend. +#[derive(Clone, Debug)] +pub struct UsageInfo { + /// Read statistics (total). + pub reads: UsageUnit, + /// Write statistics. + pub writes: UsageUnit, + /// Cache read statistics. + pub cache_reads: UsageUnit, + /// Memory used. + pub memory: usize, + + /// Moment at which current statistics has been started being collected. + pub started: Instant, + /// Timespan of the statistics. + pub span: Duration, +} + +impl UsageInfo { + /// Empty statistics. + /// + /// Means no data was collected. + pub fn empty() -> Self { + Self { + reads: UsageUnit::default(), + writes: UsageUnit::default(), + cache_reads: UsageUnit::default(), + memory: 0, + started: Instant::now(), + span: Default::default(), + } + } +} \ No newline at end of file