From 9ec686250fe80f3fd0ed0261e0ce04c544264a28 Mon Sep 17 00:00:00 2001 From: Trent Nelson Date: Tue, 4 Jan 2022 01:23:56 -0700 Subject: [PATCH 1/6] move `ExecuteTimings` from `runtime::bank` to `program_runtime::timings` --- Cargo.lock | 1 + core/Cargo.toml | 1 + core/src/banking_stage.rs | 6 ++---- core/src/cost_update_service.rs | 6 ++---- core/src/replay_stage.rs | 3 ++- ledger/Cargo.toml | 1 + ledger/src/blockstore_processor.rs | 3 ++- program-runtime/src/timings.rs | 33 ++++++++++++++++++++++++++++++ program-test/src/lib.rs | 6 ++++-- programs/bpf/Cargo.lock | 1 + programs/bpf/tests/programs.rs | 4 ++-- runtime/src/bank.rs | 32 +---------------------------- 12 files changed, 52 insertions(+), 45 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 75fca5de6901cd..997936aa490deb 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -5134,6 +5134,7 @@ dependencies = [ "solana-measure", "solana-metrics", "solana-perf", + "solana-program-runtime", "solana-rayon-threadlimit", "solana-runtime", "solana-sdk", diff --git a/core/Cargo.toml b/core/Cargo.toml index cf34c3903c75f5..5096db4b968068 100644 --- a/core/Cargo.toml +++ b/core/Cargo.toml @@ -43,6 +43,7 @@ solana-metrics = { path = "../metrics", version = "=1.10.0" } solana-net-utils = { path = "../net-utils", version = "=1.10.0" } solana-perf = { path = "../perf", version = "=1.10.0" } solana-poh = { path = "../poh", version = "=1.10.0" } +solana-program-runtime = { path = "../program-runtime", version = "=1.10.0" } solana-rpc = { path = "../rpc", version = "=1.10.0" } solana-replica-lib = { path = "../replica-lib", version = "=1.10.0" } solana-runtime = { path = "../runtime", version = "=1.10.0" } diff --git a/core/src/banking_stage.rs b/core/src/banking_stage.rs index c6740d4459d8a0..e91b18627a1a6a 100644 --- a/core/src/banking_stage.rs +++ b/core/src/banking_stage.rs @@ -18,12 +18,10 @@ use { perf_libs, }, solana_poh::poh_recorder::{BankStart, PohRecorder, PohRecorderError, TransactionRecorder}, + solana_program_runtime::timings::ExecuteTimings, solana_runtime::{ accounts_db::ErrorCounters, - bank::{ - Bank, ExecuteTimings, TransactionBalancesSet, TransactionCheckResult, - TransactionExecutionResult, - }, + bank::{Bank, TransactionBalancesSet, TransactionCheckResult, TransactionExecutionResult}, bank_utils, cost_model::CostModel, transaction_batch::TransactionBatch, diff --git a/core/src/cost_update_service.rs b/core/src/cost_update_service.rs index c21c78869cd83a..b6f3eb60d134d0 100644 --- a/core/src/cost_update_service.rs +++ b/core/src/cost_update_service.rs @@ -6,10 +6,8 @@ use { solana_ledger::blockstore::Blockstore, solana_measure::measure::Measure, - solana_runtime::{ - bank::{Bank, ExecuteTimings}, - cost_model::CostModel, - }, + solana_program_runtime::timings::ExecuteTimings, + solana_runtime::{bank::Bank, cost_model::CostModel}, solana_sdk::timing::timestamp, std::{ sync::{ diff --git a/core/src/replay_stage.rs b/core/src/replay_stage.rs index 6e75a9490cc57f..238ae0ba3a4777 100644 --- a/core/src/replay_stage.rs +++ b/core/src/replay_stage.rs @@ -40,13 +40,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, diff --git a/ledger/Cargo.toml b/ledger/Cargo.toml index 370f73765aa59d..bd83b9260fa863 100644 --- a/ledger/Cargo.toml +++ b/ledger/Cargo.toml @@ -38,6 +38,7 @@ solana-frozen-abi-macro = { path = "../frozen-abi/macro", version = "=1.10.0" } solana-transaction-status = { path = "../transaction-status", version = "=1.10.0" } solana-measure = { path = "../measure", version = "=1.10.0" } solana-metrics = { path = "../metrics", version = "=1.10.0" } +solana-program-runtime = { path = "../program-runtime", version = "=1.10.0" } solana-perf = { path = "../perf", version = "=1.10.0" } solana-rayon-threadlimit = { path = "../rayon-threadlimit", version = "=1.10.0" } solana-runtime = { path = "../runtime", version = "=1.10.0" } diff --git a/ledger/src/blockstore_processor.rs b/ledger/src/blockstore_processor.rs index e16053d15b8048..e27d96ef6f91b2 100644 --- a/ledger/src/blockstore_processor.rs +++ b/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, diff --git a/program-runtime/src/timings.rs b/program-runtime/src/timings.rs index ec47835dae3213..35ff7323c9976c 100644 --- a/program-runtime/src/timings.rs +++ b/program-runtime/src/timings.rs @@ -35,6 +35,39 @@ impl ProgramTiming { } } +#[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, +} + +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.collect_logs_us = self.collect_logs_us.saturating_add(other.collect_logs_us); + self.details.accumulate(&other.details); + } +} + #[derive(Default, Debug, PartialEq)] pub struct ExecuteDetailsTimings { pub serialize_us: u64, diff --git a/program-test/src/lib.rs b/program-test/src/lib.rs index 9eb38503e1ac6f..ad6e87a63c409d 100644 --- a/program-test/src/lib.rs +++ b/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, diff --git a/programs/bpf/Cargo.lock b/programs/bpf/Cargo.lock index 7ffda3a92f4391..f6a063df672f59 100644 --- a/programs/bpf/Cargo.lock +++ b/programs/bpf/Cargo.lock @@ -3375,6 +3375,7 @@ dependencies = [ "num-traits", "rustc_version 0.4.0", "serde", + "solana-measure", "solana-sdk", "thiserror", ] diff --git a/programs/bpf/tests/programs.rs b/programs/bpf/tests/programs.rs index e658dbbdcb4404..55f661570c015c 100644 --- a/programs/bpf/tests/programs.rs +++ b/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, diff --git a/runtime/src/bank.rs b/runtime/src/bank.rs index d0efd6f4b237c1..d223091b17a321 100644 --- a/runtime/src/bank.rs +++ b/runtime/src/bank.rs @@ -78,7 +78,7 @@ use { BuiltinProgram, Executor, Executors, ProcessInstructionWithContext, TransactionExecutor, }, log_collector::LogCollector, - timings::ExecuteDetailsTimings, + timings::{ExecuteDetailsTimings, ExecuteTimings}, }, solana_sdk::{ account::{ @@ -209,36 +209,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>; #[frozen_abi(digest = "6XG6H1FChrDdY39K62KFWj5XfDao4dd24WZgcJkdMu1E")] pub type BankSlotDelta = SlotDelta>; From 7076428af716aad0aa37c537e009484267b51a14 Mon Sep 17 00:00:00 2001 From: Carl Lin Date: Mon, 20 Dec 2021 23:03:20 -0500 Subject: [PATCH 2/6] Add execute metrics --- Cargo.lock | 1 + core/src/cost_update_service.rs | 8 ++- core/src/progress_map.rs | 71 ++++++++++++++++++++++++--- core/src/replay_stage.rs | 4 +- program-runtime/Cargo.toml | 1 + program-runtime/src/invoke_context.rs | 62 +++++++++++++++++++---- program-runtime/src/timings.rs | 50 +++++++++++++++++++ program-test/src/lib.rs | 1 + programs/bpf_loader/src/lib.rs | 4 ++ programs/bpf_loader/src/syscalls.rs | 2 + runtime/src/bank.rs | 35 ++++++++++--- runtime/src/message_processor.rs | 24 ++++----- 12 files changed, 225 insertions(+), 38 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 997936aa490deb..0cbde570215abf 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -5488,6 +5488,7 @@ dependencies = [ "rustc_version 0.4.0", "serde", "solana-logger 1.10.0", + "solana-measure", "solana-sdk", "thiserror", ] diff --git a/core/src/cost_update_service.rs b/core/src/cost_update_service.rs index b6f3eb60d134d0..55fb0e738df211 100644 --- a/core/src/cost_update_service.rs +++ b/core/src/cost_update_service.rs @@ -69,8 +69,12 @@ impl CostUpdateServiceTiming { } pub enum CostUpdate { - FrozenBank { bank: Arc }, - ExecuteTiming { execute_timings: ExecuteTimings }, + FrozenBank { + bank: Arc, + }, + ExecuteTiming { + execute_timings: Box, + }, } pub type CostUpdateReceiver = Receiver; diff --git a/core/src/progress_map.rs b/core/src/progress_map.rs index 3a0f566cb3ce8f..0ad895bd7af6f6 100644 --- a/core/src/progress_map.rs +++ b/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 diff --git a/core/src/replay_stage.rs b/core/src/replay_stage.rs index 238ae0ba3a4777..aa6d3642416b76 100644 --- a/core/src/replay_stage.rs +++ b/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)); } diff --git a/program-runtime/Cargo.toml b/program-runtime/Cargo.toml index b7e99f2e6579a5..e0e5fe33f74635 100644 --- a/program-runtime/Cargo.toml +++ b/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" diff --git a/program-runtime/src/invoke_context.rs b/program-runtime/src/invoke_context.rs index 3d3fae7d9ba8b3..c0a605427739e4 100644 --- a/program-runtime/src/invoke_context.rs +++ b/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()); diff --git a/program-runtime/src/timings.rs b/program-runtime/src/timings.rs index 35ff7323c9976c..fe89bb1c5de23c 100644 --- a/program-runtime/src/timings.rs +++ b/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); diff --git a/program-test/src/lib.rs b/program-test/src/lib.rs index ad6e87a63c409d..07913ce7f7bfdc 100644 --- a/program-test/src/lib.rs +++ b/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)))?; diff --git a/programs/bpf_loader/src/lib.rs b/programs/bpf_loader/src/lib.rs index c6cbcc120fc929..9fd92f8f175f68 100644 --- a/programs/bpf_loader/src/lib.rs +++ b/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, diff --git a/programs/bpf_loader/src/syscalls.rs b/programs/bpf_loader/src/syscalls.rs index 63c95d860db15a..b4a53e5fb6d648 100644 --- a/programs/bpf_loader/src/syscalls.rs +++ b/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)?; diff --git a/runtime/src/bank.rs b/runtime/src/bank.rs index d223091b17a321..7c54840704403f 100644 --- a/runtime/src/bank.rs +++ b/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, 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 = 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, ) } diff --git a/runtime/src/message_processor.rs b/runtime/src/message_processor.rs index 827d593f643cc1..3f726fb9efeed2 100644 --- a/runtime/src/message_processor.rs +++ b/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>>, feature_set: Arc, compute_budget: ComputeBudget, - timings: &mut ExecuteDetailsTimings, + timings: &mut ExecuteTimings, sysvars: &[(Pubkey, Vec)], 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, From 574a547d73c7fb0bc9104b890c65b847c0cbfe56 Mon Sep 17 00:00:00 2001 From: Trent Nelson Date: Tue, 4 Jan 2022 21:27:22 -0700 Subject: [PATCH 3/6] Add metrics for executor creation --- core/src/progress_map.rs | 22 ++++++++++++++++++++ program-runtime/src/timings.rs | 16 +++++++++++++++ programs/bpf_loader/src/lib.rs | 37 +++++++++++++++++++++++++++++----- 3 files changed, 70 insertions(+), 5 deletions(-) diff --git a/core/src/progress_map.rs b/core/src/progress_map.rs index 0ad895bd7af6f6..5b6038d173926f 100644 --- a/core/src/progress_map.rs +++ b/core/src/progress_map.rs @@ -126,6 +126,28 @@ impl ReplaySlotStats { 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 diff --git a/program-runtime/src/timings.rs b/program-runtime/src/timings.rs index fe89bb1c5de23c..7070a0f0a955af 100644 --- a/program-runtime/src/timings.rs +++ b/program-runtime/src/timings.rs @@ -125,6 +125,10 @@ pub struct ExecuteDetailsTimings { 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, } impl ExecuteDetailsTimings { @@ -146,6 +150,18 @@ impl ExecuteDetailsTimings { self.data_size_changed = self .data_size_changed .saturating_add(other.data_size_changed); + self.create_executor_register_syscalls_us = self + .create_executor_register_syscalls_us + .saturating_add(other.create_executor_register_syscalls_us); + self.create_executor_load_elf_us = self + .create_executor_load_elf_us + .saturating_add(other.create_executor_load_elf_us); + self.create_executor_verify_code_us = self + .create_executor_verify_code_us + .saturating_add(other.create_executor_verify_code_us); + self.create_executor_jit_compile_us = self + .create_executor_jit_compile_us + .saturating_add(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); diff --git a/programs/bpf_loader/src/lib.rs b/programs/bpf_loader/src/lib.rs index 9fd92f8f175f68..8a1fe361b43d75 100644 --- a/programs/bpf_loader/src/lib.rs +++ b/programs/bpf_loader/src/lib.rs @@ -85,7 +85,14 @@ pub fn create_executor( use_jit: bool, reject_deployment_of_broken_elfs: bool, ) -> Result, 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 +123,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::::from_elf( + let mut load_elf_time = Measure::start("load_elf_time"); + let executable = Executable::::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::::jit_compile(&mut executable) - { + let mut jit_compile_time = Measure::start("jit_compile_time"); + let jit_compile_result = + Executable::::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); } From d02f4c9bfeaab1bb30f411442225d35eaf586d7b Mon Sep 17 00:00:00 2001 From: Trent Nelson Date: Wed, 5 Jan 2022 15:56:39 -0700 Subject: [PATCH 4/6] Add helper macro for `AddAssign`ing with saturating arithmetic --- sdk/src/lib.rs | 24 ++++++++++++++++++++++++ 1 file changed, 24 insertions(+) diff --git a/sdk/src/lib.rs b/sdk/src/lib.rs index f537560b79efb8..ded554312d8bbc 100644 --- a/sdk/src/lib.rs +++ b/sdk/src/lib.rs @@ -104,6 +104,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; @@ -111,3 +120,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); + } +} From 2e9addeb05ccc25605010783e8f3d5c413f409a5 Mon Sep 17 00:00:00 2001 From: Trent Nelson Date: Wed, 5 Jan 2022 17:08:35 -0700 Subject: [PATCH 5/6] Use saturating_add_assign macro --- program-runtime/src/invoke_context.rs | 37 +++---- program-runtime/src/timings.rs | 149 ++++++++++++-------------- programs/bpf_loader/src/lib.rs | 6 +- runtime/src/bank.rs | 33 ++++-- runtime/src/message_processor.rs | 6 +- 5 files changed, 122 insertions(+), 109 deletions(-) diff --git a/program-runtime/src/invoke_context.rs b/program-runtime/src/invoke_context.rs index c0a605427739e4..0b555efc55e7da 100644 --- a/program-runtime/src/invoke_context.rs +++ b/program-runtime/src/invoke_context.rs @@ -24,6 +24,7 @@ use { native_loader, pubkey::Pubkey, rent::Rent, + saturating_add_assign, sysvar::Sysvar, transaction_context::{InstructionAccount, TransactionAccount, TransactionContext}, }, @@ -800,12 +801,12 @@ impl<'a> InvokeContext<'a> { 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()); + saturating_add_assign!( + timings + .execute_accessories + .process_instruction_verify_caller_us, + verify_caller_time.as_us() + ); verify_caller_result?; // Record instruction @@ -851,18 +852,18 @@ impl<'a> InvokeContext<'a> { }); 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()); + saturating_add_assign!( + timings + .execute_accessories + .process_instruction_process_executable_chain_us, + process_executable_chain_time.as_us() + ); + saturating_add_assign!( + timings + .execute_accessories + .process_instruction_verify_callee_us, + verify_callee_time.as_us() + ); result }); diff --git a/program-runtime/src/timings.rs b/program-runtime/src/timings.rs index 7070a0f0a955af..41799696ff34c0 100644 --- a/program-runtime/src/timings.rs +++ b/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,19 @@ 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); - self.count = self.count.saturating_add(1); + saturating_add_assign!(self.accumulated_units, compute_units_update); + 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); - self.accumulated_units = self - .accumulated_units - .saturating_add(other.accumulated_units); - self.count = self.count.saturating_add(other.count); + saturating_add_assign!(self.accumulated_us, other.accumulated_us); + saturating_add_assign!(self.accumulated_units, other.accumulated_units); + saturating_add_assign!(self.count, 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 - .total_errored_units - .saturating_add(other.total_errored_units); + saturating_add_assign!(self.total_errored_units, other.total_errored_units); } } @@ -51,20 +50,14 @@ pub struct ExecuteTimings { 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.collect_logs_us = self.collect_logs_us.saturating_add(other.collect_logs_us); + 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); @@ -86,31 +79,30 @@ pub struct ExecuteAccessoryTimings { 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); + 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); + saturating_add_assign!(self.process_instructions_us, other.process_instructions_us); + saturating_add_assign!( + self.process_instruction_verify_caller_us, + other.process_instruction_verify_caller_us + ); + saturating_add_assign!( + self.process_instruction_process_executable_chain_us, + other.process_instruction_process_executable_chain_us + ); + saturating_add_assign!( + self.process_instruction_verify_callee_us, + other.process_instruction_verify_callee_us + ); } } @@ -133,35 +125,34 @@ pub struct ExecuteDetailsTimings { } impl ExecuteDetailsTimings { pub fn accumulate(&mut self, other: &ExecuteDetailsTimings) { - self.serialize_us = self.serialize_us.saturating_add(other.serialize_us); - 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); - self.total_account_count = self - .total_account_count - .saturating_add(other.total_account_count); - self.total_data_size = self.total_data_size.saturating_add(other.total_data_size); - self.data_size_changed = self - .data_size_changed - .saturating_add(other.data_size_changed); - self.create_executor_register_syscalls_us = self - .create_executor_register_syscalls_us - .saturating_add(other.create_executor_register_syscalls_us); - self.create_executor_load_elf_us = self - .create_executor_load_elf_us - .saturating_add(other.create_executor_load_elf_us); - self.create_executor_verify_code_us = self - .create_executor_verify_code_us - .saturating_add(other.create_executor_verify_code_us); - self.create_executor_jit_compile_us = self - .create_executor_jit_compile_us - .saturating_add(other.create_executor_jit_compile_us); + saturating_add_assign!(self.serialize_us, other.serialize_us); + saturating_add_assign!(self.create_vm_us, other.create_vm_us); + saturating_add_assign!(self.execute_us, other.execute_us); + saturating_add_assign!(self.deserialize_us, other.deserialize_us); + saturating_add_assign!( + self.get_or_create_executor_us, + other.get_or_create_executor_us + ); + saturating_add_assign!(self.changed_account_count, other.changed_account_count); + saturating_add_assign!(self.total_account_count, other.total_account_count); + saturating_add_assign!(self.total_data_size, other.total_data_size); + saturating_add_assign!(self.data_size_changed, other.data_size_changed); + saturating_add_assign!( + 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); diff --git a/programs/bpf_loader/src/lib.rs b/programs/bpf_loader/src/lib.rs index 8a1fe361b43d75..a6a1075e94957b 100644 --- a/programs/bpf_loader/src/lib.rs +++ b/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}, @@ -335,7 +336,10 @@ fn process_instruction_common( } }; get_or_create_executor_time.stop(); - invoke_context.timings.get_or_create_executor_us += get_or_create_executor_time.as_us(); + saturating_add_assign!( + invoke_context.timings.get_or_create_executor_us, + get_or_create_executor_time.as_us() + ); executor.execute( next_first_instruction_account, diff --git a/runtime/src/bank.rs b/runtime/src/bank.rs index 7c54840704403f..b0f1733c71241a 100644 --- a/runtime/src/bank.rs +++ b/runtime/src/bank.rs @@ -115,7 +115,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, @@ -3561,7 +3561,10 @@ impl Bank { &loaded_transaction.program_indices, ); get_executors_time.stop(); - timings.execute_accessories.get_executors_us += get_executors_time.as_us(); + saturating_add_assign!( + 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); @@ -3605,12 +3608,18 @@ impl Bank { self.load_accounts_data_len(), ); process_message_time.stop(); - timings.execute_accessories.process_message_us += process_message_time.as_us(); + 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(); - timings.execute_accessories.update_executors_us += update_executors_time.as_us(); + saturating_add_assign!( + timings.execute_accessories.update_executors_us, + update_executors_time.as_us() + ); let status = process_result .map(|info| { @@ -3712,8 +3721,10 @@ impl Bank { 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(); + 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); @@ -3724,10 +3735,12 @@ impl Bank { 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(); + 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); } diff --git a/runtime/src/message_processor.rs b/runtime/src/message_processor.rs index 3f726fb9efeed2..92a8315ed8104e 100644 --- a/runtime/src/message_processor.rs +++ b/runtime/src/message_processor.rs @@ -16,6 +16,7 @@ use { precompiles::is_precompile, pubkey::Pubkey, rent::Rent, + saturating_add_assign, sysvar::instructions, transaction::TransactionError, transaction_context::{InstructionAccount, TransactionContext}, @@ -144,7 +145,10 @@ impl MessageProcessor { result.is_err(), ); timings.details.accumulate(&invoke_context.timings); - timings.execute_accessories.process_instructions_us += time.as_us(); + saturating_add_assign!( + timings.execute_accessories.process_instructions_us, + time.as_us() + ); result .map_err(|err| TransactionError::InstructionError(instruction_index as u8, err))?; } From d7c54f674e898bce038cc41b233e09886c51935a Mon Sep 17 00:00:00 2001 From: Trent Nelson Date: Wed, 5 Jan 2022 20:18:24 -0700 Subject: [PATCH 6/6] Consolidate process instruction execution timings to own struct --- core/src/progress_map.rs | 23 +++++++++++---- program-runtime/src/invoke_context.rs | 9 ++++-- program-runtime/src/timings.rs | 40 +++++++++++++++------------ runtime/src/message_processor.rs | 2 +- 4 files changed, 47 insertions(+), 27 deletions(-) diff --git a/core/src/progress_map.rs b/core/src/progress_map.rs index 5b6038d173926f..bc68443bf0f5f7 100644 --- a/core/src/progress_map.rs +++ b/core/src/progress_map.rs @@ -178,24 +178,35 @@ impl ReplaySlotStats { i64 ), ( - "execute_accessories_process_instruction_verify_caller_us", + "execute_accessories_process_instructions_total_us", self.execute_timings .execute_accessories - .process_instruction_verify_caller_us, + .process_instructions + .total_us, i64 ), ( - "execute_accessories_process_instruction_process_executable_chain_us", + "execute_accessories_process_instructions_verify_caller_us", self.execute_timings .execute_accessories - .process_instruction_process_executable_chain_us, + .process_instructions + .verify_caller_us, i64 ), ( - "execute_accessories_process_instruction_verify_callee_us", + "execute_accessories_process_instructions_process_executable_chain_us", self.execute_timings .execute_accessories - .process_instruction_verify_callee_us, + .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 ), ); diff --git a/program-runtime/src/invoke_context.rs b/program-runtime/src/invoke_context.rs index 0b555efc55e7da..f5af1eb3fed23d 100644 --- a/program-runtime/src/invoke_context.rs +++ b/program-runtime/src/invoke_context.rs @@ -804,7 +804,8 @@ impl<'a> InvokeContext<'a> { saturating_add_assign!( timings .execute_accessories - .process_instruction_verify_caller_us, + .process_instructions + .verify_caller_us, verify_caller_time.as_us() ); verify_caller_result?; @@ -855,13 +856,15 @@ impl<'a> InvokeContext<'a> { saturating_add_assign!( timings .execute_accessories - .process_instruction_process_executable_chain_us, + .process_instructions + .process_executable_chain_us, process_executable_chain_time.as_us() ); saturating_add_assign!( timings .execute_accessories - .process_instruction_verify_callee_us, + .process_instructions + .verify_callee_us, verify_callee_time.as_us() ); diff --git a/program-runtime/src/timings.rs b/program-runtime/src/timings.rs index 41799696ff34c0..40e6dc97531d83 100644 --- a/program-runtime/src/timings.rs +++ b/program-runtime/src/timings.rs @@ -64,6 +64,26 @@ impl ExecuteTimings { } } +#[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, @@ -71,10 +91,7 @@ pub struct ExecuteAccessoryTimings { 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, + pub process_instructions: ExecuteProcessInstructionTimings, } impl ExecuteAccessoryTimings { @@ -90,19 +107,8 @@ impl ExecuteAccessoryTimings { 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); - saturating_add_assign!(self.process_instructions_us, other.process_instructions_us); - saturating_add_assign!( - self.process_instruction_verify_caller_us, - other.process_instruction_verify_caller_us - ); - saturating_add_assign!( - self.process_instruction_process_executable_chain_us, - other.process_instruction_process_executable_chain_us - ); - saturating_add_assign!( - self.process_instruction_verify_callee_us, - other.process_instruction_verify_callee_us - ); + self.process_instructions + .accumulate(&other.process_instructions); } } diff --git a/runtime/src/message_processor.rs b/runtime/src/message_processor.rs index 92a8315ed8104e..4253e1a920e1f8 100644 --- a/runtime/src/message_processor.rs +++ b/runtime/src/message_processor.rs @@ -146,7 +146,7 @@ impl MessageProcessor { ); timings.details.accumulate(&invoke_context.timings); saturating_add_assign!( - timings.execute_accessories.process_instructions_us, + timings.execute_accessories.process_instructions.total_us, time.as_us() ); result