From b6bc5d2fa145dbc39706c7f2dc26354a233d5e92 Mon Sep 17 00:00:00 2001 From: Justin Starry Date: Thu, 21 Apr 2022 00:20:29 +0800 Subject: [PATCH] Aggregate executor update timing metrics --- ledger/src/blockstore_processor.rs | 14 ++-- program-runtime/src/invoke_context.rs | 1 + programs/bpf/tests/programs.rs | 2 +- rpc/src/transaction_status_service.rs | 39 +++++------ runtime/src/accounts.rs | 24 ++++--- runtime/src/bank.rs | 96 ++++++++++++++++----------- 6 files changed, 101 insertions(+), 75 deletions(-) diff --git a/ledger/src/blockstore_processor.rs b/ledger/src/blockstore_processor.rs index 1160c6e1c..ea22886aa 100644 --- a/ledger/src/blockstore_processor.rs +++ b/ledger/src/blockstore_processor.rs @@ -22,8 +22,8 @@ use { accounts_index::AccountSecondaryIndexes, accounts_update_notifier_interface::AccountsUpdateNotifier, bank::{ - Bank, RentDebits, TransactionBalancesSet, TransactionExecutionResult, - TransactionResults, + Bank, RentDebits, TransactionBalancesSet, TransactionExecutionDetails, + TransactionExecutionResult, TransactionResults, }, bank_forks::BankForks, bank_utils, @@ -1409,7 +1409,7 @@ pub enum TransactionStatusMessage { pub struct TransactionStatusBatch { pub bank: Arc, pub transactions: Vec, - pub execution_results: Vec, + pub execution_results: Vec>, pub balances: TransactionBalancesSet, pub token_balances: TransactionTokenBalancesSet, pub rent_debits: Vec, @@ -1437,7 +1437,13 @@ impl TransactionStatusSender { .send(TransactionStatusMessage::Batch(TransactionStatusBatch { bank, transactions, - execution_results, + execution_results: execution_results + .into_iter() + .map(|result| match result { + TransactionExecutionResult::Executed { details, .. } => Some(details), + TransactionExecutionResult::NotExecuted(_) => None, + }) + .collect(), balances, token_balances, rent_debits, diff --git a/program-runtime/src/invoke_context.rs b/program-runtime/src/invoke_context.rs index 9cfb3605b..44debd277 100644 --- a/program-runtime/src/invoke_context.rs +++ b/program-runtime/src/invoke_context.rs @@ -78,6 +78,7 @@ pub type Executors = HashMap; /// Tracks whether a given executor is "dirty" and needs to updated in the /// executors cache +#[derive(Debug)] pub struct TransactionExecutor { executor: Arc, is_miss: bool, diff --git a/programs/bpf/tests/programs.rs b/programs/bpf/tests/programs.rs index 756e29071..98b66f194 100644 --- a/programs/bpf/tests/programs.rs +++ b/programs/bpf/tests/programs.rs @@ -387,7 +387,7 @@ fn execute_transactions( post_token_balances, )| { match execution_result { - TransactionExecutionResult::Executed(details) => { + TransactionExecutionResult::Executed { details, .. } => { let TransactionExecutionDetails { status, log_messages, diff --git a/rpc/src/transaction_status_service.rs b/rpc/src/transaction_status_service.rs index 8599e63eb..35b0fed00 100644 --- a/rpc/src/transaction_status_service.rs +++ b/rpc/src/transaction_status_service.rs @@ -6,9 +6,7 @@ use { blockstore::Blockstore, blockstore_processor::{TransactionStatusBatch, TransactionStatusMessage}, }, - solana_runtime::bank::{ - DurableNonceFee, TransactionExecutionDetails, TransactionExecutionResult, - }, + solana_runtime::bank::{DurableNonceFee, TransactionExecutionDetails}, solana_transaction_status::{ extract_and_fmt_memos, InnerInstructions, Reward, TransactionStatusMeta, }, @@ -95,7 +93,7 @@ impl TransactionStatusService { token_balances.post_token_balances, rent_debits, ) { - if let TransactionExecutionResult::Executed(details) = execution_result { + if let Some(details) = execution_result { let TransactionExecutionDetails { status, log_messages, @@ -338,23 +336,22 @@ pub(crate) mod tests { let mut rent_debits = RentDebits::default(); rent_debits.insert(&pubkey, 123, 456); - let transaction_result = - TransactionExecutionResult::Executed(TransactionExecutionDetails { - status: Ok(()), - log_messages: None, - inner_instructions: None, - durable_nonce_fee: Some(DurableNonceFee::from( - &NonceFull::from_partial( - rollback_partial, - &SanitizedMessage::Legacy(message), - &[(pubkey, nonce_account)], - &rent_debits, - ) - .unwrap(), - )), - return_data: None, - executed_units: 0u64, - }); + let transaction_result = Some(TransactionExecutionDetails { + status: Ok(()), + log_messages: None, + inner_instructions: None, + durable_nonce_fee: Some(DurableNonceFee::from( + &NonceFull::from_partial( + rollback_partial, + &SanitizedMessage::Legacy(message), + &[(pubkey, nonce_account)], + &rent_debits, + ) + .unwrap(), + )), + return_data: None, + executed_units: 0u64, + }); let balances = TransactionBalancesSet { pre_balances: vec![vec![123456]], diff --git a/runtime/src/accounts.rs b/runtime/src/accounts.rs index 81b1b5e39..0248739f1 100644 --- a/runtime/src/accounts.rs +++ b/runtime/src/accounts.rs @@ -1203,7 +1203,7 @@ impl Accounts { } let execution_status = match &execution_results[i] { - TransactionExecutionResult::Executed(details) => &details.status, + TransactionExecutionResult::Executed { details, .. } => &details.status, // Don't store any accounts if tx wasn't executed TransactionExecutionResult::NotExecuted(_) => continue, }; @@ -1366,6 +1366,7 @@ mod tests { rent_collector::RentCollector, }, solana_address_lookup_table_program::state::LookupTableMeta, + solana_program_runtime::invoke_context::Executors, solana_sdk::{ account::{AccountSharedData, WritableAccount}, epoch_schedule::EpochSchedule, @@ -1381,7 +1382,9 @@ mod tests { }, std::{ borrow::Cow, + cell::RefCell, convert::TryFrom, + rc::Rc, sync::atomic::{AtomicBool, AtomicU64, Ordering}, thread, time, }, @@ -1403,14 +1406,17 @@ mod tests { status: Result<()>, nonce: Option<&NonceFull>, ) -> TransactionExecutionResult { - TransactionExecutionResult::Executed(TransactionExecutionDetails { - status, - log_messages: None, - inner_instructions: None, - durable_nonce_fee: nonce.map(DurableNonceFee::from), - return_data: None, - executed_units: 0u64, - }) + TransactionExecutionResult::Executed { + details: TransactionExecutionDetails { + status, + log_messages: None, + inner_instructions: None, + durable_nonce_fee: nonce.map(DurableNonceFee::from), + return_data: None, + executed_units: 0u64, + }, + executors: Rc::new(RefCell::new(Executors::default())), + } } fn load_accounts_with_fee_and_rent( diff --git a/runtime/src/bank.rs b/runtime/src/bank.rs index e2001aa3f..533353d46 100644 --- a/runtime/src/bank.rs +++ b/runtime/src/bank.rs @@ -618,35 +618,38 @@ pub struct TransactionExecutionDetails { /// make such checks hard to do incorrectly. #[derive(Debug, Clone)] pub enum TransactionExecutionResult { - Executed(TransactionExecutionDetails), + Executed { + details: TransactionExecutionDetails, + executors: Rc>, + }, NotExecuted(TransactionError), } impl TransactionExecutionResult { pub fn was_executed_successfully(&self) -> bool { match self { - Self::Executed(details) => details.status.is_ok(), + Self::Executed { details, .. } => details.status.is_ok(), Self::NotExecuted { .. } => false, } } pub fn was_executed(&self) -> bool { match self { - Self::Executed(_) => true, + Self::Executed { .. } => true, Self::NotExecuted(_) => false, } } pub fn details(&self) -> Option<&TransactionExecutionDetails> { match self { - Self::Executed(details) => Some(details), + Self::Executed { details, .. } => Some(details), Self::NotExecuted(_) => None, } } pub fn flattened_result(&self) -> Result<()> { match self { - Self::Executed(details) => details.status.clone(), + Self::Executed { details, .. } => details.status.clone(), Self::NotExecuted(err) => Err(err.clone()), } } @@ -3678,7 +3681,7 @@ impl Bank { let mut status_cache = self.src.status_cache.write().unwrap(); assert_eq!(sanitized_txs.len(), execution_results.len()); for (tx, execution_result) in sanitized_txs.iter().zip(execution_results) { - if let TransactionExecutionResult::Executed(details) = execution_result { + if let Some(details) = execution_result.details() { // Add the message hash to the status cache to ensure that this message // won't be processed again with a different signature. status_cache.insert( @@ -3890,7 +3893,7 @@ impl Bank { let execution_result = execution_results.pop().unwrap(); let flattened_result = execution_result.flattened_result(); let (logs, return_data) = match execution_result { - TransactionExecutionResult::Executed(details) => { + TransactionExecutionResult::Executed { details, .. } => { (details.log_messages, details.return_data) } TransactionExecutionResult::NotExecuted(_) => (None, None), @@ -4185,14 +4188,6 @@ impl Bank { 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 .and_then(|info| { let post_account_state_info = @@ -4254,14 +4249,17 @@ impl Bank { None }; - TransactionExecutionResult::Executed(TransactionExecutionDetails { - status, - log_messages, - inner_instructions, - durable_nonce_fee, - return_data, - executed_units, - }) + TransactionExecutionResult::Executed { + details: TransactionExecutionDetails { + status, + log_messages, + inner_instructions, + durable_nonce_fee, + return_data, + executed_units, + }, + executors, + } } #[allow(clippy::type_complexity)] @@ -4443,11 +4441,11 @@ impl Bank { }; if store { - if let TransactionExecutionResult::Executed(TransactionExecutionDetails { + if let Some(TransactionExecutionDetails { status, log_messages: Some(log_messages), .. - }) = execution_result + }) = execution_result.details() { let mut transaction_log_collector = self.transaction_log_collector.write().unwrap(); @@ -4623,7 +4621,7 @@ impl Bank { .zip(execution_results) .map(|(tx, execution_result)| { let (execution_status, durable_nonce_fee) = match &execution_result { - TransactionExecutionResult::Executed(details) => { + TransactionExecutionResult::Executed { details, .. } => { Ok((&details.status, details.durable_nonce_fee.as_ref())) } TransactionExecutionResult::NotExecuted(err) => Err(err.clone()), @@ -4743,6 +4741,18 @@ impl Bank { sanitized_txs.len() ); + let mut update_executors_time = Measure::start("update_executors_time"); + for execution_result in &execution_results { + if let TransactionExecutionResult::Executed { details, executors } = execution_result { + self.update_executors(details.status.is_ok(), executors.clone()); + } + } + update_executors_time.stop(); + saturating_add_assign!( + timings.execute_accessories.update_executors_us, + update_executors_time.as_us() + ); + timings.saturating_add_in_place(ExecuteTimingType::StoreUs, write_time.as_us()); timings.saturating_add_in_place( ExecuteTimingType::UpdateStakesCacheUs, @@ -7186,14 +7196,17 @@ pub(crate) mod tests { status: Result<()>, nonce: Option<&NonceFull>, ) -> TransactionExecutionResult { - TransactionExecutionResult::Executed(TransactionExecutionDetails { - status, - log_messages: None, - inner_instructions: None, - durable_nonce_fee: nonce.map(DurableNonceFee::from), - return_data: None, - executed_units: 0u64, - }) + TransactionExecutionResult::Executed { + details: TransactionExecutionDetails { + status, + log_messages: None, + inner_instructions: None, + durable_nonce_fee: nonce.map(DurableNonceFee::from), + return_data: None, + executed_units: 0u64, + }, + executors: Rc::new(RefCell::new(Executors::default())), + } } #[test] @@ -12899,13 +12912,16 @@ pub(crate) mod tests { // This is an InstructionError - fees charged assert!(matches!( transaction_results.execution_results[2], - TransactionExecutionResult::Executed(TransactionExecutionDetails { - status: Err(TransactionError::InstructionError( - 0, - InstructionError::Custom(1), - )), + TransactionExecutionResult::Executed { + details: TransactionExecutionDetails { + status: Err(TransactionError::InstructionError( + 0, + InstructionError::Custom(1), + )), + .. + }, .. - }), + }, )); assert_eq!(transaction_balances_set.pre_balances[2], vec![9, 0, 1]); assert_eq!(transaction_balances_set.post_balances[2], vec![8, 0, 1]);