From 5263c9d61f3af060ac995956120bef11c1bbf182 Mon Sep 17 00:00:00 2001 From: Joe C Date: Fri, 7 Jun 2024 15:13:49 -0500 Subject: [PATCH] SVM: Return execute timings from API (#1604) * SVM: add `execute_timings` to API return type * SVM: message processor: rename `timings` to `execute_timings` * SVM: remove `timings` mutable input --- runtime/src/bank.rs | 4 +++- svm/src/message_processor.rs | 13 ++++++++----- svm/src/transaction_processor.rs | 30 +++++++++++++++++++----------- svm/tests/conformance.rs | 2 -- svm/tests/integration_test.rs | 3 --- 5 files changed, 30 insertions(+), 22 deletions(-) diff --git a/runtime/src/bank.rs b/runtime/src/bank.rs index 248719e84ba860..cda1cfeecb2295 100644 --- a/runtime/src/bank.rs +++ b/runtime/src/bank.rs @@ -3703,13 +3703,15 @@ impl Bank { self, sanitized_txs, &mut check_results, - timings, &processing_config, ); // Accumulate the errors returned by the batch processor. error_counters.accumulate(&sanitized_output.error_metrics); + // Accumulate the transaction batch execution timings. + timings.accumulate(&sanitized_output.execute_timings); + let mut signature_count = 0; let mut executed_transactions_count: usize = 0; diff --git a/svm/src/message_processor.rs b/svm/src/message_processor.rs index 7b366e82304975..da9498d59533b8 100644 --- a/svm/src/message_processor.rs +++ b/svm/src/message_processor.rs @@ -37,7 +37,7 @@ impl MessageProcessor { message: &SanitizedMessage, program_indices: &[Vec], invoke_context: &mut InvokeContext, - timings: &mut ExecuteTimings, + execute_timings: &mut ExecuteTimings, accumulated_consumed_units: &mut u64, ) -> Result<(), TransactionError> { debug_assert_eq!(program_indices.len(), message.instructions().len()); @@ -112,23 +112,26 @@ impl MessageProcessor { &instruction_accounts, program_indices, &mut compute_units_consumed, - timings, + execute_timings, ); let time = time.end_as_us(); *accumulated_consumed_units = accumulated_consumed_units.saturating_add(compute_units_consumed); - timings.details.accumulate_program( + execute_timings.details.accumulate_program( program_id, time, compute_units_consumed, result.is_err(), ); invoke_context.timings = { - timings.details.accumulate(&invoke_context.timings); + execute_timings.details.accumulate(&invoke_context.timings); ExecuteDetailsTimings::default() }; saturating_add_assign!( - timings.execute_accessories.process_instructions.total_us, + execute_timings + .execute_accessories + .process_instructions + .total_us, time ); result diff --git a/svm/src/transaction_processor.rs b/svm/src/transaction_processor.rs index e7da3efce95602..d9d1182dd55899 100644 --- a/svm/src/transaction_processor.rs +++ b/svm/src/transaction_processor.rs @@ -62,6 +62,8 @@ pub type TransactionLogMessages = Vec; pub struct LoadAndExecuteSanitizedTransactionsOutput { /// Error metrics for transactions that were processed. pub error_metrics: TransactionErrorMetrics, + /// Timings for transaction batch execution. + pub execute_timings: ExecuteTimings, // Vector of results indicating whether a transaction was executed or could not // be executed. Note executed transactions can still have failed! pub execution_results: Vec, @@ -210,11 +212,11 @@ impl TransactionBatchProcessor { callbacks: &CB, sanitized_txs: &[SanitizedTransaction], check_results: &mut [TransactionCheckResult], - timings: &mut ExecuteTimings, config: &TransactionProcessingConfig, ) -> LoadAndExecuteSanitizedTransactionsOutput { // Initialize metrics. let mut error_metrics = TransactionErrorMetrics::default(); + let mut execute_timings = ExecuteTimings::default(); let mut program_cache_time = Measure::start("program_cache"); let mut program_accounts_map = Self::filter_executable_program_accounts( @@ -240,6 +242,7 @@ impl TransactionBatchProcessor { vec![TransactionExecutionResult::NotExecuted(ERROR); sanitized_txs.len()]; return LoadAndExecuteSanitizedTransactionsOutput { error_metrics, + execute_timings, execution_results, loaded_transactions, }; @@ -277,7 +280,7 @@ impl TransactionBatchProcessor { ); compute_budget_process_transaction_time.stop(); saturating_add_assign!( - timings + execute_timings .execute_accessories .compute_budget_process_transaction_us, compute_budget_process_transaction_time.as_us() @@ -293,7 +296,7 @@ impl TransactionBatchProcessor { tx, loaded_transaction, compute_budget, - timings, + &mut execute_timings, &mut error_metrics, &program_cache_for_tx_batch.borrow(), config, @@ -344,15 +347,17 @@ impl TransactionBatchProcessor { sanitized_txs.len(), ); - timings.saturating_add_in_place( + execute_timings.saturating_add_in_place( ExecuteTimingType::ProgramCacheUs, program_cache_time.as_us(), ); - timings.saturating_add_in_place(ExecuteTimingType::LoadUs, load_time.as_us()); - timings.saturating_add_in_place(ExecuteTimingType::ExecuteUs, execution_time.as_us()); + execute_timings.saturating_add_in_place(ExecuteTimingType::LoadUs, load_time.as_us()); + execute_timings + .saturating_add_in_place(ExecuteTimingType::ExecuteUs, execution_time.as_us()); LoadAndExecuteSanitizedTransactionsOutput { error_metrics, + execute_timings, execution_results, loaded_transactions, } @@ -561,7 +566,7 @@ impl TransactionBatchProcessor { tx: &SanitizedTransaction, loaded_transaction: &mut LoadedTransaction, compute_budget: ComputeBudget, - timings: &mut ExecuteTimings, + execute_timings: &mut ExecuteTimings, error_metrics: &mut TransactionErrorMetrics, program_cache_for_tx_batch: &ProgramCacheForTxBatch, config: &TransactionProcessingConfig, @@ -640,7 +645,7 @@ impl TransactionBatchProcessor { tx.message(), &loaded_transaction.program_indices, &mut invoke_context, - timings, + execute_timings, &mut executed_units, ); process_message_time.stop(); @@ -648,7 +653,7 @@ impl TransactionBatchProcessor { drop(invoke_context); saturating_add_assign!( - timings.execute_accessories.process_message_us, + execute_timings.execute_accessories.process_message_us, process_message_time.as_us() ); @@ -715,10 +720,13 @@ impl TransactionBatchProcessor { loaded_transaction.accounts = accounts; saturating_add_assign!( - timings.details.total_account_count, + execute_timings.details.total_account_count, loaded_transaction.accounts.len() as u64 ); - saturating_add_assign!(timings.details.changed_account_count, touched_account_count); + saturating_add_assign!( + execute_timings.details.changed_account_count, + touched_account_count + ); let return_data = if config.recording_config.enable_return_data_recording && !return_data.data.is_empty() diff --git a/svm/tests/conformance.rs b/svm/tests/conformance.rs index fe11f99c8ef4ab..7245684c4b7222 100644 --- a/svm/tests/conformance.rs +++ b/svm/tests/conformance.rs @@ -295,7 +295,6 @@ fn run_fixture(fixture: InstrFixture, filename: OsString, execute_as_instr: bool limit_to_load_programs: true, recording_config, }; - let mut timings = ExecuteTimings::default(); if execute_as_instr { execute_fixture_as_instr( @@ -314,7 +313,6 @@ fn run_fixture(fixture: InstrFixture, filename: OsString, execute_as_instr: bool &mock_bank, &transactions, transaction_check.as_mut_slice(), - &mut timings, &processor_config, ); diff --git a/svm/tests/integration_test.rs b/svm/tests/integration_test.rs index 10bc1ce5bfccef..fb738a2dd0ff2f 100644 --- a/svm/tests/integration_test.rs +++ b/svm/tests/integration_test.rs @@ -16,7 +16,6 @@ use { program::{BuiltinFunction, BuiltinProgram, FunctionRegistry}, vm::Config, }, - timings::ExecuteTimings, }, solana_sdk::{ account::{AccountSharedData, ReadableAccount, WritableAccount}, @@ -468,13 +467,11 @@ fn svm_integration() { }, ..Default::default() }; - let mut timings = ExecuteTimings::default(); let result = batch_processor.load_and_execute_sanitized_transactions( &mock_bank, &transactions, check_results.as_mut_slice(), - &mut timings, &processing_config, );