diff --git a/beacon_node/beacon_chain/src/beacon_chain.rs b/beacon_node/beacon_chain/src/beacon_chain.rs index 09bfebb9b..a7421b922 100644 --- a/beacon_node/beacon_chain/src/beacon_chain.rs +++ b/beacon_node/beacon_chain/src/beacon_chain.rs @@ -530,8 +530,9 @@ impl BeaconChain { /// Produce an `AttestationData` that is valid for the present `slot` and given `shard`. pub fn produce_attestation_data(&self, shard: u64) -> Result { 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 BeaconChain { &self, attestation: Attestation, ) -> Result<(), AttestationValidationError> { - self.op_pool - .insert_attestation(attestation, &*self.state.read(), &self.spec) + self.metrics.attestation_processing_requests.inc(); + 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 BeaconChain { pub fn process_block(&self, block: BeaconBlock) -> Result { 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 BeaconChain { ) -> Result<(BeaconBlock, BeaconState), 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 BeaconChain { 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)? - .ok_or_else(|| Error::MissingBeaconBlock(new_head))?; - let block_root = block.canonical_root(); - + .get(&new_head_root)? + .ok_or_else(|| Error::MissingBeaconBlock(new_head_root))?; let state: BeaconState = 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)?; diff --git a/beacon_node/beacon_chain/src/metrics.rs b/beacon_node/beacon_chain/src/metrics.rs index 7c068119e..0fe738a8c 100644 --- a/beacon_node/beacon_chain/src/metrics.rs +++ b/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: { - let opts = - HistogramOpts::new("block_processing_historgram", "block_processing_time"); + block_processing_times: { + let opts = HistogramOpts::new("block_processing_times", "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: { - let opts = - HistogramOpts::new("block_production_historgram", "block_production_time"); + block_production_times: { + let opts = HistogramOpts::new("block_production_times", "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(()) }