From 42d300bdc35df563598fcd65488b5fb21342a60b Mon Sep 17 00:00:00 2001 From: Paul Hauner Date: Sun, 11 Aug 2019 17:49:32 +1000 Subject: [PATCH] Add more beacon chain metrics --- beacon_node/beacon_chain/src/beacon_chain.rs | 18 ++++++++++++++---- beacon_node/beacon_chain/src/fork_choice.rs | 20 +++++++++++++++++--- beacon_node/beacon_chain/src/metrics.rs | 20 ++++++++++++++++++++ 3 files changed, 51 insertions(+), 7 deletions(-) diff --git a/beacon_node/beacon_chain/src/beacon_chain.rs b/beacon_node/beacon_chain/src/beacon_chain.rs index f5fb954b9..6f9a2b414 100644 --- a/beacon_node/beacon_chain/src/beacon_chain.rs +++ b/beacon_node/beacon_chain/src/beacon_chain.rs @@ -1060,11 +1060,8 @@ impl BeaconChain { // 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 = self @@ -1127,11 +1124,22 @@ impl BeaconChain { } } 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) -> 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 BeaconChain { // Save `self` to `self.store`. self.persist()?; + metrics::stop_timer(timer); + Ok(()) } diff --git a/beacon_node/beacon_chain/src/fork_choice.rs b/beacon_node/beacon_chain/src/fork_choice.rs index edd426f29..77fdaacdc 100644 --- a/beacon_node/beacon_chain/src/fork_choice.rs +++ b/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 ForkChoice { } pub fn find_head(&self, chain: &BeaconChain) -> Result { + 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 ForkChoice { .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 ForkChoice { block: &BeaconBlock, 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 ForkChoice { // 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 ForkChoice { attestation: &Attestation, block: &BeaconBlock, ) -> 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 ForkChoice { } } + metrics::stop_timer(timer); + Ok(()) } diff --git a/beacon_node/beacon_chain/src/metrics.rs b/beacon_node/beacon_chain/src/metrics.rs index d0b6e27fc..34f359ad8 100644 --- a/beacon_node/beacon_chain/src/metrics.rs +++ b/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 = 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 = 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 = try_create_histogram("fork_choice_time", "Full runtime of fork choice"); + pub static ref FORK_CHOICE_FIND_HEAD_TIMES: Result = + 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 = 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 = 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 = + try_create_histogram("update_head_times", "Time taken to update the canonical head"); }