From 441eb41b6bd3a36d5f673c23d392ef5a9796706d Mon Sep 17 00:00:00 2001 From: Paul Hauner Date: Sun, 11 Aug 2019 15:53:34 +1000 Subject: [PATCH] Add heavy metering to block processing --- beacon_node/beacon_chain/src/beacon_chain.rs | 34 ++++++++++++++++-- beacon_node/beacon_chain/src/metrics.rs | 36 +++++++++++++++++--- 2 files changed, 64 insertions(+), 6 deletions(-) diff --git a/beacon_node/beacon_chain/src/beacon_chain.rs b/beacon_node/beacon_chain/src/beacon_chain.rs index b0bb6a1592..f5fb954b91 100644 --- a/beacon_node/beacon_chain/src/beacon_chain.rs +++ b/beacon_node/beacon_chain/src/beacon_chain.rs @@ -806,7 +806,7 @@ impl BeaconChain { block: BeaconBlock, ) -> Result { metrics::inc_counter(&metrics::BLOCK_PROCESSING_REQUESTS); - let timer = metrics::start_timer(&metrics::BLOCK_PROCESSING_TIMES); + let full_timer = metrics::start_timer(&metrics::BLOCK_PROCESSING_TIMES); let finalized_slot = self .state @@ -869,15 +869,25 @@ impl BeaconChain { metrics::stop_timer(db_read_timer); + let catchup_timer = metrics::start_timer(&metrics::BLOCK_PROCESSING_CATCHUP_STATE); + // Transition the parent state to the block slot. let mut state: BeaconState = parent_state; for _ in state.slot.as_u64()..block.slot.as_u64() { per_slot_processing(&mut state, &self.spec)?; } + metrics::stop_timer(catchup_timer); + + let commitee_timer = metrics::start_timer(&metrics::BLOCK_PROCESSING_COMMITTEE); + state.build_committee_cache(RelativeEpoch::Previous, &self.spec)?; state.build_committee_cache(RelativeEpoch::Current, &self.spec)?; + metrics::stop_timer(commitee_timer); + + let core_timer = metrics::start_timer(&metrics::BLOCK_PROCESSING_CORE); + // Apply the received block to its parent state (which has been transitioned into this // slot). match per_block_processing(&mut state, &block, &self.spec) { @@ -888,16 +898,29 @@ impl BeaconChain { _ => {} } + metrics::stop_timer(core_timer); + + let state_root_timer = metrics::start_timer(&metrics::BLOCK_PROCESSING_STATE_ROOT); + let state_root = state.canonical_root(); if block.state_root != state_root { return Ok(BlockProcessingOutcome::StateRootMismatch); } + metrics::stop_timer(state_root_timer); + + let db_write_timer = metrics::start_timer(&metrics::BLOCK_PROCESSING_DB_WRITE); + // Store the block and state. self.store.put(&block_root, &block)?; self.store.put(&state_root, &state)?; + metrics::stop_timer(db_write_timer); + + let fork_choice_register_timer = + metrics::start_timer(&metrics::BLOCK_PROCESSING_FORK_CHOICE_REGISTER); + // Register the new block with the fork choice service. if let Err(e) = self.fork_choice.process_block(&state, &block, block_root) { error!( @@ -909,6 +932,11 @@ impl BeaconChain { ) } + metrics::stop_timer(fork_choice_register_timer); + + let find_head_timer = + metrics::start_timer(&metrics::BLOCK_PROCESSING_FORK_CHOICE_FIND_HEAD); + // Execute the fork choice algorithm, enthroning a new head if discovered. // // Note: in the future we may choose to run fork-choice less often, potentially based upon @@ -921,12 +949,14 @@ impl BeaconChain { ) }; + metrics::stop_timer(find_head_timer); + metrics::inc_counter(&metrics::BLOCK_PROCESSING_SUCCESSES); metrics::observe( &metrics::OPERATIONS_PER_BLOCK_ATTESTATION, block.body.attestations.len() as f64, ); - metrics::stop_timer(timer); + metrics::stop_timer(full_timer); Ok(BlockProcessingOutcome::Processed { block_root }) } diff --git a/beacon_node/beacon_chain/src/metrics.rs b/beacon_node/beacon_chain/src/metrics.rs index 03f4783ff9..38a7af9e15 100644 --- a/beacon_node/beacon_chain/src/metrics.rs +++ b/beacon_node/beacon_chain/src/metrics.rs @@ -4,10 +4,6 @@ lazy_static! { /* * Block Processing */ - pub static ref BLOCK_PROCESSING_DB_READ: Result = try_create_histogram( - "block_processing_db_read_times", - "Time spent loading block and state from DB" - ); pub static ref BLOCK_PROCESSING_REQUESTS: Result = try_create_int_counter( "block_processing_requests", "Count of blocks submitted for processing" @@ -18,6 +14,38 @@ lazy_static! { ); pub static ref BLOCK_PROCESSING_TIMES: Result = try_create_histogram("block_processing_times", "Full runtime of block processing"); + pub static ref BLOCK_PROCESSING_DB_READ: Result = try_create_histogram( + "block_processing_db_read_times", + "Time spent loading block and state from DB for block processing" + ); + pub static ref BLOCK_PROCESSING_CATCHUP_STATE: Result = try_create_histogram( + "block_processing_catch-up_state_times", + "Time spent skipping slots on a state before processing a block." + ); + pub static ref BLOCK_PROCESSING_COMMITTEE: Result = try_create_histogram( + "block_processing_committee_building_times", + "Time spent building/obtaining committees for block processing." + ); + pub static ref BLOCK_PROCESSING_CORE: Result = try_create_histogram( + "block_processing_core_times", + "Time spent doing the core per_block_processing state processing." + ); + pub static ref BLOCK_PROCESSING_STATE_ROOT: Result = try_create_histogram( + "block_processing_state_root_times", + "Time spent calculating the state root when processing a block." + ); + pub static ref BLOCK_PROCESSING_DB_WRITE: Result = try_create_histogram( + "block_processing_db_write_times", + "Time spent writing a newly processed block and state to DB" + ); + pub static ref BLOCK_PROCESSING_FORK_CHOICE_REGISTER: Result = try_create_histogram( + "block_processing_fork_choice_register_times", + "Time spent registering the new block with fork choice (but not finding head)" + ); + pub static ref BLOCK_PROCESSING_FORK_CHOICE_FIND_HEAD: Result = try_create_histogram( + "block_processing_fork_choice_find_head_times", + "Time spent finding the new head after processing a new block" + ); /* * Block Production