From e6c21a3036274ab68b8343f4f2a9da954d160e56 Mon Sep 17 00:00:00 2001 From: apfitzge Date: Mon, 6 Jun 2022 20:21:05 -0500 Subject: [PATCH] Convert Measure::this to measure! and remove Measure::this (#25776) * Remove the args param from Measure::this since we don't ever use it * banking_stage.rs: convert to measure! * poh_recorder.rs: convert to measure! * cost_update_service.rs: convert to measure! * poh_service.rs: convert to measure! * bank.rs: convert to measure! * measure.rs: Remove Measure::this now that all have been converted to measure! --- core/src/banking_stage.rs | 363 ++++++++++++++------------------ core/src/cost_update_service.rs | 7 +- measure/src/measure.rs | 131 ------------ poh/src/poh_recorder.rs | 29 ++- poh/src/poh_service.rs | 4 +- runtime/src/bank.rs | 108 ++++------ 6 files changed, 214 insertions(+), 428 deletions(-) diff --git a/core/src/banking_stage.rs b/core/src/banking_stage.rs index 071c665fb2..a590a933f1 100644 --- a/core/src/banking_stage.rs +++ b/core/src/banking_stage.rs @@ -24,7 +24,7 @@ use { solana_entry::entry::hash_transactions, solana_gossip::{cluster_info::ClusterInfo, contact_info::ContactInfo}, solana_ledger::blockstore_processor::TransactionStatusSender, - solana_measure::measure::Measure, + solana_measure::{measure, measure::Measure}, solana_metrics::inc_new_counter_info, solana_perf::{ data_budget::DataBudget, @@ -626,9 +626,8 @@ impl BankingStage { let packets_to_process = packets_to_process.into_iter().collect_vec(); // TODO: Right now we iterate through buffer and try the highest weighted transaction once // but we should retry the highest weighted transactions more often. - let (bank_start, poh_recorder_lock_time) = Measure::this( - |_| poh_recorder.lock().unwrap().bank_start(), - (), + let (bank_start, poh_recorder_lock_time) = measure!( + poh_recorder.lock().unwrap().bank_start(), "poh_recorder_lock", ); slot_metrics_tracker.increment_consume_buffered_packets_poh_recorder_lock_us( @@ -642,8 +641,7 @@ impl BankingStage { }) = bank_start { let (process_transactions_summary, process_packets_transactions_time) = - Measure::this( - |_| { + measure!( Self::process_packets_transactions( &working_bank, &bank_creation_time, @@ -654,9 +652,7 @@ impl BankingStage { banking_stage_stats, qos_service, slot_metrics_tracker, - ) - }, - (), + ), "process_packets_transactions", ); slot_metrics_tracker.increment_process_packets_transactions_us( @@ -676,11 +672,8 @@ impl BankingStage { ) { let poh_recorder_lock_time = { - let (poh_recorder_locked, poh_recorder_lock_time) = Measure::this( - |_| poh_recorder.lock().unwrap(), - (), - "poh_recorder_lock", - ); + let (poh_recorder_locked, poh_recorder_lock_time) = + measure!(poh_recorder.lock().unwrap(), "poh_recorder_lock"); reached_end_of_slot = Some(EndOfSlot { next_slot_leader: poh_recorder_locked.next_slot_leader(), @@ -744,11 +737,8 @@ impl BankingStage { // mark as end-of-slot to avoid aggressively lock poh for the remaining for // packet batches in buffer let poh_recorder_lock_time = { - let (poh_recorder_locked, poh_recorder_lock_time) = Measure::this( - |_| poh_recorder.lock().unwrap(), - (), - "poh_recorder_lock", - ); + let (poh_recorder_locked, poh_recorder_lock_time) = + measure!(poh_recorder.lock().unwrap(), "poh_recorder_lock"); reached_end_of_slot = Some(EndOfSlot { next_slot_leader: poh_recorder_locked.next_slot_leader(), @@ -883,8 +873,8 @@ impl BankingStage { qos_service: &QosService, slot_metrics_tracker: &mut LeaderSlotMetricsTracker, ) { - let (decision, make_decision_time) = Measure::this( - |_| { + let (decision, make_decision_time) = measure!( + { let bank_start; let ( leader_at_slot_offset, @@ -913,70 +903,60 @@ impl BankingStage { would_be_leader_shortly, ) }, - (), "make_decision", ); slot_metrics_tracker.increment_make_decision_us(make_decision_time.as_us()); match decision { BufferedPacketsDecision::Consume(max_tx_ingestion_ns) => { - let (_, consume_buffered_packets_time) = Measure::this( - |_| { - Self::consume_buffered_packets( - my_pubkey, - max_tx_ingestion_ns, - poh_recorder, - buffered_packet_batches, - transaction_status_sender, - gossip_vote_sender, - None::>, - banking_stage_stats, - recorder, - qos_service, - slot_metrics_tracker, - UNPROCESSED_BUFFER_STEP_SIZE, - ) - }, - (), + let (_, consume_buffered_packets_time) = measure!( + Self::consume_buffered_packets( + my_pubkey, + max_tx_ingestion_ns, + poh_recorder, + buffered_packet_batches, + transaction_status_sender, + gossip_vote_sender, + None::>, + banking_stage_stats, + recorder, + qos_service, + slot_metrics_tracker, + UNPROCESSED_BUFFER_STEP_SIZE, + ), "consume_buffered_packets", ); slot_metrics_tracker .increment_consume_buffered_packets_us(consume_buffered_packets_time.as_us()); } BufferedPacketsDecision::Forward => { - let (_, forward_time) = Measure::this( - |_| { - Self::handle_forwarding( - forward_option, - cluster_info, - buffered_packet_batches, - poh_recorder, - false, - data_budget, - slot_metrics_tracker, - banking_stage_stats, - ) - }, - (), + let (_, forward_time) = measure!( + Self::handle_forwarding( + forward_option, + cluster_info, + buffered_packet_batches, + poh_recorder, + false, + data_budget, + slot_metrics_tracker, + banking_stage_stats, + ), "forward", ); slot_metrics_tracker.increment_forward_us(forward_time.as_us()); } BufferedPacketsDecision::ForwardAndHold => { - let (_, forward_and_hold_time) = Measure::this( - |_| { - Self::handle_forwarding( - forward_option, - cluster_info, - buffered_packet_batches, - poh_recorder, - true, - data_budget, - slot_metrics_tracker, - banking_stage_stats, - ) - }, - (), + let (_, forward_and_hold_time) = measure!( + Self::handle_forwarding( + forward_option, + cluster_info, + buffered_packet_batches, + poh_recorder, + true, + data_budget, + slot_metrics_tracker, + banking_stage_stats, + ), "forward_and_hold", ); slot_metrics_tracker.increment_forward_and_hold_us(forward_and_hold_time.as_us()); @@ -1064,24 +1044,21 @@ impl BankingStage { loop { let my_pubkey = cluster_info.id(); if !buffered_packet_batches.is_empty() { - let (_, process_buffered_packets_time) = Measure::this( - |_| { - Self::process_buffered_packets( - &my_pubkey, - poh_recorder, - cluster_info, - &mut buffered_packet_batches, - &forward_option, - transaction_status_sender.clone(), - &gossip_vote_sender, - &banking_stage_stats, - &recorder, - data_budget, - &qos_service, - &mut slot_metrics_tracker, - ) - }, - (), + let (_, process_buffered_packets_time) = measure!( + Self::process_buffered_packets( + &my_pubkey, + poh_recorder, + cluster_info, + &mut buffered_packet_batches, + &forward_option, + transaction_status_sender.clone(), + &gossip_vote_sender, + &banking_stage_stats, + &recorder, + data_budget, + &qos_service, + &mut slot_metrics_tracker, + ), "process_buffered_packets", ); slot_metrics_tracker @@ -1089,15 +1066,14 @@ impl BankingStage { } if last_metrics_update.elapsed() >= SLOT_BOUNDARY_CHECK_PERIOD { - let (_, slot_metrics_checker_check_slot_boundary_time) = Measure::this( - |_| { + let (_, slot_metrics_checker_check_slot_boundary_time) = measure!( + { let current_poh_bank = { let poh = poh_recorder.lock().unwrap(); poh.bank_start() }; slot_metrics_tracker.update_on_leader_slot_boundary(¤t_poh_bank); }, - (), "slot_metrics_checker_check_slot_boundary", ); slot_metrics_tracker.increment_slot_metrics_check_slot_boundary_us( @@ -1118,19 +1094,16 @@ impl BankingStage { Duration::from_millis(100) }; - let (res, receive_and_buffer_packets_time) = Measure::this( - |_| { - Self::receive_and_buffer_packets( - verified_receiver, - recv_start, - recv_timeout, - id, - &mut buffered_packet_batches, - &mut banking_stage_stats, - &mut slot_metrics_tracker, - ) - }, - (), + let (res, receive_and_buffer_packets_time) = measure!( + Self::receive_and_buffer_packets( + verified_receiver, + recv_start, + recv_timeout, + id, + &mut buffered_packet_batches, + &mut banking_stage_stats, + &mut slot_metrics_tracker, + ), "receive_and_buffer_packets", ); slot_metrics_tracker @@ -1166,14 +1139,11 @@ impl BankingStage { inc_new_counter_info!("banking_stage-record_count", 1); inc_new_counter_info!("banking_stage-record_transactions", num_to_record); - let (hash, hash_time) = Measure::this(|_| hash_transactions(&transactions), (), "hash"); + let (hash, hash_time) = measure!(hash_transactions(&transactions), "hash"); record_transactions_timings.hash_us = hash_time.as_us(); - let (res, poh_record_time) = Measure::this( - |_| recorder.record(bank_slot, hash, transactions), - (), - "hash", - ); + let (res, poh_record_time) = + measure!(recorder.record(bank_slot, hash, transactions), "hash"); record_transactions_timings.poh_record_us = poh_record_time.as_us(); match res { @@ -1209,8 +1179,8 @@ impl BankingStage { let mut execute_and_commit_timings = LeaderExecuteAndCommitTimings::default(); let mut mint_decimals: HashMap = HashMap::new(); - let ((pre_balances, pre_token_balances), collect_balances_time) = Measure::this( - |_| { + let ((pre_balances, pre_token_balances), collect_balances_time) = measure!( + { // Use a shorter maximum age when adding transactions into the pipeline. This will reduce // the likelihood of any single thread getting starved and processing old ids. // TODO: Banking stage threads should be prioritized to complete faster then this queue @@ -1229,24 +1199,20 @@ impl BankingStage { (pre_balances, pre_token_balances) }, - (), "collect_balances", ); execute_and_commit_timings.collect_balances_us = collect_balances_time.as_us(); - let (load_and_execute_transactions_output, load_execute_time) = Measure::this( - |_| { - bank.load_and_execute_transactions( - batch, - MAX_PROCESSING_AGE, - transaction_status_sender.is_some(), - transaction_status_sender.is_some(), - transaction_status_sender.is_some(), - &mut execute_and_commit_timings.execute_timings, - None, // account_overrides - ) - }, - (), + let (load_and_execute_transactions_output, load_execute_time) = measure!( + bank.load_and_execute_transactions( + batch, + MAX_PROCESSING_AGE, + transaction_status_sender.is_some(), + transaction_status_sender.is_some(), + transaction_status_sender.is_some(), + &mut execute_and_commit_timings.execute_timings, + None, // account_overrides + ), "load_execute", ); execute_and_commit_timings.load_execute_us = load_execute_time.as_us(); @@ -1263,34 +1229,28 @@ impl BankingStage { } = load_and_execute_transactions_output; let transactions_attempted_execution_count = execution_results.len(); - let (executed_transactions, execution_results_to_transactions_time): (Vec<_>, Measure) = - Measure::this( - |_| { - execution_results - .iter() - .zip(batch.sanitized_transactions()) - .filter_map(|(execution_result, tx)| { - if execution_result.was_executed() { - Some(tx.to_versioned_transaction()) - } else { - None - } - }) - .collect() - }, - (), - "execution_results_to_transactions", - ); + let (executed_transactions, execution_results_to_transactions_time): (Vec<_>, Measure) = measure!( + execution_results + .iter() + .zip(batch.sanitized_transactions()) + .filter_map(|(execution_result, tx)| { + if execution_result.was_executed() { + Some(tx.to_versioned_transaction()) + } else { + None + } + }) + .collect(), + "execution_results_to_transactions", + ); let (last_blockhash, lamports_per_signature) = bank.last_blockhash_and_lamports_per_signature(); - let (freeze_lock, freeze_lock_time) = - Measure::this(|_| bank.freeze_lock(), (), "freeze_lock"); + let (freeze_lock, freeze_lock_time) = measure!(bank.freeze_lock(), "freeze_lock"); execute_and_commit_timings.freeze_lock_us = freeze_lock_time.as_us(); - let (record_transactions_summary, record_time) = Measure::this( - |_| Self::record_transactions(bank.slot(), executed_transactions, poh), - (), + let (record_transactions_summary, record_time) = measure!( + Self::record_transactions(bank.slot(), executed_transactions, poh), "record_transactions", ); execute_and_commit_timings.record_us = record_time.as_us(); @@ -1332,25 +1292,22 @@ impl BankingStage { executed_transactions_count ); - let (tx_results, commit_time) = Measure::this( - |_| { - bank.commit_transactions( - sanitized_txs, - &mut loaded_transactions, - execution_results, - last_blockhash, - lamports_per_signature, - CommitTransactionCounts { - committed_transactions_count: executed_transactions_count as u64, - committed_with_failure_result_count: executed_transactions_count - .saturating_sub(executed_with_successful_result_count) - as u64, - signature_count, - }, - &mut execute_and_commit_timings.execute_timings, - ) - }, - (), + let (tx_results, commit_time) = measure!( + bank.commit_transactions( + sanitized_txs, + &mut loaded_transactions, + execution_results, + last_blockhash, + lamports_per_signature, + CommitTransactionCounts { + committed_transactions_count: executed_transactions_count as u64, + committed_with_failure_result_count: executed_transactions_count + .saturating_sub(executed_with_successful_result_count) + as u64, + signature_count, + }, + &mut execute_and_commit_timings.execute_timings, + ), "commit", ); let commit_time_us = commit_time.as_us(); @@ -1367,8 +1324,8 @@ impl BankingStage { }) .collect(); - let (_, find_and_send_votes_time) = Measure::this( - |_| { + let (_, find_and_send_votes_time) = measure!( + { bank_utils::find_and_send_votes( sanitized_txs, &tx_results, @@ -1392,7 +1349,6 @@ impl BankingStage { ); } }, - (), "find_and_send_votes", ); execute_and_commit_timings.find_and_send_votes_us = find_and_send_votes_time.as_us(); @@ -1881,22 +1837,19 @@ impl BankingStage { let ((transactions, transaction_to_packet_indexes), packet_conversion_time): ( (Vec, Vec), _, - ) = Measure::this( - |_| { - deserialized_packets - .enumerate() - .filter_map(|(i, deserialized_packet)| { - Self::transaction_from_deserialized_packet( - deserialized_packet, - &bank.feature_set, - bank.vote_only_bank(), - bank.as_ref(), - ) - .map(|transaction| (transaction, i)) - }) - .unzip() - }, - (), + ) = measure!( + deserialized_packets + .enumerate() + .filter_map(|(i, deserialized_packet)| { + Self::transaction_from_deserialized_packet( + deserialized_packet, + &bank.feature_set, + bank.vote_only_bank(), + bank.as_ref(), + ) + .map(|transaction| (transaction, i)) + }) + .unzip(), "packet_conversion", ); @@ -1908,19 +1861,16 @@ impl BankingStage { inc_new_counter_info!("banking_stage-packet_conversion", 1); // Process transactions - let (mut process_transactions_summary, process_transactions_time) = Measure::this( - |_| { - Self::process_transactions( - bank, - bank_creation_time, - &transactions, - poh, - transaction_status_sender, - gossip_vote_sender, - qos_service, - ) - }, - (), + let (mut process_transactions_summary, process_transactions_time) = measure!( + Self::process_transactions( + bank, + bank_creation_time, + &transactions, + poh, + transaction_status_sender, + gossip_vote_sender, + qos_service, + ), "process_transaction_time", ); let process_transactions_us = process_transactions_time.as_us(); @@ -1942,16 +1892,13 @@ impl BankingStage { inc_new_counter_info!("banking_stage-unprocessed_transactions", retryable_tx_count); // Filter out the retryable transactions that are too old - let (filtered_retryable_transaction_indexes, filter_retryable_packets_time) = Measure::this( - |_| { - Self::filter_pending_packets_from_pending_txs( - bank, - &transactions, - &transaction_to_packet_indexes, - retryable_transaction_indexes, - ) - }, - (), + let (filtered_retryable_transaction_indexes, filter_retryable_packets_time) = measure!( + Self::filter_pending_packets_from_pending_txs( + bank, + &transactions, + &transaction_to_packet_indexes, + retryable_transaction_indexes, + ), "filter_pending_packets_time", ); let filter_retryable_packets_us = filter_retryable_packets_time.as_us(); diff --git a/core/src/cost_update_service.rs b/core/src/cost_update_service.rs index 3b39eaac70..cf1a55365f 100644 --- a/core/src/cost_update_service.rs +++ b/core/src/cost_update_service.rs @@ -6,7 +6,7 @@ use { crossbeam_channel::Receiver, solana_ledger::blockstore::Blockstore, - solana_measure::measure::Measure, + solana_measure::measure, solana_program_runtime::timings::ExecuteTimings, solana_runtime::{bank::Bank, cost_model::CostModel}, solana_sdk::timing::timestamp, @@ -102,9 +102,8 @@ impl CostUpdateService { CostUpdate::ExecuteTiming { mut execute_timings, } => { - let (update_count, update_cost_model_time) = Measure::this( - |_| Self::update_cost_model(&cost_model, &mut execute_timings), - (), + let (update_count, update_cost_model_time) = measure!( + Self::update_cost_model(&cost_model, &mut execute_timings), "update_cost_model_time", ); cost_update_service_timing.update(update_count, update_cost_model_time.as_us()); diff --git a/measure/src/measure.rs b/measure/src/measure.rs index 4e92da4826..e401e8a9fc 100644 --- a/measure/src/measure.rs +++ b/measure/src/measure.rs @@ -38,50 +38,6 @@ impl Measure { pub fn as_s(&self) -> f32 { self.duration as f32 / (1000.0f32 * 1000.0f32 * 1000.0f32) } - - /// Measure this function - /// - /// Use `Measure::this()` when you have a function that you want to measure. `this()` will - /// start a new `Measure`, call your function, stop the measure, then return the `Measure` - /// object along with your function's return value. - /// - /// If your function takes more than one parameter, you will need to wrap your function in a - /// closure, and wrap the arguments in a tuple. The same thing applies to methods. See the - /// tests for more details. - /// - /// # Examples - /// - /// ``` - /// // Call a function with a single argument - /// # use solana_measure::measure::Measure; - /// # fn my_function(fizz: i32) -> i32 { fizz } - /// let (result, measure) = Measure::this(my_function, 42, "my_func"); - /// # assert_eq!(result, 42); - /// ``` - /// - /// ``` - /// // Call a function with multiple arguments - /// # use solana_measure::measure::Measure; - /// let (result, measure) = Measure::this(|(arg1, arg2)| std::cmp::min(arg1, arg2), (42, 123), "minimum"); - /// # assert_eq!(result, 42); - /// ``` - /// - /// ``` - /// // Call a method - /// # use solana_measure::measure::Measure; - /// # struct Foo { x: i32 } - /// # impl Foo { fn bar(&self, arg: i32) -> i32 { self.x + arg } } - /// # let baz = 8; - /// let foo = Foo { x: 42 }; - /// let (result, measure) = Measure::this(|(this, args)| Foo::bar(&this, args), (&foo, baz), "Foo::bar"); - /// # assert_eq!(result, 50); - /// ``` - pub fn this R>(func: F, args: T, name: &'static str) -> (R, Self) { - let mut measure = Self::start(name); - let result = func(args); - measure.stop(); - (result, measure) - } } impl fmt::Display for Measure { @@ -150,91 +106,4 @@ mod tests { let measure = Measure::start("test_not_stopped"); assert_eq!(format!("{}", measure), "test_not_stopped running"); } - - fn my_multiply(x: i32, y: i32) -> i32 { - x * y - } - - fn my_multiply_tuple(args: (i32, i32)) -> i32 { - let (x, y) = args; - my_multiply(x, y) - } - - fn square(x: i32) -> i32 { - my_multiply(x, x) - } - - struct SomeStruct { - x: i32, - } - impl SomeStruct { - fn add_to(&self, x: i32) -> i32 { - x + self.x - } - } - - #[test] - fn test_measure_this() { - // Ensure that the measurement side actually works - { - let (_result, measure) = Measure::this(|s| sleep(Duration::from_secs(s)), 1, "test"); - assert!(measure.as_s() >= 0.99f32 && measure.as_s() <= 1.01f32); - assert!(measure.as_ms() >= 990 && measure.as_ms() <= 1_010); - assert!(measure.as_us() >= 999_000 && measure.as_us() <= 1_010_000); - } - - // Ensure that this() can be called with a simple closure - { - let expected = 1; - let (actual, _measure) = Measure::this(|x| x, expected, "test"); - assert_eq!(actual, expected); - } - - // Ensure that this() can be called with a tuple - { - let (result, _measure) = Measure::this(|(x, y)| x + y, (1, 2), "test"); - assert_eq!(result, 1 + 2); - } - - // Ensure that this() can be called with a normal function - { - let (result, _measure) = Measure::this(|(x, y)| my_multiply(x, y), (3, 4), "test"); - assert_eq!(result, 3 * 4); - } - - // Ensure that this() can be called with a normal function with one argument - { - let (result, _measure) = Measure::this(square, 5, "test"); - assert_eq!(result, 5 * 5) - } - - // Ensure that this() can be called with a normal function - { - let (result, _measure) = Measure::this(my_multiply_tuple, (3, 4), "test"); - assert_eq!(result, 3 * 4); - } - - // Ensure that this() can be called with a method (and self) - { - let some_struct = SomeStruct { x: 42 }; - let (result, _measure) = Measure::this( - |(obj, x)| SomeStruct::add_to(&obj, x), - (some_struct, 4), - "test", - ); - assert_eq!(result, 42 + 4); - } - - // Ensure that this() can be called with a method (and &self) - { - let some_struct = SomeStruct { x: 42 }; - let (result, _measure) = Measure::this( - |(obj, x)| SomeStruct::add_to(obj, x), - (&some_struct, 4), - "test", - ); - assert_eq!(result, 42 + 4); - assert_eq!(some_struct.add_to(6), 42 + 6); - } - } } diff --git a/poh/src/poh_recorder.rs b/poh/src/poh_recorder.rs index 9f295e7e3f..df2112b6ad 100644 --- a/poh/src/poh_recorder.rs +++ b/poh/src/poh_recorder.rs @@ -21,7 +21,7 @@ use { genesis_utils::{create_genesis_config, GenesisConfigInfo}, leader_schedule_cache::LeaderScheduleCache, }, - solana_measure::measure::Measure, + solana_measure::measure, solana_metrics::poh_timing_point::{send_poh_timing_point, PohTimingSender, SlotPohTimingInfo}, solana_runtime::bank::Bank, solana_sdk::{ @@ -647,8 +647,8 @@ impl PohRecorder { } pub fn tick(&mut self) { - let ((poh_entry, target_time), tick_lock_contention_time) = Measure::this( - |_| { + let ((poh_entry, target_time), tick_lock_contention_time) = measure!( + { let mut poh_l = self.poh.lock().unwrap(); let poh_entry = poh_l.tick(); let target_time = if poh_entry.is_some() { @@ -658,7 +658,6 @@ impl PohRecorder { }; (poh_entry, target_time) }, - (), "tick_lock_contention", ); self.tick_lock_contention_us += tick_lock_contention_time.as_us(); @@ -685,11 +684,11 @@ impl PohRecorder { )); let (_flush_res, flush_cache_and_tick_time) = - Measure::this(|_| self.flush_cache(true), (), "flush_cache_and_tick"); + measure!(self.flush_cache(true), "flush_cache_and_tick"); self.flush_cache_tick_us += flush_cache_and_tick_time.as_us(); - let sleep_time = Measure::this( - |_| { + let sleep_time = measure!( + { let target_time = target_time.unwrap(); // sleep is not accurate enough to get a predictable time. // Kernel can not schedule the thread for a while. @@ -698,7 +697,6 @@ impl PohRecorder { std::hint::spin_loop(); } }, - (), "poh_sleep", ) .1; @@ -749,13 +747,12 @@ impl PohRecorder { // cannot be generated by `record()` assert!(!transactions.is_empty(), "No transactions provided"); - let ((), report_metrics_time) = - Measure::this(|_| self.report_metrics(bank_slot), (), "report_metrics"); + let ((), report_metrics_time) = measure!(self.report_metrics(bank_slot), "report_metrics"); self.report_metrics_us += report_metrics_time.as_us(); loop { let (flush_cache_res, flush_cache_time) = - Measure::this(|_| self.flush_cache(false), (), "flush_cache"); + measure!(self.flush_cache(false), "flush_cache"); self.flush_cache_no_tick_us += flush_cache_time.as_us(); flush_cache_res?; @@ -767,19 +764,18 @@ impl PohRecorder { return Err(PohRecorderError::MaxHeightReached); } - let (mut poh_lock, poh_lock_time) = - Measure::this(|_| self.poh.lock().unwrap(), (), "poh_lock"); + let (mut poh_lock, poh_lock_time) = measure!(self.poh.lock().unwrap(), "poh_lock"); self.record_lock_contention_us += poh_lock_time.as_us(); let (record_mixin_res, record_mixin_time) = - Measure::this(|_| poh_lock.record(mixin), (), "record_mixin"); + measure!(poh_lock.record(mixin), "record_mixin"); self.record_us += record_mixin_time.as_us(); drop(poh_lock); if let Some(poh_entry) = record_mixin_res { - let (send_entry_res, send_entry_time) = Measure::this( - |_| { + let (send_entry_res, send_entry_time) = measure!( + { let entry = Entry { num_hashes: poh_entry.num_hashes, hash: poh_entry.hash, @@ -788,7 +784,6 @@ impl PohRecorder { let bank_clone = working_bank.bank.clone(); self.sender.send((bank_clone, (entry, self.tick_height))) }, - (), "send_poh_entry", ); self.send_entry_us += send_entry_time.as_us(); diff --git a/poh/src/poh_service.rs b/poh/src/poh_service.rs index 7ce52844bf..925d053dff 100644 --- a/poh/src/poh_service.rs +++ b/poh/src/poh_service.rs @@ -5,7 +5,7 @@ use { crossbeam_channel::Receiver, log::*, solana_entry::poh::Poh, - solana_measure::measure::Measure, + solana_measure::{measure, measure::Measure}, solana_sdk::poh_config::PohConfig, std::{ sync::{ @@ -264,7 +264,7 @@ impl PohService { ); // what do we do on failure here? Ignore for now. let (_send_res, send_record_result_time) = - Measure::this(|_| record.sender.send(res), (), "send_record_result"); + measure!(record.sender.send(res), "send_record_result"); timing.total_send_record_result_us += send_record_result_time.as_us(); timing.num_hashes += 1; // note: may have also ticked inside record diff --git a/runtime/src/bank.rs b/runtime/src/bank.rs index 240c5d016f..a12d850aee 100644 --- a/runtime/src/bank.rs +++ b/runtime/src/bank.rs @@ -1703,8 +1703,8 @@ impl Bank { let epoch_schedule = parent.epoch_schedule; let epoch = epoch_schedule.get_epoch(slot); - let (rc, bank_rc_time) = Measure::this( - |_| BankRc { + let (rc, bank_rc_time) = measure!( + BankRc { accounts: Arc::new(Accounts::new_from_parent( &parent.rc.accounts, slot, @@ -1714,20 +1714,18 @@ impl Bank { slot, bank_id_generator: parent.rc.bank_id_generator.clone(), }, - (), "bank_rc_creation", ); - let (src, status_cache_rc_time) = Measure::this( - |_| StatusCacheRc { + let (src, status_cache_rc_time) = measure!( + StatusCacheRc { status_cache: parent.src.status_cache.clone(), }, - (), "status_cache_rc_creation", ); - let ((fee_rate_governor, fee_calculator), fee_components_time) = Measure::this( - |_| { + let ((fee_rate_governor, fee_calculator), fee_components_time) = measure!( + { let fee_rate_governor = FeeRateGovernor::new_derived( &parent.fee_rate_governor, parent.signature_count(), @@ -1741,65 +1739,54 @@ impl Bank { }; (fee_rate_governor, fee_calculator) }, - (), "fee_components_creation", ); let bank_id = rc.bank_id_generator.fetch_add(1, Relaxed) + 1; - let (blockhash_queue, blockhash_queue_time) = Measure::this( - |_| RwLock::new(parent.blockhash_queue.read().unwrap().clone()), - (), + let (blockhash_queue, blockhash_queue_time) = measure!( + RwLock::new(parent.blockhash_queue.read().unwrap().clone()), "blockhash_queue_creation", ); - let (stakes_cache, stakes_cache_time) = Measure::this( - |_| StakesCache::new(parent.stakes_cache.stakes().clone()), - (), + let (stakes_cache, stakes_cache_time) = measure!( + StakesCache::new(parent.stakes_cache.stakes().clone()), "stakes_cache_creation", ); let (epoch_stakes, epoch_stakes_time) = - Measure::this(|_| parent.epoch_stakes.clone(), (), "epoch_stakes_creation"); + measure!(parent.epoch_stakes.clone(), "epoch_stakes_creation"); - let (builtin_programs, builtin_programs_time) = Measure::this( - |_| parent.builtin_programs.clone(), - (), - "builtin_programs_creation", - ); + let (builtin_programs, builtin_programs_time) = + measure!(parent.builtin_programs.clone(), "builtin_programs_creation"); - let (rewards_pool_pubkeys, rewards_pool_pubkeys_time) = Measure::this( - |_| parent.rewards_pool_pubkeys.clone(), - (), + let (rewards_pool_pubkeys, rewards_pool_pubkeys_time) = measure!( + parent.rewards_pool_pubkeys.clone(), "rewards_pool_pubkeys_creation", ); - let (cached_executors, cached_executors_time) = Measure::this( - |_| { + let (cached_executors, cached_executors_time) = measure!( + { let parent_bank_executors = parent.cached_executors.read().unwrap(); RwLock::new(CachedExecutors::new_from_parent_bank_executors( &parent_bank_executors, epoch, )) }, - (), "cached_executors_creation", ); - let (transaction_debug_keys, transaction_debug_keys_time) = Measure::this( - |_| parent.transaction_debug_keys.clone(), - (), + let (transaction_debug_keys, transaction_debug_keys_time) = measure!( + parent.transaction_debug_keys.clone(), "transation_debug_keys_creation", ); - let (transaction_log_collector_config, transaction_log_collector_config_time) = - Measure::this( - |_| parent.transaction_log_collector_config.clone(), - (), - "transaction_log_collector_config_creation", - ); + let (transaction_log_collector_config, transaction_log_collector_config_time) = measure!( + parent.transaction_log_collector_config.clone(), + "transaction_log_collector_config_creation", + ); let (feature_set, feature_set_time) = - Measure::this(|_| parent.feature_set.clone(), (), "feature_set_creation"); + measure!(parent.feature_set.clone(), "feature_set_creation"); let accounts_data_size_initial = parent.load_accounts_data_size(); let mut new = Bank { @@ -1878,8 +1865,8 @@ impl Bank { fee_structure: parent.fee_structure.clone(), }; - let (_, ancestors_time) = Measure::this( - |_| { + let (_, ancestors_time) = measure!( + { let mut ancestors = Vec::with_capacity(1 + new.parents().len()); ancestors.push(new.slot()); new.parents().iter().for_each(|p| { @@ -1887,48 +1874,43 @@ impl Bank { }); new.ancestors = Ancestors::from(ancestors); }, - (), "ancestors_creation", ); // Following code may touch AccountsDb, requiring proper ancestors let parent_epoch = parent.epoch(); - let (_, update_epoch_time) = Measure::this( - |_| { + let (_, update_epoch_time) = measure!( + { if parent_epoch < new.epoch() { - let (thread_pool, thread_pool_time) = Measure::this( - |_| ThreadPoolBuilder::new().build().unwrap(), - (), + let (thread_pool, thread_pool_time) = measure!( + ThreadPoolBuilder::new().build().unwrap(), "thread_pool_creation", ); - let (_, apply_feature_activations_time) = Measure::this( - |_| new.apply_feature_activations(false, false), - (), + let (_, apply_feature_activations_time) = measure!( + new.apply_feature_activations(false, false), "apply_feature_activation", ); // Add new entry to stakes.stake_history, set appropriate epoch and // update vote accounts with warmed up stakes before saving a // snapshot of stakes in epoch stakes - let (_, activate_epoch_time) = Measure::this( - |_| new.stakes_cache.activate_epoch(epoch, &thread_pool), - (), + let (_, activate_epoch_time) = measure!( + new.stakes_cache.activate_epoch(epoch, &thread_pool), "activate_epoch", ); // Save a snapshot of stakes for use in consensus and stake weighted networking let leader_schedule_epoch = epoch_schedule.get_leader_schedule_epoch(slot); - let (_, update_epoch_stakes_time) = Measure::this( - |_| new.update_epoch_stakes(leader_schedule_epoch), - (), + let (_, update_epoch_stakes_time) = measure!( + new.update_epoch_stakes(leader_schedule_epoch), "update_epoch_stakes", ); let mut metrics = RewardsMetrics::default(); // After saving a snapshot of stakes, apply stake rewards and commission - let (_, update_rewards_with_thread_pool_time) = Measure::this( - |_| { + let (_, update_rewards_with_thread_pool_time) = measure!( + { new.update_rewards_with_thread_pool( parent_epoch, reward_calc_tracer, @@ -1936,7 +1918,6 @@ impl Bank { &mut metrics, ) }, - (), "update_rewards_with_thread_pool", ); @@ -2004,27 +1985,22 @@ impl Bank { new.update_epoch_stakes(leader_schedule_epoch); } }, - (), "update_epoch", ); // Update sysvars before processing transactions - let (_, update_sysvars_time) = Measure::this( - |_| { + let (_, update_sysvars_time) = measure!( + { new.update_slot_hashes(); new.update_stake_history(Some(parent_epoch)); new.update_clock(Some(parent_epoch)); new.update_fees(); }, - (), "update_sysvars", ); - let (_, fill_sysvar_cache_time) = Measure::this( - |_| new.fill_missing_sysvar_cache_entries(), - (), - "fill_sysvar_cache", - ); + let (_, fill_sysvar_cache_time) = + measure!(new.fill_missing_sysvar_cache_entries(), "fill_sysvar_cache"); time.stop();