Skip to content

Commit

Permalink
Clean up metrics in Bank::commit_transactions (#2327)
Browse files Browse the repository at this point in the history
  • Loading branch information
@jstarry
jstarry authored Jul 30, 2024
1 parent b0df394 commit 24bd082
Show file tree
Hide file tree
Showing 2 changed files with 46 additions and 75 deletions.
108 changes: 40 additions & 68 deletions runtime/src/bank.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -135,7 +135,6 @@ use {
rent_debits::RentDebits,
reserved_account_keys::ReservedAccountKeys,
reward_info::RewardInfo,
saturating_add_assign,
signature::{Keypair, Signature},
slot_hashes::SlotHashes,
slot_history::{Check, SlotHistory},
Expand Down Expand Up @@ -3594,7 +3593,6 @@ impl Bank {
processing_config: TransactionProcessingConfig,
) -> LoadAndExecuteTransactionsOutput {
let sanitized_txs = batch.sanitized_transactions();
debug!("processing transactions: {}", sanitized_txs.len());
let mut error_counters = TransactionErrorMetrics::default();

let retryable_transaction_indexes: Vec<_> = batch
Expand Down Expand Up @@ -3633,16 +3631,13 @@ impl Bank {
})
.collect();

let mut check_time = Measure::start("check_transactions");
let check_results = self.check_transactions(
let (check_results, check_us) = measure_us!(self.check_transactions(
sanitized_txs,
batch.lock_results(),
max_age,
&mut error_counters,
);
check_time.stop();
debug!("check: {}us", check_time.as_us());
timings.saturating_add_in_place(ExecuteTimingType::CheckUs, check_time.as_us());
));
timings.saturating_add_in_place(ExecuteTimingType::CheckUs, check_us);

let (blockhash, lamports_per_signature) = self.last_blockhash_and_lamports_per_signature();
let processing_environment = TransactionProcessingEnvironment {
Expand Down Expand Up @@ -3680,8 +3675,9 @@ impl Bank {
let transaction_log_collector_config =
self.transaction_log_collector_config.read().unwrap();

let mut collect_logs_time = Measure::start("collect_logs_time");
for (execution_result, tx) in sanitized_output.execution_results.iter().zip(sanitized_txs) {
let ((), collect_logs_us) = measure_us!(for (execution_result, tx) in
sanitized_output.execution_results.iter().zip(sanitized_txs)
{
if let Some(debug_keys) = &self.transaction_debug_keys {
for key in tx.message().account_keys().iter() {
if debug_keys.contains(key) {
Expand Down Expand Up @@ -3774,18 +3770,8 @@ impl Bank {
*err_count += 1;
}
}
}
collect_logs_time.stop();
timings
.saturating_add_in_place(ExecuteTimingType::CollectLogsUs, collect_logs_time.as_us());

if *err_count > 0 {
debug!(
"{} errors of {} txs",
*err_count,
*err_count + executed_with_successful_result_count
);
}
});
timings.saturating_add_in_place(ExecuteTimingType::CollectLogsUs, collect_logs_us);

LoadAndExecuteTransactionsOutput {
execution_results: sanitized_output.execution_results,
Expand Down Expand Up @@ -3949,8 +3935,7 @@ impl Bank {
.fetch_max(executed_transactions_count, Relaxed);
}

let mut write_time = Measure::start("write_time");
{
let ((), store_accounts_us) = measure_us!({
let durable_nonce = DurableNonce::from_blockhash(&last_blockhash);
let (accounts_to_store, transactions) = collect_accounts_to_store(
sanitized_txs,
Expand All @@ -3961,44 +3946,30 @@ impl Bank {
self.rc
.accounts
.store_cached((self.slot(), accounts_to_store.as_slice()), &transactions);
}
});

let rent_debits = self.collect_rent(&mut execution_results);

// Cached vote and stake accounts are synchronized with accounts-db
// after each transaction.
let mut update_stakes_cache_time = Measure::start("update_stakes_cache_time");
self.update_stakes_cache(sanitized_txs, &execution_results);
update_stakes_cache_time.stop();

// once committed there is no way to unroll
write_time.stop();
debug!(
"store: {}us txs_len={}",
write_time.as_us(),
sanitized_txs.len()
);

let mut store_executors_which_were_deployed_time =
Measure::start("store_executors_which_were_deployed_time");
let mut cache = None;
for execution_result in &execution_results {
if let TransactionExecutionResult::Executed(executed_tx) = execution_result {
let programs_modified_by_tx = &executed_tx.programs_modified_by_tx;
if executed_tx.was_successful() && !programs_modified_by_tx.is_empty() {
cache
.get_or_insert_with(|| {
self.transaction_processor.program_cache.write().unwrap()
})
.merge(programs_modified_by_tx);
let ((), update_stakes_cache_us) =
measure_us!(self.update_stakes_cache(sanitized_txs, &execution_results));

let ((), update_executors_us) = measure_us!({
let mut cache = None;
for execution_result in &execution_results {
if let TransactionExecutionResult::Executed(executed_tx) = execution_result {
let programs_modified_by_tx = &executed_tx.programs_modified_by_tx;
if executed_tx.was_successful() && !programs_modified_by_tx.is_empty() {
cache
.get_or_insert_with(|| {
self.transaction_processor.program_cache.write().unwrap()
})
.merge(programs_modified_by_tx);
}
}
}
}
drop(cache);
store_executors_which_were_deployed_time.stop();
saturating_add_assign!(
timings.execute_accessories.update_executors_us,
store_executors_which_were_deployed_time.as_us()
);
});

let accounts_data_len_delta = execution_results
.iter()
Expand All @@ -4012,25 +3983,15 @@ impl Bank {
.sum();
self.update_accounts_data_size_delta_on_chain(accounts_data_len_delta);

timings.saturating_add_in_place(ExecuteTimingType::StoreUs, write_time.as_us());
timings.saturating_add_in_place(
ExecuteTimingType::UpdateStakesCacheUs,
update_stakes_cache_time.as_us(),
);
let ((), update_transaction_statuses_us) =
measure_us!(self.update_transaction_statuses(sanitized_txs, &execution_results));

let mut update_transaction_statuses_time = Measure::start("update_transaction_statuses");
self.update_transaction_statuses(sanitized_txs, &execution_results);
let fee_collection_results = if self.feature_set.is_active(&reward_full_priority_fee::id())
{
self.filter_program_errors_and_collect_fee_details(&execution_results)
} else {
self.filter_program_errors_and_collect_fee(&execution_results)
};
update_transaction_statuses_time.stop();
timings.saturating_add_in_place(
ExecuteTimingType::UpdateTransactionStatuses,
update_transaction_statuses_time.as_us(),
);

let loaded_accounts_stats = Self::collect_loaded_accounts_stats(&execution_results);
assert_eq!(
Expand All @@ -4039,6 +4000,17 @@ impl Bank {
"loaded_account_stats and execution_results are not the same size"
);

timings.saturating_add_in_place(ExecuteTimingType::StoreUs, store_accounts_us);
timings.saturating_add_in_place(
ExecuteTimingType::UpdateStakesCacheUs,
update_stakes_cache_us,
);
timings.saturating_add_in_place(ExecuteTimingType::UpdateExecutorsUs, update_executors_us);
timings.saturating_add_in_place(
ExecuteTimingType::UpdateTransactionStatuses,
update_transaction_statuses_us,
);

TransactionResults {
fee_collection_results,
loaded_accounts_stats,
Expand Down
13 changes: 6 additions & 7 deletions timings/src/lib.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -50,6 +50,7 @@ pub enum ExecuteTimingType {
ExecuteUs,
StoreUs,
UpdateStakesCacheUs,
UpdateExecutorsUs,
NumExecuteBatches,
CollectLogsUs,
TotalBatchesLen,
Expand Down Expand Up @@ -150,6 +151,11 @@ eager_macro_rules! { $eager_1
.index(ExecuteTimingType::UpdateStakesCacheUs),
i64
),
(
"execute_accessories_update_executors_us",
*$self.metrics.index(ExecuteTimingType::UpdateExecutorsUs),
i64
),
(
"total_batches_len",
(if $is_unified_scheduler_enabled {
Expand Down Expand Up @@ -259,11 +265,6 @@ eager_macro_rules! { $eager_1
$self.execute_accessories.process_message_us,
i64
),
(
"execute_accessories_update_executors_us",
$self.execute_accessories.update_executors_us,
i64
),
(
"execute_accessories_process_instructions_total_us",
$self
Expand Down Expand Up @@ -351,7 +352,6 @@ pub struct ExecuteAccessoryTimings {
pub feature_set_clone_us: u64,
pub get_executors_us: u64,
pub process_message_us: u64,
pub update_executors_us: u64,
pub process_instructions: ExecuteProcessInstructionTimings,
}

Expand All @@ -360,7 +360,6 @@ impl ExecuteAccessoryTimings {
saturating_add_assign!(self.feature_set_clone_us, other.feature_set_clone_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);
}
Expand Down

0 comments on commit 24bd082

Please sign in to comment.