Add execute metrics (backport #22296) (#22335)

* move `ExecuteTimings` from `runtime::bank` to `program_runtime::timings`

(cherry picked from commit 7d32909e17)

# Conflicts:
#	core/Cargo.toml
#	ledger/Cargo.toml
#	programs/bpf/Cargo.lock

* Add execute metrics

(cherry picked from commit b25e4a200b)

* Add metrics for executor creation

(cherry picked from commit 848b6dfbdd)

* Add helper macro for `AddAssign`ing with saturating arithmetic

(cherry picked from commit deb9344e49)

* Use saturating_add_assign macro

(cherry picked from commit 72fc6096a0)

* Consolidate process instruction execution timings to own struct

(cherry picked from commit 390ef0fbcd)

Co-authored-by: Trent Nelson <trent@solana.com>
Co-authored-by: Carl Lin <carl@solana.com>

Cargo.lock

@@ -5098,6 +5098,7 @@ dependencies = [
  "solana-measure",
  "solana-metrics",
  "solana-perf",
+ "solana-program-runtime",
  "solana-rayon-threadlimit",
  "solana-runtime",
  "solana-sdk",
@@ -5453,6 +5454,7 @@ dependencies = [
  "rustc_version 0.4.0",
  "serde",
  "solana-logger 1.9.4",
+ "solana-measure",
  "solana-sdk",
  "thiserror",
 ]

core/Cargo.toml

@@ -45,6 +45,7 @@ solana-metrics = { path = "../metrics", version = "=1.9.4" }
 solana-net-utils = { path = "../net-utils", version = "=1.9.4" }
 solana-perf = { path = "../perf", version = "=1.9.4" }
 solana-poh = { path = "../poh", version = "=1.9.4" }
+solana-program-runtime = { path = "../program-runtime", version = "=1.9.4" }
 solana-rpc = { path = "../rpc", version = "=1.9.4" }
 solana-replica-lib = { path = "../replica-lib", version = "=1.9.4" }
 solana-runtime = { path = "../runtime", version = "=1.9.4" }

core/src/banking_stage.rs

@@ -19,12 +19,10 @@ use {
         perf_libs,
     },
     solana_poh::poh_recorder::{BankStart, PohRecorder, PohRecorderError, TransactionRecorder},
+    solana_program_runtime::timings::ExecuteTimings,
     solana_runtime::{
         accounts_db::ErrorCounters,
-        bank::{
+        bank::{Bank, TransactionBalancesSet, TransactionCheckResult, TransactionExecutionResult},
-            Bank, ExecuteTimings, TransactionBalancesSet, TransactionCheckResult,
-            TransactionExecutionResult,
-        },
         bank_utils,
         cost_model::CostModel,
         transaction_batch::TransactionBatch,

core/src/cost_update_service.rs

@@ -6,10 +6,8 @@
 use {
     solana_ledger::blockstore::Blockstore,
     solana_measure::measure::Measure,
-    solana_runtime::{
+    solana_program_runtime::timings::ExecuteTimings,
-        bank::{Bank, ExecuteTimings},
+    solana_runtime::{bank::Bank, cost_model::CostModel},
-        cost_model::CostModel,
-    },
     solana_sdk::timing::timestamp,
     std::{
         sync::{
@@ -71,8 +69,12 @@ impl CostUpdateServiceTiming {
 }
 
 pub enum CostUpdate {
-    FrozenBank { bank: Arc<Bank> },
+    FrozenBank {
-    ExecuteTiming { execute_timings: ExecuteTimings },
+        bank: Arc<Bank>,
+    },
+    ExecuteTiming {
+        execute_timings: Box<ExecuteTimings>,
+    },
 }
 
 pub type CostUpdateReceiver = Receiver<CostUpdate>;

core/src/progress_map.rs

@@ -81,45 +81,133 @@ 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_details_create_executor_register_syscalls_us",
+                self.execute_timings
+                    .details
+                    .create_executor_register_syscalls_us,
+                i64
+            ),
+            (
+                "execute_details_create_executor_load_elf_us",
+                self.execute_timings.details.create_executor_load_elf_us,
+                i64
+            ),
+            (
+                "execute_details_create_executor_verify_code_us",
+                self.execute_timings.details.create_executor_verify_code_us,
+                i64
+            ),
+            (
+                "execute_details_create_executor_jit_compile_us",
+                self.execute_timings.details.create_executor_jit_compile_us,
+                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_instructions_total_us",
+                self.execute_timings
+                    .execute_accessories
+                    .process_instructions
+                    .total_us,
+                i64
+            ),
+            (
+                "execute_accessories_process_instructions_verify_caller_us",
+                self.execute_timings
+                    .execute_accessories
+                    .process_instructions
+                    .verify_caller_us,
+                i64
+            ),
+            (
+                "execute_accessories_process_instructions_process_executable_chain_us",
+                self.execute_timings
+                    .execute_accessories
+                    .process_instructions
+                    .process_executable_chain_us,
+                i64
+            ),
+            (
+                "execute_accessories_process_instructions_verify_callee_us",
+                self.execute_timings
+                    .execute_accessories
+                    .process_instructions
+                    .verify_callee_us,
+                i64
+            ),
         );
 
         let mut per_pubkey_timings: Vec<_> = self

core/src/replay_stage.rs

@@ -39,13 +39,14 @@ use {
     solana_measure::measure::Measure,
     solana_metrics::inc_new_counter_info,
     solana_poh::poh_recorder::{PohRecorder, GRACE_TICKS_FACTOR, MAX_GRACE_SLOTS},
+    solana_program_runtime::timings::ExecuteTimings,
     solana_rpc::{
         optimistically_confirmed_bank_tracker::{BankNotification, BankNotificationSender},
         rpc_subscriptions::RpcSubscriptions,
     },
     solana_runtime::{
         accounts_background_service::AbsRequestSender,
-        bank::{Bank, ExecuteTimings, NewBankOptions},
+        bank::{Bank, NewBankOptions},
         bank_forks::BankForks,
         commitment::BlockCommitmentCache,
         vote_sender_types::ReplayVoteSender,
@@ -2170,7 +2171,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));
         }
 

ledger/Cargo.toml

@@ -40,6 +40,7 @@ solana-logger = { path = "../logger", version = "=1.9.4" }
 solana-measure = { path = "../measure", version = "=1.9.4" }
 solana-metrics = { path = "../metrics", version = "=1.9.4" }
 solana-perf = { path = "../perf", version = "=1.9.4" }
+solana-program-runtime = { path = "../program-runtime", version = "=1.9.4" }
 solana-rayon-threadlimit = { path = "../rayon-threadlimit", version = "=1.9.4" }
 solana-runtime = { path = "../runtime", version = "=1.9.4" }
 solana-sdk = { path = "../sdk", version = "=1.9.4" }

ledger/src/blockstore_processor.rs

@@ -14,13 +14,14 @@ use {
     },
     solana_measure::measure::Measure,
     solana_metrics::{datapoint_error, inc_new_counter_debug},
+    solana_program_runtime::timings::ExecuteTimings,
     solana_rayon_threadlimit::get_thread_count,
     solana_runtime::{
         accounts_db::{AccountShrinkThreshold, AccountsDbConfig},
         accounts_index::AccountSecondaryIndexes,
         accounts_update_notifier_interface::AccountsUpdateNotifier,
         bank::{
-            Bank, ExecuteTimings, RentDebits, TransactionBalancesSet, TransactionExecutionResult,
+            Bank, RentDebits, TransactionBalancesSet, TransactionExecutionResult,
             TransactionResults,
         },
         bank_forks::BankForks,

program-runtime/Cargo.toml

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

program-runtime/src/invoke_context.rs

@@ -1,9 +1,14 @@
 use {
     crate::{
-        accounts_data_meter::AccountsDataMeter, ic_logger_msg, ic_msg,
+        accounts_data_meter::AccountsDataMeter,
-        instruction_recorder::InstructionRecorder, log_collector::LogCollector,
+        ic_logger_msg, ic_msg,
-        native_loader::NativeLoader, pre_account::PreAccount, timings::ExecuteDetailsTimings,
+        instruction_recorder::InstructionRecorder,
+        log_collector::LogCollector,
+        native_loader::NativeLoader,
+        pre_account::PreAccount,
+        timings::{ExecuteDetailsTimings, ExecuteTimings},
     },
+    solana_measure::measure::Measure,
     solana_sdk::{
         account::{AccountSharedData, ReadableAccount},
         account_utils::StateMut,
@@ -20,6 +25,7 @@ use {
         message::Message,
         pubkey::Pubkey,
         rent::Rent,
+        saturating_add_assign,
         sysvar::Sysvar,
     },
     std::{cell::RefCell, collections::HashMap, fmt::Debug, rc::Rc, sync::Arc},
@@ -567,6 +573,7 @@ impl<'a> InvokeContext<'a> {
             &program_indices,
             &account_indices,
             &caller_write_privileges,
+            &mut ExecuteTimings::default(),
         )
         .result?;
 
@@ -709,12 +716,22 @@ impl<'a> InvokeContext<'a> {
         program_indices: &[usize],
         account_indices: &[usize],
         caller_write_privileges: &[bool],
+        timings: &mut ExecuteTimings,
     ) -> ProcessInstructionResult {
         let is_lowest_invocation_level = self.invoke_stack.is_empty();
         if !is_lowest_invocation_level {
             // Verify the calling program hasn't misbehaved
+            let mut verify_caller_time = Measure::start("verify_caller_time");
             let result =
                 self.verify_and_update(instruction, account_indices, caller_write_privileges);
+            verify_caller_time.stop();
+            saturating_add_assign!(
+                timings
+                    .execute_accessories
+                    .process_instructions
+                    .verify_caller_us,
+                verify_caller_time.as_us()
+            );
             if result.is_err() {
                 return ProcessInstructionResult {
                     compute_units_consumed: 0,
@@ -727,22 +744,45 @@ impl<'a> InvokeContext<'a> {
         let result = self
             .push(message, instruction, program_indices, account_indices)
             .and_then(|_| {
+                let mut process_executable_chain_time =
+                    Measure::start("process_executable_chain_time");
                 self.return_data = (*instruction.program_id(&message.account_keys), 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 {
+                let mut verify_callee_time = Measure::start("verify_callee_time");
-                    self.verify(message, instruction, program_indices)
+                let result = execution_result.and_then(|_| {
-                } else {
+                    if is_lowest_invocation_level {
-                    let write_privileges: Vec<bool> = (0..message.account_keys.len())
+                        self.verify(message, instruction, program_indices)
-                        .map(|i| message.is_writable(i))
+                    } else {
-                        .collect();
+                        let write_privileges: Vec<bool> = (0..message.account_keys.len())
-                    self.verify_and_update(instruction, account_indices, &write_privileges)
+                            .map(|i| message.is_writable(i))
-                }
+                            .collect();
+                        self.verify_and_update(instruction, account_indices, &write_privileges)
+                    }
+                });
+                verify_callee_time.stop();
+
+                saturating_add_assign!(
+                    timings
+                        .execute_accessories
+                        .process_instructions
+                        .process_executable_chain_us,
+                    process_executable_chain_time.as_us()
+                );
+                saturating_add_assign!(
+                    timings
+                        .execute_accessories
+                        .process_instructions
+                        .verify_callee_us,
+                    verify_callee_time.as_us()
+                );
+
+                result
             });
 
         // Pop the invoke_stack to restore previous state
@@ -1387,6 +1427,7 @@ mod tests {
                     &program_indices[1..],
                     &account_indices,
                     &caller_write_privileges,
+                    &mut ExecuteTimings::default(),
                 )
                 .result,
             Err(InstructionError::ExternalAccountDataModified)
@@ -1403,6 +1444,7 @@ mod tests {
                     &program_indices[1..],
                     &account_indices,
                     &caller_write_privileges,
+                    &mut ExecuteTimings::default(),
                 )
                 .result,
             Err(InstructionError::ReadonlyDataModified)
@@ -1461,6 +1503,7 @@ mod tests {
                     &program_indices[1..],
                     &account_indices,
                     &caller_write_privileges,
+                    &mut ExecuteTimings::default(),
                 ),
                 case.1
             );
@@ -1712,6 +1755,7 @@ mod tests {
                 &program_indices[1..],
                 &account_indices,
                 &caller_write_privileges,
+                &mut ExecuteTimings::default(),
             );
 
             // Because the instruction had compute cost > 0, then regardless of the execution result,
@@ -1786,6 +1830,7 @@ mod tests {
                     &program_indices,
                     &account_indices,
                     &caller_write_privileges,
+                    &mut ExecuteTimings::default(),
                 )
                 .result;
 
@@ -1816,6 +1861,7 @@ mod tests {
                     &program_indices,
                     &account_indices,
                     &caller_write_privileges,
+                    &mut ExecuteTimings::default(),
                 )
                 .result;
 
@@ -1846,6 +1892,7 @@ mod tests {
                     &program_indices,
                     &account_indices,
                     &caller_write_privileges,
+                    &mut ExecuteTimings::default(),
                 )
                 .result;
 

program-runtime/src/timings.rs

@@ -1,4 +1,7 @@
-use {solana_sdk::pubkey::Pubkey, std::collections::HashMap};
+use {
+    solana_sdk::{pubkey::Pubkey, saturating_add_assign},
+    std::collections::HashMap,
+};
 
 #[derive(Default, Debug, PartialEq)]
 pub struct ProgramTiming {
@@ -15,23 +18,97 @@ impl ProgramTiming {
         for tx_error_compute_consumed in self.errored_txs_compute_consumed.drain(..) {
             let compute_units_update =
                 std::cmp::max(current_estimated_program_cost, tx_error_compute_consumed);
-            self.accumulated_units = self.accumulated_units.saturating_add(compute_units_update);
+            saturating_add_assign!(self.accumulated_units, compute_units_update);
-            self.count = self.count.saturating_add(1);
+            saturating_add_assign!(self.count, 1);
         }
     }
 
     pub fn accumulate_program_timings(&mut self, other: &ProgramTiming) {
-        self.accumulated_us = self.accumulated_us.saturating_add(other.accumulated_us);
+        saturating_add_assign!(self.accumulated_us, other.accumulated_us);
-        self.accumulated_units = self
+        saturating_add_assign!(self.accumulated_units, other.accumulated_units);
-            .accumulated_units
+        saturating_add_assign!(self.count, other.count);
-            .saturating_add(other.accumulated_units);
-        self.count = self.count.saturating_add(other.count);
         // Clones the entire vector, maybe not great...
         self.errored_txs_compute_consumed
             .extend(other.errored_txs_compute_consumed.clone());
-        self.total_errored_units = self
+        saturating_add_assign!(self.total_errored_units, other.total_errored_units);
-            .total_errored_units
+    }
-            .saturating_add(other.total_errored_units);
+}
+
+#[derive(Default, Debug)]
+pub struct ExecuteTimings {
+    pub check_us: u64,
+    pub load_us: u64,
+    pub execute_us: u64,
+    pub store_us: u64,
+    pub update_stakes_cache_us: u64,
+    pub total_batches_len: usize,
+    pub num_execute_batches: u64,
+    pub collect_logs_us: u64,
+    pub details: ExecuteDetailsTimings,
+    pub execute_accessories: ExecuteAccessoryTimings,
+}
+
+impl ExecuteTimings {
+    pub fn accumulate(&mut self, other: &ExecuteTimings) {
+        saturating_add_assign!(self.check_us, other.check_us);
+        saturating_add_assign!(self.load_us, other.load_us);
+        saturating_add_assign!(self.execute_us, other.execute_us);
+        saturating_add_assign!(self.store_us, other.store_us);
+        saturating_add_assign!(self.update_stakes_cache_us, other.update_stakes_cache_us);
+        saturating_add_assign!(self.total_batches_len, other.total_batches_len);
+        saturating_add_assign!(self.num_execute_batches, other.num_execute_batches);
+        saturating_add_assign!(self.collect_logs_us, other.collect_logs_us);
+        self.details.accumulate(&other.details);
+        self.execute_accessories
+            .accumulate(&other.execute_accessories);
+    }
+}
+
+#[derive(Default, Debug)]
+pub struct ExecuteProcessInstructionTimings {
+    pub total_us: u64,
+    pub verify_caller_us: u64,
+    pub process_executable_chain_us: u64,
+    pub verify_callee_us: u64,
+}
+
+impl ExecuteProcessInstructionTimings {
+    pub fn accumulate(&mut self, other: &ExecuteProcessInstructionTimings) {
+        saturating_add_assign!(self.total_us, other.total_us);
+        saturating_add_assign!(self.verify_caller_us, other.verify_caller_us);
+        saturating_add_assign!(
+            self.process_executable_chain_us,
+            other.process_executable_chain_us
+        );
+        saturating_add_assign!(self.verify_callee_us, other.verify_callee_us);
+    }
+}
+
+#[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: ExecuteProcessInstructionTimings,
+}
+
+impl ExecuteAccessoryTimings {
+    pub fn accumulate(&mut self, other: &ExecuteAccessoryTimings) {
+        saturating_add_assign!(
+            self.compute_budget_process_transaction_us,
+            other.feature_set_clone_us
+        );
+        saturating_add_assign!(
+            self.compute_budget_process_transaction_us,
+            other.compute_budget_process_transaction_us
+        );
+        saturating_add_assign!(self.get_executors_us, other.get_executors_us);
+        saturating_add_assign!(self.process_message_us, other.process_message_us);
+        saturating_add_assign!(self.update_executors_us, other.update_executors_us);
+        self.process_instructions
+            .accumulate(&other.process_instructions);
     }
 }
 
@@ -41,28 +118,47 @@ 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,
     pub data_size_changed: usize,
+    pub create_executor_register_syscalls_us: u64,
+    pub create_executor_load_elf_us: u64,
+    pub create_executor_verify_code_us: u64,
+    pub create_executor_jit_compile_us: u64,
     pub per_program_timings: HashMap<Pubkey, ProgramTiming>,
 }
 impl ExecuteDetailsTimings {
     pub fn accumulate(&mut self, other: &ExecuteDetailsTimings) {
-        self.serialize_us = self.serialize_us.saturating_add(other.serialize_us);
+        saturating_add_assign!(self.serialize_us, other.serialize_us);
-        self.create_vm_us = self.create_vm_us.saturating_add(other.create_vm_us);
+        saturating_add_assign!(self.create_vm_us, other.create_vm_us);
-        self.execute_us = self.execute_us.saturating_add(other.execute_us);
+        saturating_add_assign!(self.execute_us, other.execute_us);
-        self.deserialize_us = self.deserialize_us.saturating_add(other.deserialize_us);
+        saturating_add_assign!(self.deserialize_us, other.deserialize_us);
-        self.changed_account_count = self
+        saturating_add_assign!(
-            .changed_account_count
+            self.get_or_create_executor_us,
-            .saturating_add(other.changed_account_count);
+            other.get_or_create_executor_us
-        self.total_account_count = self
+        );
-            .total_account_count
+        saturating_add_assign!(self.changed_account_count, other.changed_account_count);
-            .saturating_add(other.total_account_count);
+        saturating_add_assign!(self.total_account_count, other.total_account_count);
-        self.total_data_size = self.total_data_size.saturating_add(other.total_data_size);
+        saturating_add_assign!(self.total_data_size, other.total_data_size);
-        self.data_size_changed = self
+        saturating_add_assign!(self.data_size_changed, other.data_size_changed);
-            .data_size_changed
+        saturating_add_assign!(
-            .saturating_add(other.data_size_changed);
+            self.create_executor_register_syscalls_us,
+            other.create_executor_register_syscalls_us
+        );
+        saturating_add_assign!(
+            self.create_executor_load_elf_us,
+            other.create_executor_load_elf_us
+        );
+        saturating_add_assign!(
+            self.create_executor_verify_code_us,
+            other.create_executor_verify_code_us
+        );
+        saturating_add_assign!(
+            self.create_executor_jit_compile_us,
+            other.create_executor_jit_compile_us
+        );
         for (id, other) in &other.per_program_timings {
             let program_timing = self.per_program_timings.entry(*id).or_default();
             program_timing.accumulate_program_timings(other);

program-test/src/lib.rs

@@ -11,9 +11,11 @@ use {
     log::*,
     solana_banks_client::start_client,
     solana_banks_server::banks_server::start_local_server,
-    solana_program_runtime::{ic_msg, invoke_context::ProcessInstructionWithContext, stable_log},
+    solana_program_runtime::{
+        ic_msg, invoke_context::ProcessInstructionWithContext, stable_log, timings::ExecuteTimings,
+    },
     solana_runtime::{
-        bank::{Bank, ExecuteTimings},
+        bank::Bank,
         bank_forks::BankForks,
         builtins::Builtin,
         commitment::BlockCommitmentCache,
@@ -321,6 +323,7 @@ impl solana_sdk::program_stubs::SyscallStubs for SyscallStubs {
                 &program_indices,
                 &account_indices,
                 &caller_privileges,
+                &mut ExecuteTimings::default(),
             )
             .result
             .map_err(|err| ProgramError::try_from(err).unwrap_or_else(|err| panic!("{}", err)))?;

programs/bpf/Cargo.lock

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

programs/bpf/tests/programs.rs

@@ -17,7 +17,7 @@ use solana_bpf_loader_program::{
 use solana_bpf_rust_invoke::instructions::*;
 use solana_bpf_rust_realloc::instructions::*;
 use solana_bpf_rust_realloc_invoke::instructions::*;
-use solana_program_runtime::invoke_context::with_mock_invoke_context;
+use solana_program_runtime::{invoke_context::with_mock_invoke_context, timings::ExecuteTimings};
 use solana_rbpf::{
     elf::Executable,
     static_analysis::Analysis,
@@ -25,7 +25,7 @@ use solana_rbpf::{
 };
 use solana_runtime::{
     bank::{
-        Bank, DurableNonceFee, ExecuteTimings, TransactionBalancesSet, TransactionExecutionDetails,
+        Bank, DurableNonceFee, TransactionBalancesSet, TransactionExecutionDetails,
         TransactionExecutionResult, TransactionResults,
     },
     bank_client::BankClient,

programs/bpf_loader/src/lib.rs

@@ -51,6 +51,7 @@ use {
         program_utils::limited_deserialize,
         pubkey::Pubkey,
         rent::Rent,
+        saturating_add_assign,
         system_instruction::{self, MAX_PERMITTED_DATA_LENGTH},
     },
     std::{cell::RefCell, fmt::Debug, pin::Pin, rc::Rc, sync::Arc},
@@ -85,7 +86,14 @@ pub fn create_executor(
     use_jit: bool,
     reject_deployment_of_broken_elfs: bool,
 ) -> Result<Arc<BpfExecutor>, InstructionError> {
-    let syscall_registry = syscalls::register_syscalls(invoke_context).map_err(|e| {
+    let mut register_syscalls_time = Measure::start("register_syscalls_time");
+    let register_syscall_result = syscalls::register_syscalls(invoke_context);
+    register_syscalls_time.stop();
+    invoke_context.timings.create_executor_register_syscalls_us = invoke_context
+        .timings
+        .create_executor_register_syscalls_us
+        .saturating_add(register_syscalls_time.as_us());
+    let syscall_registry = register_syscall_result.map_err(|e| {
         ic_msg!(invoke_context, "Failed to register syscalls: {}", e);
         InstructionError::ProgramEnvironmentSetupFailure
     })?;
@@ -116,20 +124,40 @@ pub fn create_executor(
     let mut executable = {
         let keyed_accounts = invoke_context.get_keyed_accounts()?;
         let programdata = keyed_account_at_index(keyed_accounts, programdata_account_index)?;
-        Executable::<BpfError, ThisInstructionMeter>::from_elf(
+        let mut load_elf_time = Measure::start("load_elf_time");
+        let executable = Executable::<BpfError, ThisInstructionMeter>::from_elf(
             &programdata.try_account_ref()?.data()[programdata_offset..],
             None,
             config,
             syscall_registry,
-        )
+        );
+        load_elf_time.stop();
+        invoke_context.timings.create_executor_load_elf_us = invoke_context
+            .timings
+            .create_executor_load_elf_us
+            .saturating_add(load_elf_time.as_us());
+        executable
     }
     .map_err(|e| map_ebpf_error(invoke_context, e))?;
     let text_bytes = executable.get_text_bytes().1;
+    let mut verify_code_time = Measure::start("verify_code_time");
     verifier::check(text_bytes, &config)
         .map_err(|e| map_ebpf_error(invoke_context, EbpfError::UserError(e.into())))?;
+    verify_code_time.stop();
+    invoke_context.timings.create_executor_verify_code_us = invoke_context
+        .timings
+        .create_executor_verify_code_us
+        .saturating_add(verify_code_time.as_us());
     if use_jit {
-        if let Err(err) = Executable::<BpfError, ThisInstructionMeter>::jit_compile(&mut executable)
+        let mut jit_compile_time = Measure::start("jit_compile_time");
-        {
+        let jit_compile_result =
+            Executable::<BpfError, ThisInstructionMeter>::jit_compile(&mut executable);
+        jit_compile_time.stop();
+        invoke_context.timings.create_executor_jit_compile_us = invoke_context
+            .timings
+            .create_executor_jit_compile_us
+            .saturating_add(jit_compile_time.as_us());
+        if let Err(err) = jit_compile_result {
             ic_msg!(invoke_context, "Failed to compile program {:?}", err);
             return Err(InstructionError::ProgramFailedToCompile);
         }
@@ -291,6 +319,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 +335,12 @@ fn process_instruction_common(
                 executor
             }
         };
+        get_or_create_executor_time.stop();
+        saturating_add_assign!(
+            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

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

runtime/src/bank.rs

@@ -82,7 +82,7 @@ use {
             TransactionAccountRefCells, TransactionExecutor,
         },
         log_collector::LogCollector,
-        timings::ExecuteDetailsTimings,
+        timings::ExecuteTimings,
     },
     solana_sdk::{
         account::{
@@ -119,7 +119,7 @@ use {
         precompiles::get_precompiles,
         program_utils::limited_deserialize,
         pubkey::Pubkey,
-        secp256k1_program,
+        saturating_add_assign, secp256k1_program,
         signature::{Keypair, Signature},
         slot_hashes::SlotHashes,
         slot_history::SlotHistory,
@@ -212,36 +212,6 @@ impl RentDebits {
     }
 }
 
-#[derive(Default, Debug)]
-pub struct ExecuteTimings {
-    pub check_us: u64,
-    pub load_us: u64,
-    pub execute_us: u64,
-    pub store_us: u64,
-    pub update_stakes_cache_us: u64,
-    pub total_batches_len: usize,
-    pub num_execute_batches: u64,
-    pub details: ExecuteDetailsTimings,
-}
-impl ExecuteTimings {
-    pub fn accumulate(&mut self, other: &ExecuteTimings) {
-        self.check_us = self.check_us.saturating_add(other.check_us);
-        self.load_us = self.load_us.saturating_add(other.load_us);
-        self.execute_us = self.execute_us.saturating_add(other.execute_us);
-        self.store_us = self.store_us.saturating_add(other.store_us);
-        self.update_stakes_cache_us = self
-            .update_stakes_cache_us
-            .saturating_add(other.update_stakes_cache_us);
-        self.total_batches_len = self
-            .total_batches_len
-            .saturating_add(other.total_batches_len);
-        self.num_execute_batches = self
-            .num_execute_batches
-            .saturating_add(other.num_execute_batches);
-        self.details.accumulate(&other.details);
-    }
-}
-
 type BankStatusCache = StatusCache<Result<()>>;
 #[frozen_abi(digest = "6XG6H1FChrDdY39K62KFWj5XfDao4dd24WZgcJkdMu1E")]
 pub type BankSlotDelta = SlotDelta<Result<()>>;
@@ -3607,7 +3577,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() {
@@ -3620,11 +3590,17 @@ 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();
+        saturating_add_assign!(
+            timings.execute_accessories.get_executors_us,
+            get_executors_time.as_us()
+        );
 
         let account_refcells = Self::accounts_to_refcells(&mut loaded_transaction.accounts);
 
@@ -3644,6 +3620,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,
@@ -3655,14 +3633,25 @@ impl Bank {
             instruction_recorders.as_deref(),
             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();
+        saturating_add_assign!(
+            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();
+        saturating_add_assign!(
+            timings.execute_accessories.update_executors_us,
+            update_executors_time.as_us()
+        );
 
         let status = process_result
             .map(|info| {
@@ -3763,19 +3752,36 @@ 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();
+                    saturating_add_assign!(
+                        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();
+                        saturating_add_assign!(
+                            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);
                         }
                     }
@@ -3789,7 +3795,7 @@ impl Bank {
                         durable_nonce_fee,
                         enable_cpi_recording,
                         enable_log_recording,
-                        execute_details_timings,
+                        timings,
                         &mut error_counters,
                     )
                 }

runtime/src/message_processor.rs

@@ -8,7 +8,7 @@ use {
             TransactionAccountRefCell,
         },
         log_collector::LogCollector,
-        timings::ExecuteDetailsTimings,
+        timings::ExecuteTimings,
     },
     solana_sdk::{
         account::WritableAccount,
@@ -19,6 +19,7 @@ use {
         precompiles::is_precompile,
         pubkey::Pubkey,
         rent::Rent,
+        saturating_add_assign,
         sysvar::instructions,
         transaction::TransactionError,
     },
@@ -62,7 +63,7 @@ impl MessageProcessor {
         instruction_recorders: Option<&[InstructionRecorder]>,
         feature_set: Arc<FeatureSet>,
         compute_budget: ComputeBudget,
-        timings: &mut ExecuteDetailsTimings,
+        timings: &mut ExecuteTimings,
         sysvars: &[(Pubkey, Vec<u8>)],
         blockhash: Hash,
         lamports_per_signature: u64,
@@ -120,15 +121,26 @@ impl MessageProcessor {
             let ProcessInstructionResult {
                 compute_units_consumed,
                 result,
-            } = invoke_context.process_instruction(message, instruction, program_indices, &[], &[]);
+            } = invoke_context.process_instruction(
+                message,
+                instruction,
+                program_indices,
+                &[],
+                &[],
+                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);
+            saturating_add_assign!(
+                timings.execute_accessories.process_instructions.total_us,
+                time.as_us()
+            );
             result
                 .map_err(|err| TransactionError::InstructionError(instruction_index as u8, err))?;
         }
@@ -255,7 +267,7 @@ mod tests {
             None,
             Arc::new(FeatureSet::all_enabled()),
             ComputeBudget::new(),
-            &mut ExecuteDetailsTimings::default(),
+            &mut ExecuteTimings::default(),
             &[],
             Hash::default(),
             0,
@@ -285,7 +297,7 @@ mod tests {
             None,
             Arc::new(FeatureSet::all_enabled()),
             ComputeBudget::new(),
-            &mut ExecuteDetailsTimings::default(),
+            &mut ExecuteTimings::default(),
             &[],
             Hash::default(),
             0,
@@ -319,7 +331,7 @@ mod tests {
             None,
             Arc::new(FeatureSet::all_enabled()),
             ComputeBudget::new(),
-            &mut ExecuteDetailsTimings::default(),
+            &mut ExecuteTimings::default(),
             &[],
             Hash::default(),
             0,
@@ -464,7 +476,7 @@ mod tests {
             None,
             Arc::new(FeatureSet::all_enabled()),
             ComputeBudget::new(),
-            &mut ExecuteDetailsTimings::default(),
+            &mut ExecuteTimings::default(),
             &[],
             Hash::default(),
             0,
@@ -498,7 +510,7 @@ mod tests {
             None,
             Arc::new(FeatureSet::all_enabled()),
             ComputeBudget::new(),
-            &mut ExecuteDetailsTimings::default(),
+            &mut ExecuteTimings::default(),
             &[],
             Hash::default(),
             0,
@@ -529,7 +541,7 @@ mod tests {
             None,
             Arc::new(FeatureSet::all_enabled()),
             ComputeBudget::new(),
-            &mut ExecuteDetailsTimings::default(),
+            &mut ExecuteTimings::default(),
             &[],
             Hash::default(),
             0,
@@ -587,7 +599,7 @@ mod tests {
             None,
             Arc::new(FeatureSet::all_enabled()),
             ComputeBudget::new(),
-            &mut ExecuteDetailsTimings::default(),
+            &mut ExecuteTimings::default(),
             &[],
             Hash::default(),
             0,

sdk/src/lib.rs

@@ -103,6 +103,15 @@ macro_rules! program_stubs {
     () => {};
 }
 
+/// Convenience macro for `AddAssign` with saturating arithmetic.
+/// Replace by `std::num::Saturating` once stable
+#[macro_export]
+macro_rules! saturating_add_assign {
+    ($i:expr, $v:expr) => {{
+        $i = $i.saturating_add($v)
+    }};
+}
+
 #[macro_use]
 extern crate serde_derive;
 pub extern crate bs58;
@@ -110,3 +119,18 @@ extern crate log as logger;
 
 #[macro_use]
 extern crate solana_frozen_abi_macro;
+
+#[cfg(test)]
+mod tests {
+    #[test]
+    fn test_saturating_add_assign() {
+        let mut i = 0u64;
+        let v = 1;
+        saturating_add_assign!(i, v);
+        assert_eq!(i, 1);
+
+        i = u64::MAX;
+        saturating_add_assign!(i, v);
+        assert_eq!(i, u64::MAX);
+    }
+}