Add execute metrics

Cargo.lock

@@ -5488,6 +5488,7 @@ dependencies = [
  "rustc_version 0.4.0",
  "serde",
  "solana-logger 1.10.0",
+ "solana-measure",
  "solana-sdk",
  "thiserror",
 ]

core/src/cost_update_service.rs

@@ -69,8 +69,12 @@ impl CostUpdateServiceTiming {
 }
 
 pub enum CostUpdate {
-    FrozenBank { bank: Arc<Bank> },
-    ExecuteTiming { execute_timings: ExecuteTimings },
+    FrozenBank {
+        bank: Arc<Bank>,
+    },
+    ExecuteTiming {
+        execute_timings: Box<ExecuteTimings>,
+    },
 }
 
 pub type CostUpdateReceiver = Receiver<CostUpdate>;

core/src/progress_map.rs

@@ -82,45 +82,100 @@ impl ReplaySlotStats {
                 i64
             ),
             (
-                "serialize_us",
+                "execute_details_serialize_us",
                 self.execute_timings.details.serialize_us,
                 i64
             ),
             (
-                "create_vm_us",
+                "execute_details_create_vm_us",
                 self.execute_timings.details.create_vm_us,
                 i64
             ),
             (
-                "execute_inner_us",
+                "execute_details_execute_inner_us",
                 self.execute_timings.details.execute_us,
                 i64
             ),
             (
-                "deserialize_us",
+                "execute_details_deserialize_us",
                 self.execute_timings.details.deserialize_us,
                 i64
             ),
             (
-                "changed_account_count",
+                "execute_details_get_or_create_executor_us",
+                self.execute_timings.details.get_or_create_executor_us,
+                i64
+            ),
+            (
+                "execute_details_changed_account_count",
                 self.execute_timings.details.changed_account_count,
                 i64
             ),
             (
-                "total_account_count",
+                "execute_details_total_account_count",
                 self.execute_timings.details.total_account_count,
                 i64
             ),
             (
-                "total_data_size",
+                "execute_details_total_data_size",
                 self.execute_timings.details.total_data_size,
                 i64
             ),
             (
-                "data_size_changed",
+                "execute_details_data_size_changed",
                 self.execute_timings.details.data_size_changed,
                 i64
             ),
+            (
+                "execute_accessories_feature_set_clone_us",
+                self.execute_timings
+                    .execute_accessories
+                    .feature_set_clone_us,
+                i64
+            ),
+            (
+                "execute_accessories_compute_budget_process_transaction_us",
+                self.execute_timings
+                    .execute_accessories
+                    .compute_budget_process_transaction_us,
+                i64
+            ),
+            (
+                "execute_accessories_get_executors_us",
+                self.execute_timings.execute_accessories.get_executors_us,
+                i64
+            ),
+            (
+                "execute_accessories_process_message_us",
+                self.execute_timings.execute_accessories.process_message_us,
+                i64
+            ),
+            (
+                "execute_accessories_update_executors_us",
+                self.execute_timings.execute_accessories.update_executors_us,
+                i64
+            ),
+            (
+                "execute_accessories_process_instruction_verify_caller_us",
+                self.execute_timings
+                    .execute_accessories
+                    .process_instruction_verify_caller_us,
+                i64
+            ),
+            (
+                "execute_accessories_process_instruction_process_executable_chain_us",
+                self.execute_timings
+                    .execute_accessories
+                    .process_instruction_process_executable_chain_us,
+                i64
+            ),
+            (
+                "execute_accessories_process_instruction_verify_callee_us",
+                self.execute_timings
+                    .execute_accessories
+                    .process_instruction_verify_callee_us,
+                i64
+            ),
         );
 
         let mut per_pubkey_timings: Vec<_> = self

core/src/replay_stage.rs

