diff --git a/core/src/banking_stage.rs b/core/src/banking_stage.rs index 5eebb1d63e6676..115679d8ee5959 100644 --- a/core/src/banking_stage.rs +++ b/core/src/banking_stage.rs @@ -20,10 +20,7 @@ use { solana_poh::poh_recorder::{PohRecorder, PohRecorderError, TransactionRecorder}, solana_runtime::{ accounts_db::ErrorCounters, - bank::{ - Bank, ExecuteTimings, TransactionBalancesSet, TransactionCheckResult, - TransactionExecutionResult, - }, + bank::{Bank, TransactionBalancesSet, TransactionCheckResult, TransactionExecutionResult}, bank_utils, cost_model::CostModel, cost_tracker::CostTracker, @@ -36,6 +33,7 @@ use { Slot, DEFAULT_TICKS_PER_SLOT, MAX_PROCESSING_AGE, MAX_TRANSACTION_FORWARDING_DELAY, MAX_TRANSACTION_FORWARDING_DELAY_GPU, }, + execute_timings::ExecuteTimings, feature_set, message::Message, pubkey::Pubkey, diff --git a/core/src/cost_update_service.rs b/core/src/cost_update_service.rs index 0c06356eb4626d..bae545f08ad3b4 100644 --- a/core/src/cost_update_service.rs +++ b/core/src/cost_update_service.rs @@ -6,11 +6,8 @@ use { solana_ledger::blockstore::Blockstore, solana_measure::measure::Measure, - solana_runtime::{ - bank::{Bank, ExecuteTimings}, - cost_model::CostModel, - }, - solana_sdk::timing::timestamp, + solana_runtime::{bank::Bank, cost_model::CostModel}, + solana_sdk::{execute_timings::ExecuteTimings, timing::timestamp}, std::{ sync::{ atomic::{AtomicBool, Ordering}, @@ -71,8 +68,12 @@ impl CostUpdateServiceTiming { } pub enum CostUpdate { - FrozenBank { bank: Arc }, - ExecuteTiming { execute_timings: ExecuteTimings }, + FrozenBank { + bank: Arc, + }, + ExecuteTiming { + execute_timings: Box, + }, } pub type CostUpdateReceiver = Receiver; @@ -221,7 +222,10 @@ impl CostUpdateService { #[cfg(test)] mod tests { - use {super::*, solana_runtime::message_processor::ProgramTiming, solana_sdk::pubkey::Pubkey}; + use { + super::*, + solana_sdk::{execute_timings::ProgramTiming, pubkey::Pubkey}, + }; #[test] fn test_update_cost_model_with_empty_execute_timings() { diff --git a/core/src/progress_map.rs b/core/src/progress_map.rs index 549616d88fcdcf..29ff7bc7156821 100644 --- a/core/src/progress_map.rs +++ b/core/src/progress_map.rs @@ -81,45 +81,122 @@ impl ReplaySlotStats { i64 ), ( - "serialize_us", + "execute_details_serialize_us", self.execute_timings.details.serialize_us, i64 ), ( - "create_vm_us", + "execute_details_create_vm_us", self.execute_timings.details.create_vm_us, i64 ), ( - "execute_inner_us", + "execute_details_execute_inner_us", self.execute_timings.details.execute_us, i64 ), ( - "deserialize_us", + "execute_details_deserialize_us", self.execute_timings.details.deserialize_us, i64 ), ( - "changed_account_count", + "execute_details_get_or_create_executor_us", + self.execute_timings.details.get_or_create_executor_us, + i64 + ), + ( + "execute_details_changed_account_count", self.execute_timings.details.changed_account_count, i64 ), ( - "total_account_count", + "execute_details_total_account_count", self.execute_timings.details.total_account_count, i64 ), ( - "total_data_size", + "execute_details_total_data_size", self.execute_timings.details.total_data_size, i64 ), ( - "data_size_changed", + "execute_details_data_size_changed", self.execute_timings.details.data_size_changed, i64 ), + ( + "execute_details_create_executor_register_syscalls_us", + self.execute_timings + .details + .create_executor_register_syscalls_us, + i64 + ), + ( + "execute_details_create_executor_load_elf_us", + self.execute_timings.details.create_executor_load_elf_us, + i64 + ), + ( + "execute_details_create_executor_verify_code_us", + self.execute_timings.details.create_executor_verify_code_us, + i64 + ), + ( + "execute_details_create_executor_jit_compile_us", + self.execute_timings.details.create_executor_jit_compile_us, + i64 + ), + ( + "execute_accessories_feature_set_clone_us", + self.execute_timings + .execute_accessories + .feature_set_clone_us, + i64 + ), + ( + "execute_accessories_compute_budget_process_transaction_us", + self.execute_timings + .execute_accessories + .compute_budget_process_transaction_us, + i64 + ), + ( + "execute_accessories_get_executors_us", + self.execute_timings.execute_accessories.get_executors_us, + i64 + ), + ( + "execute_accessories_process_message_us", + self.execute_timings.execute_accessories.process_message_us, + i64 + ), + ( + "execute_accessories_update_executors_us", + self.execute_timings.execute_accessories.update_executors_us, + i64 + ), + ( + "execute_accessories_process_instruction_verify_caller_us", + self.execute_timings + .execute_accessories + .process_instruction_verify_caller_us, + i64 + ), + ( + "execute_accessories_process_instruction_process_executable_chain_us", + self.execute_timings + .execute_accessories + .process_instruction_process_executable_chain_us, + i64 + ), + ( + "execute_accessories_process_instruction_verify_callee_us", + self.execute_timings + .execute_accessories + .process_instruction_verify_callee_us, + i64 + ), ); let mut per_pubkey_timings: Vec<_> = self diff --git a/core/src/replay_stage.rs b/core/src/replay_stage.rs index 1faf0f35f2117e..79c28a255297c8 100644 --- a/core/src/replay_stage.rs +++ b/core/src/replay_stage.rs @@ -43,13 +43,14 @@ use { }, solana_runtime::{ accounts_background_service::AbsRequestSender, - bank::{Bank, ExecuteTimings, NewBankOptions}, + bank::{Bank, NewBankOptions}, bank_forks::BankForks, commitment::BlockCommitmentCache, vote_sender_types::ReplayVoteSender, }, solana_sdk::{ clock::{Slot, MAX_PROCESSING_AGE, NUM_CONSECUTIVE_LEADER_SLOTS}, + execute_timings::ExecuteTimings, genesis_config::ClusterType, hash::Hash, pubkey::Pubkey, @@ -1876,7 +1877,9 @@ impl ReplayStage { // send accumulated excute-timings to cost_update_service if !execute_timings.details.per_program_timings.is_empty() { cost_update_sender - .send(CostUpdate::ExecuteTiming { execute_timings }) + .send(CostUpdate::ExecuteTiming { + execute_timings: Box::new(execute_timings), + }) .unwrap_or_else(|err| warn!("cost_update_sender failed: {:?}", err)); } diff --git a/ledger/src/blockstore_processor.rs b/ledger/src/blockstore_processor.rs index f8f32816a816ee..a8984361273a61 100644 --- a/ledger/src/blockstore_processor.rs +++ b/ledger/src/blockstore_processor.rs @@ -23,7 +23,7 @@ use { accounts_index::AccountSecondaryIndexes, accounts_update_notifier_interface::AccountsUpdateNotifier, bank::{ - Bank, ExecuteTimings, InnerInstructionsList, RentDebits, TransactionBalancesSet, + Bank, InnerInstructionsList, RentDebits, TransactionBalancesSet, TransactionExecutionResult, TransactionLogMessages, TransactionResults, }, bank_forks::BankForks, @@ -37,6 +37,7 @@ use { }, solana_sdk::{ clock::{Slot, MAX_PROCESSING_AGE}, + execute_timings::ExecuteTimings, feature_set, genesis_config::GenesisConfig, hash::Hash, diff --git a/program-test/src/lib.rs b/program-test/src/lib.rs index ca6cfa7d3d9f92..f4f06771af05a7 100644 --- a/program-test/src/lib.rs +++ b/program-test/src/lib.rs @@ -12,7 +12,7 @@ use { solana_banks_client::start_client, solana_banks_server::banks_server::start_local_server, solana_runtime::{ - bank::{Bank, Builtin, ExecuteTimings}, + bank::{Bank, Builtin}, bank_forks::BankForks, commitment::BlockCommitmentCache, genesis_utils::{create_genesis_config_with_leader_ex, GenesisConfigInfo}, @@ -23,6 +23,7 @@ use { clock::{Clock, Slot}, entrypoint::{ProgramResult, SUCCESS}, epoch_schedule::EpochSchedule, + execute_timings::ExecuteTimings, feature_set::demote_program_write_locks, fee_calculator::{FeeCalculator, FeeRateGovernor}, genesis_config::{ClusterType, GenesisConfig}, diff --git a/programs/bpf/tests/programs.rs b/programs/bpf/tests/programs.rs index 81a65329849ce8..c7a3358ff8cd43 100644 --- a/programs/bpf/tests/programs.rs +++ b/programs/bpf/tests/programs.rs @@ -21,7 +21,7 @@ use solana_rbpf::{ vm::{Config, Tracer}, }; use solana_runtime::{ - bank::{Bank, ExecuteTimings, NonceRollbackInfo, TransactionBalancesSet, TransactionResults}, + bank::{Bank, NonceRollbackInfo, TransactionBalancesSet, TransactionResults}, bank_client::BankClient, genesis_utils::{create_genesis_config, GenesisConfigInfo}, loader_utils::{ @@ -37,6 +37,7 @@ use solana_sdk::{ clock::MAX_PROCESSING_AGE, compute_budget, entrypoint::{MAX_PERMITTED_DATA_INCREASE, SUCCESS}, + execute_timings::ExecuteTimings, instruction::{AccountMeta, CompiledInstruction, Instruction, InstructionError}, keyed_account::KeyedAccount, message::Message, diff --git a/programs/bpf_loader/src/lib.rs b/programs/bpf_loader/src/lib.rs index 3dc0dd5a9073d1..7d2ca2de864226 100644 --- a/programs/bpf_loader/src/lib.rs +++ b/programs/bpf_loader/src/lib.rs @@ -52,6 +52,7 @@ use { program_utils::limited_deserialize, pubkey::Pubkey, rent::Rent, + saturating_add_assign, system_instruction::{self, MAX_PERMITTED_DATA_LENGTH}, }, std::{cell::RefCell, fmt::Debug, pin::Pin, rc::Rc, sync::Arc}, @@ -86,7 +87,16 @@ pub fn create_executor( use_jit: bool, reject_deployment_of_broken_elfs: bool, ) -> Result, InstructionError> { - let syscall_registry = syscalls::register_syscalls(invoke_context).map_err(|e| { + let mut register_syscalls_time = Measure::start("register_syscalls_time"); + let register_syscall_result = syscalls::register_syscalls(invoke_context); + register_syscalls_time.stop(); + saturating_add_assign!( + invoke_context + .get_timings() + .create_executor_register_syscalls_us, + register_syscalls_time.as_us() + ); + let syscall_registry = register_syscall_result.map_err(|e| { ic_msg!(invoke_context, "Failed to register syscalls: {}", e); InstructionError::ProgramEnvironmentSetupFailure })?; @@ -108,9 +118,8 @@ pub fn create_executor( }; let program_id; let load_elf_us: u64; - let verify_elf_us: u64; let mut jit_compile_us = 0u64; - let mut executable = { + let executable_result = { let keyed_accounts = invoke_context.get_keyed_accounts()?; let program = keyed_account_at_index(keyed_accounts, program_account_index)?; program_id = *program.unsigned_key(); @@ -126,20 +135,35 @@ pub fn create_executor( load_elf_time.stop(); load_elf_us = load_elf_time.as_us(); executable - } - .map_err(|e| map_ebpf_error(invoke_context, e))?; + }; + + saturating_add_assign!( + invoke_context.get_timings().create_executor_load_elf_us, + load_elf_us + ); + + let mut executable = executable_result.map_err(|e| map_ebpf_error(invoke_context, e))?; + let text_bytes = executable.get_text_bytes().1; let mut verify_code_time = Measure::start("verify_code_time"); verifier::check(text_bytes, &config) .map_err(|e| map_ebpf_error(invoke_context, EbpfError::UserError(e.into())))?; verify_code_time.stop(); - verify_elf_us = verify_code_time.as_us(); + let verify_elf_us = verify_code_time.as_us(); + saturating_add_assign!( + invoke_context.get_timings().create_executor_verify_code_us, + verify_elf_us + ); if use_jit { let mut jit_compile_time = Measure::start("jit_compile_time"); let jit_compile_result = Executable::::jit_compile(&mut executable); jit_compile_time.stop(); jit_compile_us = jit_compile_time.as_us(); + saturating_add_assign!( + invoke_context.get_timings().create_executor_jit_compile_us, + jit_compile_us + ); if let Err(err) = jit_compile_result { ic_msg!(invoke_context, "Failed to compile program {:?}", err); return Err(InstructionError::ProgramFailedToCompile); @@ -273,7 +297,9 @@ fn process_instruction_common( return Err(InstructionError::IncorrectProgramId); } - let executor = match invoke_context.get_executor(program_id) { + let mut get_or_create_executor_time = Measure::start("get_or_create_executor_time"); + let maybe_executor = invoke_context.get_executor(program_id); + let executor = match maybe_executor { Some(executor) => executor, None => { let executor = @@ -282,6 +308,12 @@ fn process_instruction_common( executor } }; + get_or_create_executor_time.stop(); + saturating_add_assign!( + invoke_context.get_timings().get_or_create_executor_us, + get_or_create_executor_time.as_us() + ); + executor.execute( loader_id, program_id, @@ -1053,6 +1085,7 @@ mod tests { account_utils::StateMut, client::SyncClient, clock::Clock, + execute_timings::ExecuteDetailsTimings, feature_set::FeatureSet, genesis_config::create_genesis_config, instruction::Instruction, @@ -1330,6 +1363,7 @@ mod tests { sysvars: vec![], disabled_features: vec![].into_iter().collect(), return_data: None, + execute_timings: ExecuteDetailsTimings::default(), }; assert_eq!( Err(InstructionError::ProgramFailedToComplete), diff --git a/runtime/benches/message_processor.rs b/runtime/benches/message_processor.rs index 75e60a1c4581ae..a2bd223d521f01 100644 --- a/runtime/benches/message_processor.rs +++ b/runtime/benches/message_processor.rs @@ -4,8 +4,10 @@ extern crate test; use { log::*, - solana_runtime::message_processor::{ExecuteDetailsTimings, PreAccount}, - solana_sdk::{account::AccountSharedData, pubkey, rent::Rent}, + solana_runtime::message_processor::PreAccount, + solana_sdk::{ + account::AccountSharedData, execute_timings::ExecuteDetailsTimings, pubkey, rent::Rent, + }, test::Bencher, }; diff --git a/runtime/src/bank.rs b/runtime/src/bank.rs index e2a23ed9fcbfca..21a0d7c482bf50 100644 --- a/runtime/src/bank.rs +++ b/runtime/src/bank.rs @@ -51,9 +51,7 @@ use { inline_spl_token, instruction_recorder::InstructionRecorder, log_collector::LogCollector, - message_processor::{ - ExecuteDetailsTimings, Executors, MessageProcessor, TransactionExecutor, - }, + message_processor::{Executors, MessageProcessor, TransactionExecutor}, rent_collector::RentCollector, stake_weighted_timestamp::{ calculate_stake_weighted_timestamp, MaxAllowableDrift, MAX_ALLOWABLE_DRIFT_PERCENTAGE, @@ -90,6 +88,7 @@ use { compute_budget, epoch_info::EpochInfo, epoch_schedule::EpochSchedule, + execute_timings::ExecuteTimings, feature, feature_set::{self, tx_wide_compute_cap, FeatureSet}, fee_calculator::{FeeCalculator, FeeRateGovernor}, @@ -198,31 +197,6 @@ impl RentDebits { } } -#[derive(Default, Debug)] -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 details: ExecuteDetailsTimings, -} - -impl ExecuteTimings { - pub fn accumulate(&mut self, other: &ExecuteTimings) { - self.check_us += other.check_us; - self.load_us += other.load_us; - self.execute_us += other.execute_us; - self.store_us += other.store_us; - self.update_stakes_cache_us += other.update_stakes_cache_us; - self.total_batches_len += other.total_batches_len; - self.num_execute_batches += other.num_execute_batches; - self.details.accumulate(&other.details); - } -} - type BankStatusCache = StatusCache>; #[frozen_abi(digest = "5Br3PNyyX1L7XoS4jYLt5JTeMXowLSsu7v9LhokC8vnq")] pub type BankSlotDelta = SlotDelta>; @@ -3541,7 +3515,15 @@ impl Bank { (Err(e.clone()), None) } (Ok(loaded_transaction), nonce_rollback) => { + let mut feature_set_clone_time = Measure::start("feature_set_clone_time"); let feature_set = self.feature_set.clone(); + + feature_set_clone_time.stop(); + saturating_add_assign!( + timings.execute_accessories.feature_set_clone_us, + feature_set_clone_time.as_us() + ); + signature_count += u64::from(tx.message().header.num_required_signatures); let mut bpf_compute_budget = self @@ -3559,8 +3541,14 @@ impl Bank { }; if process_result.is_ok() { + let mut get_executors_time = Measure::start("get_executors_time"); let executors = self.get_executors(&tx.message, &loaded_transaction.loaders); + get_executors_time.stop(); + saturating_add_assign!( + timings.execute_accessories.get_executors_us, + get_executors_time.as_us() + ); let (account_refcells, loader_refcells) = Self::accounts_to_refcells( &mut loaded_transaction.accounts, @@ -3586,6 +3574,7 @@ impl Bank { bpf_compute_budget.max_units, ))); + let mut process_message_time = Measure::start("process_message_time"); process_result = self.message_processor.process_message( tx.message(), &loader_refcells, @@ -3597,10 +3586,15 @@ impl Bank { feature_set, bpf_compute_budget, compute_meter, - &mut timings.details, + timings, self.rc.accounts.clone(), &self.ancestors, ); + process_message_time.stop(); + saturating_add_assign!( + timings.execute_accessories.process_message_us, + process_message_time.as_us() + ); transaction_log_messages.push(Self::collect_log_messages(log_collector)); inner_instructions.push(Self::compile_recorded_instructions( @@ -3618,7 +3612,13 @@ impl Bank { process_result = Err(e); } + let mut update_executors_time = Measure::start("update_executors_time"); self.update_executors(process_result.is_ok(), executors); + update_executors_time.stop(); + saturating_add_assign!( + timings.execute_accessories.update_executors_us, + update_executors_time.as_us() + ); } else { transaction_log_messages.push(None); inner_instructions.push(None); diff --git a/runtime/src/message_processor.rs b/runtime/src/message_processor.rs index aabc1ac3f8dd6d..9eee43e8ef2e06 100644 --- a/runtime/src/message_processor.rs +++ b/runtime/src/message_processor.rs @@ -11,6 +11,7 @@ use { account::{AccountSharedData, ReadableAccount, WritableAccount}, account_utils::StateMut, bpf_loader_upgradeable::{self, UpgradeableLoaderState}, + execute_timings::{ExecuteDetailsTimings, ExecuteTimings}, feature_set::{ demote_program_write_locks, fix_write_privs, instructions_sysvar_enabled, neon_evm_compute_budget, remove_native_loader, requestable_heap_size, @@ -27,7 +28,7 @@ use { }, pubkey::Pubkey, rent::Rent, - system_program, + saturating_add_assign, system_program, sysvar::instructions, transaction::TransactionError, }, @@ -93,100 +94,6 @@ impl TransactionExecutor { } } -#[derive(Default, Debug, PartialEq)] -pub struct ProgramTiming { - pub accumulated_us: u64, - pub accumulated_units: u64, - pub count: u32, - pub errored_txs_compute_consumed: Vec, - // Sum of all units in `errored_txs_compute_consumed` - pub total_errored_units: u64, -} - -impl ProgramTiming { - pub fn coalesce_error_timings(&mut self, current_estimated_program_cost: u64) { - for tx_error_compute_consumed in self.errored_txs_compute_consumed.drain(..) { - let compute_units_update = - std::cmp::max(current_estimated_program_cost, tx_error_compute_consumed); - self.accumulated_units = self.accumulated_units.saturating_add(compute_units_update); - self.count = self.count.saturating_add(1); - } - } - - pub fn accumulate_program_timings(&mut self, other: &ProgramTiming) { - self.accumulated_us = self.accumulated_us.saturating_add(other.accumulated_us); - self.accumulated_units = self - .accumulated_units - .saturating_add(other.accumulated_units); - self.count = self.count.saturating_add(other.count); - // Clones the entire vector, maybe not great... - self.errored_txs_compute_consumed - .extend(other.errored_txs_compute_consumed.clone()); - self.total_errored_units = self - .total_errored_units - .saturating_add(other.total_errored_units); - } -} - -#[derive(Default, Debug, PartialEq)] -pub struct ExecuteDetailsTimings { - pub serialize_us: u64, - pub create_vm_us: u64, - pub execute_us: u64, - pub deserialize_us: u64, - pub changed_account_count: u64, - pub total_account_count: u64, - pub total_data_size: usize, - pub data_size_changed: usize, - pub per_program_timings: HashMap, -} -impl ExecuteDetailsTimings { - pub fn accumulate(&mut self, other: &ExecuteDetailsTimings) { - self.serialize_us = self.serialize_us.saturating_add(other.serialize_us); - self.create_vm_us = self.create_vm_us.saturating_add(other.create_vm_us); - self.execute_us = self.execute_us.saturating_add(other.execute_us); - self.deserialize_us = self.deserialize_us.saturating_add(other.deserialize_us); - self.changed_account_count = self - .changed_account_count - .saturating_add(other.changed_account_count); - self.total_account_count = self - .total_account_count - .saturating_add(other.total_account_count); - self.total_data_size = self.total_data_size.saturating_add(other.total_data_size); - self.data_size_changed = self - .data_size_changed - .saturating_add(other.data_size_changed); - for (id, other) in &other.per_program_timings { - let program_timing = self.per_program_timings.entry(*id).or_default(); - program_timing.accumulate_program_timings(other); - } - } - - pub fn accumulate_program( - &mut self, - program_id: &Pubkey, - us: u64, - compute_units_consumed: u64, - is_error: bool, - ) { - let program_timing = self.per_program_timings.entry(*program_id).or_default(); - program_timing.accumulated_us = program_timing.accumulated_us.saturating_add(us); - if is_error { - program_timing - .errored_txs_compute_consumed - .push(compute_units_consumed); - program_timing.total_errored_units = program_timing - .total_errored_units - .saturating_add(compute_units_consumed); - } else { - program_timing.accumulated_units = program_timing - .accumulated_units - .saturating_add(compute_units_consumed); - program_timing.count = program_timing.count.saturating_add(1); - }; - } -} - // The relevant state of an account before an Instruction executes, used // to verify account integrity after the Instruction completes #[derive(Clone, Debug, Default)] @@ -633,6 +540,9 @@ impl<'a> InvokeContext for ThisInvokeContext<'a> { fn get_return_data(&self) -> &Option<(Pubkey, Vec)> { &self.return_data } + fn get_timings(&mut self) -> &mut ExecuteDetailsTimings { + &mut self.timings + } } pub struct ThisLogger { log_collector: Option>, @@ -1305,7 +1215,7 @@ impl MessageProcessor { feature_set: Arc, bpf_compute_budget: BpfComputeBudget, compute_meter: Rc>, - timings: &mut ExecuteDetailsTimings, + timings: &mut ExecuteTimings, account_db: Arc, ancestors: &Ancestors, ) -> Result<(), InstructionError> { @@ -1371,7 +1281,7 @@ impl MessageProcessor { executable_accounts, accounts, &rent_collector.rent, - timings, + &mut timings.details, invoke_context.get_logger(), invoke_context.is_feature_active(&updated_verify_policy::id()), invoke_context.is_feature_active(&demote_program_write_locks::id()), @@ -1381,14 +1291,18 @@ impl MessageProcessor { time.stop(); let post_remaining_units = invoke_context.get_compute_meter().borrow().get_remaining(); let compute_units_consumed = pre_remaining_units.saturating_sub(post_remaining_units); - timings.accumulate_program( + timings.details.accumulate_program( program_id, time.as_us(), compute_units_consumed, execute_or_verify_result.is_err(), ); - timings.accumulate(&invoke_context.timings); + timings.details.accumulate(&invoke_context.timings); + saturating_add_assign!( + timings.execute_accessories.process_instructions_us, + time.as_us() + ); execute_or_verify_result } @@ -1410,7 +1324,7 @@ impl MessageProcessor { feature_set: Arc, bpf_compute_budget: BpfComputeBudget, compute_meter: Rc>, - timings: &mut ExecuteDetailsTimings, + timings: &mut ExecuteTimings, account_db: Arc, ancestors: &Ancestors, ) -> Result<(), TransactionError> { @@ -2118,7 +2032,7 @@ mod tests { Arc::new(FeatureSet::all_enabled()), BpfComputeBudget::new(), Rc::new(RefCell::new(MockComputeMeter::default())), - &mut ExecuteDetailsTimings::default(), + &mut ExecuteTimings::default(), Arc::new(Accounts::default()), &ancestors, ); @@ -2146,7 +2060,7 @@ mod tests { Arc::new(FeatureSet::all_enabled()), BpfComputeBudget::new(), Rc::new(RefCell::new(MockComputeMeter::default())), - &mut ExecuteDetailsTimings::default(), + &mut ExecuteTimings::default(), Arc::new(Accounts::default()), &ancestors, ); @@ -2178,7 +2092,7 @@ mod tests { Arc::new(FeatureSet::all_enabled()), BpfComputeBudget::new(), Rc::new(RefCell::new(MockComputeMeter::default())), - &mut ExecuteDetailsTimings::default(), + &mut ExecuteTimings::default(), Arc::new(Accounts::default()), &ancestors, ); @@ -2302,7 +2216,7 @@ mod tests { Arc::new(FeatureSet::all_enabled()), BpfComputeBudget::new(), Rc::new(RefCell::new(MockComputeMeter::default())), - &mut ExecuteDetailsTimings::default(), + &mut ExecuteTimings::default(), Arc::new(Accounts::default()), &ancestors, ); @@ -2334,7 +2248,7 @@ mod tests { Arc::new(FeatureSet::all_enabled()), BpfComputeBudget::new(), Rc::new(RefCell::new(MockComputeMeter::default())), - &mut ExecuteDetailsTimings::default(), + &mut ExecuteTimings::default(), Arc::new(Accounts::default()), &ancestors, ); @@ -2364,7 +2278,7 @@ mod tests { Arc::new(FeatureSet::all_enabled()), BpfComputeBudget::new(), Rc::new(RefCell::new(MockComputeMeter::default())), - &mut ExecuteDetailsTimings::default(), + &mut ExecuteTimings::default(), Arc::new(Accounts::default()), &ancestors, ); diff --git a/sdk/src/execute_timings.rs b/sdk/src/execute_timings.rs new file mode 100644 index 00000000000000..4b2b9664adae2e --- /dev/null +++ b/sdk/src/execute_timings.rs @@ -0,0 +1,265 @@ +use { + solana_sdk::{pubkey::Pubkey, saturating_add_assign}, + std::collections::HashMap, +}; + +#[derive(Default, Debug, PartialEq)] +pub struct ProgramTiming { + pub accumulated_us: u64, + pub accumulated_units: u64, + pub count: u32, + pub errored_txs_compute_consumed: Vec, + // Sum of all units in `errored_txs_compute_consumed` + pub total_errored_units: u64, +} + +impl ProgramTiming { + pub fn coalesce_error_timings(&mut self, current_estimated_program_cost: u64) { + for tx_error_compute_consumed in self.errored_txs_compute_consumed.drain(..) { + let compute_units_update = + std::cmp::max(current_estimated_program_cost, tx_error_compute_consumed); + saturating_add_assign!(self.accumulated_units, compute_units_update); + saturating_add_assign!(self.count, 1); + } + } + + pub fn accumulate_program_timings(&mut self, other: &ProgramTiming) { + saturating_add_assign!(self.accumulated_us, other.accumulated_us); + saturating_add_assign!(self.accumulated_units, other.accumulated_units); + saturating_add_assign!(self.count, other.count); + // Clones the entire vector, maybe not great... + self.errored_txs_compute_consumed + .extend(other.errored_txs_compute_consumed.clone()); + saturating_add_assign!(self.total_errored_units, other.total_errored_units); + } +} + +#[derive(Default, Debug)] +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 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); + self.details.accumulate(&other.details); + self.execute_accessories + .accumulate(&other.execute_accessories); + } +} + +#[derive(Default, Debug)] +pub struct ExecuteAccessoryTimings { + pub feature_set_clone_us: u64, + pub compute_budget_process_transaction_us: u64, + pub get_executors_us: u64, + pub process_message_us: u64, + pub update_executors_us: u64, + pub process_instructions_us: u64, + pub process_instruction_verify_caller_us: u64, + pub process_instruction_process_executable_chain_us: u64, + pub process_instruction_verify_callee_us: u64, +} + +impl ExecuteAccessoryTimings { + pub fn accumulate(&mut self, other: &ExecuteAccessoryTimings) { + saturating_add_assign!( + self.compute_budget_process_transaction_us, + other.feature_set_clone_us + ); + saturating_add_assign!( + self.compute_budget_process_transaction_us, + other.compute_budget_process_transaction_us + ); + saturating_add_assign!(self.get_executors_us, other.get_executors_us); + saturating_add_assign!(self.process_message_us, other.process_message_us); + saturating_add_assign!(self.update_executors_us, other.update_executors_us); + saturating_add_assign!(self.process_instructions_us, other.process_instructions_us); + saturating_add_assign!( + self.process_instruction_verify_caller_us, + other.process_instruction_verify_caller_us + ); + saturating_add_assign!( + self.process_instruction_process_executable_chain_us, + other.process_instruction_process_executable_chain_us + ); + saturating_add_assign!( + self.process_instruction_verify_callee_us, + other.process_instruction_verify_callee_us + ); + } +} + +#[derive(Default, Debug, PartialEq)] +pub struct ExecuteDetailsTimings { + pub serialize_us: u64, + pub create_vm_us: u64, + pub execute_us: u64, + pub deserialize_us: u64, + pub get_or_create_executor_us: u64, + pub changed_account_count: u64, + pub total_account_count: u64, + pub total_data_size: usize, + pub data_size_changed: usize, + pub create_executor_register_syscalls_us: u64, + pub create_executor_load_elf_us: u64, + pub create_executor_verify_code_us: u64, + pub create_executor_jit_compile_us: u64, + pub per_program_timings: HashMap, +} +impl ExecuteDetailsTimings { + pub fn accumulate(&mut self, other: &ExecuteDetailsTimings) { + saturating_add_assign!(self.serialize_us, other.serialize_us); + saturating_add_assign!(self.create_vm_us, other.create_vm_us); + saturating_add_assign!(self.execute_us, other.execute_us); + saturating_add_assign!(self.deserialize_us, other.deserialize_us); + saturating_add_assign!( + self.get_or_create_executor_us, + other.get_or_create_executor_us + ); + saturating_add_assign!(self.changed_account_count, other.changed_account_count); + saturating_add_assign!(self.total_account_count, other.total_account_count); + saturating_add_assign!(self.total_data_size, other.total_data_size); + saturating_add_assign!(self.data_size_changed, other.data_size_changed); + saturating_add_assign!( + self.create_executor_register_syscalls_us, + other.create_executor_register_syscalls_us + ); + saturating_add_assign!( + self.create_executor_load_elf_us, + other.create_executor_load_elf_us + ); + saturating_add_assign!( + self.create_executor_verify_code_us, + other.create_executor_verify_code_us + ); + saturating_add_assign!( + self.create_executor_jit_compile_us, + other.create_executor_jit_compile_us + ); + for (id, other) in &other.per_program_timings { + let program_timing = self.per_program_timings.entry(*id).or_default(); + program_timing.accumulate_program_timings(other); + } + } + + pub fn accumulate_program( + &mut self, + program_id: &Pubkey, + us: u64, + compute_units_consumed: u64, + is_error: bool, + ) { + let program_timing = self.per_program_timings.entry(*program_id).or_default(); + program_timing.accumulated_us = program_timing.accumulated_us.saturating_add(us); + if is_error { + program_timing + .errored_txs_compute_consumed + .push(compute_units_consumed); + saturating_add_assign!(program_timing.total_errored_units, compute_units_consumed); + } else { + saturating_add_assign!(program_timing.accumulated_units, compute_units_consumed); + saturating_add_assign!(program_timing.count, 1); + }; + } +} + +#[cfg(test)] +mod tests { + use super::*; + + fn construct_execute_timings_with_program( + program_id: &Pubkey, + us: u64, + compute_units_consumed: u64, + ) -> ExecuteDetailsTimings { + let mut execute_details_timings = ExecuteDetailsTimings::default(); + + // Accumulate an erroring transaction + let is_error = true; + execute_details_timings.accumulate_program( + program_id, + us, + compute_units_consumed, + is_error, + ); + + // Accumulate a non-erroring transaction + let is_error = false; + execute_details_timings.accumulate_program( + program_id, + us, + compute_units_consumed, + is_error, + ); + + let program_timings = execute_details_timings + .per_program_timings + .get(program_id) + .unwrap(); + + // Both error and success transactions count towards `accumulated_us` + assert_eq!(program_timings.accumulated_us, us.saturating_mul(2)); + assert_eq!(program_timings.accumulated_units, compute_units_consumed); + assert_eq!(program_timings.count, 1,); + assert_eq!( + program_timings.errored_txs_compute_consumed, + vec![compute_units_consumed] + ); + assert_eq!(program_timings.total_errored_units, compute_units_consumed,); + + execute_details_timings + } + + #[test] + fn test_execute_details_timing_acumulate_program() { + // Acumulate an erroring transaction + let program_id = Pubkey::new_unique(); + let us = 100; + let compute_units_consumed = 1; + construct_execute_timings_with_program(&program_id, us, compute_units_consumed); + } + + #[test] + fn test_execute_details_timing_acumulate() { + // Acumulate an erroring transaction + let program_id = Pubkey::new_unique(); + let us = 100; + let compute_units_consumed = 1; + let mut execute_details_timings = ExecuteDetailsTimings::default(); + + // Construct another separate instance of ExecuteDetailsTimings with non default fields + let mut other_execute_details_timings = + construct_execute_timings_with_program(&program_id, us, compute_units_consumed); + let account_count = 1; + let data_size_changed = 1; + other_execute_details_timings.serialize_us = us; + other_execute_details_timings.create_vm_us = us; + other_execute_details_timings.execute_us = us; + other_execute_details_timings.deserialize_us = us; + other_execute_details_timings.changed_account_count = account_count; + other_execute_details_timings.total_account_count = account_count; + other_execute_details_timings.total_data_size = data_size_changed; + other_execute_details_timings.data_size_changed = data_size_changed; + + // Accumulate the other instance into the current instance + execute_details_timings.accumulate(&other_execute_details_timings); + + // Check that the two instances are equal + assert_eq!(execute_details_timings, other_execute_details_timings); + } +} diff --git a/sdk/src/lib.rs b/sdk/src/lib.rs index 6a3a70948242ca..957658430a4a20 100644 --- a/sdk/src/lib.rs +++ b/sdk/src/lib.rs @@ -23,6 +23,7 @@ pub mod entrypoint; pub mod entrypoint_deprecated; pub mod entrypoint_native; pub mod epoch_info; +pub mod execute_timings; pub mod exit; pub mod feature; pub mod feature_set; diff --git a/sdk/src/process_instruction.rs b/sdk/src/process_instruction.rs index d479c932314b2f..98c029be6af785 100644 --- a/sdk/src/process_instruction.rs +++ b/sdk/src/process_instruction.rs @@ -2,6 +2,7 @@ use { itertools::Itertools, solana_sdk::{ account::AccountSharedData, + execute_timings::ExecuteDetailsTimings, instruction::{CompiledInstruction, Instruction, InstructionError}, keyed_account::{create_keyed_accounts_unified, KeyedAccount}, pubkey::Pubkey, @@ -109,6 +110,8 @@ pub trait InvokeContext { fn set_return_data(&mut self, return_data: Option<(Pubkey, Vec)>); /// Get the return data fn get_return_data(&self) -> &Option<(Pubkey, Vec)>; + /// Get timings + fn get_timings(&mut self) -> &mut ExecuteDetailsTimings; } /// Convenience macro to log a message with an `Rc>` @@ -389,6 +392,7 @@ pub struct MockInvokeContext<'a> { pub sysvars: Vec<(Pubkey, Option>>)>, pub disabled_features: HashSet, pub return_data: Option<(Pubkey, Vec)>, + pub execute_timings: ExecuteDetailsTimings, } impl<'a> MockInvokeContext<'a> { @@ -406,6 +410,7 @@ impl<'a> MockInvokeContext<'a> { sysvars: vec![], disabled_features: HashSet::default(), return_data: None, + execute_timings: ExecuteDetailsTimings::default(), }; invoke_context .invoke_stack @@ -530,4 +535,7 @@ impl<'a> InvokeContext for MockInvokeContext<'a> { fn get_return_data(&self) -> &Option<(Pubkey, Vec)> { &self.return_data } + fn get_timings(&mut self) -> &mut ExecuteDetailsTimings { + &mut self.execute_timings + } }