Add metrics to BeaconChain, tidy fork choice

beacon_node/beacon_chain/src/beacon_chain.rs

@@ -530,8 +530,9 @@ impl<T: BeaconChainTypes> BeaconChain<T> {
     /// Produce an `AttestationData` that is valid for the present `slot` and given `shard`.
     pub fn produce_attestation_data(&self, shard: u64) -> Result<AttestationData, Error> {
         trace!("BeaconChain::produce_attestation: shard: {}", shard);
+
         self.metrics.attestation_production_requests.inc();
-        let timer = self.metrics.attestation_production_histogram.start_timer();
+        let timer = self.metrics.attestation_production_times.start_timer();
 
         let state = self.state.read();
 
@@ -583,8 +584,20 @@ impl<T: BeaconChainTypes> BeaconChain<T> {
         &self,
         attestation: Attestation,
     ) -> Result<(), AttestationValidationError> {
-        self.op_pool
+        self.metrics.attestation_processing_requests.inc();
-            .insert_attestation(attestation, &*self.state.read(), &self.spec)
+        let timer = self.metrics.attestation_processing_times.start_timer();
+
+        let result = self
+            .op_pool
+            .insert_attestation(attestation, &*self.state.read(), &self.spec);
+
+        if result.is_ok() {
+            self.metrics.attestation_production_successes.inc();
+        }
+
+        timer.observe_duration();
+
+        result
     }
 
     /// Accept some deposit and queue it for inclusion in an appropriate block.
@@ -632,7 +645,7 @@ impl<T: BeaconChainTypes> BeaconChain<T> {
     pub fn process_block(&self, block: BeaconBlock) -> Result<BlockProcessingOutcome, Error> {
         debug!("Processing block with slot {}...", block.slot);
         self.metrics.block_processing_requests.inc();
-        let timer = self.metrics.block_processing_historgram.start_timer();
+        let timer = self.metrics.block_processing_times.start_timer();
 
         let block_root = block.block_header().canonical_root();
 
@@ -732,7 +745,7 @@ impl<T: BeaconChainTypes> BeaconChain<T> {
     ) -> Result<(BeaconBlock, BeaconState<T::EthSpec>), BlockProductionError> {
         debug!("Producing block at slot {}...", self.state.read().slot);
         self.metrics.block_production_requests.inc();
-        let timer = self.metrics.block_production_historgram.start_timer();
+        let timer = self.metrics.block_production_times.start_timer();
 
         let mut state = self.state.read().clone();
 
@@ -789,29 +802,40 @@ impl<T: BeaconChainTypes> BeaconChain<T> {
         Ok((block, state))
     }
 
-    // TODO: Left this as is, modify later
+    /// Execute the fork choice algorithm and enthrone the result as the canonical head.
     pub fn fork_choice(&self) -> Result<(), Error> {
-        let present_head = self.finalized_head().beacon_block_root;
+        self.metrics.fork_choice_requests.inc();
 
-        let new_head = self
+        let present_head_root = self.finalized_head().beacon_block_root;
+
+        let timer = self.metrics.fork_choice_times.start_timer();
+
+        let new_head_root = self
             .fork_choice
             .write()
-            .find_head(&present_head, &self.spec)?;
+            .find_head(&present_head_root, &self.spec)?;
+
+        timer.observe_duration();
+
+        if new_head_root != present_head_root {
+            self.metrics.fork_choice_changed_head.inc();
 
-        if new_head != present_head {
             let block: BeaconBlock = self
                 .store
-                .get(&new_head)?
+                .get(&new_head_root)?
-                .ok_or_else(|| Error::MissingBeaconBlock(new_head))?;
+                .ok_or_else(|| Error::MissingBeaconBlock(new_head_root))?;
-            let block_root = block.canonical_root();
-
             let state: BeaconState<T::EthSpec> = self
                 .store
                 .get(&block.state_root)?
                 .ok_or_else(|| Error::MissingBeaconState(block.state_root))?;
-            let state_root = state.canonical_root();
 
-            self.update_canonical_head(block, block_root, state.clone(), state_root);
+            // Log if we switched to a new chain.
+            if present_head_root != block.previous_block_root {
+                self.metrics.fork_choice_reorg_count.inc();
+            };
+
+            let state_root = block.state_root;
+            self.update_canonical_head(block, new_head_root, state.clone(), state_root);
 
             // Update the canonical `BeaconState`.
             self.update_state(state)?;

beacon_node/beacon_chain/src/metrics.rs

@@ -4,13 +4,20 @@ use prometheus::{Histogram, HistogramOpts, IntCounter, Opts, Registry};
 pub struct Metrics {
     pub block_processing_requests: IntCounter,
     pub block_processing_successes: IntCounter,
-    pub block_processing_historgram: Histogram,
+    pub block_processing_times: Histogram,
     pub block_production_requests: IntCounter,
     pub block_production_successes: IntCounter,
-    pub block_production_historgram: Histogram,
+    pub block_production_times: Histogram,
     pub attestation_production_requests: IntCounter,
     pub attestation_production_successes: IntCounter,
-    pub attestation_production_histogram: Histogram,
+    pub attestation_production_times: Histogram,
+    pub attestation_processing_requests: IntCounter,
+    pub attestation_processing_successes: IntCounter,
+    pub attestation_processing_times: Histogram,
+    pub fork_choice_requests: IntCounter,
+    pub fork_choice_changed_head: IntCounter,
+    pub fork_choice_reorg_count: IntCounter,
+    pub fork_choice_times: Histogram,
 }
 
 impl Metrics {
@@ -24,9 +31,8 @@ impl Metrics {
                 let opts = Opts::new("valid_blocks_processed", "total_valid_blocks_processed");
                 IntCounter::with_opts(opts)?
             },
-            block_processing_historgram: {
+            block_processing_times: {
-                let opts =
+                let opts = HistogramOpts::new("block_processing_times", "block_processing_time");
-                    HistogramOpts::new("block_processing_historgram", "block_processing_time");
                 Histogram::with_opts(opts)?
             },
             block_production_requests: {
@@ -37,9 +43,8 @@ impl Metrics {
                 let opts = Opts::new("block_production_successes", "blocks_successfully_produced");
                 IntCounter::with_opts(opts)?
             },
-            block_production_historgram: {
+            block_production_times: {
-                let opts =
+                let opts = HistogramOpts::new("block_production_times", "block_production_time");
-                    HistogramOpts::new("block_production_historgram", "block_production_time");
                 Histogram::with_opts(opts)?
             },
             attestation_production_requests: {
@@ -56,26 +61,73 @@ impl Metrics {
                 );
                 IntCounter::with_opts(opts)?
             },
-            attestation_production_histogram: {
+            attestation_production_times: {
                 let opts = HistogramOpts::new(
-                    "attestation_production_histogram",
+                    "attestation_production_times",
                     "attestation_production_time",
                 );
                 Histogram::with_opts(opts)?
             },
+            attestation_processing_requests: {
+                let opts = Opts::new(
+                    "attestation_processing_requests",
+                    "total_attestation_processing_requests",
+                );
+                IntCounter::with_opts(opts)?
+            },
+            attestation_processing_successes: {
+                let opts = Opts::new(
+                    "attestation_processing_successes",
+                    "total_attestation_processing_successes",
+                );
+                IntCounter::with_opts(opts)?
+            },
+            attestation_processing_times: {
+                let opts = HistogramOpts::new(
+                    "attestation_processing_times",
+                    "attestation_processing_time",
+                );
+                Histogram::with_opts(opts)?
+            },
+            fork_choice_requests: {
+                let opts = Opts::new("fork_choice_requests", "total_times_fork_choice_called");
+                IntCounter::with_opts(opts)?
+            },
+            fork_choice_changed_head: {
+                let opts = Opts::new(
+                    "fork_choice_changed_head",
+                    "total_times_fork_choice_chose_a_new_head",
+                );
+                IntCounter::with_opts(opts)?
+            },
+            fork_choice_reorg_count: {
+                let opts = Opts::new("fork_choice_reorg_depth", "depth_of_reorg");
+                IntCounter::with_opts(opts)?
+            },
+            fork_choice_times: {
+                let opts = HistogramOpts::new("fork_choice_time", "total_time_to_run_fork_choice");
+                Histogram::with_opts(opts)?
+            },
         })
     }
 
     pub fn register(&self, registry: &Registry) -> Result<(), Error> {
         registry.register(Box::new(self.block_processing_requests.clone()))?;
         registry.register(Box::new(self.block_processing_successes.clone()))?;
-        registry.register(Box::new(self.block_processing_historgram.clone()))?;
+        registry.register(Box::new(self.block_processing_times.clone()))?;
         registry.register(Box::new(self.block_production_requests.clone()))?;
         registry.register(Box::new(self.block_production_successes.clone()))?;
-        registry.register(Box::new(self.block_production_historgram.clone()))?;
+        registry.register(Box::new(self.block_production_times.clone()))?;
         registry.register(Box::new(self.attestation_production_requests.clone()))?;
         registry.register(Box::new(self.attestation_production_successes.clone()))?;
-        registry.register(Box::new(self.attestation_production_histogram.clone()))?;
+        registry.register(Box::new(self.attestation_production_times.clone()))?;
+        registry.register(Box::new(self.attestation_processing_requests.clone()))?;
+        registry.register(Box::new(self.attestation_processing_successes.clone()))?;
+        registry.register(Box::new(self.attestation_processing_times.clone()))?;
+        registry.register(Box::new(self.fork_choice_requests.clone()))?;
+        registry.register(Box::new(self.fork_choice_changed_head.clone()))?;
+        registry.register(Box::new(self.fork_choice_reorg_count.clone()))?;
+        registry.register(Box::new(self.fork_choice_times.clone()))?;
 
         Ok(())
     }