From b064956e20ae2999bf6a798e4d88dbbcdd6badd9 Mon Sep 17 00:00:00 2001 From: "mergify[bot]" <37929162+mergify[bot]@users.noreply.github.com> Date: Fri, 15 Jan 2021 21:13:09 +0000 Subject: [PATCH] Add load/execute/store timings (#14561) (#14590) Co-authored-by: sakridge --- core/src/banking_stage.rs | 9 +++- core/src/progress_map.rs | 3 ++ ledger/src/blockstore_processor.rs | 70 ++++++++++++++++++++++-------- program-test/src/lib.rs | 12 ++++- programs/bpf/tests/programs.rs | 3 +- runtime/src/bank.rs | 39 +++++++++++++++-- 6 files changed, 112 insertions(+), 24 deletions(-) diff --git a/core/src/banking_stage.rs b/core/src/banking_stage.rs index ae593f61c3..345d313257 100644 --- a/core/src/banking_stage.rs +++ b/core/src/banking_stage.rs @@ -23,7 +23,10 @@ use solana_perf::{ }; use solana_runtime::{ accounts_db::ErrorCounters, - bank::{Bank, TransactionBalancesSet, TransactionCheckResult, TransactionExecutionResult}, + bank::{ + Bank, ExecuteTimings, TransactionBalancesSet, TransactionCheckResult, + TransactionExecutionResult, + }, bank_utils, transaction_batch::TransactionBatch, vote_sender_types::ReplayVoteSender, @@ -530,6 +533,8 @@ impl BankingStage { } else { vec![] }; + + let mut execute_timings = ExecuteTimings::default(); let ( mut loaded_accounts, results, @@ -543,6 +548,7 @@ impl BankingStage { MAX_PROCESSING_AGE, transaction_status_sender.is_some(), transaction_status_sender.is_some(), + &mut execute_timings, ); load_execute_time.stop(); @@ -569,6 +575,7 @@ impl BankingStage { &results, tx_count, signature_count, + &mut execute_timings, ); bank_utils::find_and_send_votes(txs, &tx_results, Some(gossip_vote_sender)); diff --git a/core/src/progress_map.rs b/core/src/progress_map.rs index 8b27687f83..de63860f01 100644 --- a/core/src/progress_map.rs +++ b/core/src/progress_map.rs @@ -61,6 +61,9 @@ impl ReplaySlotStats { ), ("total_entries", num_entries as i64, i64), ("total_shreds", num_shreds as i64, i64), + ("load_us", self.execute_timings.load_us, i64), + ("execute_us", self.execute_timings.execute_us, i64), + ("store_us", self.execute_timings.store_us, i64), ); } } diff --git a/ledger/src/blockstore_processor.rs b/ledger/src/blockstore_processor.rs index e70fc43c3d..58e6958be7 100644 --- a/ledger/src/blockstore_processor.rs +++ b/ledger/src/blockstore_processor.rs @@ -18,8 +18,8 @@ use solana_rayon_threadlimit::get_thread_count; use solana_runtime::{ accounts_index::AccountIndex, bank::{ - Bank, InnerInstructionsList, TransactionBalancesSet, TransactionExecutionResult, - TransactionLogMessages, TransactionResults, + Bank, ExecuteTimings, InnerInstructionsList, TransactionBalancesSet, + TransactionExecutionResult, TransactionLogMessages, TransactionResults, }, bank_forks::BankForks, bank_utils, @@ -102,6 +102,7 @@ fn execute_batch( bank: &Arc, transaction_status_sender: Option, replay_vote_sender: Option<&ReplayVoteSender>, + timings: &mut ExecuteTimings, ) -> Result<()> { let (tx_results, balances, inner_instructions, transaction_logs) = batch.bank().load_execute_and_commit_transactions( @@ -110,6 +111,7 @@ fn execute_batch( transaction_status_sender.is_some(), transaction_status_sender.is_some(), transaction_status_sender.is_some(), + timings, ); bank_utils::find_and_send_votes(batch.transactions(), &tx_results, replay_vote_sender); @@ -143,22 +145,35 @@ fn execute_batches( entry_callback: Option<&ProcessCallback>, transaction_status_sender: Option, replay_vote_sender: Option<&ReplayVoteSender>, + timings: &mut ExecuteTimings, ) -> Result<()> { inc_new_counter_debug!("bank-par_execute_entries-count", batches.len()); - let results: Vec> = PAR_THREAD_POOL.with(|thread_pool| { - thread_pool.borrow().install(|| { - batches - .into_par_iter() - .map_with(transaction_status_sender, |sender, batch| { - let result = execute_batch(batch, bank, sender.clone(), replay_vote_sender); - if let Some(entry_callback) = entry_callback { - entry_callback(bank); - } - result - }) - .collect() - }) - }); + let (results, new_timings): (Vec>, Vec) = + PAR_THREAD_POOL.with(|thread_pool| { + thread_pool.borrow().install(|| { + batches + .into_par_iter() + .map_with(transaction_status_sender, |sender, batch| { + let mut timings = ExecuteTimings::default(); + let result = execute_batch( + batch, + bank, + sender.clone(), + replay_vote_sender, + &mut timings, + ); + if let Some(entry_callback) = entry_callback { + entry_callback(bank); + } + (result, timings) + }) + .unzip() + }) + }); + + for timing in new_timings { + timings.accumulate(&timing); + } first_err(&results) } @@ -182,6 +197,7 @@ pub fn process_entries( None, transaction_status_sender, replay_vote_sender, + &mut ExecuteTimings::default(), ) } @@ -192,6 +208,7 @@ fn process_entries_with_callback( entry_callback: Option<&ProcessCallback>, transaction_status_sender: Option, replay_vote_sender: Option<&ReplayVoteSender>, + timings: &mut ExecuteTimings, ) -> Result<()> { // accumulator for entries that can be processed in parallel let mut batches = vec![]; @@ -209,6 +226,7 @@ fn process_entries_with_callback( entry_callback, transaction_status_sender.clone(), replay_vote_sender, + timings, )?; batches.clear(); for hash in &tick_hashes { @@ -265,6 +283,7 @@ fn process_entries_with_callback( entry_callback, transaction_status_sender.clone(), replay_vote_sender, + timings, )?; batches.clear(); } @@ -276,6 +295,7 @@ fn process_entries_with_callback( entry_callback, transaction_status_sender, replay_vote_sender, + timings, )?; for hash in tick_hashes { bank.register_tick(&hash); @@ -567,6 +587,7 @@ pub struct ConfirmationTiming { pub transaction_verify_elapsed: u64, pub fetch_elapsed: u64, pub fetch_fail_elapsed: u64, + pub execute_timings: ExecuteTimings, } impl Default for ConfirmationTiming { @@ -578,6 +599,7 @@ impl Default for ConfirmationTiming { transaction_verify_elapsed: 0, fetch_elapsed: 0, fetch_fail_elapsed: 0, + execute_timings: ExecuteTimings::default(), } } } @@ -673,6 +695,7 @@ pub fn confirm_slot( }; let mut replay_elapsed = Measure::start("replay_elapsed"); + let mut execute_timings = ExecuteTimings::default(); let process_result = process_entries_with_callback( bank, &entries, @@ -680,11 +703,14 @@ pub fn confirm_slot( entry_callback, transaction_status_sender, replay_vote_sender, + &mut execute_timings, ) .map_err(BlockstoreProcessorError::from); replay_elapsed.stop(); timing.replay_elapsed += replay_elapsed.as_us(); + timing.execute_timings.accumulate(&execute_timings); + if let Some(mut verifier) = verifier { let verified = verifier.finish_verify(&entries); timing.poh_verify_elapsed += verifier.poh_duration_us(); @@ -2826,7 +2852,16 @@ pub mod tests { let entry = next_entry(&new_blockhash, 1, vec![tx]); entries.push(entry); - process_entries_with_callback(&bank0, &entries, true, None, None, None).unwrap(); + process_entries_with_callback( + &bank0, + &entries, + true, + None, + None, + None, + &mut ExecuteTimings::default(), + ) + .unwrap(); assert_eq!(bank0.get_balance(&keypair.pubkey()), 1) } @@ -2918,6 +2953,7 @@ pub mod tests { false, false, false, + &mut ExecuteTimings::default(), ); let (err, signature) = get_first_error(&batch, fee_collection_results).unwrap(); // First error found should be for the 2nd transaction, due to iteration_order diff --git a/program-test/src/lib.rs b/program-test/src/lib.rs index b38198a24a..4dc3ca12ab 100644 --- a/program-test/src/lib.rs +++ b/program-test/src/lib.rs @@ -13,7 +13,7 @@ use { rent::Rent, }, solana_runtime::{ - bank::{Bank, Builtin}, + bank::{Bank, Builtin, ExecuteTimings}, bank_forks::BankForks, genesis_utils::create_genesis_config_with_leader, }, @@ -654,7 +654,15 @@ impl ProgramTest { // `bank.commit_transactions()` so that the fee calculator in the child bank will be // initialized with a non-zero fee. assert_eq!(bank.signature_count(), 0); - bank.commit_transactions(&[], None, &mut [], &[], 0, 1); + bank.commit_transactions( + &[], + None, + &mut [], + &[], + 0, + 1, + &mut ExecuteTimings::default(), + ); assert_eq!(bank.signature_count(), 1); // Advance beyond slot 0 for a slightly more realistic test environment diff --git a/programs/bpf/tests/programs.rs b/programs/bpf/tests/programs.rs index 05062b7603..fadafad8ee 100644 --- a/programs/bpf/tests/programs.rs +++ b/programs/bpf/tests/programs.rs @@ -9,7 +9,7 @@ use solana_bpf_loader_program::{ }; use solana_rbpf::vm::EbpfVm; use solana_runtime::{ - bank::Bank, + bank::{Bank, ExecuteTimings}, bank_client::BankClient, genesis_utils::{create_genesis_config, GenesisConfigInfo}, loader_utils::{ @@ -184,6 +184,7 @@ fn process_transaction_and_record_inner( false, true, false, + &mut ExecuteTimings::default(), ); let inner_instructions = inner.swap_remove(0); let result = results diff --git a/runtime/src/bank.rs b/runtime/src/bank.rs index 172903beb9..fd5cf9517b 100644 --- a/runtime/src/bank.rs +++ b/runtime/src/bank.rs @@ -93,6 +93,21 @@ pub const SECONDS_PER_YEAR: f64 = 365.25 * 24.0 * 60.0 * 60.0; pub const MAX_LEADER_SCHEDULE_STAKES: Epoch = 5; +#[derive(Default)] +pub struct ExecuteTimings { + pub load_us: u64, + pub execute_us: u64, + pub store_us: u64, +} + +impl ExecuteTimings { + pub fn accumulate(&mut self, other: &ExecuteTimings) { + self.load_us += other.load_us; + self.execute_us += other.execute_us; + self.store_us += other.store_us; + } +} + type BankStatusCache = StatusCache>; #[frozen_abi(digest = "MUmkgPsCRrWL2HEsMEvpkWMis35kbBnaEZtrph5P6bk")] pub type BankSlotDelta = SlotDelta>; @@ -2369,6 +2384,7 @@ impl Bank { MAX_PROCESSING_AGE - MAX_TRANSACTION_FORWARDING_DELAY, false, true, + &mut ExecuteTimings::default(), ); let transaction_result = executed[0].0.clone().map(|_| ()); @@ -2779,6 +2795,7 @@ impl Bank { max_age: usize, enable_cpi_recording: bool, enable_log_recording: bool, + timings: &mut ExecuteTimings, ) -> ( Vec, Vec, @@ -2920,6 +2937,8 @@ impl Bank { execution_time.as_us(), txs.len(), ); + timings.load_us += load_time.as_us(); + timings.execute_us += execution_time.as_us(); let mut tx_count: u64 = 0; let err_count = &mut error_counters.total; @@ -3075,6 +3094,7 @@ impl Bank { executed: &[TransactionExecutionResult], tx_count: u64, signature_count: u64, + timings: &mut ExecuteTimings, ) -> TransactionResults { assert!( !self.freeze_started(), @@ -3114,6 +3134,7 @@ impl Bank { // once committed there is no way to unroll write_time.stop(); debug!("store: {}us txs_len={}", write_time.as_us(), txs.len(),); + timings.store_us += write_time.as_us(); self.update_transaction_statuses(txs, iteration_order, &executed); let fee_collection_results = self.filter_program_errors_and_collect_fee(txs, iteration_order, executed); @@ -3697,6 +3718,7 @@ impl Bank { collect_balances: bool, enable_cpi_recording: bool, enable_log_recording: bool, + timings: &mut ExecuteTimings, ) -> ( TransactionResults, TransactionBalancesSet, @@ -3722,6 +3744,7 @@ impl Bank { max_age, enable_cpi_recording, enable_log_recording, + timings, ); let results = self.commit_transactions( @@ -3731,6 +3754,7 @@ impl Bank { &executed, tx_count, signature_count, + timings, ); let post_balances = if collect_balances { self.collect_balances(batch) @@ -3748,9 +3772,16 @@ impl Bank { #[must_use] pub fn process_transactions(&self, txs: &[Transaction]) -> Vec> { let batch = self.prepare_batch(txs, None); - self.load_execute_and_commit_transactions(&batch, MAX_PROCESSING_AGE, false, false, false) - .0 - .fee_collection_results + self.load_execute_and_commit_transactions( + &batch, + MAX_PROCESSING_AGE, + false, + false, + false, + &mut ExecuteTimings::default(), + ) + .0 + .fee_collection_results } /// Create, sign, and process a Transaction from `keypair` to `to` of @@ -7551,6 +7582,7 @@ pub(crate) mod tests { false, false, false, + &mut ExecuteTimings::default(), ) .0 .fee_collection_results; @@ -9526,6 +9558,7 @@ pub(crate) mod tests { true, false, false, + &mut ExecuteTimings::default(), ); assert!(inner_instructions[0].iter().all(|ix| ix.is_empty()));