@@ -2248,7 +2248,9 @@ impl ReplayStage {
         // send accumulated excute-timings to cost_update_service
         if !execute_timings.details.per_program_timings.is_empty() {
             cost_update_sender
-                .send(CostUpdate::ExecuteTiming { execute_timings })
+                .send(CostUpdate::ExecuteTiming {
+                    execute_timings: Box::new(execute_timings),
+                })
                 .unwrap_or_else(|err| warn!("cost_update_sender failed: {:?}", err));
         }
 

program-runtime/Cargo.toml

@@ -19,6 +19,7 @@ log = "0.4.14"
 num-derive = { version = "0.3" }
 num-traits = { version = "0.2" }
 serde = { version = "1.0.129", features = ["derive", "rc"] }
+solana-measure = { path = "../measure", version = "=1.10.0" }
 solana-sdk = { path = "../sdk", version = "=1.10.0" }
 thiserror = "1.0"
 

program-runtime/src/invoke_context.rs

@@ -1,9 +1,14 @@
 use {
     crate::{
-        accounts_data_meter::AccountsDataMeter, ic_logger_msg, ic_msg,
-        instruction_recorder::InstructionRecorder, log_collector::LogCollector,
-        native_loader::NativeLoader, pre_account::PreAccount, timings::ExecuteDetailsTimings,
+        accounts_data_meter::AccountsDataMeter,
+        ic_logger_msg, ic_msg,
+        instruction_recorder::InstructionRecorder,
+        log_collector::LogCollector,
+        native_loader::NativeLoader,
+        pre_account::PreAccount,
+        timings::{ExecuteDetailsTimings, ExecuteTimings},
     },
+    solana_measure::measure::Measure,
     solana_sdk::{
         account::{AccountSharedData, ReadableAccount},
         bpf_loader_upgradeable::{self, UpgradeableLoaderState},
@@ -603,6 +608,7 @@ impl<'a> InvokeContext<'a> {
             &instruction_accounts,
             &program_indices,
             &mut compute_units_consumed,
+            &mut ExecuteTimings::default(),
         )?;
 
         // Verify the called program has not misbehaved
@@ -773,6 +779,7 @@ impl<'a> InvokeContext<'a> {
         instruction_accounts: &[InstructionAccount],
         program_indices: &[usize],
         compute_units_consumed: &mut u64,
+        timings: &mut ExecuteTimings,
     ) -> Result<(), InstructionError> {
         *compute_units_consumed = 0;
         let program_id = program_indices
@@ -790,7 +797,16 @@ impl<'a> InvokeContext<'a> {
             }
         } else {
             // Verify the calling program hasn't misbehaved
-            self.verify_and_update(instruction_accounts, true)?;
+            let mut verify_caller_time = Measure::start("verify_caller_time");
+            let verify_caller_result = self.verify_and_update(instruction_accounts, true);
+            verify_caller_time.stop();
+            timings
+                .execute_accessories
+                .process_instruction_verify_caller_us = timings
+                .execute_accessories
+                .process_instruction_verify_caller_us
+                .saturating_add(verify_caller_time.as_us());
+            verify_caller_result?;
 
             // Record instruction
             if let Some(instruction_recorder) = &self.instruction_recorder {
@@ -805,6 +821,7 @@ impl<'a> InvokeContext<'a> {
                         .map(|instruction_account| instruction_account.index_in_transaction as u8)
                         .collect(),
                 };
+
                 instruction_recorder
                     .borrow_mut()
                     .record_compiled_instruction(compiled_instruction);
@@ -814,19 +831,40 @@ impl<'a> InvokeContext<'a> {
         let result = self
             .push(instruction_accounts, program_indices, instruction_data)
             .and_then(|_| {
+                let mut process_executable_chain_time =
+                    Measure::start("process_executable_chain_time");
                 self.return_data = (program_id, Vec::new());
                 let pre_remaining_units = self.compute_meter.borrow().get_remaining();
                 let execution_result = self.process_executable_chain(instruction_data);
                 let post_remaining_units = self.compute_meter.borrow().get_remaining();
                 *compute_units_consumed = pre_remaining_units.saturating_sub(post_remaining_units);
-                execution_result?;
+                process_executable_chain_time.stop();
 
                 // Verify the called program has not misbehaved
-                if is_lowest_invocation_level {
-                    self.verify(instruction_accounts, program_indices)
-                } else {
-                    self.verify_and_update(instruction_accounts, false)
-                }
+                let mut verify_callee_time = Measure::start("verify_callee_time");
+                let result = execution_result.and_then(|_| {
+                    if is_lowest_invocation_level {
+                        self.verify(instruction_accounts, program_indices)
+                    } else {
+                        self.verify_and_update(instruction_accounts, false)
+                    }
+                });
+                verify_callee_time.stop();
+
+                timings
+                    .execute_accessories
+                    .process_instruction_process_executable_chain_us = timings
+                    .execute_accessories
+                    .process_instruction_process_executable_chain_us
+                    .saturating_add(process_executable_chain_time.as_us());
+                timings
+                    .execute_accessories
+                    .process_instruction_verify_callee_us = timings
+                    .execute_accessories
+                    .process_instruction_verify_callee_us
+                    .saturating_add(verify_callee_time.as_us());
+
+                result
             });
 
         // Pop the invoke_stack to restore previous state
@@ -1526,6 +1564,7 @@ mod tests {
                 &inner_instruction_accounts,
                 &program_indices,
                 &mut compute_units_consumed,
+                &mut ExecuteTimings::default(),
             );
 
             // Because the instruction had compute cost > 0, then regardless of the execution result,
@@ -1639,6 +1678,7 @@ mod tests {
                 &instruction_accounts,
                 &[2],
                 &mut 0,
+                &mut ExecuteTimings::default(),
             );
 
             assert!(result.is_ok());
@@ -1656,6 +1696,7 @@ mod tests {
                 &instruction_accounts,
                 &[2],
                 &mut 0,
+                &mut ExecuteTimings::default(),
             );
 
             assert!(result.is_ok());
@@ -1673,6 +1714,7 @@ mod tests {
                 &instruction_accounts,
                 &[2],
                 &mut 0,
+                &mut ExecuteTimings::default(),
             );
 
             assert!(result.is_err());

program-runtime/src/timings.rs

@@ -46,6 +46,7 @@ pub struct ExecuteTimings {
     pub num_execute_batches: u64,
     pub collect_logs_us: u64,
     pub details: ExecuteDetailsTimings,
+    pub execute_accessories: ExecuteAccessoryTimings,
 }
 
 impl ExecuteTimings {
@@ -65,6 +66,51 @@ impl ExecuteTimings {
             .saturating_add(other.num_execute_batches);
         self.collect_logs_us = self.collect_logs_us.saturating_add(other.collect_logs_us);
         self.details.accumulate(&other.details);
+        self.execute_accessories
+            .accumulate(&other.execute_accessories);
+    }
+}
+
+#[derive(Default, Debug)]
+pub struct ExecuteAccessoryTimings {
+    pub feature_set_clone_us: u64,
+    pub compute_budget_process_transaction_us: u64,
+    pub get_executors_us: u64,
+    pub process_message_us: u64,
+    pub update_executors_us: u64,
+    pub process_instructions_us: u64,
+    pub process_instruction_verify_caller_us: u64,
+    pub process_instruction_process_executable_chain_us: u64,
+    pub process_instruction_verify_callee_us: u64,
+}
+
+impl ExecuteAccessoryTimings {
+    pub fn accumulate(&mut self, other: &ExecuteAccessoryTimings) {
+        self.compute_budget_process_transaction_us = self
+            .feature_set_clone_us
+            .saturating_add(other.feature_set_clone_us);
+        self.compute_budget_process_transaction_us = self
+            .compute_budget_process_transaction_us
+            .saturating_add(other.compute_budget_process_transaction_us);
+        self.get_executors_us = self.get_executors_us.saturating_add(other.get_executors_us);
+        self.process_message_us = self
+            .process_message_us
+            .saturating_add(other.process_message_us);
+        self.update_executors_us = self
+            .update_executors_us
+            .saturating_add(other.update_executors_us);
+        self.process_instructions_us = self
+            .process_instructions_us
+            .saturating_add(other.process_instructions_us);
+        self.process_instruction_verify_caller_us = self
+            .process_instruction_verify_caller_us
+            .saturating_add(other.process_instruction_verify_caller_us);
+        self.process_instruction_process_executable_chain_us = self
+            .process_instruction_process_executable_chain_us
+            .saturating_add(other.process_instruction_process_executable_chain_us);
+        self.process_instruction_verify_callee_us = self
+            .process_instruction_verify_callee_us
+            .saturating_add(other.process_instruction_verify_callee_us);
     }
 }
 
@@ -74,6 +120,7 @@ pub struct ExecuteDetailsTimings {
     pub create_vm_us: u64,
     pub execute_us: u64,
     pub deserialize_us: u64,
+    pub get_or_create_executor_us: u64,
     pub changed_account_count: u64,
     pub total_account_count: u64,
     pub total_data_size: usize,
@@ -86,6 +133,9 @@ impl ExecuteDetailsTimings {
         self.create_vm_us = self.create_vm_us.saturating_add(other.create_vm_us);
         self.execute_us = self.execute_us.saturating_add(other.execute_us);
         self.deserialize_us = self.deserialize_us.saturating_add(other.deserialize_us);
+        self.get_or_create_executor_us = self
+            .get_or_create_executor_us
+            .saturating_add(other.get_or_create_executor_us);
         self.changed_account_count = self
             .changed_account_count
             .saturating_add(other.changed_account_count);

program-test/src/lib.rs

@@ -303,6 +303,7 @@ impl solana_sdk::program_stubs::SyscallStubs for SyscallStubs {
                 &instruction_accounts,
                 &program_indices,
                 &mut compute_units_consumed,
+                &mut ExecuteTimings::default(),
             )
             .map_err(|err| ProgramError::try_from(err).unwrap_or_else(|err| panic!("{}", err)))?;
 

programs/bpf_loader/src/lib.rs

@@ -291,6 +291,7 @@ fn process_instruction_common(
             0
         };
 
+        let mut get_or_create_executor_time = Measure::start("get_or_create_executor_time");
         let executor = match invoke_context.get_executor(program_id) {
             Some(executor) => executor,
             None => {
@@ -306,6 +307,9 @@ fn process_instruction_common(
                 executor
             }
         };
+        get_or_create_executor_time.stop();
+        invoke_context.timings.get_or_create_executor_us += get_or_create_executor_time.as_us();
+
         executor.execute(
             next_first_instruction_account,
             instruction_data,

programs/bpf_loader/src/syscalls.rs

@@ -6,6 +6,7 @@ use {
         ic_logger_msg, ic_msg,
         invoke_context::{ComputeMeter, InvokeContext},
         stable_log,
+        timings::ExecuteTimings,
     },
     solana_rbpf::{
         aligned_memory::AlignedMemory,
@@ -2634,6 +2635,7 @@ fn call<'a, 'b: 'a>(
             &instruction_accounts,
             &program_indices,
             &mut compute_units_consumed,
+            &mut ExecuteTimings::default(),
         )
         .map_err(SyscallError::InstructionError)?;
 

runtime/src/bank.rs

@@ -78,7 +78,7 @@ use {
             BuiltinProgram, Executor, Executors, ProcessInstructionWithContext, TransactionExecutor,
         },
         log_collector::LogCollector,
-        timings::{ExecuteDetailsTimings, ExecuteTimings},
+        timings::ExecuteTimings,
     },
     solana_sdk::{
         account::{
@@ -3541,7 +3541,7 @@ impl Bank {
         durable_nonce_fee: Option<DurableNonceFee>,
         enable_cpi_recording: bool,
         enable_log_recording: bool,
-        execute_details_timings: &mut ExecuteDetailsTimings,
+        timings: &mut ExecuteTimings,
         error_counters: &mut ErrorCounters,
     ) -> TransactionExecutionResult {
         let legacy_message = match tx.message().legacy_message() {
@@ -3554,11 +3554,14 @@ impl Bank {
             }
         };
 
+        let mut get_executors_time = Measure::start("get_executors_time");
         let executors = self.get_executors(
             tx.message(),
             &loaded_transaction.accounts,
             &loaded_transaction.program_indices,
         );
+        get_executors_time.stop();
+        timings.execute_accessories.get_executors_us += get_executors_time.as_us();
 
         let mut transaction_accounts = Vec::new();
         std::mem::swap(&mut loaded_transaction.accounts, &mut transaction_accounts);
@@ -3582,6 +3585,8 @@ impl Bank {
         };
 
         let (blockhash, lamports_per_signature) = self.last_blockhash_and_lamports_per_signature();
+
+        let mut process_message_time = Measure::start("process_message_time");
         let process_result = MessageProcessor::process_message(
             &self.builtin_programs.vec,
             legacy_message,
@@ -3593,14 +3598,19 @@ impl Bank {
             instruction_recorder.clone(),
             self.feature_set.clone(),
             compute_budget,
-            execute_details_timings,
+            timings,
             &*self.sysvar_cache.read().unwrap(),
             blockhash,
             lamports_per_signature,
             self.load_accounts_data_len(),
         );
+        process_message_time.stop();
+        timings.execute_accessories.process_message_us += process_message_time.as_us();
 
+        let mut update_executors_time = Measure::start("update_executors_time");
         self.update_executors(process_result.is_ok(), executors);
+        update_executors_time.stop();
+        timings.execute_accessories.update_executors_us += update_executors_time.as_us();
 
         let status = process_result
             .map(|info| {
@@ -3693,19 +3703,32 @@ impl Bank {
         let mut execution_time = Measure::start("execution_time");
         let mut signature_count: u64 = 0;
 
-        let execute_details_timings = &mut timings.details;
         let execution_results: Vec<TransactionExecutionResult> = loaded_txs
             .iter_mut()
             .zip(sanitized_txs.iter())
             .map(|(accs, tx)| match accs {
                 (Err(e), _nonce) => TransactionExecutionResult::NotExecuted(e.clone()),
                 (Ok(loaded_transaction), nonce) => {
+                    let mut feature_set_clone_time = Measure::start("feature_set_clone");
                     let feature_set = self.feature_set.clone();
+                    feature_set_clone_time.stop();
+                    timings.execute_accessories.feature_set_clone_us +=
+                        feature_set_clone_time.as_us();
+
                     signature_count += u64::from(tx.message().header().num_required_signatures);
 
                     let mut compute_budget = self.compute_budget.unwrap_or_else(ComputeBudget::new);
                     if feature_set.is_active(&tx_wide_compute_cap::id()) {
-                        if let Err(err) = compute_budget.process_transaction(tx, feature_set) {
+                        let mut compute_budget_process_transaction_time =
+                            Measure::start("compute_budget_process_transaction_time");
+                        let process_transaction_result =
+                            compute_budget.process_transaction(tx, feature_set);
+                        compute_budget_process_transaction_time.stop();
+                        timings
+                            .execute_accessories
+                            .compute_budget_process_transaction_us +=
+                            compute_budget_process_transaction_time.as_us();
+                        if let Err(err) = process_transaction_result {
                             return TransactionExecutionResult::NotExecuted(err);
                         }
                     }
@@ -3719,7 +3742,7 @@ impl Bank {
                         durable_nonce_fee,
                         enable_cpi_recording,
                         enable_log_recording,
-                        execute_details_timings,
+                        timings,
                         &mut error_counters,
                     )
                 }

runtime/src/message_processor.rs

@@ -5,7 +5,7 @@ use {
         instruction_recorder::InstructionRecorder,
         invoke_context::{BuiltinProgram, Executors, InvokeContext},
         log_collector::LogCollector,
-        timings::ExecuteDetailsTimings,
+        timings::ExecuteTimings,
     },
     solana_sdk::{
         account::WritableAccount,
@@ -60,7 +60,7 @@ impl MessageProcessor {
         instruction_recorder: Option<Rc<RefCell<InstructionRecorder>>>,
         feature_set: Arc<FeatureSet>,
         compute_budget: ComputeBudget,
-        timings: &mut ExecuteDetailsTimings,
+        timings: &mut ExecuteTimings,
         sysvars: &[(Pubkey, Vec<u8>)],
         blockhash: Hash,
         lamports_per_signature: u64,
@@ -134,15 +134,17 @@ impl MessageProcessor {
                 &instruction_accounts,
                 program_indices,
                 &mut compute_units_consumed,
+                timings,
             );
             time.stop();
-            timings.accumulate_program(
+            timings.details.accumulate_program(
                 instruction.program_id(&message.account_keys),
                 time.as_us(),
                 compute_units_consumed,
                 result.is_err(),
             );
-            timings.accumulate(&invoke_context.timings);
+            timings.details.accumulate(&invoke_context.timings);
+            timings.execute_accessories.process_instructions_us += time.as_us();
             result
                 .map_err(|err| TransactionError::InstructionError(instruction_index as u8, err))?;
         }
@@ -264,7 +266,7 @@ mod tests {
             None,
             Arc::new(FeatureSet::all_enabled()),
             ComputeBudget::new(),
-            &mut ExecuteDetailsTimings::default(),
+            &mut ExecuteTimings::default(),
             &[],
             Hash::default(),
             0,
@@ -305,7 +307,7 @@ mod tests {
             None,
             Arc::new(FeatureSet::all_enabled()),
             ComputeBudget::new(),
-            &mut ExecuteDetailsTimings::default(),
+            &mut ExecuteTimings::default(),
             &[],
             Hash::default(),
             0,
@@ -338,7 +340,7 @@ mod tests {
             None,
             Arc::new(FeatureSet::all_enabled()),
             ComputeBudget::new(),
-            &mut ExecuteDetailsTimings::default(),
+            &mut ExecuteTimings::default(),
             &[],
             Hash::default(),
             0,
@@ -464,7 +466,7 @@ mod tests {
             None,
             Arc::new(FeatureSet::all_enabled()),
             ComputeBudget::new(),
-            &mut ExecuteDetailsTimings::default(),
+            &mut ExecuteTimings::default(),
             &[],
             Hash::default(),
             0,
@@ -498,7 +500,7 @@ mod tests {
             None,
             Arc::new(FeatureSet::all_enabled()),
             ComputeBudget::new(),
-            &mut ExecuteDetailsTimings::default(),
+            &mut ExecuteTimings::default(),
             &[],
             Hash::default(),
             0,
@@ -529,7 +531,7 @@ mod tests {
             None,
             Arc::new(FeatureSet::all_enabled()),
             ComputeBudget::new(),
-            &mut ExecuteDetailsTimings::default(),
+            &mut ExecuteTimings::default(),
             &[],
             Hash::default(),
             0,
@@ -602,7 +604,7 @@ mod tests {
             None,
             Arc::new(FeatureSet::all_enabled()),
             ComputeBudget::new(),
-            &mut ExecuteDetailsTimings::default(),
+            &mut ExecuteTimings::default(),
             &[],
             Hash::default(),
             0,