From 7f5dd736f42a408b62885669f7d76ef5baa13572 Mon Sep 17 00:00:00 2001 From: Shawn Tabrizi Date: Wed, 24 Jun 2020 21:03:55 +0200 Subject: [PATCH] Add DB Read/Write Tracking to Benchmarking Pipeline (#6386) * initial mockup * add and wipe * track writes * start to add to pipeline * return all reads/writes * Log reads and writes from bench db * causes panic * Allow multiple commits * commit before ending benchmark * doesn't work??? * fix * Update lib.rs * switch to struct for `BenchmarkResults` * add to output * fix test * line width * @kianenigma review * Add Whitelist to DB Tracking in Benchmarks Pipeline (#6405) * hardcoded whitelist * Add whitelist to pipeline * Remove whitelist pipeline from CLI, add to runtime * clean-up unused db initialized whitelist * Add regression analysis to DB Tracking (#6475) * Add selector * add tests * debug formatter for easy formula * Update client/db/src/bench.rs Co-authored-by: Kian Paimani <5588131+kianenigma@users.noreply.github.com> Co-authored-by: arkpar Co-authored-by: Kian Paimani <5588131+kianenigma@users.noreply.github.com> --- Cargo.lock | 1 + bin/node/runtime/Cargo.toml | 1 + bin/node/runtime/src/lib.rs | 20 ++- client/db/src/bench.rs | 169 +++++++++++++++++++- frame/benchmarking/src/analysis.rs | 140 ++++++++++++---- frame/benchmarking/src/lib.rs | 56 ++++++- frame/benchmarking/src/utils.rs | 26 ++- primitives/externalities/src/lib.rs | 21 +++ primitives/runtime-interface/src/impls.rs | 4 + primitives/state-machine/src/backend.rs | 17 +- primitives/state-machine/src/basic.rs | 12 ++ primitives/state-machine/src/ext.rs | 13 ++ primitives/state-machine/src/read_only.rs | 12 ++ utils/frame/benchmarking-cli/src/command.rs | 39 +++-- 14 files changed, 471 insertions(+), 60 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index c1ea4a479c0ef..1520373790495 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3518,6 +3518,7 @@ dependencies = [ "frame-system", "frame-system-benchmarking", "frame-system-rpc-runtime-api", + "hex-literal", "integer-sqrt", "node-primitives", "pallet-authority-discovery", diff --git a/bin/node/runtime/Cargo.toml b/bin/node/runtime/Cargo.toml index b26b53cd6c589..3614e4ca0dc8a 100644 --- a/bin/node/runtime/Cargo.toml +++ b/bin/node/runtime/Cargo.toml @@ -18,6 +18,7 @@ codec = { package = "parity-scale-codec", version = "1.3.1", default-features = integer-sqrt = { version = "0.1.2" } serde = { version = "1.0.102", optional = true } static_assertions = "1.1.0" +hex-literal = "0.2.1" # primitives sp-authority-discovery = { version = "2.0.0-rc3", default-features = false, path = "../../../primitives/authority-discovery" } diff --git a/bin/node/runtime/src/lib.rs b/bin/node/runtime/src/lib.rs index 90bb63874e116..8b6831b41ebf9 100644 --- a/bin/node/runtime/src/lib.rs +++ b/bin/node/runtime/src/lib.rs @@ -1075,8 +1075,26 @@ impl_runtime_apis! { impl pallet_offences_benchmarking::Trait for Runtime {} impl frame_system_benchmarking::Trait for Runtime {} + let whitelist: Vec> = vec![ + // Block Number + // frame_system::Number::::hashed_key().to_vec(), + hex_literal::hex!("26aa394eea5630e07c48ae0c9558cef702a5c1b19ab7a04f536c519aca4983ac").to_vec(), + // Total Issuance + hex_literal::hex!("c2261276cc9d1f8598ea4b6a74b15c2f57c875e4cff74148e4628f264b974c80").to_vec(), + // Execution Phase + hex_literal::hex!("26aa394eea5630e07c48ae0c9558cef7ff553b5a9862a516939d82b3d3d8661a").to_vec(), + // Event Count + hex_literal::hex!("26aa394eea5630e07c48ae0c9558cef70a98fdbe9ce6c55837576c60c7af3850").to_vec(), + // System Events + hex_literal::hex!("26aa394eea5630e07c48ae0c9558cef780d41e5e16056765bc8461851072c9d7").to_vec(), + // Caller 0 Account + hex_literal::hex!("26aa394eea5630e07c48ae0c9558cef7b99d880ec681799c0cf30e8886371da946c154ffd9992e395af90b5b13cc6f295c77033fce8a9045824a6690bbf99c6db269502f0a8d1d2a008542d5690a0749").to_vec(), + // Treasury Account + hex_literal::hex!("26aa394eea5630e07c48ae0c9558cef7b99d880ec681799c0cf30e8886371da95ecffd7b6c0f78751baa9d281e0bfa3a6d6f646c70792f74727372790000000000000000000000000000000000000000").to_vec(), + ]; + let mut batches = Vec::::new(); - let params = (&pallet, &benchmark, &lowest_range_values, &highest_range_values, &steps, repeat); + let params = (&pallet, &benchmark, &lowest_range_values, &highest_range_values, &steps, repeat, &whitelist); add_benchmark!(params, batches, b"balances", Balances); add_benchmark!(params, batches, b"collective", Council); diff --git a/client/db/src/bench.rs b/client/db/src/bench.rs index 99ce1edae00c5..c3bed3e24f617 100644 --- a/client/db/src/bench.rs +++ b/client/db/src/bench.rs @@ -24,10 +24,10 @@ use std::collections::HashMap; use hash_db::{Prefix, Hasher}; use sp_trie::{MemoryDB, prefixed_key}; -use sp_core::storage::ChildInfo; +use sp_core::{storage::ChildInfo, hexdisplay::HexDisplay}; use sp_runtime::traits::{Block as BlockT, HashFor}; use sp_runtime::Storage; -use sp_state_machine::{DBValue, backend::Backend as StateBackend}; +use sp_state_machine::{DBValue, backend::Backend as StateBackend, StorageCollection}; use kvdb::{KeyValueDB, DBTransaction}; use crate::storage_cache::{CachingState, SharedCache, new_shared_cache}; @@ -50,6 +50,40 @@ impl sp_state_machine::Storage> for StorageDb { root: Cell, @@ -59,6 +93,9 @@ pub struct BenchmarkingState { genesis: HashMap, (Vec, i32)>, record: Cell>>, shared_cache: SharedCache, // shared cache is always empty + key_tracker: RefCell, KeyTracker>>, + read_write_tracker: RefCell, + whitelist: RefCell>>, } impl BenchmarkingState { @@ -76,8 +113,13 @@ impl BenchmarkingState { genesis_root: Default::default(), record: Default::default(), shared_cache: new_shared_cache(0, (1, 10)), + key_tracker: Default::default(), + read_write_tracker: Default::default(), + whitelist: Default::default(), }; + state.add_whitelist_to_tracker(); + state.reopen()?; let child_delta = genesis.children_default.iter().map(|(_storage_key, child_content)| ( &child_content.child_info, @@ -89,7 +131,7 @@ impl BenchmarkingState { ); state.genesis = transaction.clone().drain(); state.genesis_root = root.clone(); - state.commit(root, transaction)?; + state.commit(root, transaction, Vec::new())?; state.record.take(); Ok(state) } @@ -109,6 +151,86 @@ impl BenchmarkingState { )); Ok(()) } + + fn add_whitelist_to_tracker(&self) { + let mut key_tracker = self.key_tracker.borrow_mut(); + + let whitelisted = KeyTracker { + has_been_read: true, + has_been_written: true, + }; + + let whitelist = self.whitelist.borrow(); + + whitelist.iter().for_each(|key| { + key_tracker.insert(key.to_vec(), whitelisted); + }); + } + + fn wipe_tracker(&self) { + *self.key_tracker.borrow_mut() = HashMap::new(); + self.add_whitelist_to_tracker(); + *self.read_write_tracker.borrow_mut() = Default::default(); + } + + fn add_read_key(&self, key: &[u8]) { + log::trace!(target: "benchmark", "Read: {}", HexDisplay::from(&key)); + + let mut key_tracker = self.key_tracker.borrow_mut(); + let mut read_write_tracker = self.read_write_tracker.borrow_mut(); + + let maybe_tracker = key_tracker.get(key); + + let has_been_read = KeyTracker { + has_been_read: true, + has_been_written: false, + }; + + match maybe_tracker { + None => { + key_tracker.insert(key.to_vec(), has_been_read); + read_write_tracker.add_read(); + }, + Some(tracker) => { + if !tracker.has_been_read { + key_tracker.insert(key.to_vec(), has_been_read); + read_write_tracker.add_read(); + } else { + read_write_tracker.add_repeat_read(); + } + } + } + } + + fn add_write_key(&self, key: &[u8]) { + log::trace!(target: "benchmark", "Write: {}", HexDisplay::from(&key)); + + let mut key_tracker = self.key_tracker.borrow_mut(); + let mut read_write_tracker = self.read_write_tracker.borrow_mut(); + + let maybe_tracker = key_tracker.get(key); + + // If we have written to the key, we also consider that we have read from it. + let has_been_written = KeyTracker { + has_been_read: true, + has_been_written: true, + }; + + match maybe_tracker { + None => { + key_tracker.insert(key.to_vec(), has_been_written); + read_write_tracker.add_write(); + }, + Some(tracker) => { + if !tracker.has_been_written { + key_tracker.insert(key.to_vec(), has_been_written); + read_write_tracker.add_write(); + } else { + read_write_tracker.add_repeat_write(); + } + } + } + } } fn state_err() -> String { @@ -121,10 +243,12 @@ impl StateBackend> for BenchmarkingState { type TrieBackendStorage = as StateBackend>>::TrieBackendStorage; fn storage(&self, key: &[u8]) -> Result>, Self::Error> { + self.add_read_key(key); self.state.borrow().as_ref().ok_or_else(state_err)?.storage(key) } fn storage_hash(&self, key: &[u8]) -> Result, Self::Error> { + self.add_read_key(key); self.state.borrow().as_ref().ok_or_else(state_err)?.storage_hash(key) } @@ -133,10 +257,12 @@ impl StateBackend> for BenchmarkingState { child_info: &ChildInfo, key: &[u8], ) -> Result>, Self::Error> { + self.add_read_key(key); self.state.borrow().as_ref().ok_or_else(state_err)?.child_storage(child_info, key) } fn exists_storage(&self, key: &[u8]) -> Result { + self.add_read_key(key); self.state.borrow().as_ref().ok_or_else(state_err)?.exists_storage(key) } @@ -145,10 +271,12 @@ impl StateBackend> for BenchmarkingState { child_info: &ChildInfo, key: &[u8], ) -> Result { + self.add_read_key(key); self.state.borrow().as_ref().ok_or_else(state_err)?.exists_child_storage(child_info, key) } fn next_storage_key(&self, key: &[u8]) -> Result>, Self::Error> { + self.add_read_key(key); self.state.borrow().as_ref().ok_or_else(state_err)?.next_storage_key(key) } @@ -157,6 +285,7 @@ impl StateBackend> for BenchmarkingState { child_info: &ChildInfo, key: &[u8], ) -> Result>, Self::Error> { + self.add_read_key(key); self.state.borrow().as_ref().ok_or_else(state_err)?.next_child_storage_key(child_info, key) } @@ -230,8 +359,11 @@ impl StateBackend> for BenchmarkingState { None } - fn commit(&self, storage_root: as Hasher>::Out, mut transaction: Self::Transaction) - -> Result<(), Self::Error> + fn commit(&self, + storage_root: as Hasher>::Out, + mut transaction: Self::Transaction, + storage_changes: StorageCollection, + ) -> Result<(), Self::Error> { if let Some(db) = self.db.take() { let mut db_transaction = DBTransaction::new(); @@ -245,10 +377,17 @@ impl StateBackend> for BenchmarkingState { } keys.push(key); } - self.record.set(keys); + let mut record = self.record.take(); + record.extend(keys); + self.record.set(record); db.write(db_transaction).map_err(|_| String::from("Error committing transaction"))?; self.root.set(storage_root); - self.db.set(Some(db)) + self.db.set(Some(db)); + + // Track DB Writes + storage_changes.iter().for_each(|(key, _)| { + self.add_write_key(key); + }); } else { return Err("Trying to commit to a closed db".into()) } @@ -272,9 +411,25 @@ impl StateBackend> for BenchmarkingState { self.root.set(self.genesis_root.clone()); self.reopen()?; + self.wipe_tracker(); Ok(()) } + /// Get the key tracking information for the state db. + fn read_write_count(&self) -> (u32, u32, u32, u32) { + let count = *self.read_write_tracker.borrow_mut(); + (count.reads, count.repeat_reads, count.writes, count.repeat_writes) + } + + /// Reset the key tracking information for the state db. + fn reset_read_write_count(&self) { + self.wipe_tracker() + } + + fn set_whitelist(&self, new: Vec>) { + *self.whitelist.borrow_mut() = new; + } + fn register_overlay_stats(&mut self, stats: &sp_state_machine::StateMachineStats) { self.state.borrow_mut().as_mut().map(|s| s.register_overlay_stats(stats)); } diff --git a/frame/benchmarking/src/analysis.rs b/frame/benchmarking/src/analysis.rs index 0446430975550..621f3a2941ff5 100644 --- a/frame/benchmarking/src/analysis.rs +++ b/frame/benchmarking/src/analysis.rs @@ -29,24 +29,40 @@ pub struct Analysis { model: Option, } +pub enum BenchmarkSelector { + ExtrinsicTime, + StorageRootTime, + Reads, + Writes, +} + impl Analysis { - pub fn median_slopes(r: &Vec) -> Option { - let results = r[0].0.iter().enumerate().map(|(i, &(param, _))| { + pub fn median_slopes(r: &Vec, selector: BenchmarkSelector) -> Option { + let results = r[0].components.iter().enumerate().map(|(i, &(param, _))| { let mut counted = BTreeMap::, usize>::new(); - for (params, _, _) in r.iter() { - let mut p = params.iter().map(|x| x.1).collect::>(); + for result in r.iter() { + let mut p = result.components.iter().map(|x| x.1).collect::>(); p[i] = 0; *counted.entry(p).or_default() += 1; } let others: Vec = counted.iter().max_by_key(|i| i.1).expect("r is not empty; qed").0.clone(); let values = r.iter() .filter(|v| - v.0.iter() + v.components.iter() .map(|x| x.1) .zip(others.iter()) .enumerate() .all(|(j, (v1, v2))| j == i || v1 == *v2) - ).map(|(ps, v, _)| (ps[i].1, *v)) + ).map(|result| { + // Extract the data we are interested in analyzing + let data = match selector { + BenchmarkSelector::ExtrinsicTime => result.extrinsic_time, + BenchmarkSelector::StorageRootTime => result.storage_root_time, + BenchmarkSelector::Reads => result.reads.into(), + BenchmarkSelector::Writes => result.writes.into(), + }; + (result.components[i].1, data) + }) .collect::>(); (format!("{:?}", param), i, others, values) }).collect::>(); @@ -97,12 +113,18 @@ impl Analysis { }) } - pub fn min_squares_iqr(r: &Vec) -> Option { + pub fn min_squares_iqr(r: &Vec, selector: BenchmarkSelector) -> Option { let mut results = BTreeMap::, Vec>::new(); - for &(ref params, t, _) in r.iter() { - let p = params.iter().map(|x| x.1).collect::>(); - results.entry(p).or_default().push(t); + for result in r.iter() { + let p = result.components.iter().map(|x| x.1).collect::>(); + results.entry(p).or_default().push(match selector { + BenchmarkSelector::ExtrinsicTime => result.extrinsic_time, + BenchmarkSelector::StorageRootTime => result.storage_root_time, + BenchmarkSelector::Reads => result.reads.into(), + BenchmarkSelector::Writes => result.writes.into(), + }) } + for (_, rs) in results.iter_mut() { rs.sort(); let ql = rs.len() / 4; @@ -111,7 +133,7 @@ impl Analysis { let mut data = vec![("Y", results.iter().flat_map(|x| x.1.iter().map(|v| *v as f64)).collect())]; - let names = r[0].0.iter().map(|x| format!("{:?}", x.0)).collect::>(); + let names = r[0].components.iter().map(|x| format!("{:?}", x.0)).collect::>(); data.extend(names.iter() .enumerate() .map(|(i, p)| ( @@ -217,40 +239,88 @@ impl std::fmt::Display for Analysis { } } +impl std::fmt::Debug for Analysis { + fn fmt(&self, f: &mut std::fmt::Formatter) -> std::fmt::Result { + write!(f, "{}", self.base)?; + for (&m, n) in self.slopes.iter().zip(self.names.iter()) { + write!(f, " + ({} * {})", m, n)?; + } + write!(f,"") + } +} + #[cfg(test)] mod tests { use super::*; use crate::BenchmarkParameter; + fn benchmark_result( + components: Vec<(BenchmarkParameter, u32)>, + extrinsic_time: u128, + storage_root_time: u128, + reads: u32, + writes: u32, + ) -> BenchmarkResults { + BenchmarkResults { + components, + extrinsic_time, + storage_root_time, + reads, + repeat_reads: 0, + writes, + repeat_writes: 0, + } + } + #[test] fn analysis_median_slopes_should_work() { - let a = Analysis::median_slopes(&vec![ - (vec![(BenchmarkParameter::n, 1), (BenchmarkParameter::m, 5)], 11_500_000, 0), - (vec![(BenchmarkParameter::n, 2), (BenchmarkParameter::m, 5)], 12_500_000, 0), - (vec![(BenchmarkParameter::n, 3), (BenchmarkParameter::m, 5)], 13_500_000, 0), - (vec![(BenchmarkParameter::n, 4), (BenchmarkParameter::m, 5)], 14_500_000, 0), - (vec![(BenchmarkParameter::n, 3), (BenchmarkParameter::m, 1)], 13_100_000, 0), - (vec![(BenchmarkParameter::n, 3), (BenchmarkParameter::m, 3)], 13_300_000, 0), - (vec![(BenchmarkParameter::n, 3), (BenchmarkParameter::m, 7)], 13_700_000, 0), - (vec![(BenchmarkParameter::n, 3), (BenchmarkParameter::m, 10)], 14_000_000, 0), - ]).unwrap(); - assert_eq!(a.base, 10_000_000); - assert_eq!(a.slopes, vec![1_000_000, 100_000]); + let data = vec![ + benchmark_result(vec![(BenchmarkParameter::n, 1), (BenchmarkParameter::m, 5)], 11_500_000, 0, 3, 10), + benchmark_result(vec![(BenchmarkParameter::n, 2), (BenchmarkParameter::m, 5)], 12_500_000, 0, 4, 10), + benchmark_result(vec![(BenchmarkParameter::n, 3), (BenchmarkParameter::m, 5)], 13_500_000, 0, 5, 10), + benchmark_result(vec![(BenchmarkParameter::n, 4), (BenchmarkParameter::m, 5)], 14_500_000, 0, 6, 10), + benchmark_result(vec![(BenchmarkParameter::n, 3), (BenchmarkParameter::m, 1)], 13_100_000, 0, 5, 2), + benchmark_result(vec![(BenchmarkParameter::n, 3), (BenchmarkParameter::m, 3)], 13_300_000, 0, 5, 6), + benchmark_result(vec![(BenchmarkParameter::n, 3), (BenchmarkParameter::m, 7)], 13_700_000, 0, 5, 14), + benchmark_result(vec![(BenchmarkParameter::n, 3), (BenchmarkParameter::m, 10)], 14_000_000, 0, 5, 20), + ]; + + let extrinsic_time = Analysis::median_slopes(&data, BenchmarkSelector::ExtrinsicTime).unwrap(); + assert_eq!(extrinsic_time.base, 10_000_000); + assert_eq!(extrinsic_time.slopes, vec![1_000_000, 100_000]); + + let reads = Analysis::median_slopes(&data, BenchmarkSelector::Reads).unwrap(); + assert_eq!(reads.base, 2); + assert_eq!(reads.slopes, vec![1, 0]); + + let writes = Analysis::median_slopes(&data, BenchmarkSelector::Writes).unwrap(); + assert_eq!(writes.base, 0); + assert_eq!(writes.slopes, vec![0, 2]); } #[test] fn analysis_median_min_squares_should_work() { - let a = Analysis::min_squares_iqr(&vec![ - (vec![(BenchmarkParameter::n, 1), (BenchmarkParameter::m, 5)], 11_500_000, 0), - (vec![(BenchmarkParameter::n, 2), (BenchmarkParameter::m, 5)], 12_500_000, 0), - (vec![(BenchmarkParameter::n, 3), (BenchmarkParameter::m, 5)], 13_500_000, 0), - (vec![(BenchmarkParameter::n, 4), (BenchmarkParameter::m, 5)], 14_500_000, 0), - (vec![(BenchmarkParameter::n, 3), (BenchmarkParameter::m, 1)], 13_100_000, 0), - (vec![(BenchmarkParameter::n, 3), (BenchmarkParameter::m, 3)], 13_300_000, 0), - (vec![(BenchmarkParameter::n, 3), (BenchmarkParameter::m, 7)], 13_700_000, 0), - (vec![(BenchmarkParameter::n, 3), (BenchmarkParameter::m, 10)], 14_000_000, 0), - ]).unwrap(); - assert_eq!(a.base, 10_000_000); - assert_eq!(a.slopes, vec![1_000_000, 100_000]); + let data = vec![ + benchmark_result(vec![(BenchmarkParameter::n, 1), (BenchmarkParameter::m, 5)], 11_500_000, 0, 3, 10), + benchmark_result(vec![(BenchmarkParameter::n, 2), (BenchmarkParameter::m, 5)], 12_500_000, 0, 4, 10), + benchmark_result(vec![(BenchmarkParameter::n, 3), (BenchmarkParameter::m, 5)], 13_500_000, 0, 5, 10), + benchmark_result(vec![(BenchmarkParameter::n, 4), (BenchmarkParameter::m, 5)], 14_500_000, 0, 6, 10), + benchmark_result(vec![(BenchmarkParameter::n, 3), (BenchmarkParameter::m, 1)], 13_100_000, 0, 5, 2), + benchmark_result(vec![(BenchmarkParameter::n, 3), (BenchmarkParameter::m, 3)], 13_300_000, 0, 5, 6), + benchmark_result(vec![(BenchmarkParameter::n, 3), (BenchmarkParameter::m, 7)], 13_700_000, 0, 5, 14), + benchmark_result(vec![(BenchmarkParameter::n, 3), (BenchmarkParameter::m, 10)], 14_000_000, 0, 5, 20), + ]; + + let extrinsic_time = Analysis::min_squares_iqr(&data, BenchmarkSelector::ExtrinsicTime).unwrap(); + assert_eq!(extrinsic_time.base, 10_000_000); + assert_eq!(extrinsic_time.slopes, vec![1_000_000, 100_000]); + + let reads = Analysis::min_squares_iqr(&data, BenchmarkSelector::Reads).unwrap(); + assert_eq!(reads.base, 2); + assert_eq!(reads.slopes, vec![1, 0]); + + let writes = Analysis::min_squares_iqr(&data, BenchmarkSelector::Writes).unwrap(); + assert_eq!(writes.base, 0); + assert_eq!(writes.slopes, vec![0, 2]); } } diff --git a/frame/benchmarking/src/lib.rs b/frame/benchmarking/src/lib.rs index 7cbac3397a978..7a7848305a01c 100644 --- a/frame/benchmarking/src/lib.rs +++ b/frame/benchmarking/src/lib.rs @@ -26,7 +26,7 @@ mod analysis; pub use utils::*; #[cfg(feature = "std")] -pub use analysis::Analysis; +pub use analysis::{Analysis, BenchmarkSelector}; #[doc(hidden)] pub use sp_io::storage::root as storage_root; pub use sp_runtime::traits::Zero; @@ -771,6 +771,7 @@ macro_rules! impl_benchmark { highest_range_values: &[u32], steps: &[u32], repeat: u32, + whitelist: &[Vec] ) -> Result, &'static str> { // Map the input to the selected benchmark. let extrinsic = sp_std::str::from_utf8(extrinsic) @@ -780,6 +781,9 @@ macro_rules! impl_benchmark { _ => return Err("Could not find extrinsic."), }; + // Add whitelist to DB + $crate::benchmarking::set_whitelist(whitelist.to_vec()); + // Warm up the DB $crate::benchmarking::commit_db(); $crate::benchmarking::wipe_db(); @@ -841,6 +845,9 @@ macro_rules! impl_benchmark { // This will enable worst case scenario for reading from the database. $crate::benchmarking::commit_db(); + // Reset the read/write counter so we don't count operations in the setup process. + $crate::benchmarking::reset_read_write_count(); + // Time the extrinsic logic. frame_support::debug::trace!( target: "benchmark", @@ -851,11 +858,17 @@ macro_rules! impl_benchmark { closure_to_benchmark()?; let finish_extrinsic = $crate::benchmarking::current_time(); let elapsed_extrinsic = finish_extrinsic - start_extrinsic; - + // Commit the changes to get proper write count + $crate::benchmarking::commit_db(); frame_support::debug::trace!( target: "benchmark", "End Benchmark: {} ns", elapsed_extrinsic ); + let read_write_count = $crate::benchmarking::read_write_count(); + frame_support::debug::trace!( + target: "benchmark", + "Read/Write Count {:?}", read_write_count + ); // Time the storage root recalculation. let start_storage_root = $crate::benchmarking::current_time(); @@ -863,7 +876,15 @@ macro_rules! impl_benchmark { let finish_storage_root = $crate::benchmarking::current_time(); let elapsed_storage_root = finish_storage_root - start_storage_root; - results.push((c.clone(), elapsed_extrinsic, elapsed_storage_root)); + results.push($crate::BenchmarkResults { + components: c.clone(), + extrinsic_time: elapsed_extrinsic, + storage_root_time: elapsed_storage_root, + reads: read_write_count.0, + repeat_reads: read_write_count.1, + writes: read_write_count.2, + repeat_writes: read_write_count.3, + }); // Wipe the DB back to the genesis state. $crate::benchmarking::wipe_db(); @@ -892,6 +913,7 @@ macro_rules! impl_benchmark { highest_range_values: &[u32], steps: &[u32], repeat: u32, + whitelist: &[Vec] ) -> Result, &'static str> { // Map the input to the selected benchmark. let extrinsic = sp_std::str::from_utf8(extrinsic) @@ -901,6 +923,9 @@ macro_rules! impl_benchmark { _ => return Err("Could not find extrinsic."), }; + // Add whitelist to DB + $crate::benchmarking::set_whitelist(whitelist.to_vec()); + // Warm up the DB $crate::benchmarking::commit_db(); $crate::benchmarking::wipe_db(); @@ -963,6 +988,9 @@ macro_rules! impl_benchmark { // This will enable worst case scenario for reading from the database. $crate::benchmarking::commit_db(); + // Reset the read/write counter so we don't count operations in the setup process. + $crate::benchmarking::reset_read_write_count(); + // Time the extrinsic logic. frame_support::debug::trace!( target: "benchmark", @@ -973,11 +1001,17 @@ macro_rules! impl_benchmark { closure_to_benchmark()?; let finish_extrinsic = $crate::benchmarking::current_time(); let elapsed_extrinsic = finish_extrinsic - start_extrinsic; - + // Commit the changes to get proper write count + $crate::benchmarking::commit_db(); frame_support::debug::trace!( target: "benchmark", "End Benchmark: {} ns", elapsed_extrinsic ); + let read_write_count = $crate::benchmarking::read_write_count(); + frame_support::debug::trace!( + target: "benchmark", + "Read/Write Count {:?}", read_write_count + ); // Time the storage root recalculation. let start_storage_root = $crate::benchmarking::current_time(); @@ -985,7 +1019,15 @@ macro_rules! impl_benchmark { let finish_storage_root = $crate::benchmarking::current_time(); let elapsed_storage_root = finish_storage_root - start_storage_root; - results.push((c.clone(), elapsed_extrinsic, elapsed_storage_root)); + results.push($crate::BenchmarkResults { + components: c.clone(), + extrinsic_time: elapsed_extrinsic, + storage_root_time: elapsed_storage_root, + reads: read_write_count.0, + repeat_reads: read_write_count.1, + writes: read_write_count.2, + repeat_writes: read_write_count.3, + }); // Wipe the DB back to the genesis state. $crate::benchmarking::wipe_db(); @@ -1139,7 +1181,7 @@ macro_rules! impl_benchmark_test { #[macro_export] macro_rules! add_benchmark { ( $params:ident, $batches:ident, $name:literal, $( $location:tt )* ) => ( - let (pallet, benchmark, lowest_range_values, highest_range_values, steps, repeat) = $params; + let (pallet, benchmark, lowest_range_values, highest_range_values, steps, repeat, whitelist) = $params; if &pallet[..] == &$name[..] || &pallet[..] == &b"*"[..] { if &pallet[..] == &b"*"[..] || &benchmark[..] == &b"*"[..] { for benchmark in $( $location )*::benchmarks().into_iter() { @@ -1150,6 +1192,7 @@ macro_rules! add_benchmark { &highest_range_values[..], &steps[..], repeat, + whitelist, )?, pallet: $name.to_vec(), benchmark: benchmark.to_vec(), @@ -1163,6 +1206,7 @@ macro_rules! add_benchmark { &highest_range_values[..], &steps[..], repeat, + whitelist, )?, pallet: $name.to_vec(), benchmark: benchmark.clone(), diff --git a/frame/benchmarking/src/utils.rs b/frame/benchmarking/src/utils.rs index 31ec3783cc061..7f9d9121100e3 100644 --- a/frame/benchmarking/src/utils.rs +++ b/frame/benchmarking/src/utils.rs @@ -44,7 +44,16 @@ pub struct BenchmarkBatch { /// Results from running benchmarks on a FRAME pallet. /// Contains duration of the function call in nanoseconds along with the benchmark parameters /// used for that benchmark result. -pub type BenchmarkResults = (Vec<(BenchmarkParameter, u32)>, u128, u128); +#[derive(Encode, Decode, Default, Clone, PartialEq, Debug)] +pub struct BenchmarkResults { + pub components: Vec<(BenchmarkParameter, u32)>, + pub extrinsic_time: u128, + pub storage_root_time: u128, + pub reads: u32, + pub repeat_reads: u32, + pub writes: u32, + pub repeat_writes: u32, +} sp_api::decl_runtime_apis! { /// Runtime api for benchmarking a FRAME runtime. @@ -83,6 +92,20 @@ pub trait Benchmarking { fn commit_db(&mut self) { self.commit() } + + /// Get the read/write count + fn read_write_count(&self) -> (u32, u32, u32, u32) { + self.read_write_count() + } + + /// Reset the read/write count + fn reset_read_write_count(&mut self) { + self.reset_read_write_count() + } + + fn set_whitelist(&mut self, new: Vec>) { + self.set_whitelist(new) + } } /// The pallet benchmarking trait. @@ -106,6 +129,7 @@ pub trait Benchmarking { highest_range_values: &[u32], steps: &[u32], repeat: u32, + whitelist: &[Vec] ) -> Result, &'static str>; } diff --git a/primitives/externalities/src/lib.rs b/primitives/externalities/src/lib.rs index 210fe5b4ef009..8e141867195b7 100644 --- a/primitives/externalities/src/lib.rs +++ b/primitives/externalities/src/lib.rs @@ -233,6 +233,27 @@ pub trait Externalities: ExtensionStore { /// /// Commits all changes to the database and clears all caches. fn commit(&mut self); + + /// !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! + /// Benchmarking related functionality and shouldn't be used anywhere else! + /// !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! + /// + /// Gets the current read/write count for the benchmarking process. + fn read_write_count(&self) -> (u32, u32, u32, u32); + + /// !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! + /// Benchmarking related functionality and shouldn't be used anywhere else! + /// !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! + /// + /// Resets read/write count for the benchmarking process. + fn reset_read_write_count(&mut self); + + /// !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! + /// Benchmarking related functionality and shouldn't be used anywhere else! + /// !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! + /// + /// Adds new storage keys to the DB tracking whitelist. + fn set_whitelist(&mut self, new: Vec>); } /// Extension for the [`Externalities`] trait. diff --git a/primitives/runtime-interface/src/impls.rs b/primitives/runtime-interface/src/impls.rs index 217316c3dd79c..259d3517f001d 100644 --- a/primitives/runtime-interface/src/impls.rs +++ b/primitives/runtime-interface/src/impls.rs @@ -365,6 +365,10 @@ impl PassBy for Option { type PassBy = Codec; } +impl PassBy for (u32, u32, u32, u32) { + type PassBy = Codec; +} + /// Implement `PassBy` with `Inner` for the given fixed sized hash types. macro_rules! for_primitive_types { { $( $hash:ident $n:expr ),* $(,)? } => { diff --git a/primitives/state-machine/src/backend.rs b/primitives/state-machine/src/backend.rs index 20a3ab7500a98..9ec03c4d1e249 100644 --- a/primitives/state-machine/src/backend.rs +++ b/primitives/state-machine/src/backend.rs @@ -212,7 +212,22 @@ pub trait Backend: std::fmt::Debug { } /// Commit given transaction to storage. - fn commit(&self, _: H::Out, _: Self::Transaction) -> Result<(), Self::Error> { + fn commit(&self, _: H::Out, _: Self::Transaction, _: StorageCollection) -> Result<(), Self::Error> { + unimplemented!() + } + + /// Get the read/write count of the db + fn read_write_count(&self) -> (u32, u32, u32, u32) { + unimplemented!() + } + + /// Get the read/write count of the db + fn reset_read_write_count(&self) { + unimplemented!() + } + + /// Update the whitelist for tracking db reads/writes + fn set_whitelist(&self, _: Vec>) { unimplemented!() } } diff --git a/primitives/state-machine/src/basic.rs b/primitives/state-machine/src/basic.rs index dbb4c6c2b82f2..6f1d2a4b5ad91 100644 --- a/primitives/state-machine/src/basic.rs +++ b/primitives/state-machine/src/basic.rs @@ -322,6 +322,18 @@ impl Externalities for BasicExternalities { fn wipe(&mut self) {} fn commit(&mut self) {} + + fn read_write_count(&self) -> (u32, u32, u32, u32) { + unimplemented!("read_write_count is not supported in Basic") + } + + fn reset_read_write_count(&mut self) { + unimplemented!("reset_read_write_count is not supported in Basic") + } + + fn set_whitelist(&mut self, _: Vec>) { + unimplemented!("set_whitelist is not supported in Basic") + } } impl sp_externalities::ExtensionStore for BasicExternalities { diff --git a/primitives/state-machine/src/ext.rs b/primitives/state-machine/src/ext.rs index 2cd63cde975de..e25a08adb0423 100644 --- a/primitives/state-machine/src/ext.rs +++ b/primitives/state-machine/src/ext.rs @@ -590,9 +590,22 @@ where self.backend.commit( changes.transaction_storage_root, changes.transaction, + changes.main_storage_changes, ).expect(EXT_NOT_ALLOWED_TO_FAIL); self.mark_dirty(); } + + fn read_write_count(&self) -> (u32, u32, u32, u32) { + self.backend.read_write_count() + } + + fn reset_read_write_count(&mut self) { + self.backend.reset_read_write_count() + } + + fn set_whitelist(&mut self, new: Vec>) { + self.backend.set_whitelist(new) + } } diff --git a/primitives/state-machine/src/read_only.rs b/primitives/state-machine/src/read_only.rs index 2a5d7fda364de..b8a35ced1eb0c 100644 --- a/primitives/state-machine/src/read_only.rs +++ b/primitives/state-machine/src/read_only.rs @@ -185,6 +185,18 @@ impl<'a, H: Hasher, B: 'a + Backend> Externalities for ReadOnlyExternalities< fn wipe(&mut self) {} fn commit(&mut self) {} + + fn read_write_count(&self) -> (u32, u32, u32, u32) { + unimplemented!("read_write_count is not supported in ReadOnlyExternalities") + } + + fn reset_read_write_count(&mut self) { + unimplemented!("reset_read_write_count is not supported in ReadOnlyExternalities") + } + + fn set_whitelist(&mut self, _: Vec>) { + unimplemented!("set_whitelist is not supported in ReadOnlyExternalities") + } } impl<'a, H: Hasher, B: 'a + Backend> sp_externalities::ExtensionStore for ReadOnlyExternalities<'a, H, B> { diff --git a/utils/frame/benchmarking-cli/src/command.rs b/utils/frame/benchmarking-cli/src/command.rs index f867d75d2ab17..7f55672885d46 100644 --- a/utils/frame/benchmarking-cli/src/command.rs +++ b/utils/frame/benchmarking-cli/src/command.rs @@ -17,7 +17,7 @@ use crate::BenchmarkCmd; use codec::{Decode, Encode}; -use frame_benchmarking::{Analysis, BenchmarkBatch}; +use frame_benchmarking::{Analysis, BenchmarkBatch, BenchmarkSelector}; use sc_cli::{SharedParams, CliConfiguration, ExecutionStrategy, Result}; use sc_client_db::BenchmarkingState; use sc_executor::NativeExecutor; @@ -107,15 +107,22 @@ impl BenchmarkCmd { if self.raw_data { // Print the table header - batch.results[0].0.iter().for_each(|param| print!("{:?},", param.0)); + batch.results[0].components.iter().for_each(|param| print!("{:?},", param.0)); - print!("extrinsic_time,storage_root_time\n"); + print!("extrinsic_time,storage_root_time,reads,repeat_reads,writes,repeat_writes\n"); // Print the values batch.results.iter().for_each(|result| { - let parameters = &result.0; + let parameters = &result.components; parameters.iter().for_each(|param| print!("{:?},", param.1)); // Print extrinsic time and storage root time - print!("{:?},{:?}\n", result.1, result.2); + print!("{:?},{:?},{:?},{:?},{:?},{:?}\n", + result.extrinsic_time, + result.storage_root_time, + result.reads, + result.repeat_reads, + result.writes, + result.repeat_writes, + ); }); println!(); @@ -123,13 +130,27 @@ impl BenchmarkCmd { // Conduct analysis. if !self.no_median_slopes { - if let Some(analysis) = Analysis::median_slopes(&batch.results) { - println!("Median Slopes Analysis\n========\n{}", analysis); + println!("Median Slopes Analysis\n========"); + if let Some(analysis) = Analysis::median_slopes(&batch.results, BenchmarkSelector::ExtrinsicTime) { + println!("-- Extrinsic Time --\n{}", analysis); + } + if let Some(analysis) = Analysis::median_slopes(&batch.results, BenchmarkSelector::Reads) { + println!("Reads = {:?}", analysis); + } + if let Some(analysis) = Analysis::median_slopes(&batch.results, BenchmarkSelector::Writes) { + println!("Writes = {:?}", analysis); } } if !self.no_min_squares { - if let Some(analysis) = Analysis::min_squares_iqr(&batch.results) { - println!("Min Squares Analysis\n========\n{}", analysis); + println!("Min Squares Analysis\n========"); + if let Some(analysis) = Analysis::min_squares_iqr(&batch.results, BenchmarkSelector::ExtrinsicTime) { + println!("-- Extrinsic Time --\n{}", analysis); + } + if let Some(analysis) = Analysis::min_squares_iqr(&batch.results, BenchmarkSelector::Reads) { + println!("Reads = {:?}", analysis); + } + if let Some(analysis) = Analysis::min_squares_iqr(&batch.results, BenchmarkSelector::Writes) { + println!("Writes = {:?}", analysis); } } },