From bdfffd0151026abbfa60b164d2d5356132ab766f Mon Sep 17 00:00:00 2001 From: "mergify[bot]" <37929162+mergify[bot]@users.noreply.github.com> Date: Thu, 14 Jan 2021 23:48:36 +0000 Subject: [PATCH] Add load/execute/store timings (#14561) (#14591) (cherry picked from commit 907f518f6d7f1a974c72bc8149d535771dd34fdc) 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 364d85bfc9..15386c2a2a 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, @@ -544,6 +547,8 @@ impl BankingStage { vec![] }; + let mut execute_timings = ExecuteTimings::default(); + let ( mut loaded_accounts, results, @@ -557,6 +562,7 @@ impl BankingStage { MAX_PROCESSING_AGE, transaction_status_sender.is_some(), transaction_status_sender.is_some(), + &mut execute_timings, ); load_execute_time.stop(); @@ -583,6 +589,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 9bf6c4aefd..782446466c 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, @@ -106,6 +106,7 @@ fn execute_batch( bank: &Arc, transaction_status_sender: Option, replay_vote_sender: Option<&ReplayVoteSender>, + timings: &mut ExecuteTimings, ) -> Result<()> { let record_token_balances = transaction_status_sender.is_some(); @@ -124,6 +125,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); @@ -167,22 +169,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) } @@ -206,6 +221,7 @@ pub fn process_entries( None, transaction_status_sender, replay_vote_sender, + &mut ExecuteTimings::default(), ) } @@ -216,6 +232,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![]; @@ -233,6 +250,7 @@ fn process_entries_with_callback( entry_callback, transaction_status_sender.clone(), replay_vote_sender, + timings, )?; batches.clear(); for hash in &tick_hashes { @@ -289,6 +307,7 @@ fn process_entries_with_callback( entry_callback, transaction_status_sender.clone(), replay_vote_sender, + timings, )?; batches.clear(); } @@ -300,6 +319,7 @@ fn process_entries_with_callback( entry_callback, transaction_status_sender, replay_vote_sender, + timings, )?; for hash in tick_hashes { bank.register_tick(&hash); @@ -594,6 +614,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 { @@ -605,6 +626,7 @@ impl Default for ConfirmationTiming { transaction_verify_elapsed: 0, fetch_elapsed: 0, fetch_fail_elapsed: 0, + execute_timings: ExecuteTimings::default(), } } } @@ -700,6 +722,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, @@ -707,11 +730,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(); @@ -2891,7 +2917,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) } @@ -2984,6 +3019,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 3ab5dca7a0..783833a997 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, }, @@ -627,7 +627,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 a526ea8fdf..2905901453 100644 --- a/programs/bpf/tests/programs.rs +++ b/programs/bpf/tests/programs.rs @@ -11,7 +11,7 @@ use solana_bpf_loader_program::{ }; use solana_rbpf::vm::{Config, Executable, Tracer}; use solana_runtime::{ - bank::Bank, + bank::{Bank, ExecuteTimings}, bank_client::BankClient, genesis_utils::{create_genesis_config, GenesisConfigInfo}, loader_utils::{ @@ -229,6 +229,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 7ce87e404d..416666a208 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>; @@ -2437,6 +2452,7 @@ impl Bank { MAX_PROCESSING_AGE - MAX_TRANSACTION_FORWARDING_DELAY, false, true, + &mut ExecuteTimings::default(), ); let transaction_result = executed[0].0.clone().map(|_| ()); @@ -2847,6 +2863,7 @@ impl Bank { max_age: usize, enable_cpi_recording: bool, enable_log_recording: bool, + timings: &mut ExecuteTimings, ) -> ( Vec, Vec, @@ -2988,6 +3005,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; @@ -3143,6 +3162,7 @@ impl Bank { executed: &[TransactionExecutionResult], tx_count: u64, signature_count: u64, + timings: &mut ExecuteTimings, ) -> TransactionResults { assert!( !self.freeze_started(), @@ -3182,6 +3202,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); @@ -3764,6 +3785,7 @@ impl Bank { collect_balances: bool, enable_cpi_recording: bool, enable_log_recording: bool, + timings: &mut ExecuteTimings, ) -> ( TransactionResults, TransactionBalancesSet, @@ -3789,6 +3811,7 @@ impl Bank { max_age, enable_cpi_recording, enable_log_recording, + timings, ); let results = self.commit_transactions( @@ -3798,6 +3821,7 @@ impl Bank { &executed, tx_count, signature_count, + timings, ); let post_balances = if collect_balances { self.collect_balances(batch) @@ -3815,9 +3839,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 @@ -7664,6 +7695,7 @@ pub(crate) mod tests { false, false, false, + &mut ExecuteTimings::default(), ) .0 .fee_collection_results; @@ -9644,6 +9676,7 @@ pub(crate) mod tests { true, false, false, + &mut ExecuteTimings::default(), ); assert!(inner_instructions[0].iter().all(|ix| ix.is_empty()));