From be35c1c1b7ce8e0b93d0b2d60a7b6a4eb77cf461 Mon Sep 17 00:00:00 2001 From: "Jeff Washington (jwash)" <75863576+jeffwashington@users.noreply.github.com> Date: Wed, 3 Mar 2021 17:07:45 -0600 Subject: [PATCH] add execute detail timings (#15638) --- Cargo.lock | 1 + core/src/banking_stage.rs | 5 ++ ledger/src/blockstore_processor.rs | 12 +++- programs/bpf/Cargo.lock | 1 + programs/bpf_loader/Cargo.toml | 1 + programs/bpf_loader/src/lib.rs | 16 +++++ runtime/benches/message_processor.rs | 30 +++++++-- runtime/src/bank.rs | 13 +++- runtime/src/message_processor.rs | 92 ++++++++++++++++++++++++++-- sdk/src/process_instruction.rs | 16 +++++ 10 files changed, 169 insertions(+), 18 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index fa4257831..219a5cac2 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -4134,6 +4134,7 @@ dependencies = [ "rand 0.7.3", "rand_core 0.6.2", "rustversion", + "solana-measure", "solana-runtime", "solana-sdk", "solana_rbpf", diff --git a/core/src/banking_stage.rs b/core/src/banking_stage.rs index 560f11204..157e18038 100644 --- a/core/src/banking_stage.rs +++ b/core/src/banking_stage.rs @@ -776,6 +776,11 @@ impl BankingStage { txs.len(), ); + debug!( + "process_and_record_transactions_locked: {:?}", + execute_timings + ); + (Ok(num_to_commit), retryable_txs) } diff --git a/ledger/src/blockstore_processor.rs b/ledger/src/blockstore_processor.rs index 4919dab03..1564b4923 100644 --- a/ledger/src/blockstore_processor.rs +++ b/ledger/src/blockstore_processor.rs @@ -214,15 +214,19 @@ pub fn process_entries( transaction_status_sender: Option, replay_vote_sender: Option<&ReplayVoteSender>, ) -> Result<()> { - process_entries_with_callback( + let mut timings = ExecuteTimings::default(); + let result = process_entries_with_callback( bank, entries, randomize, None, transaction_status_sender, replay_vote_sender, - &mut ExecuteTimings::default(), - ) + &mut timings, + ); + + debug!("process_entries: {:?}", timings); + result } fn process_entries_with_callback( @@ -602,6 +606,8 @@ fn confirm_full_slot( opts.allow_dead_slots, )?; + debug!("confirm_full_slot: {:?}", timing.execute_timings); + if !bank.is_complete() { Err(BlockstoreProcessorError::InvalidBlock( BlockError::Incomplete, diff --git a/programs/bpf/Cargo.lock b/programs/bpf/Cargo.lock index a74a6463b..dc598c6f4 100644 --- a/programs/bpf/Cargo.lock +++ b/programs/bpf/Cargo.lock @@ -2598,6 +2598,7 @@ dependencies = [ "num-derive 0.3.0", "num-traits", "rand_core 0.6.2", + "solana-measure", "solana-runtime", "solana-sdk", "solana_rbpf", diff --git a/programs/bpf_loader/Cargo.toml b/programs/bpf_loader/Cargo.toml index e98d0419a..092b446dc 100644 --- a/programs/bpf_loader/Cargo.toml +++ b/programs/bpf_loader/Cargo.toml @@ -16,6 +16,7 @@ log = "0.4.11" num-derive = "0.3" num-traits = "0.2" rand_core = "0.6.2" +solana-measure = { path = "../../measure", version = "1.6.0" } solana-runtime = { path = "../../runtime", version = "1.6.0" } solana-sdk = { path = "../../sdk", version = "1.6.0" } solana_rbpf = "=0.2.5" diff --git a/programs/bpf_loader/src/lib.rs b/programs/bpf_loader/src/lib.rs index 87a4128fd..0fb09de55 100644 --- a/programs/bpf_loader/src/lib.rs +++ b/programs/bpf_loader/src/lib.rs @@ -15,6 +15,7 @@ use crate::{ syscalls::SyscallError, }; use log::{log_enabled, trace, Level::Trace}; +use solana_measure::measure::Measure; use solana_rbpf::{ ebpf::MM_HEAP_START, error::{EbpfError, UserDefinedError}, @@ -770,8 +771,12 @@ impl Executor for BpfExecutor { let mut keyed_accounts_iter = keyed_accounts.iter(); let _ = next_keyed_account(&mut keyed_accounts_iter)?; let parameter_accounts = keyed_accounts_iter.as_slice(); + let mut serialize_time = Measure::start("serialize"); let mut parameter_bytes = serialize_parameters(loader_id, program_id, parameter_accounts, &instruction_data)?; + serialize_time.stop(); + let mut create_vm_time = Measure::start("create_vm"); + let mut execute_time; { let compute_meter = invoke_context.get_compute_meter(); let mut vm = match create_vm( @@ -787,7 +792,9 @@ impl Executor for BpfExecutor { return Err(InstructionError::ProgramEnvironmentSetupFailure); } }; + create_vm_time.stop(); + execute_time = Measure::start("execute"); stable_log::program_invoke(&logger, program_id, invoke_depth); let mut instruction_meter = ThisInstructionMeter::new(compute_meter.clone()); let before = compute_meter.borrow().get_remaining(); @@ -833,8 +840,17 @@ impl Executor for BpfExecutor { return Err(error); } } + execute_time.stop(); } + let mut deserialize_time = Measure::start("deserialize"); deserialize_parameters(loader_id, parameter_accounts, ¶meter_bytes)?; + deserialize_time.stop(); + invoke_context.update_timing( + serialize_time.as_us(), + create_vm_time.as_us(), + execute_time.as_us(), + deserialize_time.as_us(), + ); stable_log::program_success(&logger, program_id); Ok(()) } diff --git a/runtime/benches/message_processor.rs b/runtime/benches/message_processor.rs index 638fbf085..bf8246e9f 100644 --- a/runtime/benches/message_processor.rs +++ b/runtime/benches/message_processor.rs @@ -3,7 +3,7 @@ extern crate test; use log::*; -use solana_runtime::message_processor::PreAccount; +use solana_runtime::message_processor::{ExecuteDetailsTimings, PreAccount}; use solana_sdk::{account::Account, pubkey, rent::Rent}; use test::Bencher; @@ -20,14 +20,26 @@ fn bench_verify_account_changes_data(bencher: &mut Bencher) { ); let post = Account::new(0, BUFSIZE, &owner); assert_eq!( - pre.verify(&owner, Some(false), &Rent::default(), &post), + pre.verify( + &owner, + Some(false), + &Rent::default(), + &post, + &mut ExecuteDetailsTimings::default() + ), Ok(()) ); // this one should be faster bencher.iter(|| { - pre.verify(&owner, Some(false), &Rent::default(), &post) - .unwrap(); + pre.verify( + &owner, + Some(false), + &Rent::default(), + &post, + &mut ExecuteDetailsTimings::default(), + ) + .unwrap(); }); let summary = bencher.bench(|_bencher| {}).unwrap(); info!("data no change by owner: {} ns/iter", summary.median); @@ -44,8 +56,14 @@ fn bench_verify_account_changes_data(bencher: &mut Bencher) { false, ); bencher.iter(|| { - pre.verify(&non_owner, Some(false), &Rent::default(), &post) - .unwrap(); + pre.verify( + &non_owner, + Some(false), + &Rent::default(), + &post, + &mut ExecuteDetailsTimings::default(), + ) + .unwrap(); }); let summary = bencher.bench(|_bencher| {}).unwrap(); info!("data no change by non owner: {} ns/iter", summary.median); diff --git a/runtime/src/bank.rs b/runtime/src/bank.rs index 4c1872ceb..731681c1e 100644 --- a/runtime/src/bank.rs +++ b/runtime/src/bank.rs @@ -15,7 +15,7 @@ use crate::{ inline_spl_token_v2_0, instruction_recorder::InstructionRecorder, log_collector::LogCollector, - message_processor::{Executors, MessageProcessor}, + message_processor::{ExecuteDetailsTimings, Executors, MessageProcessor}, rent_collector::RentCollector, stakes::Stakes, status_cache::{SlotDelta, StatusCache}, @@ -93,11 +93,12 @@ pub const SECONDS_PER_YEAR: f64 = 365.25 * 24.0 * 60.0 * 60.0; pub const MAX_LEADER_SCHEDULE_STAKES: Epoch = 5; -#[derive(Default)] +#[derive(Default, Debug)] pub struct ExecuteTimings { pub load_us: u64, pub execute_us: u64, pub store_us: u64, + pub details: ExecuteDetailsTimings, } impl ExecuteTimings { @@ -105,6 +106,7 @@ impl ExecuteTimings { self.load_us += other.load_us; self.execute_us += other.execute_us; self.store_us += other.store_us; + self.details.accumulate(&other.details); } } @@ -2415,6 +2417,8 @@ impl Bank { let txs = &[transaction]; let batch = self.prepare_simulation_batch(txs); + let mut timings = ExecuteTimings::default(); + let ( _loaded_accounts, executed, @@ -2431,7 +2435,7 @@ impl Bank { MAX_PROCESSING_AGE - MAX_TRANSACTION_FORWARDING_DELAY, false, true, - &mut ExecuteTimings::default(), + &mut timings, ); let transaction_result = executed[0].0.clone().map(|_| ()); @@ -2439,6 +2443,8 @@ impl Bank { .get(0) .map_or(vec![], |messages| messages.to_vec()); + debug!("simulate_transaction: {:?}", timings); + (transaction_result, log_messages) } @@ -2923,6 +2929,7 @@ impl Bank { instruction_recorders.as_deref(), self.feature_set.clone(), bpf_compute_budget, + &mut timings.details, ); if enable_log_recording { diff --git a/runtime/src/message_processor.rs b/runtime/src/message_processor.rs index 5750981b2..793ac964e 100644 --- a/runtime/src/message_processor.rs +++ b/runtime/src/message_processor.rs @@ -52,6 +52,31 @@ impl Executors { } } +#[derive(Default, Debug)] +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, +} + +impl ExecuteDetailsTimings { + pub fn accumulate(&mut self, other: &ExecuteDetailsTimings) { + self.serialize_us += other.serialize_us; + self.create_vm_us += other.create_vm_us; + self.execute_us += other.execute_us; + self.deserialize_us += other.deserialize_us; + self.changed_account_count += other.changed_account_count; + self.total_account_count += other.total_account_count; + self.total_data_size += other.total_data_size; + self.data_size_changed += other.data_size_changed; + } +} + // The relevant state of an account before an Instruction executes, used // to verify account integrity after the Instruction completes #[derive(Clone, Debug, Default)] @@ -59,6 +84,7 @@ pub struct PreAccount { key: Pubkey, is_writable: bool, account: RefCell, + changed: bool, } impl PreAccount { pub fn new(key: &Pubkey, account: &Account, is_writable: bool) -> Self { @@ -66,6 +92,7 @@ impl PreAccount { key: *key, is_writable, account: RefCell::new(account.clone()), + changed: false, } } @@ -75,6 +102,7 @@ impl PreAccount { is_writable: Option, rent: &Rent, post: &Account, + timings: &mut ExecuteDetailsTimings, ) -> Result<(), InstructionError> { let pre = self.account.borrow(); @@ -88,7 +116,8 @@ impl PreAccount { // only if the account is writable and // only if the account is not executable and // only if the data is zero-initialized or empty - if pre.owner != post.owner + let owner_changed = pre.owner != post.owner; + if owner_changed && (!is_writable // line coverage used to get branch coverage || pre.executable || *program_id != pre.owner @@ -105,7 +134,8 @@ impl PreAccount { } // The balance of read-only and executable accounts may not change - if pre.lamports != post.lamports { + let lamports_changed = pre.lamports != post.lamports; + if lamports_changed { if !is_writable { return Err(InstructionError::ReadonlyLamportChange); } @@ -116,7 +146,8 @@ impl PreAccount { // Only the system program can change the size of the data // and only if the system program owns the account - if pre.data.len() != post.data.len() + let data_len_changed = pre.data.len() != post.data.len(); + if data_len_changed && (!system_program::check_id(program_id) // line coverage used to get branch coverage || !system_program::check_id(&pre.owner)) { @@ -141,7 +172,8 @@ impl PreAccount { } // executable is one-way (false->true) and only the account owner may set it. - if pre.executable != post.executable { + let executable_changed = pre.executable != post.executable; + if executable_changed { if !rent.is_exempt(post.lamports, post.data.len()) { return Err(InstructionError::ExecutableAccountNotRentExempt); } @@ -154,10 +186,24 @@ impl PreAccount { } // No one modifies rent_epoch (yet). - if pre.rent_epoch != post.rent_epoch { + let rent_epoch_changed = pre.rent_epoch != post.rent_epoch; + if rent_epoch_changed { return Err(InstructionError::RentEpochModified); } + timings.total_account_count += 1; + timings.total_data_size += post.data.len(); + if owner_changed + || lamports_changed + || data_len_changed + || executable_changed + || rent_epoch_changed + || self.changed + { + timings.changed_account_count += 1; + timings.data_size_changed += post.data.len(); + } + Ok(()) } @@ -174,6 +220,8 @@ impl PreAccount { // Copy without allocate pre.data.clone_from_slice(&account.data); } + + self.changed = true; } pub fn key(&self) -> Pubkey { @@ -222,6 +270,7 @@ pub struct ThisInvokeContext<'a> { executors: Rc>, instruction_recorder: Option, feature_set: Arc, + pub timings: ExecuteDetailsTimings, } impl<'a> ThisInvokeContext<'a> { #[allow(clippy::too_many_arguments)] @@ -253,6 +302,7 @@ impl<'a> ThisInvokeContext<'a> { executors, instruction_recorder, feature_set, + timings: ExecuteDetailsTimings::default(), } } } @@ -293,6 +343,7 @@ impl<'a> InvokeContext for ThisInvokeContext<'a> { &self.rent, track_writable_deescalation, caller_privileges, + &mut self.timings, ), None => Err(InstructionError::GenericError), // Should never happen } @@ -346,6 +397,18 @@ impl<'a> InvokeContext for ThisInvokeContext<'a> { } }) } + fn update_timing( + &mut self, + serialize_us: u64, + create_vm_us: u64, + execute_us: u64, + deserialize_us: u64, + ) { + self.timings.serialize_us += serialize_us; + self.timings.create_vm_us += create_vm_us; + self.timings.execute_us += execute_us; + self.timings.deserialize_us += deserialize_us; + } } pub struct ThisLogger { log_collector: Option>, @@ -836,6 +899,7 @@ impl MessageProcessor { executable_accounts: &[(Pubkey, RefCell)], accounts: &[Rc>], rent: &Rent, + timings: &mut ExecuteDetailsTimings, ) -> Result<(), InstructionError> { // Verify all executable accounts have zero outstanding refs Self::verify_account_references(executable_accounts)?; @@ -854,6 +918,7 @@ impl MessageProcessor { Some(message.is_writable(account_index)), rent, &account, + timings, )?; pre_sum += u128::from(pre_accounts[unique_index].lamports()); post_sum += u128::from(account.lamports); @@ -879,6 +944,7 @@ impl MessageProcessor { rent: &Rent, track_writable_deescalation: bool, caller_privileges: Option<&[bool]>, + timings: &mut ExecuteDetailsTimings, ) -> Result<(), InstructionError> { // Verify the per-account instruction results let (mut pre_sum, mut post_sum) = (0_u128, 0_u128); @@ -903,7 +969,7 @@ impl MessageProcessor { .try_borrow_mut() .map_err(|_| InstructionError::AccountBorrowOutstanding)?; - pre_account.verify(&program_id, is_writable, &rent, &account)?; + pre_account.verify(&program_id, is_writable, &rent, &account, timings)?; pre_sum += u128::from(pre_account.lamports()); post_sum += u128::from(account.lamports); @@ -944,6 +1010,7 @@ impl MessageProcessor { instruction_index: usize, feature_set: Arc, bpf_compute_budget: BpfComputeBudget, + timings: &mut ExecuteDetailsTimings, ) -> Result<(), InstructionError> { // Fixup the special instructions key if present // before the account pre-values are taken care of @@ -989,7 +1056,11 @@ impl MessageProcessor { executable_accounts, accounts, &rent_collector.rent, + timings, )?; + + timings.accumulate(&invoke_context.timings); + Ok(()) } @@ -1009,6 +1080,7 @@ impl MessageProcessor { instruction_recorders: Option<&[InstructionRecorder]>, feature_set: Arc, bpf_compute_budget: BpfComputeBudget, + timings: &mut ExecuteDetailsTimings, ) -> Result<(), TransactionError> { for (instruction_index, instruction) in message.instructions.iter().enumerate() { let instruction_recorder = instruction_recorders @@ -1027,6 +1099,7 @@ impl MessageProcessor { instruction_index, feature_set.clone(), bpf_compute_budget, + timings, ) .map_err(|err| TransactionError::InstructionError(instruction_index as u8, err))?; } @@ -1247,6 +1320,7 @@ mod tests { Some(self.is_writable), &self.rent, &self.post, + &mut ExecuteDetailsTimings::default(), ) } } @@ -1646,6 +1720,7 @@ mod tests { None, Arc::new(FeatureSet::all_enabled()), BpfComputeBudget::new(), + &mut ExecuteDetailsTimings::default(), ); assert_eq!(result, Ok(())); assert_eq!(accounts[0].borrow().lamports, 100); @@ -1671,6 +1746,7 @@ mod tests { None, Arc::new(FeatureSet::all_enabled()), BpfComputeBudget::new(), + &mut ExecuteDetailsTimings::default(), ); assert_eq!( result, @@ -1700,6 +1776,7 @@ mod tests { None, Arc::new(FeatureSet::all_enabled()), BpfComputeBudget::new(), + &mut ExecuteDetailsTimings::default(), ); assert_eq!( result, @@ -1813,6 +1890,7 @@ mod tests { None, Arc::new(FeatureSet::all_enabled()), BpfComputeBudget::new(), + &mut ExecuteDetailsTimings::default(), ); assert_eq!( result, @@ -1842,6 +1920,7 @@ mod tests { None, Arc::new(FeatureSet::all_enabled()), BpfComputeBudget::new(), + &mut ExecuteDetailsTimings::default(), ); assert_eq!(result, Ok(())); @@ -1868,6 +1947,7 @@ mod tests { None, Arc::new(FeatureSet::all_enabled()), BpfComputeBudget::new(), + &mut ExecuteDetailsTimings::default(), ); assert_eq!(result, Ok(())); assert_eq!(accounts[0].borrow().lamports, 80); diff --git a/sdk/src/process_instruction.rs b/sdk/src/process_instruction.rs index 0878f5d79..1659e95f6 100644 --- a/sdk/src/process_instruction.rs +++ b/sdk/src/process_instruction.rs @@ -60,6 +60,14 @@ pub trait InvokeContext { fn is_feature_active(&self, feature_id: &Pubkey) -> bool; /// Get an account from a pre-account fn get_account(&self, pubkey: &Pubkey) -> Option>; + /// Update timing + fn update_timing( + &mut self, + serialize_us: u64, + create_vm_us: u64, + execute_us: u64, + deserialize_us: u64, + ); } /// Convenience macro to log a message with an `Rc>` @@ -328,4 +336,12 @@ impl InvokeContext for MockInvokeContext { fn get_account(&self, _pubkey: &Pubkey) -> Option> { None } + fn update_timing( + &mut self, + _serialize_us: u64, + _create_vm_us: u64, + _execute_us: u64, + _deserialize_us: u64, + ) { + } }