diff --git a/Cargo.lock b/Cargo.lock index c6fbf9ba7b..280af1f8c0 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -5701,6 +5701,7 @@ version = "1.10.0" dependencies = [ "base64 0.13.0", "bincode", + "enum-iterator", "itertools 0.10.3", "libc", "libloading", diff --git a/core/src/progress_map.rs b/core/src/progress_map.rs index f6af353466..7e9f083a12 100644 --- a/core/src/progress_map.rs +++ b/core/src/progress_map.rs @@ -1,3 +1,6 @@ +use solana_program_runtime::timings::ExecuteTimingType; +use std::ops::Index; + use { crate::{ cluster_info_vote_listener::SlotVoteTracker, @@ -62,23 +65,60 @@ impl ReplaySlotStats { ), ("total_entries", num_entries as i64, i64), ("total_shreds", num_shreds as i64, i64), - ("check_us", self.execute_timings.check_us, i64), - ("load_us", self.execute_timings.load_us, i64), - ("execute_us", self.execute_timings.execute_us, i64), - ("store_us", self.execute_timings.store_us, i64), + ( + "check_us", + *self + .execute_timings + .metrics + .index(ExecuteTimingType::CheckUs), + i64 + ), + ( + "load_us", + *self + .execute_timings + .metrics + .index(ExecuteTimingType::LoadUs), + i64 + ), + ( + "execute_us", + *self + .execute_timings + .metrics + .index(ExecuteTimingType::ExecuteUs), + i64 + ), + ( + "store_us", + *self + .execute_timings + .metrics + .index(ExecuteTimingType::StoreUs), + i64 + ), ( "update_stakes_cache_us", - self.execute_timings.update_stakes_cache_us, + *self + .execute_timings + .metrics + .index(ExecuteTimingType::UpdateStakesCacheUs), i64 ), ( "total_batches_len", - self.execute_timings.total_batches_len, + *self + .execute_timings + .metrics + .index(ExecuteTimingType::TotalBatchesLen), i64 ), ( "num_execute_batches", - self.execute_timings.num_execute_batches, + *self + .execute_timings + .metrics + .index(ExecuteTimingType::NumExecuteBatches), i64 ), ( diff --git a/ledger/src/blockstore_processor.rs b/ledger/src/blockstore_processor.rs index 00ce996cf7..ec9deba79a 100644 --- a/ledger/src/blockstore_processor.rs +++ b/ledger/src/blockstore_processor.rs @@ -1,3 +1,5 @@ +use solana_program_runtime::timings::ExecuteTimingType; + use { crate::{ block_error::BlockError, blockstore::Blockstore, blockstore_db::BlockstoreError, @@ -283,8 +285,8 @@ fn execute_batches_internal( }) }); - timings.total_batches_len += batches.len(); - timings.num_execute_batches += 1; + timings.saturating_add_in_place(ExecuteTimingType::TotalBatchesLen, batches.len() as u64); + timings.saturating_add_in_place(ExecuteTimingType::NumExecuteBatches, 1); for timing in new_timings { timings.accumulate(&timing); } diff --git a/program-runtime/Cargo.toml b/program-runtime/Cargo.toml index cb5a4cf334..62de468a3c 100644 --- a/program-runtime/Cargo.toml +++ b/program-runtime/Cargo.toml @@ -24,6 +24,7 @@ solana-frozen-abi-macro = { path = "../frozen-abi/macro", version = "=1.10.0" } solana-measure = { path = "../measure", version = "=1.10.0" } solana-sdk = { path = "../sdk", version = "=1.10.0" } thiserror = "1.0" +enum-iterator = "0.7.0" [dev-dependencies] solana-logger = { path = "../logger", version = "=1.10.0" } diff --git a/program-runtime/src/timings.rs b/program-runtime/src/timings.rs index 1ca577f287..8143493048 100644 --- a/program-runtime/src/timings.rs +++ b/program-runtime/src/timings.rs @@ -1,3 +1,7 @@ +use core::fmt; +use enum_iterator::IntoEnumIterator; +use std::ops::{Index, IndexMut}; + use { solana_sdk::{pubkey::Pubkey, saturating_add_assign}, std::collections::HashMap, @@ -34,34 +38,73 @@ impl ProgramTiming { } } -#[derive(Default, Debug)] +/// Used as an index for `Metrics`. +#[derive(Debug, IntoEnumIterator)] +pub enum ExecuteTimingType { + CheckUs, + LoadUs, + ExecuteUs, + StoreUs, + UpdateStakesCacheUs, + NumExecuteBatches, + CollectLogsUs, + TotalBatchesLen, +} + +pub struct Metrics([u64; ExecuteTimingType::VARIANT_COUNT]); + +impl Index for Metrics { + type Output = u64; + fn index(&self, index: ExecuteTimingType) -> &Self::Output { + self.0.index(index as usize) + } +} + +impl IndexMut for Metrics { + fn index_mut(&mut self, index: ExecuteTimingType) -> &mut Self::Output { + self.0.index_mut(index as usize) + } +} + +impl Default for Metrics { + fn default() -> Self { + Metrics([0; ExecuteTimingType::VARIANT_COUNT]) + } +} + +impl core::fmt::Debug for Metrics { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + self.0.fmt(f) + } +} + +#[derive(Debug, Default)] pub struct ExecuteTimings { - pub check_us: u64, - pub load_us: u64, - pub execute_us: u64, - pub store_us: u64, - pub update_stakes_cache_us: u64, - pub total_batches_len: usize, - pub num_execute_batches: u64, - pub collect_logs_us: u64, + pub metrics: Metrics, pub details: ExecuteDetailsTimings, pub execute_accessories: ExecuteAccessoryTimings, } impl ExecuteTimings { pub fn accumulate(&mut self, other: &ExecuteTimings) { - saturating_add_assign!(self.check_us, other.check_us); - saturating_add_assign!(self.load_us, other.load_us); - saturating_add_assign!(self.execute_us, other.execute_us); - saturating_add_assign!(self.store_us, other.store_us); - saturating_add_assign!(self.update_stakes_cache_us, other.update_stakes_cache_us); - saturating_add_assign!(self.total_batches_len, other.total_batches_len); - saturating_add_assign!(self.num_execute_batches, other.num_execute_batches); - saturating_add_assign!(self.collect_logs_us, other.collect_logs_us); + for (t1, t2) in self.metrics.0.iter_mut().zip(other.metrics.0.iter()) { + saturating_add_assign!(*t1, *t2); + } self.details.accumulate(&other.details); self.execute_accessories .accumulate(&other.execute_accessories); } + + pub fn saturating_add_in_place(&mut self, timing_type: ExecuteTimingType, value_to_add: u64) { + let idx = timing_type as usize; + match self.metrics.0.get_mut(idx) { + Some(elem) => *elem = elem.saturating_add(value_to_add), + None => debug_assert!( + idx < ExecuteTimingType::VARIANT_COUNT, + "Index out of bounds" + ), + } + } } #[derive(Default, Debug)] @@ -275,4 +318,16 @@ mod tests { // Check that the two instances are equal assert_eq!(execute_details_timings, other_execute_details_timings); } + + #[test] + fn execute_timings_saturating_add_in_place() { + let mut timings = ExecuteTimings::default(); + timings.saturating_add_in_place(ExecuteTimingType::CheckUs, 1); + let check_us = timings.metrics.index(ExecuteTimingType::CheckUs); + assert_eq!(1, *check_us); + + timings.saturating_add_in_place(ExecuteTimingType::CheckUs, 2); + let check_us = timings.metrics.index(ExecuteTimingType::CheckUs); + assert_eq!(3, *check_us); + } } diff --git a/programs/bpf/Cargo.lock b/programs/bpf/Cargo.lock index c4744ab486..bb99b19249 100644 --- a/programs/bpf/Cargo.lock +++ b/programs/bpf/Cargo.lock @@ -3445,6 +3445,7 @@ version = "1.10.0" dependencies = [ "base64 0.13.0", "bincode", + "enum-iterator", "itertools 0.10.3", "libc", "libloading", diff --git a/runtime/src/bank.rs b/runtime/src/bank.rs index 866f8a0acf..1cf0a936f3 100644 --- a/runtime/src/bank.rs +++ b/runtime/src/bank.rs @@ -33,6 +33,7 @@ //! It offers a high-level API that signs transactions //! on behalf of the caller, and a low-level API for when they have //! already been signed and verified. +use solana_program_runtime::timings::ExecuteTimingType; #[allow(deprecated)] use solana_sdk::recent_blockhashes_account; use { @@ -4066,9 +4067,10 @@ impl Bank { execution_time.as_us(), sanitized_txs.len(), ); - timings.check_us = timings.check_us.saturating_add(check_time.as_us()); - timings.load_us = timings.load_us.saturating_add(load_time.as_us()); - timings.execute_us = timings.execute_us.saturating_add(execution_time.as_us()); + + timings.saturating_add_in_place(ExecuteTimingType::CheckUs, check_time.as_us()); + timings.saturating_add_in_place(ExecuteTimingType::LoadUs, load_time.as_us()); + timings.saturating_add_in_place(ExecuteTimingType::ExecuteUs, execution_time.as_us()); let mut executed_transactions_count: usize = 0; let mut executed_with_successful_result_count: usize = 0; @@ -4411,10 +4413,13 @@ impl Bank { write_time.as_us(), sanitized_txs.len() ); - timings.store_us = timings.store_us.saturating_add(write_time.as_us()); - timings.update_stakes_cache_us = timings - .update_stakes_cache_us - .saturating_add(update_stakes_cache_time.as_us()); + + timings.saturating_add_in_place(ExecuteTimingType::StoreUs, write_time.as_us()); + timings.saturating_add_in_place( + ExecuteTimingType::UpdateStakesCacheUs, + update_stakes_cache_time.as_us(), + ); + self.update_transaction_statuses(sanitized_txs, &execution_results); let fee_collection_results = self.filter_program_errors_and_collect_fee(sanitized_txs, &execution_results);