add execute detail timings

core/src/banking_stage.rs

@@ -701,6 +701,8 @@ impl BankingStage {
             txs.len(),
         );
 
+        debug!("process_and_record_transactions_locked: {:?}", execute_timings);
+
         (Ok(num_to_commit), retryable_txs)
     }
 

core/src/replay_stage.rs

@@ -1417,6 +1417,7 @@ impl ReplayStage {
             }
         }
         inc_new_counter_info!("replay_stage-replay_transactions", tx_count);
+        debug!("replay_active_banks: {:?}", bank_progress.replay_progress.execute_timings);
         did_complete_bank
     }
 

ledger/src/blockstore_processor.rs

@@ -214,15 +214,19 @@ pub fn process_entries(
     transaction_status_sender: Option<TransactionStatusSender>,
     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,

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"

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,12 @@ impl Executor for BpfExecutor {
                     return Err(error);
                 }
             }
+            execute_time.stop();
         }
+        let mut deserialize_time = Measure::start("deserialize");
         deserialize_parameters(loader_id, parameter_accounts, &parameter_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(())
     }

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,18 +93,20 @@ 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 {
     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;
+        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,14 +2435,16 @@ impl Bank {
             MAX_PROCESSING_AGE - MAX_TRANSACTION_FORWARDING_DELAY,
             false,
             true,
-            &mut ExecuteTimings::default(),
+            &mut timings,
         );
 
         let transaction_result = executed[0].0.clone().map(|_| ());
         let log_messages = log_messages
             .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 {