Add more beacon chain metrics

beacon_node/beacon_chain/src/beacon_chain.rs

@@ -1060,11 +1060,8 @@ impl<T: BeaconChainTypes> BeaconChain<T> {
         // Determine the root of the block that is the head of the chain.
         let beacon_block_root = self.fork_choice.find_head(&self)?;
 
-        // End fork choice metrics timer.
-        metrics::stop_timer(timer);
-
         // If a new head was chosen.
-        if beacon_block_root != self.head().beacon_block_root {
+        let result = if beacon_block_root != self.head().beacon_block_root {
             metrics::inc_counter(&metrics::FORK_CHOICE_CHANGED_HEAD);
 
             let beacon_block: BeaconBlock<T::EthSpec> = self
@@ -1127,11 +1124,22 @@ impl<T: BeaconChainTypes> BeaconChain<T> {
             }
         } else {
             Ok(())
+        };
+
+        // End fork choice metrics timer.
+        metrics::stop_timer(timer);
+
+        if let Err(_) = result {
+            metrics::inc_counter(&metrics::FORK_CHOICE_ERRORS);
         }
+
+        result
     }
 
     /// Update the canonical head to `new_head`.
     fn update_canonical_head(&self, new_head: CheckPoint<T::EthSpec>) -> Result<(), Error> {
+        let timer = metrics::start_timer(&metrics::UPDATE_HEAD_TIMES);
+
         // Update the checkpoint that stores the head of the chain at the time it received the
         // block.
         *self.canonical_head.write() = new_head;
@@ -1158,6 +1166,8 @@ impl<T: BeaconChainTypes> BeaconChain<T> {
         // Save `self` to `self.store`.
         self.persist()?;
 
+        metrics::stop_timer(timer);
+
         Ok(())
     }
 

beacon_node/beacon_chain/src/fork_choice.rs

@@ -1,4 +1,4 @@
-use crate::{BeaconChain, BeaconChainTypes};
+use crate::{metrics, BeaconChain, BeaconChainTypes};
 use lmd_ghost::LmdGhost;
 use state_processing::common::get_attesting_indices;
 use std::sync::Arc;
@@ -46,6 +46,8 @@ impl<T: BeaconChainTypes> ForkChoice<T> {
     }
 
     pub fn find_head(&self, chain: &BeaconChain<T>) -> Result<Hash256> {
+        let timer = metrics::start_timer(&metrics::FORK_CHOICE_FIND_HEAD_TIMES);
+
         let start_slot = |epoch: Epoch| epoch.start_slot(T::EthSpec::slots_per_epoch());
 
         // From the specification:
@@ -97,9 +99,14 @@ impl<T: BeaconChainTypes> ForkChoice<T> {
                 .map(|v| v.effective_balance)
         };
 
-        self.backend
+        let result = self
+            .backend
             .find_head(start_block_slot, start_block_root, weight)
-            .map_err(Into::into)
+            .map_err(Into::into);
+
+        metrics::stop_timer(timer);
+
+        result
     }
 
     /// Process all attestations in the given `block`.
@@ -112,6 +119,7 @@ impl<T: BeaconChainTypes> ForkChoice<T> {
         block: &BeaconBlock<T::EthSpec>,
         block_root: Hash256,
     ) -> Result<()> {
+        let timer = metrics::start_timer(&metrics::FORK_CHOICE_PROCESS_BLOCK_TIMES);
         // Note: we never count the block as a latest message, only attestations.
         //
         // I (Paul H) do not have an explicit reference to this, but I derive it from this
@@ -136,6 +144,8 @@ impl<T: BeaconChainTypes> ForkChoice<T> {
         // a block that has the majority of votes applied to it.
         self.backend.process_block(block, block_root)?;
 
+        metrics::stop_timer(timer);
+
         Ok(())
     }
 
@@ -148,6 +158,8 @@ impl<T: BeaconChainTypes> ForkChoice<T> {
         attestation: &Attestation<T::EthSpec>,
         block: &BeaconBlock<T::EthSpec>,
     ) -> Result<()> {
+        let timer = metrics::start_timer(&metrics::FORK_CHOICE_PROCESS_ATTESTATION_TIMES);
+
         let block_hash = attestation.data.beacon_block_root;
 
         // Ignore any attestations to the zero hash.
@@ -175,6 +187,8 @@ impl<T: BeaconChainTypes> ForkChoice<T> {
             }
         }
 
+        metrics::stop_timer(timer);
+
         Ok(())
     }
 

beacon_node/beacon_chain/src/metrics.rs

@@ -108,6 +108,10 @@ lazy_static! {
         "fork_choice_requests",
         "Count of occasions where fork choice has tried to find a head"
     );
+    pub static ref FORK_CHOICE_ERRORS: Result<IntCounter> = try_create_int_counter(
+        "fork_choice_errors",
+        "Count of occasions where fork choice has returned an error when trying to find a head"
+    );
     pub static ref FORK_CHOICE_CHANGED_HEAD: Result<IntCounter> = try_create_int_counter(
         "fork_choice_changed_head",
         "Count of occasions fork choice has found a new head"
@@ -118,4 +122,20 @@ lazy_static! {
     );
     pub static ref FORK_CHOICE_TIMES: Result<Histogram> =
         try_create_histogram("fork_choice_time", "Full runtime of fork choice");
+    pub static ref FORK_CHOICE_FIND_HEAD_TIMES: Result<Histogram> =
+        try_create_histogram("fork_choice_find_head_time", "Full runtime of fork choice find_head function");
+    pub static ref FORK_CHOICE_PROCESS_BLOCK_TIMES: Result<Histogram> = try_create_histogram(
+        "fork_choice_process_block_time",
+        "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(
+        "fork_choice_process_attestation_time",
+        "Time taken to add an attestation to fork choice"
+    );
+
+    /*
+     * Head Updating
+     */
+    pub static ref UPDATE_HEAD_TIMES: Result<Histogram> =
+        try_create_histogram("update_head_times", "Time taken to update the canonical head");
 }