Merge branch 'block-processing-times' of github.com:sigp/lighthouse into block-processing-times

beacon_node/beacon_chain/src/beacon_chain.rs

@@ -547,11 +547,14 @@ impl<T: BeaconChainTypes> BeaconChain<T> {
         &self,
         attestation: Attestation<T::EthSpec>,
     ) -> Result<AttestationProcessingOutcome, Error> {
+        metrics::inc_counter(&metrics::ATTESTATION_PROCESSING_REQUESTS);
+        let timer = metrics::start_timer(&metrics::ATTESTATION_PROCESSING_TIMES);
+
         // From the store, load the attestation's "head block".
         //
         // An honest validator would have set this block to be the head of the chain (i.e., the
         // result of running fork choice).
-        if let Some(attestation_head_block) = self
+        let result = if let Some(attestation_head_block) = self
             .store
             .get::<BeaconBlock<T::EthSpec>>(&attestation.data.beacon_block_root)?
         {
@@ -680,7 +683,15 @@ impl<T: BeaconChainTypes> BeaconChain<T> {
             Ok(AttestationProcessingOutcome::UnknownHeadBlock {
                 beacon_block_root: attestation.data.beacon_block_root,
             })
+        };
+
+        metrics::stop_timer(timer);
+
+        if let Ok(AttestationProcessingOutcome::Processed) = &result {
+            metrics::inc_counter(&metrics::ATTESTATION_PROCESSING_SUCCESSES);
         }
+
+        result
     }
 
     /// Verifies the `attestation` against the `state` to which it is attesting.
@@ -707,9 +718,6 @@ impl<T: BeaconChainTypes> BeaconChain<T> {
         state: &BeaconState<T::EthSpec>,
         block: &BeaconBlock<T::EthSpec>,
     ) -> Result<AttestationProcessingOutcome, Error> {
-        metrics::inc_counter(&metrics::ATTESTATION_PROCESSING_REQUESTS);
-        let timer = metrics::start_timer(&metrics::ATTESTATION_PROCESSING_TIMES);
-
         // Find the highest between:
         //
         // - The highest valid finalized epoch we've ever seen (i.e., the head).
@@ -719,6 +727,16 @@ impl<T: BeaconChainTypes> BeaconChain<T> {
             state.finalized_checkpoint.epoch,
         );
 
+        // A helper function to allow attestation processing to be metered.
+        let verify_attestation_for_state = |state, attestation, spec, verify_signatures| {
+            let timer = metrics::start_timer(&metrics::ATTESTATION_PROCESSING_CORE);
+
+            let result = verify_attestation_for_state(state, attestation, spec, verify_signatures);
+
+            metrics::stop_timer(timer);
+            result
+        };
+
         let result = if block.slot <= finalized_epoch.start_slot(T::EthSpec::slots_per_epoch()) {
             // Ignore any attestation where the slot of `data.beacon_block_root` is equal to or
             // prior to the finalized epoch.
@@ -758,8 +776,6 @@ impl<T: BeaconChainTypes> BeaconChain<T> {
             Ok(AttestationProcessingOutcome::Processed)
         };
 
-        timer.map(|t| t.observe_duration());
-
         result
     }
 
@@ -827,8 +843,12 @@ impl<T: BeaconChainTypes> BeaconChain<T> {
             return Ok(BlockProcessingOutcome::GenesisBlock);
         }
 
+        let block_root_timer = metrics::start_timer(&metrics::BLOCK_PROCESSING_BLOCK_ROOT);
+
         let block_root = block.canonical_root();
 
+        metrics::stop_timer(block_root_timer);
+
         if block_root == self.genesis_block_root {
             return Ok(BlockProcessingOutcome::GenesisBlock);
         }

beacon_node/beacon_chain/src/metrics.rs

@@ -15,7 +15,11 @@ lazy_static! {
         "Count of blocks processed without error"
     );
     pub static ref BLOCK_PROCESSING_TIMES: Result<Histogram> =
-        try_create_histogram("block_processing_seconds", "Full runtime of block processing");
+        try_create_histogram("beacon_block_processing_seconds", "Full runtime of block processing");
+    pub static ref BLOCK_PROCESSING_BLOCK_ROOT: Result<Histogram> = try_create_histogram(
+        "beacon_block_processing_block_root_seconds",
+        "Time spent calculating the block root when processing a block."
+    );
     pub static ref BLOCK_PROCESSING_DB_READ: Result<Histogram> = try_create_histogram(
         "beacon_block_processing_db_read_seconds",
         "Time spent loading block and state from DB for block processing"
@@ -86,6 +90,10 @@ lazy_static! {
         "beacon_attestation_processing_seconds",
         "Full runtime of attestation processing"
     );
+    pub static ref ATTESTATION_PROCESSING_CORE: Result<Histogram> = try_create_histogram(
+        "beacon_attestation_processing_core_seconds",
+        "Time spent on the core spec processing of attestation processing"
+    );
 
     /*
      * Attestation Production
@@ -123,15 +131,15 @@ lazy_static! {
         "Count of occasions fork choice has switched to a different chain"
     );
     pub static ref FORK_CHOICE_TIMES: Result<Histogram> =
-        try_create_histogram("beacon_fork_choice_time", "Full runtime of fork choice");
+        try_create_histogram("beacon_fork_choice_seconds", "Full runtime of fork choice");
     pub static ref FORK_CHOICE_FIND_HEAD_TIMES: Result<Histogram> =
-        try_create_histogram("beacon_fork_choice_find_head_time", "Full runtime of fork choice find_head function");
+        try_create_histogram("beacon_fork_choice_find_head_seconds", "Full runtime of fork choice find_head function");
     pub static ref FORK_CHOICE_PROCESS_BLOCK_TIMES: Result<Histogram> = try_create_histogram(
-        "beacon_fork_choice_process_block_time",
+        "beacon_fork_choice_process_block_seconds",
         "Time taken to add a block and all attestations to fork choice"
     );
     pub static ref FORK_CHOICE_PROCESS_ATTESTATION_TIMES: Result<Histogram> = try_create_histogram(
-        "beacon_fork_choice_process_attestation_time",
+        "beacon_fork_choice_process_attestation_seconds",
         "Time taken to add an attestation to fork choice"
     );