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

* consolidate execute timings to a common module

* Add execute metrics

* Add metrics for executor creation

* Use saturating_add_assign macro

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

core/src/banking_stage.rs

@@ -20,10 +20,7 @@ use {
     solana_poh::poh_recorder::{PohRecorder, PohRecorderError, TransactionRecorder},
     solana_runtime::{
         accounts_db::ErrorCounters,
-        bank::{
-            Bank, ExecuteTimings, TransactionBalancesSet, TransactionCheckResult,
-            TransactionExecutionResult,
-        },
+        bank::{Bank, TransactionBalancesSet, TransactionCheckResult, TransactionExecutionResult},
         bank_utils,
         cost_model::CostModel,
         cost_tracker::CostTracker,
@@ -36,6 +33,7 @@ use {
             Slot, DEFAULT_TICKS_PER_SLOT, MAX_PROCESSING_AGE, MAX_TRANSACTION_FORWARDING_DELAY,
             MAX_TRANSACTION_FORWARDING_DELAY_GPU,
         },
+        execute_timings::ExecuteTimings,
         feature_set,
         message::Message,
         pubkey::Pubkey,

core/src/cost_update_service.rs

@@ -6,11 +6,8 @@
 use {
     solana_ledger::blockstore::Blockstore,
     solana_measure::measure::Measure,
-    solana_runtime::{
-        bank::{Bank, ExecuteTimings},
-        cost_model::CostModel,
-    },
-    solana_sdk::timing::timestamp,
+    solana_runtime::{bank::Bank, cost_model::CostModel},
+    solana_sdk::{execute_timings::ExecuteTimings, timing::timestamp},
     std::{
         sync::{
             atomic::{AtomicBool, Ordering},
@@ -71,8 +68,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>;
@@ -221,7 +222,10 @@ impl CostUpdateService {
 
 #[cfg(test)]
 mod tests {
-    use {super::*, solana_runtime::message_processor::ProgramTiming, solana_sdk::pubkey::Pubkey};
+    use {
+        super::*,
+        solana_sdk::{execute_timings::ProgramTiming, pubkey::Pubkey},
+    };
 
     #[test]
     fn test_update_cost_model_with_empty_execute_timings() {

core/src/progress_map.rs

@@ -81,45 +81,122 @@ 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_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

@@ -43,13 +43,14 @@ use {
     },
     solana_runtime::{
         accounts_background_service::AbsRequestSender,
-        bank::{Bank, ExecuteTimings, NewBankOptions},
+        bank::{Bank, NewBankOptions},
         bank_forks::BankForks,
         commitment::BlockCommitmentCache,
         vote_sender_types::ReplayVoteSender,
     },
     solana_sdk::{
         clock::{Slot, MAX_PROCESSING_AGE, NUM_CONSECUTIVE_LEADER_SLOTS},
+        execute_timings::ExecuteTimings,
         genesis_config::ClusterType,
         hash::Hash,
         pubkey::Pubkey,
@@ -1876,7 +1877,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/src/blockstore_processor.rs

@@ -23,7 +23,7 @@ use {
         accounts_index::AccountSecondaryIndexes,
         accounts_update_notifier_interface::AccountsUpdateNotifier,
         bank::{
-            Bank, ExecuteTimings, InnerInstructionsList, RentDebits, TransactionBalancesSet,
+            Bank, InnerInstructionsList, RentDebits, TransactionBalancesSet,
             TransactionExecutionResult, TransactionLogMessages, TransactionResults,
         },
         bank_forks::BankForks,
@@ -37,6 +37,7 @@ use {
     },
     solana_sdk::{
         clock::{Slot, MAX_PROCESSING_AGE},
+        execute_timings::ExecuteTimings,
         feature_set,
         genesis_config::GenesisConfig,
         hash::Hash,

program-test/src/lib.rs

@@ -12,7 +12,7 @@ use {
     solana_banks_client::start_client,
     solana_banks_server::banks_server::start_local_server,
     solana_runtime::{
-        bank::{Bank, Builtin, ExecuteTimings},
+        bank::{Bank, Builtin},
         bank_forks::BankForks,
         commitment::BlockCommitmentCache,
         genesis_utils::{create_genesis_config_with_leader_ex, GenesisConfigInfo},
@@ -23,6 +23,7 @@ use {
         clock::{Clock, Slot},
         entrypoint::{ProgramResult, SUCCESS},
         epoch_schedule::EpochSchedule,
+        execute_timings::ExecuteTimings,
         feature_set::demote_program_write_locks,
         fee_calculator::{FeeCalculator, FeeRateGovernor},
         genesis_config::{ClusterType, GenesisConfig},

programs/bpf/tests/programs.rs

@@ -21,7 +21,7 @@ use solana_rbpf::{
     vm::{Config, Tracer},
 };
 use solana_runtime::{
-    bank::{Bank, ExecuteTimings, NonceRollbackInfo, TransactionBalancesSet, TransactionResults},
+    bank::{Bank, NonceRollbackInfo, TransactionBalancesSet, TransactionResults},
     bank_client::BankClient,
     genesis_utils::{create_genesis_config, GenesisConfigInfo},
     loader_utils::{
@@ -37,6 +37,7 @@ use solana_sdk::{
     clock::MAX_PROCESSING_AGE,
     compute_budget,
     entrypoint::{MAX_PERMITTED_DATA_INCREASE, SUCCESS},
+    execute_timings::ExecuteTimings,
     instruction::{AccountMeta, CompiledInstruction, Instruction, InstructionError},
     keyed_account::KeyedAccount,
     message::Message,

programs/bpf_loader/src/lib.rs

@@ -52,6 +52,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},
@@ -86,7 +87,16 @@ 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();
+    saturating_add_assign!(
+        invoke_context
+            .get_timings()
+            .create_executor_register_syscalls_us,
+        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
     })?;
@@ -108,9 +118,8 @@ pub fn create_executor(
     };
     let program_id;
     let load_elf_us: u64;
-    let verify_elf_us: u64;
     let mut jit_compile_us = 0u64;
-    let mut executable = {
+    let executable_result = {
         let keyed_accounts = invoke_context.get_keyed_accounts()?;
         let program = keyed_account_at_index(keyed_accounts, program_account_index)?;
         program_id = *program.unsigned_key();
@@ -126,20 +135,35 @@ pub fn create_executor(
         load_elf_time.stop();
         load_elf_us = load_elf_time.as_us();
         executable
-    }
-    .map_err(|e| map_ebpf_error(invoke_context, e))?;
+    };
+
+    saturating_add_assign!(
+        invoke_context.get_timings().create_executor_load_elf_us,
+        load_elf_us
+    );
+
+    let mut executable = executable_result.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();
-    verify_elf_us = verify_code_time.as_us();
+    let verify_elf_us = verify_code_time.as_us();
+    saturating_add_assign!(
+        invoke_context.get_timings().create_executor_verify_code_us,
+        verify_elf_us
+    );
     if use_jit {
         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();
         jit_compile_us = jit_compile_time.as_us();
+        saturating_add_assign!(
+            invoke_context.get_timings().create_executor_jit_compile_us,
+            jit_compile_us
+        );
         if let Err(err) = jit_compile_result {
             ic_msg!(invoke_context, "Failed to compile program {:?}", err);
             return Err(InstructionError::ProgramFailedToCompile);
@@ -273,7 +297,9 @@ fn process_instruction_common(
             return Err(InstructionError::IncorrectProgramId);
         }
 
-        let executor = match invoke_context.get_executor(program_id) {
+        let mut get_or_create_executor_time = Measure::start("get_or_create_executor_time");
+        let maybe_executor = invoke_context.get_executor(program_id);
+        let executor = match maybe_executor {
             Some(executor) => executor,
             None => {
                 let executor =
@@ -282,6 +308,12 @@ fn process_instruction_common(
                 executor
             }
         };
+        get_or_create_executor_time.stop();
+        saturating_add_assign!(
+            invoke_context.get_timings().get_or_create_executor_us,
+            get_or_create_executor_time.as_us()
+        );
+
         executor.execute(
             loader_id,
             program_id,
@@ -1053,6 +1085,7 @@ mod tests {
             account_utils::StateMut,
             client::SyncClient,
             clock::Clock,
+            execute_timings::ExecuteDetailsTimings,
             feature_set::FeatureSet,
             genesis_config::create_genesis_config,
             instruction::Instruction,
@@ -1330,6 +1363,7 @@ mod tests {
             sysvars: vec![],
             disabled_features: vec![].into_iter().collect(),
             return_data: None,
+            execute_timings: ExecuteDetailsTimings::default(),
         };
         assert_eq!(
             Err(InstructionError::ProgramFailedToComplete),

runtime/benches/message_processor.rs

@@ -4,8 +4,10 @@ extern crate test;
 
 use {
     log::*,
-    solana_runtime::message_processor::{ExecuteDetailsTimings, PreAccount},
-    solana_sdk::{account::AccountSharedData, pubkey, rent::Rent},
+    solana_runtime::message_processor::PreAccount,
+    solana_sdk::{
+        account::AccountSharedData, execute_timings::ExecuteDetailsTimings, pubkey, rent::Rent,
+    },
     test::Bencher,
 };