Add load/execute/store timings (#14561)

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));

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),
         );
     }
 }

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,
+        Bank, ExecuteTimings, InnerInstructionsList, TransactionBalancesSet,
-        TransactionLogMessages, TransactionResults,
+        TransactionExecutionResult, TransactionLogMessages, TransactionResults,
     },
     bank_forks::BankForks,
     bank_utils,
@@ -106,6 +106,7 @@ fn execute_batch(
     bank: &Arc<Bank>,
     transaction_status_sender: Option<TransactionStatusSender>,
     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<TransactionStatusSender>,
     replay_vote_sender: Option<&ReplayVoteSender>,
+    timings: &mut ExecuteTimings,
 ) -> Result<()> {
     inc_new_counter_debug!("bank-par_execute_entries-count", batches.len());
-    let results: Vec<Result<()>> = PAR_THREAD_POOL.with(|thread_pool| {
+    let (results, new_timings): (Vec<Result<()>>, Vec<ExecuteTimings>) =
-        thread_pool.borrow().install(|| {
+        PAR_THREAD_POOL.with(|thread_pool| {
-            batches
+            thread_pool.borrow().install(|| {
-                .into_par_iter()
+                batches
-                .map_with(transaction_status_sender, |sender, batch| {
+                    .into_par_iter()
-                    let result = execute_batch(batch, bank, sender.clone(), replay_vote_sender);
+                    .map_with(transaction_status_sender, |sender, batch| {
-                    if let Some(entry_callback) = entry_callback {
+                        let mut timings = ExecuteTimings::default();
-                        entry_callback(bank);
+                        let result = execute_batch(
-                    }
+                            batch,
-                    result
+                            bank,
-                })
+                            sender.clone(),
-                .collect()
+                            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<TransactionStatusSender>,
     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

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

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

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<Result<()>>;
 #[frozen_abi(digest = "MUmkgPsCRrWL2HEsMEvpkWMis35kbBnaEZtrph5P6bk")]
 pub type BankSlotDelta = SlotDelta<Result<()>>;
@@ -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<TransactionLoadResult>,
         Vec<TransactionExecutionResult>,
@@ -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<Result<()>> {
         let batch = self.prepare_batch(txs, None);
-        self.load_execute_and_commit_transactions(&batch, MAX_PROCESSING_AGE, false, false, false)
+        self.load_execute_and_commit_transactions(
-            .0
+            &batch,
-            .fee_collection_results
+            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()));