From b25e4a200b87949dc30be63e413fdbba90c55449 Mon Sep 17 00:00:00 2001 From: Carl Lin Date: Mon, 20 Dec 2021 23:03:20 -0500 Subject: [PATCH] Add execute metrics --- Cargo.lock | 1 + core/src/cost_update_service.rs | 8 ++- core/src/progress_map.rs | 71 ++++++++++++++++++++++++--- core/src/replay_stage.rs | 4 +- program-runtime/Cargo.toml | 1 + program-runtime/src/invoke_context.rs | 62 +++++++++++++++++++---- program-runtime/src/timings.rs | 50 +++++++++++++++++++ program-test/src/lib.rs | 1 + programs/bpf_loader/src/lib.rs | 4 ++ programs/bpf_loader/src/syscalls.rs | 2 + runtime/src/bank.rs | 35 ++++++++++--- runtime/src/message_processor.rs | 24 ++++----- 12 files changed, 225 insertions(+), 38 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 997936aa4..0cbde5702 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -5488,6 +5488,7 @@ dependencies = [ "rustc_version 0.4.0", "serde", "solana-logger 1.10.0", + "solana-measure", "solana-sdk", "thiserror", ] diff --git a/core/src/cost_update_service.rs b/core/src/cost_update_service.rs index b6f3eb60d..55fb0e738 100644 --- a/core/src/cost_update_service.rs +++ b/core/src/cost_update_service.rs @@ -69,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 3a0f566cb..0ad895bd7 100644 --- a/core/src/progress_map.rs +++ b/core/src/progress_map.rs @@ -82,45 +82,100 @@ 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_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 238ae0ba3..aa6d36424 100644 --- a/core/src/replay_stage.rs +++ b/core/src/replay_stage.rs @@ -2248,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/program-runtime/Cargo.toml b/program-runtime/Cargo.toml index b7e99f2e6..e0e5fe33f 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 3d3fae7d9..c0a605427 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}, @@ -603,6 +608,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 +779,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 +797,16 @@ 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(); + timings + .execute_accessories + .process_instruction_verify_caller_us = timings + .execute_accessories + .process_instruction_verify_caller_us + .saturating_add(verify_caller_time.as_us()); + verify_caller_result?; // Record instruction if let Some(instruction_recorder) = &self.instruction_recorder { @@ -805,6 +821,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 +831,40 @@ 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(); + + timings + .execute_accessories + .process_instruction_process_executable_chain_us = timings + .execute_accessories + .process_instruction_process_executable_chain_us + .saturating_add(process_executable_chain_time.as_us()); + timings + .execute_accessories + .process_instruction_verify_callee_us = timings + .execute_accessories + .process_instruction_verify_callee_us + .saturating_add(verify_callee_time.as_us()); + + result }); // Pop the invoke_stack to restore previous state @@ -1526,6 +1564,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 +1678,7 @@ mod tests { &instruction_accounts, &[2], &mut 0, + &mut ExecuteTimings::default(), ); assert!(result.is_ok()); @@ -1656,6 +1696,7 @@ mod tests { &instruction_accounts, &[2], &mut 0, + &mut ExecuteTimings::default(), ); assert!(result.is_ok()); @@ -1673,6 +1714,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 35ff7323c..fe89bb1c5 100644 --- a/program-runtime/src/timings.rs +++ b/program-runtime/src/timings.rs @@ -46,6 +46,7 @@ pub struct ExecuteTimings { pub num_execute_batches: u64, pub collect_logs_us: u64, pub details: ExecuteDetailsTimings, + pub execute_accessories: ExecuteAccessoryTimings, } impl ExecuteTimings { @@ -65,6 +66,51 @@ impl ExecuteTimings { .saturating_add(other.num_execute_batches); self.collect_logs_us = self.collect_logs_us.saturating_add(other.collect_logs_us); 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) { + self.compute_budget_process_transaction_us = self + .feature_set_clone_us + .saturating_add(other.feature_set_clone_us); + self.compute_budget_process_transaction_us = self + .compute_budget_process_transaction_us + .saturating_add(other.compute_budget_process_transaction_us); + self.get_executors_us = self.get_executors_us.saturating_add(other.get_executors_us); + self.process_message_us = self + .process_message_us + .saturating_add(other.process_message_us); + self.update_executors_us = self + .update_executors_us + .saturating_add(other.update_executors_us); + self.process_instructions_us = self + .process_instructions_us + .saturating_add(other.process_instructions_us); + self.process_instruction_verify_caller_us = self + .process_instruction_verify_caller_us + .saturating_add(other.process_instruction_verify_caller_us); + self.process_instruction_process_executable_chain_us = self + .process_instruction_process_executable_chain_us + .saturating_add(other.process_instruction_process_executable_chain_us); + self.process_instruction_verify_callee_us = self + .process_instruction_verify_callee_us + .saturating_add(other.process_instruction_verify_callee_us); } } @@ -74,6 +120,7 @@ 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, @@ -86,6 +133,9 @@ impl ExecuteDetailsTimings { 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.get_or_create_executor_us = self + .get_or_create_executor_us + .saturating_add(other.get_or_create_executor_us); self.changed_account_count = self .changed_account_count .saturating_add(other.changed_account_count); diff --git a/program-test/src/lib.rs b/program-test/src/lib.rs index ad6e87a63..07913ce7f 100644 --- a/program-test/src/lib.rs +++ b/program-test/src/lib.rs @@ -303,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_loader/src/lib.rs b/programs/bpf_loader/src/lib.rs index c6cbcc120..9fd92f8f1 100644 --- a/programs/bpf_loader/src/lib.rs +++ b/programs/bpf_loader/src/lib.rs @@ -291,6 +291,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 +307,9 @@ fn process_instruction_common( executor } }; + get_or_create_executor_time.stop(); + 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 63c95d860..b4a53e5fb 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 d223091b1..7c5484070 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, ExecuteTimings}, + timings::ExecuteTimings, }, solana_sdk::{ account::{ @@ -3541,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() { @@ -3554,11 +3554,14 @@ 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(); + 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); @@ -3582,6 +3585,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, @@ -3593,14 +3598,19 @@ 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(); + 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(); + timings.execute_accessories.update_executors_us += update_executors_time.as_us(); let status = process_result .map(|info| { @@ -3693,19 +3703,32 @@ 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(); + 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(); + 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); } } @@ -3719,7 +3742,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 827d593f6..3f726fb9e 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, @@ -60,7 +60,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 +134,17 @@ 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); + timings.execute_accessories.process_instructions_us += time.as_us(); result .map_err(|err| TransactionError::InstructionError(instruction_index as u8, err))?; } @@ -264,7 +266,7 @@ mod tests { None, Arc::new(FeatureSet::all_enabled()), ComputeBudget::new(), - &mut ExecuteDetailsTimings::default(), + &mut ExecuteTimings::default(), &[], Hash::default(), 0, @@ -305,7 +307,7 @@ mod tests { None, Arc::new(FeatureSet::all_enabled()), ComputeBudget::new(), - &mut ExecuteDetailsTimings::default(), + &mut ExecuteTimings::default(), &[], Hash::default(), 0, @@ -338,7 +340,7 @@ mod tests { None, Arc::new(FeatureSet::all_enabled()), ComputeBudget::new(), - &mut ExecuteDetailsTimings::default(), + &mut ExecuteTimings::default(), &[], Hash::default(), 0, @@ -464,7 +466,7 @@ mod tests { None, Arc::new(FeatureSet::all_enabled()), ComputeBudget::new(), - &mut ExecuteDetailsTimings::default(), + &mut ExecuteTimings::default(), &[], Hash::default(), 0, @@ -498,7 +500,7 @@ mod tests { None, Arc::new(FeatureSet::all_enabled()), ComputeBudget::new(), - &mut ExecuteDetailsTimings::default(), + &mut ExecuteTimings::default(), &[], Hash::default(), 0, @@ -529,7 +531,7 @@ mod tests { None, Arc::new(FeatureSet::all_enabled()), ComputeBudget::new(), - &mut ExecuteDetailsTimings::default(), + &mut ExecuteTimings::default(), &[], Hash::default(), 0, @@ -602,7 +604,7 @@ mod tests { None, Arc::new(FeatureSet::all_enabled()), ComputeBudget::new(), - &mut ExecuteDetailsTimings::default(), + &mut ExecuteTimings::default(), &[], Hash::default(), 0,