diff --git a/Cargo.lock b/Cargo.lock index 75fca5de6901cd..0cbde570215abf 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -5134,6 +5134,7 @@ dependencies = [ "solana-measure", "solana-metrics", "solana-perf", + "solana-program-runtime", "solana-rayon-threadlimit", "solana-runtime", "solana-sdk", @@ -5487,6 +5488,7 @@ dependencies = [ "rustc_version 0.4.0", "serde", "solana-logger 1.10.0", + "solana-measure", "solana-sdk", "thiserror", ] diff --git a/core/Cargo.toml b/core/Cargo.toml index cf34c3903c75f5..5096db4b968068 100644 --- a/core/Cargo.toml +++ b/core/Cargo.toml @@ -43,6 +43,7 @@ solana-metrics = { path = "../metrics", version = "=1.10.0" } solana-net-utils = { path = "../net-utils", version = "=1.10.0" } solana-perf = { path = "../perf", version = "=1.10.0" } solana-poh = { path = "../poh", version = "=1.10.0" } +solana-program-runtime = { path = "../program-runtime", version = "=1.10.0" } solana-rpc = { path = "../rpc", version = "=1.10.0" } solana-replica-lib = { path = "../replica-lib", version = "=1.10.0" } solana-runtime = { path = "../runtime", version = "=1.10.0" } diff --git a/core/src/banking_stage.rs b/core/src/banking_stage.rs index c6740d4459d8a0..e91b18627a1a6a 100644 --- a/core/src/banking_stage.rs +++ b/core/src/banking_stage.rs @@ -18,12 +18,10 @@ use { perf_libs, }, solana_poh::poh_recorder::{BankStart, PohRecorder, PohRecorderError, TransactionRecorder}, + solana_program_runtime::timings::ExecuteTimings, solana_runtime::{ accounts_db::ErrorCounters, - bank::{ - Bank, ExecuteTimings, TransactionBalancesSet, TransactionCheckResult, - TransactionExecutionResult, - }, + bank::{Bank, TransactionBalancesSet, TransactionCheckResult, TransactionExecutionResult}, bank_utils, cost_model::CostModel, transaction_batch::TransactionBatch, diff --git a/core/src/cost_update_service.rs b/core/src/cost_update_service.rs index c21c78869cd83a..55fb0e738df211 100644 --- a/core/src/cost_update_service.rs +++ b/core/src/cost_update_service.rs @@ -6,10 +6,8 @@ use { solana_ledger::blockstore::Blockstore, solana_measure::measure::Measure, - solana_runtime::{ - bank::{Bank, ExecuteTimings}, - cost_model::CostModel, - }, + solana_program_runtime::timings::ExecuteTimings, + solana_runtime::{bank::Bank, cost_model::CostModel}, solana_sdk::timing::timestamp, std::{ sync::{ @@ -71,8 +69,12 @@ impl CostUpdateServiceTiming { } pub enum CostUpdate { - FrozenBank { bank: Arc }, - ExecuteTiming { execute_timings: ExecuteTimings }, + FrozenBank { + bank: Arc, + }, + ExecuteTiming { + execute_timings: Box, + }, } pub type CostUpdateReceiver = Receiver; diff --git a/core/src/progress_map.rs b/core/src/progress_map.rs index 3a0f566cb3ce8f..bc68443bf0f5f7 100644 --- a/core/src/progress_map.rs +++ b/core/src/progress_map.rs @@ -82,45 +82,133 @@ 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_instructions_total_us", + self.execute_timings + .execute_accessories + .process_instructions + .total_us, + i64 + ), + ( + "execute_accessories_process_instructions_verify_caller_us", + self.execute_timings + .execute_accessories + .process_instructions + .verify_caller_us, + i64 + ), + ( + "execute_accessories_process_instructions_process_executable_chain_us", + self.execute_timings + .execute_accessories + .process_instructions + .process_executable_chain_us, + i64 + ), + ( + "execute_accessories_process_instructions_verify_callee_us", + self.execute_timings + .execute_accessories + .process_instructions + .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 6e75a9490cc57f..aa6d3642416b76 100644 --- a/core/src/replay_stage.rs +++ b/core/src/replay_stage.rs @@ -40,13 +40,14 @@ use { solana_measure::measure::Measure, solana_metrics::inc_new_counter_info, solana_poh::poh_recorder::{PohRecorder, GRACE_TICKS_FACTOR, MAX_GRACE_SLOTS}, + solana_program_runtime::timings::ExecuteTimings, solana_rpc::{ optimistically_confirmed_bank_tracker::{BankNotification, BankNotificationSender}, rpc_subscriptions::RpcSubscriptions, }, solana_runtime::{ accounts_background_service::AbsRequestSender, - bank::{Bank, ExecuteTimings, NewBankOptions}, + bank::{Bank, NewBankOptions}, bank_forks::BankForks, commitment::BlockCommitmentCache, vote_sender_types::ReplayVoteSender, @@ -2247,7 +2248,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/Cargo.toml b/ledger/Cargo.toml index 370f73765aa59d..bd83b9260fa863 100644 --- a/ledger/Cargo.toml +++ b/ledger/Cargo.toml @@ -38,6 +38,7 @@ solana-frozen-abi-macro = { path = "../frozen-abi/macro", version = "=1.10.0" } solana-transaction-status = { path = "../transaction-status", version = "=1.10.0" } solana-measure = { path = "../measure", version = "=1.10.0" } solana-metrics = { path = "../metrics", version = "=1.10.0" } +solana-program-runtime = { path = "../program-runtime", version = "=1.10.0" } solana-perf = { path = "../perf", version = "=1.10.0" } solana-rayon-threadlimit = { path = "../rayon-threadlimit", version = "=1.10.0" } solana-runtime = { path = "../runtime", version = "=1.10.0" } diff --git a/ledger/src/blockstore_processor.rs b/ledger/src/blockstore_processor.rs index e16053d15b8048..e27d96ef6f91b2 100644 --- a/ledger/src/blockstore_processor.rs +++ b/ledger/src/blockstore_processor.rs @@ -14,13 +14,14 @@ use { }, solana_measure::measure::Measure, solana_metrics::{datapoint_error, inc_new_counter_debug}, + solana_program_runtime::timings::ExecuteTimings, solana_rayon_threadlimit::get_thread_count, solana_runtime::{ accounts_db::{AccountShrinkThreshold, AccountsDbConfig}, accounts_index::AccountSecondaryIndexes, accounts_update_notifier_interface::AccountsUpdateNotifier, bank::{ - Bank, ExecuteTimings, RentDebits, TransactionBalancesSet, TransactionExecutionResult, + Bank, RentDebits, TransactionBalancesSet, TransactionExecutionResult, TransactionResults, }, bank_forks::BankForks, diff --git a/program-runtime/Cargo.toml b/program-runtime/Cargo.toml index b7e99f2e6579a5..e0e5fe33f74635 100644 --- a/program-runtime/Cargo.toml +++ b/program-runtime/Cargo.toml @@ -19,6 +19,7 @@ log = "0.4.14" num-derive = { version = "0.3" } num-traits = { version = "0.2" } serde = { version = "1.0.129", features = ["derive", "rc"] } +solana-measure = { path = "../measure", version = "=1.10.0" } solana-sdk = { path = "../sdk", version = "=1.10.0" } thiserror = "1.0" diff --git a/program-runtime/src/invoke_context.rs b/program-runtime/src/invoke_context.rs index 3d3fae7d9ba8b3..f5af1eb3fed23d 100644 --- a/program-runtime/src/invoke_context.rs +++ b/program-runtime/src/invoke_context.rs @@ -1,9 +1,14 @@ use { crate::{ - accounts_data_meter::AccountsDataMeter, ic_logger_msg, ic_msg, - instruction_recorder::InstructionRecorder, log_collector::LogCollector, - native_loader::NativeLoader, pre_account::PreAccount, timings::ExecuteDetailsTimings, + accounts_data_meter::AccountsDataMeter, + ic_logger_msg, ic_msg, + instruction_recorder::InstructionRecorder, + log_collector::LogCollector, + native_loader::NativeLoader, + pre_account::PreAccount, + timings::{ExecuteDetailsTimings, ExecuteTimings}, }, + solana_measure::measure::Measure, solana_sdk::{ account::{AccountSharedData, ReadableAccount}, bpf_loader_upgradeable::{self, UpgradeableLoaderState}, @@ -19,6 +24,7 @@ use { native_loader, pubkey::Pubkey, rent::Rent, + saturating_add_assign, sysvar::Sysvar, transaction_context::{InstructionAccount, TransactionAccount, TransactionContext}, }, @@ -603,6 +609,7 @@ impl<'a> InvokeContext<'a> { &instruction_accounts, &program_indices, &mut compute_units_consumed, + &mut ExecuteTimings::default(), )?; // Verify the called program has not misbehaved @@ -773,6 +780,7 @@ impl<'a> InvokeContext<'a> { instruction_accounts: &[InstructionAccount], program_indices: &[usize], compute_units_consumed: &mut u64, + timings: &mut ExecuteTimings, ) -> Result<(), InstructionError> { *compute_units_consumed = 0; let program_id = program_indices @@ -790,7 +798,17 @@ impl<'a> InvokeContext<'a> { } } else { // Verify the calling program hasn't misbehaved - self.verify_and_update(instruction_accounts, true)?; + let mut verify_caller_time = Measure::start("verify_caller_time"); + let verify_caller_result = self.verify_and_update(instruction_accounts, true); + verify_caller_time.stop(); + saturating_add_assign!( + timings + .execute_accessories + .process_instructions + .verify_caller_us, + verify_caller_time.as_us() + ); + verify_caller_result?; // Record instruction if let Some(instruction_recorder) = &self.instruction_recorder { @@ -805,6 +823,7 @@ impl<'a> InvokeContext<'a> { .map(|instruction_account| instruction_account.index_in_transaction as u8) .collect(), }; + instruction_recorder .borrow_mut() .record_compiled_instruction(compiled_instruction); @@ -814,19 +833,42 @@ impl<'a> InvokeContext<'a> { let result = self .push(instruction_accounts, program_indices, instruction_data) .and_then(|_| { + let mut process_executable_chain_time = + Measure::start("process_executable_chain_time"); self.return_data = (program_id, Vec::new()); let pre_remaining_units = self.compute_meter.borrow().get_remaining(); let execution_result = self.process_executable_chain(instruction_data); let post_remaining_units = self.compute_meter.borrow().get_remaining(); *compute_units_consumed = pre_remaining_units.saturating_sub(post_remaining_units); - execution_result?; + process_executable_chain_time.stop(); // Verify the called program has not misbehaved - if is_lowest_invocation_level { - self.verify(instruction_accounts, program_indices) - } else { - self.verify_and_update(instruction_accounts, false) - } + let mut verify_callee_time = Measure::start("verify_callee_time"); + let result = execution_result.and_then(|_| { + if is_lowest_invocation_level { + self.verify(instruction_accounts, program_indices) + } else { + self.verify_and_update(instruction_accounts, false) + } + }); + verify_callee_time.stop(); + + saturating_add_assign!( + timings + .execute_accessories + .process_instructions + .process_executable_chain_us, + process_executable_chain_time.as_us() + ); + saturating_add_assign!( + timings + .execute_accessories + .process_instructions + .verify_callee_us, + verify_callee_time.as_us() + ); + + result }); // Pop the invoke_stack to restore previous state @@ -1526,6 +1568,7 @@ mod tests { &inner_instruction_accounts, &program_indices, &mut compute_units_consumed, + &mut ExecuteTimings::default(), ); // Because the instruction had compute cost > 0, then regardless of the execution result, @@ -1639,6 +1682,7 @@ mod tests { &instruction_accounts, &[2], &mut 0, + &mut ExecuteTimings::default(), ); assert!(result.is_ok()); @@ -1656,6 +1700,7 @@ mod tests { &instruction_accounts, &[2], &mut 0, + &mut ExecuteTimings::default(), ); assert!(result.is_ok()); @@ -1673,6 +1718,7 @@ mod tests { &instruction_accounts, &[2], &mut 0, + &mut ExecuteTimings::default(), ); assert!(result.is_err()); diff --git a/program-runtime/src/timings.rs b/program-runtime/src/timings.rs index ec47835dae3213..40e6dc97531d83 100644 --- a/program-runtime/src/timings.rs +++ b/program-runtime/src/timings.rs @@ -1,4 +1,7 @@ -use {solana_sdk::pubkey::Pubkey, std::collections::HashMap}; +use { + solana_sdk::{pubkey::Pubkey, saturating_add_assign}, + std::collections::HashMap, +}; #[derive(Default, Debug, PartialEq)] pub struct ProgramTiming { @@ -15,23 +18,97 @@ impl ProgramTiming { 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); + saturating_add_assign!(self.accumulated_units, compute_units_update); + saturating_add_assign!(self.count, 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); + 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()); - self.total_errored_units = self - .total_errored_units - .saturating_add(other.total_errored_units); + 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 collect_logs_us: 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); + saturating_add_assign!(self.collect_logs_us, other.collect_logs_us); + self.details.accumulate(&other.details); + self.execute_accessories + .accumulate(&other.execute_accessories); + } +} + +#[derive(Default, Debug)] +pub struct ExecuteProcessInstructionTimings { + pub total_us: u64, + pub verify_caller_us: u64, + pub process_executable_chain_us: u64, + pub verify_callee_us: u64, +} + +impl ExecuteProcessInstructionTimings { + pub fn accumulate(&mut self, other: &ExecuteProcessInstructionTimings) { + saturating_add_assign!(self.total_us, other.total_us); + saturating_add_assign!(self.verify_caller_us, other.verify_caller_us); + saturating_add_assign!( + self.process_executable_chain_us, + other.process_executable_chain_us + ); + saturating_add_assign!(self.verify_callee_us, other.verify_callee_us); + } +} + +#[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: ExecuteProcessInstructionTimings, +} + +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); + self.process_instructions + .accumulate(&other.process_instructions); } } @@ -41,28 +118,47 @@ pub struct ExecuteDetailsTimings { 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) { - 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); + 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); diff --git a/program-test/src/lib.rs b/program-test/src/lib.rs index 9eb38503e1ac6f..07913ce7f7bfdc 100644 --- a/program-test/src/lib.rs +++ b/program-test/src/lib.rs @@ -11,9 +11,11 @@ use { log::*, solana_banks_client::start_client, solana_banks_server::banks_server::start_local_server, - solana_program_runtime::{ic_msg, invoke_context::ProcessInstructionWithContext, stable_log}, + solana_program_runtime::{ + ic_msg, invoke_context::ProcessInstructionWithContext, stable_log, timings::ExecuteTimings, + }, solana_runtime::{ - bank::{Bank, ExecuteTimings}, + bank::Bank, bank_forks::BankForks, builtins::Builtin, commitment::BlockCommitmentCache, @@ -301,6 +303,7 @@ impl solana_sdk::program_stubs::SyscallStubs for SyscallStubs { &instruction_accounts, &program_indices, &mut compute_units_consumed, + &mut ExecuteTimings::default(), ) .map_err(|err| ProgramError::try_from(err).unwrap_or_else(|err| panic!("{}", err)))?; diff --git a/programs/bpf/Cargo.lock b/programs/bpf/Cargo.lock index 7ffda3a92f4391..f6a063df672f59 100644 --- a/programs/bpf/Cargo.lock +++ b/programs/bpf/Cargo.lock @@ -3375,6 +3375,7 @@ dependencies = [ "num-traits", "rustc_version 0.4.0", "serde", + "solana-measure", "solana-sdk", "thiserror", ] diff --git a/programs/bpf/tests/programs.rs b/programs/bpf/tests/programs.rs index e658dbbdcb4404..55f661570c015c 100644 --- a/programs/bpf/tests/programs.rs +++ b/programs/bpf/tests/programs.rs @@ -17,7 +17,7 @@ use solana_bpf_loader_program::{ use solana_bpf_rust_invoke::instructions::*; use solana_bpf_rust_realloc::instructions::*; use solana_bpf_rust_realloc_invoke::instructions::*; -use solana_program_runtime::invoke_context::with_mock_invoke_context; +use solana_program_runtime::{invoke_context::with_mock_invoke_context, timings::ExecuteTimings}; use solana_rbpf::{ elf::Executable, static_analysis::Analysis, @@ -25,7 +25,7 @@ use solana_rbpf::{ }; use solana_runtime::{ bank::{ - Bank, DurableNonceFee, ExecuteTimings, TransactionBalancesSet, TransactionExecutionDetails, + Bank, DurableNonceFee, TransactionBalancesSet, TransactionExecutionDetails, TransactionExecutionResult, TransactionResults, }, bank_client::BankClient, diff --git a/programs/bpf_loader/src/lib.rs b/programs/bpf_loader/src/lib.rs index c6cbcc120fc929..a6a1075e94957b 100644 --- a/programs/bpf_loader/src/lib.rs +++ b/programs/bpf_loader/src/lib.rs @@ -51,6 +51,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}, @@ -85,7 +86,14 @@ 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(); + invoke_context.timings.create_executor_register_syscalls_us = invoke_context + .timings + .create_executor_register_syscalls_us + .saturating_add(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 })?; @@ -116,20 +124,40 @@ pub fn create_executor( let mut executable = { let keyed_accounts = invoke_context.get_keyed_accounts()?; let programdata = keyed_account_at_index(keyed_accounts, programdata_account_index)?; - Executable::::from_elf( + let mut load_elf_time = Measure::start("load_elf_time"); + let executable = Executable::::from_elf( &programdata.try_account_ref()?.data()[programdata_offset..], None, config, syscall_registry, - ) + ); + load_elf_time.stop(); + invoke_context.timings.create_executor_load_elf_us = invoke_context + .timings + .create_executor_load_elf_us + .saturating_add(load_elf_time.as_us()); + executable } .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(); + invoke_context.timings.create_executor_verify_code_us = invoke_context + .timings + .create_executor_verify_code_us + .saturating_add(verify_code_time.as_us()); if use_jit { - if let Err(err) = Executable::::jit_compile(&mut executable) - { + let mut jit_compile_time = Measure::start("jit_compile_time"); + let jit_compile_result = + Executable::::jit_compile(&mut executable); + jit_compile_time.stop(); + invoke_context.timings.create_executor_jit_compile_us = invoke_context + .timings + .create_executor_jit_compile_us + .saturating_add(jit_compile_time.as_us()); + if let Err(err) = jit_compile_result { ic_msg!(invoke_context, "Failed to compile program {:?}", err); return Err(InstructionError::ProgramFailedToCompile); } @@ -291,6 +319,7 @@ fn process_instruction_common( 0 }; + let mut get_or_create_executor_time = Measure::start("get_or_create_executor_time"); let executor = match invoke_context.get_executor(program_id) { Some(executor) => executor, None => { @@ -306,6 +335,12 @@ fn process_instruction_common( executor } }; + get_or_create_executor_time.stop(); + saturating_add_assign!( + invoke_context.timings.get_or_create_executor_us, + get_or_create_executor_time.as_us() + ); + executor.execute( next_first_instruction_account, instruction_data, diff --git a/programs/bpf_loader/src/syscalls.rs b/programs/bpf_loader/src/syscalls.rs index 63c95d860db15a..b4a53e5fb6d648 100644 --- a/programs/bpf_loader/src/syscalls.rs +++ b/programs/bpf_loader/src/syscalls.rs @@ -6,6 +6,7 @@ use { ic_logger_msg, ic_msg, invoke_context::{ComputeMeter, InvokeContext}, stable_log, + timings::ExecuteTimings, }, solana_rbpf::{ aligned_memory::AlignedMemory, @@ -2634,6 +2635,7 @@ fn call<'a, 'b: 'a>( &instruction_accounts, &program_indices, &mut compute_units_consumed, + &mut ExecuteTimings::default(), ) .map_err(SyscallError::InstructionError)?; diff --git a/runtime/src/bank.rs b/runtime/src/bank.rs index d0efd6f4b237c1..b0f1733c71241a 100644 --- a/runtime/src/bank.rs +++ b/runtime/src/bank.rs @@ -78,7 +78,7 @@ use { BuiltinProgram, Executor, Executors, ProcessInstructionWithContext, TransactionExecutor, }, log_collector::LogCollector, - timings::ExecuteDetailsTimings, + timings::ExecuteTimings, }, solana_sdk::{ account::{ @@ -115,7 +115,7 @@ use { precompiles::get_precompiles, program_utils::limited_deserialize, pubkey::Pubkey, - secp256k1_program, + saturating_add_assign, secp256k1_program, signature::{Keypair, Signature}, slot_hashes::SlotHashes, slot_history::SlotHistory, @@ -209,36 +209,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 = self.check_us.saturating_add(other.check_us); - self.load_us = self.load_us.saturating_add(other.load_us); - self.execute_us = self.execute_us.saturating_add(other.execute_us); - self.store_us = self.store_us.saturating_add(other.store_us); - self.update_stakes_cache_us = self - .update_stakes_cache_us - .saturating_add(other.update_stakes_cache_us); - self.total_batches_len = self - .total_batches_len - .saturating_add(other.total_batches_len); - self.num_execute_batches = self - .num_execute_batches - .saturating_add(other.num_execute_batches); - self.details.accumulate(&other.details); - } -} - type BankStatusCache = StatusCache>; #[frozen_abi(digest = "6XG6H1FChrDdY39K62KFWj5XfDao4dd24WZgcJkdMu1E")] pub type BankSlotDelta = SlotDelta>; @@ -3571,7 +3541,7 @@ impl Bank { durable_nonce_fee: Option, enable_cpi_recording: bool, enable_log_recording: bool, - execute_details_timings: &mut ExecuteDetailsTimings, + timings: &mut ExecuteTimings, error_counters: &mut ErrorCounters, ) -> TransactionExecutionResult { let legacy_message = match tx.message().legacy_message() { @@ -3584,11 +3554,17 @@ impl Bank { } }; + let mut get_executors_time = Measure::start("get_executors_time"); let executors = self.get_executors( tx.message(), &loaded_transaction.accounts, &loaded_transaction.program_indices, ); + get_executors_time.stop(); + saturating_add_assign!( + timings.execute_accessories.get_executors_us, + get_executors_time.as_us() + ); let mut transaction_accounts = Vec::new(); std::mem::swap(&mut loaded_transaction.accounts, &mut transaction_accounts); @@ -3612,6 +3588,8 @@ impl Bank { }; let (blockhash, lamports_per_signature) = self.last_blockhash_and_lamports_per_signature(); + + let mut process_message_time = Measure::start("process_message_time"); let process_result = MessageProcessor::process_message( &self.builtin_programs.vec, legacy_message, @@ -3623,14 +3601,25 @@ impl Bank { instruction_recorder.clone(), self.feature_set.clone(), compute_budget, - execute_details_timings, + timings, &*self.sysvar_cache.read().unwrap(), blockhash, lamports_per_signature, self.load_accounts_data_len(), ); + process_message_time.stop(); + saturating_add_assign!( + timings.execute_accessories.process_message_us, + process_message_time.as_us() + ); + 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() + ); let status = process_result .map(|info| { @@ -3723,19 +3712,36 @@ impl Bank { let mut execution_time = Measure::start("execution_time"); let mut signature_count: u64 = 0; - let execute_details_timings = &mut timings.details; let execution_results: Vec = loaded_txs .iter_mut() .zip(sanitized_txs.iter()) .map(|(accs, tx)| match accs { (Err(e), _nonce) => TransactionExecutionResult::NotExecuted(e.clone()), (Ok(loaded_transaction), nonce) => { + let mut feature_set_clone_time = Measure::start("feature_set_clone"); 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 compute_budget = self.compute_budget.unwrap_or_else(ComputeBudget::new); if feature_set.is_active(&tx_wide_compute_cap::id()) { - if let Err(err) = compute_budget.process_transaction(tx, feature_set) { + let mut compute_budget_process_transaction_time = + Measure::start("compute_budget_process_transaction_time"); + let process_transaction_result = + compute_budget.process_transaction(tx, feature_set); + compute_budget_process_transaction_time.stop(); + saturating_add_assign!( + timings + .execute_accessories + .compute_budget_process_transaction_us, + compute_budget_process_transaction_time.as_us() + ); + if let Err(err) = process_transaction_result { return TransactionExecutionResult::NotExecuted(err); } } @@ -3749,7 +3755,7 @@ impl Bank { durable_nonce_fee, enable_cpi_recording, enable_log_recording, - execute_details_timings, + timings, &mut error_counters, ) } diff --git a/runtime/src/message_processor.rs b/runtime/src/message_processor.rs index 827d593f643cc1..4253e1a920e1f8 100644 --- a/runtime/src/message_processor.rs +++ b/runtime/src/message_processor.rs @@ -5,7 +5,7 @@ use { instruction_recorder::InstructionRecorder, invoke_context::{BuiltinProgram, Executors, InvokeContext}, log_collector::LogCollector, - timings::ExecuteDetailsTimings, + timings::ExecuteTimings, }, solana_sdk::{ account::WritableAccount, @@ -16,6 +16,7 @@ use { precompiles::is_precompile, pubkey::Pubkey, rent::Rent, + saturating_add_assign, sysvar::instructions, transaction::TransactionError, transaction_context::{InstructionAccount, TransactionContext}, @@ -60,7 +61,7 @@ impl MessageProcessor { instruction_recorder: Option>>, feature_set: Arc, compute_budget: ComputeBudget, - timings: &mut ExecuteDetailsTimings, + timings: &mut ExecuteTimings, sysvars: &[(Pubkey, Vec)], blockhash: Hash, lamports_per_signature: u64, @@ -134,15 +135,20 @@ impl MessageProcessor { &instruction_accounts, program_indices, &mut compute_units_consumed, + timings, ); time.stop(); - timings.accumulate_program( + timings.details.accumulate_program( instruction.program_id(&message.account_keys), time.as_us(), compute_units_consumed, result.is_err(), ); - timings.accumulate(&invoke_context.timings); + timings.details.accumulate(&invoke_context.timings); + saturating_add_assign!( + timings.execute_accessories.process_instructions.total_us, + time.as_us() + ); result .map_err(|err| TransactionError::InstructionError(instruction_index as u8, err))?; } @@ -264,7 +270,7 @@ mod tests { None, Arc::new(FeatureSet::all_enabled()), ComputeBudget::new(), - &mut ExecuteDetailsTimings::default(), + &mut ExecuteTimings::default(), &[], Hash::default(), 0, @@ -305,7 +311,7 @@ mod tests { None, Arc::new(FeatureSet::all_enabled()), ComputeBudget::new(), - &mut ExecuteDetailsTimings::default(), + &mut ExecuteTimings::default(), &[], Hash::default(), 0, @@ -338,7 +344,7 @@ mod tests { None, Arc::new(FeatureSet::all_enabled()), ComputeBudget::new(), - &mut ExecuteDetailsTimings::default(), + &mut ExecuteTimings::default(), &[], Hash::default(), 0, @@ -464,7 +470,7 @@ mod tests { None, Arc::new(FeatureSet::all_enabled()), ComputeBudget::new(), - &mut ExecuteDetailsTimings::default(), + &mut ExecuteTimings::default(), &[], Hash::default(), 0, @@ -498,7 +504,7 @@ mod tests { None, Arc::new(FeatureSet::all_enabled()), ComputeBudget::new(), - &mut ExecuteDetailsTimings::default(), + &mut ExecuteTimings::default(), &[], Hash::default(), 0, @@ -529,7 +535,7 @@ mod tests { None, Arc::new(FeatureSet::all_enabled()), ComputeBudget::new(), - &mut ExecuteDetailsTimings::default(), + &mut ExecuteTimings::default(), &[], Hash::default(), 0, @@ -602,7 +608,7 @@ mod tests { None, Arc::new(FeatureSet::all_enabled()), ComputeBudget::new(), - &mut ExecuteDetailsTimings::default(), + &mut ExecuteTimings::default(), &[], Hash::default(), 0, diff --git a/sdk/src/lib.rs b/sdk/src/lib.rs index f537560b79efb8..ded554312d8bbc 100644 --- a/sdk/src/lib.rs +++ b/sdk/src/lib.rs @@ -104,6 +104,15 @@ macro_rules! program_stubs { () => {}; } +/// Convenience macro for `AddAssign` with saturating arithmetic. +/// Replace by `std::num::Saturating` once stable +#[macro_export] +macro_rules! saturating_add_assign { + ($i:expr, $v:expr) => {{ + $i = $i.saturating_add($v) + }}; +} + #[macro_use] extern crate serde_derive; pub extern crate bs58; @@ -111,3 +120,18 @@ extern crate log as logger; #[macro_use] extern crate solana_frozen_abi_macro; + +#[cfg(test)] +mod tests { + #[test] + fn test_saturating_add_assign() { + let mut i = 0u64; + let v = 1; + saturating_add_assign!(i, v); + assert_eq!(i, 1); + + i = u64::MAX; + saturating_add_assign!(i, v); + assert_eq!(i, u64::MAX); + } +}