From dcc2b10efaa9c4f6706f7fb81d1319ef0f07dde9 Mon Sep 17 00:00:00 2001 From: sakridge Date: Wed, 16 Dec 2020 17:17:03 -0800 Subject: [PATCH] Add timings for store accounts (#12882) (#14169) --- runtime/src/accounts_db.rs | 105 +++++++++++++++++++++++++++++++++++++ 1 file changed, 105 insertions(+) diff --git a/runtime/src/accounts_db.rs b/runtime/src/accounts_db.rs index f98e5ad1c5..76ec91cd80 100644 --- a/runtime/src/accounts_db.rs +++ b/runtime/src/accounts_db.rs @@ -461,6 +461,16 @@ struct AccountsStats { delta_hash_accumulate_time_total_us: AtomicU64, delta_hash_merge_time_total_us: AtomicU64, delta_hash_num: AtomicU64, + + last_store_report: AtomicU64, + store_hash_accounts: AtomicU64, + store_accounts: AtomicU64, + store_update_index: AtomicU64, + store_handle_reclaims: AtomicU64, + store_append_accounts: AtomicU64, + store_find_store: AtomicU64, + store_num_accounts: AtomicU64, + store_total_data: AtomicU64, } fn make_min_priority_thread_pool() -> ThreadPool { @@ -1786,11 +1796,19 @@ impl AccountsDB { }) .collect(); let mut infos: Vec = Vec::with_capacity(with_meta.len()); + let mut total_append_accounts_us = 0; + let mut total_storage_find_us = 0; while infos.len() < with_meta.len() { + let mut storage_find = Measure::start("storage_finder"); let storage = storage_finder(slot); + storage_find.stop(); + total_storage_find_us += storage_find.as_us(); + let mut append_accounts = Measure::start("append_accounts"); let rvs = storage .accounts .append_accounts(&with_meta[infos.len()..], &hashes[infos.len()..]); + append_accounts.stop(); + total_append_accounts_us += append_accounts.as_us(); if rvs.is_empty() { storage.set_status(AccountStorageStatus::Full); @@ -1812,6 +1830,13 @@ impl AccountsDB { // restore the state to available storage.set_status(AccountStorageStatus::Available); } + self.stats + .store_append_accounts + .fetch_add(total_append_accounts_us, Ordering::Relaxed); + self.stats + .store_find_store + .fetch_add(total_storage_find_us, Ordering::Relaxed); + infos } @@ -2285,14 +2310,20 @@ impl AccountsDB { cluster_type: &ClusterType, ) -> Vec { let mut stats = BankHashStats::default(); + let mut total_data = 0; let hashes: Vec<_> = accounts .iter() .map(|(pubkey, account)| { + total_data += account.data.len(); stats.update(account); Self::hash_account(slot, account, pubkey, cluster_type) }) .collect(); + self.stats + .store_total_data + .fetch_add(total_data as u64, Ordering::Relaxed); + let mut bank_hashes = self.bank_hashes.write().unwrap(); let slot_info = bank_hashes .entry(slot) @@ -2354,6 +2385,7 @@ impl AccountsDB { /// Store the account update. pub fn store(&self, slot: Slot, accounts: &[(&Pubkey, &Account)]) { self.assert_frozen_accounts(accounts); + let mut hash_time = Measure::start("hash_accounts"); let hashes = self.hash_accounts( slot, accounts, @@ -2361,7 +2393,12 @@ impl AccountsDB { .cluster_type .expect("Cluster type must be set at initialization"), ); + hash_time.stop(); + self.stats + .store_hash_accounts + .fetch_add(hash_time.as_us(), Ordering::Relaxed); self.store_accounts_default(slot, accounts, &hashes); + self.report_store_timings(); } fn store_accounts_default<'a>( @@ -2400,6 +2437,9 @@ impl AccountsDB { })) }); + self.stats + .store_num_accounts + .fetch_add(accounts.len() as u64, Ordering::Relaxed); let mut store_accounts_time = Measure::start("store_accounts"); let infos = self.store_accounts_to( slot, @@ -2409,10 +2449,16 @@ impl AccountsDB { write_version_producer, ); store_accounts_time.stop(); + self.stats + .store_accounts + .fetch_add(store_accounts_time.as_us(), Ordering::Relaxed); let mut update_index_time = Measure::start("update_index"); let reclaims = self.update_index(slot, infos, accounts); update_index_time.stop(); + self.stats + .store_update_index + .fetch_add(update_index_time.as_us(), Ordering::Relaxed); // A store for a single slot should: // 1) Only make "reclaims" for the same slot @@ -2425,6 +2471,9 @@ impl AccountsDB { let mut handle_reclaims_time = Measure::start("handle_reclaims"); self.handle_reclaims(&reclaims, Some(slot), true, None); handle_reclaims_time.stop(); + self.stats + .store_handle_reclaims + .fetch_add(handle_reclaims_time.as_us(), Ordering::Relaxed); StoreAccountsTiming { store_accounts_elapsed: store_accounts_time.as_us(), @@ -2433,6 +2482,62 @@ impl AccountsDB { } } + fn report_store_timings(&self) { + let last = self.stats.last_store_report.load(Ordering::Relaxed); + let now = solana_sdk::timing::timestamp(); + if now - last > 1000 + && self + .stats + .last_store_report + .compare_and_swap(last, now, Ordering::Relaxed) + == last + { + datapoint_info!( + "accounts_db_store_timings", + ( + "hash_accounts", + self.stats.store_hash_accounts.swap(0, Ordering::Relaxed), + i64 + ), + ( + "store_accounts", + self.stats.store_accounts.swap(0, Ordering::Relaxed), + i64 + ), + ( + "update_index", + self.stats.store_update_index.swap(0, Ordering::Relaxed), + i64 + ), + ( + "handle_reclaims", + self.stats.store_handle_reclaims.swap(0, Ordering::Relaxed), + i64 + ), + ( + "append_accounts", + self.stats.store_append_accounts.swap(0, Ordering::Relaxed), + i64 + ), + ( + "find_storage", + self.stats.store_find_store.swap(0, Ordering::Relaxed), + i64 + ), + ( + "num_accounts", + self.stats.store_num_accounts.swap(0, Ordering::Relaxed), + i64 + ), + ( + "total_data", + self.stats.store_total_data.swap(0, Ordering::Relaxed), + i64 + ), + ); + } + } + pub fn add_root(&self, slot: Slot) { self.accounts_index.add_root(slot) }