From 7b1da6276319cf5b907d39f6d59bdb68c34fcb66 Mon Sep 17 00:00:00 2001 From: "mergify[bot]" <37929162+mergify[bot]@users.noreply.github.com> Date: Fri, 7 Jan 2022 09:11:18 +0000 Subject: [PATCH] Add execute metrics (backport #22296) (#22335) * move `ExecuteTimings` from `runtime::bank` to `program_runtime::timings` (cherry picked from commit 7d32909e1762c63b0066198a080ae310e2c89619) # Conflicts: # core/Cargo.toml # ledger/Cargo.toml # programs/bpf/Cargo.lock * Add execute metrics (cherry picked from commit b25e4a200b87949dc30be63e413fdbba90c55449) * Add metrics for executor creation (cherry picked from commit 848b6dfbddd8aca73d3d7f790b9427f48cc586aa) * Add helper macro for `AddAssign`ing with saturating arithmetic (cherry picked from commit deb9344e49ad1c5e6cdbdf602d6cd1a93771990d) * Use saturating_add_assign macro (cherry picked from commit 72fc6096a0e184095825b35ffd1716975d3e3461) * Consolidate process instruction execution timings to own struct (cherry picked from commit 390ef0fbcd000f5b1cd190913d4b5e3e19dabd56) Co-authored-by: Trent Nelson Co-authored-by: Carl Lin --- Cargo.lock | 2 + core/Cargo.toml | 1 + core/src/banking_stage.rs | 6 +- core/src/cost_update_service.rs | 14 +-- core/src/progress_map.rs | 104 ++++++++++++++++-- core/src/replay_stage.rs | 7 +- ledger/Cargo.toml | 1 + ledger/src/blockstore_processor.rs | 3 +- program-runtime/Cargo.toml | 1 + program-runtime/src/invoke_context.rs | 71 ++++++++++--- program-runtime/src/timings.rs | 146 +++++++++++++++++++++----- program-test/src/lib.rs | 7 +- programs/bpf/Cargo.lock | 1 + programs/bpf/tests/programs.rs | 4 +- programs/bpf_loader/src/lib.rs | 45 +++++++- programs/bpf_loader/src/syscalls.rs | 2 + runtime/src/bank.rs | 80 +++++++------- runtime/src/message_processor.rs | 36 ++++--- sdk/src/lib.rs | 24 +++++ 19 files changed, 439 insertions(+), 116 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index c7153ab761..9eb657f858 100644 --- a/Cargo.lock +++ b/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", ] diff --git a/core/Cargo.toml b/core/Cargo.toml index 447a674a94..1d0272901e 100644 --- a/core/Cargo.toml +++ b/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" } diff --git a/core/src/banking_stage.rs b/core/src/banking_stage.rs index 2fd74d6a8b..2e9ffd9900 100644 --- a/core/src/banking_stage.rs +++ b/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, 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 c21c78869c..55fb0e738d 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::{ @@ -71,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 bea2ceb244..3559c9dc62 100644 --- a/core/src/progress_map.rs +++ b/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 diff --git a/core/src/replay_stage.rs b/core/src/replay_stage.rs index 9222b3a3a5..6b4115dacc 100644 --- a/core/src/replay_stage.rs +++ b/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)); } diff --git a/ledger/Cargo.toml b/ledger/Cargo.toml index f89904a57e..ddae2fd3e3 100644 --- a/ledger/Cargo.toml +++ b/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" } diff --git a/ledger/src/blockstore_processor.rs b/ledger/src/blockstore_processor.rs index e16053d15b..e27d96ef6f 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/Cargo.toml b/program-runtime/Cargo.toml index f35f8fb1e3..48ccddc0a8 100644 --- a/program-runtime/Cargo.toml +++ b/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" diff --git a/program-runtime/src/invoke_context.rs b/program-runtime/src/invoke_context.rs index 7b4247e4c4..3dec99671f 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}, 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 { - self.verify(message, instruction, program_indices) - } else { - let write_privileges: Vec = (0..message.account_keys.len()) - .map(|i| message.is_writable(i)) - .collect(); - self.verify_and_update(instruction, account_indices, &write_privileges) - } + let mut verify_callee_time = Measure::start("verify_callee_time"); + let result = execution_result.and_then(|_| { + if is_lowest_invocation_level { + self.verify(message, instruction, program_indices) + } else { + let write_privileges: Vec = (0..message.account_keys.len()) + .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; diff --git a/program-runtime/src/timings.rs b/program-runtime/src/timings.rs index ec47835dae..40e6dc9753 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,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); - 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); + } +} + +#[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, } 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.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); + 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/program-test/src/lib.rs b/program-test/src/lib.rs index 16338e20ef..ff7be77d44 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, @@ -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)))?; diff --git a/programs/bpf/Cargo.lock b/programs/bpf/Cargo.lock index 35790b0e2b..f2d48d1745 100644 --- a/programs/bpf/Cargo.lock +++ b/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", ] diff --git a/programs/bpf/tests/programs.rs b/programs/bpf/tests/programs.rs index 1b64b2d9f0..2fe1dddfbc 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/programs/bpf_loader/src/lib.rs b/programs/bpf_loader/src/lib.rs index 5bf484151c..20bcacaeff 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}, @@ -85,7 +86,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 +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::::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); } @@ -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, diff --git a/programs/bpf_loader/src/syscalls.rs b/programs/bpf_loader/src/syscalls.rs index ea4db31321..d10ee05646 100644 --- a/programs/bpf_loader/src/syscalls.rs +++ b/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)?; diff --git a/runtime/src/bank.rs b/runtime/src/bank.rs index 8f59afca13..4acd9d863f 100644 --- a/runtime/src/bank.rs +++ b/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>; #[frozen_abi(digest = "6XG6H1FChrDdY39K62KFWj5XfDao4dd24WZgcJkdMu1E")] pub type BankSlotDelta = SlotDelta>; @@ -3607,7 +3577,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() { @@ -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 = 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, ) } diff --git a/runtime/src/message_processor.rs b/runtime/src/message_processor.rs index 8667a7f3cc..44e27a2cf7 100644 --- a/runtime/src/message_processor.rs +++ b/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, compute_budget: ComputeBudget, - timings: &mut ExecuteDetailsTimings, + timings: &mut ExecuteTimings, sysvars: &[(Pubkey, Vec)], 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, diff --git a/sdk/src/lib.rs b/sdk/src/lib.rs index 2df94726a1..a63d2615db 100644 --- a/sdk/src/lib.rs +++ b/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); + } +}