Add heavy metering to block processing

beacon_node/beacon_chain/src/beacon_chain.rs

@@ -806,7 +806,7 @@ impl<T: BeaconChainTypes> BeaconChain<T> {
         block: BeaconBlock<T::EthSpec>,
     ) -> Result<BlockProcessingOutcome, Error> {
         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<T: BeaconChainTypes> BeaconChain<T> {
 
         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<T::EthSpec> = 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<T: BeaconChainTypes> BeaconChain<T> {
             _ => {}
         }
 
+        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<T: BeaconChainTypes> BeaconChain<T> {
             )
         }
 
+        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<T: BeaconChainTypes> BeaconChain<T> {
             )
         };
 
+        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 })
     }

beacon_node/beacon_chain/src/metrics.rs

@@ -4,10 +4,6 @@ lazy_static! {
     /*
      * Block Processing
      */
-    pub static ref BLOCK_PROCESSING_DB_READ: Result<Histogram> = try_create_histogram(
-        "block_processing_db_read_times",
-        "Time spent loading block and state from DB"
-    );
     pub static ref BLOCK_PROCESSING_REQUESTS: Result<IntCounter> = 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<Histogram> =
         try_create_histogram("block_processing_times", "Full runtime of block processing");
+    pub static ref BLOCK_PROCESSING_DB_READ: Result<Histogram> = 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<Histogram> = 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<Histogram> = try_create_histogram(
+        "block_processing_committee_building_times",
+        "Time spent building/obtaining committees for block processing."
+    );
+    pub static ref BLOCK_PROCESSING_CORE: Result<Histogram> = 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<Histogram> = 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<Histogram> = 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<Histogram> = 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<Histogram> = try_create_histogram(
+        "block_processing_fork_choice_find_head_times",
+        "Time spent finding the new head after processing a new block"
+    );
 
     /*
      * Block Production