From e369e293a507c602be1901b462001bfd8e4e825c Mon Sep 17 00:00:00 2001 From: Paul Hauner Date: Tue, 13 Aug 2019 09:20:39 +1000 Subject: [PATCH 1/4] Make prom metric names more consistent --- beacon_node/beacon_chain/src/metrics.rs | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/beacon_node/beacon_chain/src/metrics.rs b/beacon_node/beacon_chain/src/metrics.rs index a4b36cd37..574fbb4a4 100644 --- a/beacon_node/beacon_chain/src/metrics.rs +++ b/beacon_node/beacon_chain/src/metrics.rs @@ -15,7 +15,7 @@ lazy_static! { "Count of blocks processed without error" ); pub static ref BLOCK_PROCESSING_TIMES: Result = - 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_DB_READ: Result = try_create_histogram( "beacon_block_processing_db_read_seconds", "Time spent loading block and state from DB for block processing" @@ -123,15 +123,15 @@ lazy_static! { "Count of occasions fork choice has switched to a different chain" ); pub static ref FORK_CHOICE_TIMES: Result = - 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 = - 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 = 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 = try_create_histogram( - "beacon_fork_choice_process_attestation_time", + "beacon_fork_choice_process_attestation_seconds", "Time taken to add an attestation to fork choice" ); From b076b07022c9f359315b52700de301d23530e1f0 Mon Sep 17 00:00:00 2001 From: Paul Hauner Date: Tue, 13 Aug 2019 12:11:18 +1000 Subject: [PATCH 2/4] Add more metrics, tidy existing metrics --- beacon_node/beacon_chain/src/beacon_chain.rs | 4 ++ beacon_node/beacon_chain/src/metrics.rs | 4 ++ beacon_node/eth2-libp2p/src/discovery.rs | 8 ++- beacon_node/eth2-libp2p/src/metrics.rs | 14 +++-- beacon_node/store/src/impls.rs | 20 ++++++- beacon_node/store/src/impls/beacon_state.rs | 21 +++++++- beacon_node/store/src/metrics.rs | 57 ++++++++++++++++++++ eth2/utils/slot_clock/src/metrics.rs | 3 ++ 8 files changed, 120 insertions(+), 11 deletions(-) diff --git a/beacon_node/beacon_chain/src/beacon_chain.rs b/beacon_node/beacon_chain/src/beacon_chain.rs index 0e0583309..faffa46f5 100644 --- a/beacon_node/beacon_chain/src/beacon_chain.rs +++ b/beacon_node/beacon_chain/src/beacon_chain.rs @@ -827,8 +827,12 @@ impl BeaconChain { 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); } diff --git a/beacon_node/beacon_chain/src/metrics.rs b/beacon_node/beacon_chain/src/metrics.rs index 574fbb4a4..db213a0cf 100644 --- a/beacon_node/beacon_chain/src/metrics.rs +++ b/beacon_node/beacon_chain/src/metrics.rs @@ -16,6 +16,10 @@ lazy_static! { ); pub static ref BLOCK_PROCESSING_TIMES: Result = try_create_histogram("beacon_block_processing_seconds", "Full runtime of block processing"); + pub static ref BLOCK_PROCESSING_BLOCK_ROOT: Result = 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 = try_create_histogram( "beacon_block_processing_db_read_seconds", "Time spent loading block and state from DB for block processing" diff --git a/beacon_node/eth2-libp2p/src/discovery.rs b/beacon_node/eth2-libp2p/src/discovery.rs index d9f2f7465..ca98db324 100644 --- a/beacon_node/eth2-libp2p/src/discovery.rs +++ b/beacon_node/eth2-libp2p/src/discovery.rs @@ -159,13 +159,17 @@ where } fn inject_connected(&mut self, peer_id: PeerId, _endpoint: ConnectedPoint) { - metrics::inc_counter(&metrics::PEER_CONNECT_COUNT); self.connected_peers.insert(peer_id); + + metrics::inc_counter(&metrics::PEER_CONNECT_EVENT_COUNT); + metrics::set_gauge(&metrics::PEERS_CONNECTED, self.connected_peers() as i64); } fn inject_disconnected(&mut self, peer_id: &PeerId, _endpoint: ConnectedPoint) { - metrics::inc_counter(&metrics::PEER_DISCONNECT_COUNT); self.connected_peers.remove(peer_id); + + metrics::inc_counter(&metrics::PEER_DISCONNECT_EVENT_COUNT); + metrics::set_gauge(&metrics::PEERS_CONNECTED, self.connected_peers() as i64); } fn inject_replaced( diff --git a/beacon_node/eth2-libp2p/src/metrics.rs b/beacon_node/eth2-libp2p/src/metrics.rs index a47037669..b678ef6b4 100644 --- a/beacon_node/eth2-libp2p/src/metrics.rs +++ b/beacon_node/eth2-libp2p/src/metrics.rs @@ -2,15 +2,19 @@ pub use lighthouse_metrics::*; lazy_static! { pub static ref ADDRESS_UPDATE_COUNT: Result = try_create_int_counter( - "libp2p_address_update_count", + "libp2p_address_update_total", "Count of libp2p socked updated events (when our view of our IP address has changed)" ); - pub static ref PEER_CONNECT_COUNT: Result = try_create_int_counter( - "libp2p_peer_connect_count", + pub static ref PEERS_CONNECTED: Result = try_create_int_gauge( + "libp2p_peer_connected_peers_total", + "Count of libp2p peers currently connected" + ); + pub static ref PEER_CONNECT_EVENT_COUNT: Result = try_create_int_counter( + "libp2p_peer_connect_event_total", "Count of libp2p peer connect events (not the current number of connected peers)" ); - pub static ref PEER_DISCONNECT_COUNT: Result = try_create_int_counter( - "libp2p_peer_disconnect_count", + pub static ref PEER_DISCONNECT_EVENT_COUNT: Result = try_create_int_counter( + "libp2p_peer_disconnect_event_total", "Count of libp2p peer disconnect events" ); } diff --git a/beacon_node/store/src/impls.rs b/beacon_node/store/src/impls.rs index e88b70f39..1c29c245b 100644 --- a/beacon_node/store/src/impls.rs +++ b/beacon_node/store/src/impls.rs @@ -9,10 +9,26 @@ impl StoreItem for BeaconBlock { } fn as_store_bytes(&self) -> Vec { - self.as_ssz_bytes() + let timer = metrics::start_timer(&metrics::BEACON_STATE_WRITE_TIMES); + let bytes = self.as_ssz_bytes(); + + metrics::stop_timer(timer); + metrics::inc_counter(&metrics::BEACON_STATE_WRITE_COUNT); + metrics::inc_counter_by(&metrics::BEACON_STATE_WRITE_BYTES, bytes.len() as i64); + + bytes } fn from_store_bytes(bytes: &mut [u8]) -> Result { - Self::from_ssz_bytes(bytes).map_err(Into::into) + let timer = metrics::start_timer(&metrics::BEACON_STATE_READ_TIMES); + + let len = bytes.len(); + let result = Self::from_ssz_bytes(bytes).map_err(Into::into); + + metrics::stop_timer(timer); + metrics::inc_counter(&metrics::BEACON_STATE_READ_COUNT); + metrics::inc_counter_by(&metrics::BEACON_STATE_READ_BYTES, len as i64); + + result } } diff --git a/beacon_node/store/src/impls/beacon_state.rs b/beacon_node/store/src/impls/beacon_state.rs index 591663fe0..69e83cd63 100644 --- a/beacon_node/store/src/impls/beacon_state.rs +++ b/beacon_node/store/src/impls/beacon_state.rs @@ -53,12 +53,29 @@ impl StoreItem for BeaconState { } fn as_store_bytes(&self) -> Vec { + let timer = metrics::start_timer(&metrics::BEACON_STATE_WRITE_TIMES); + let container = StorageContainer::new(self); - container.as_ssz_bytes() + let bytes = container.as_ssz_bytes(); + + metrics::stop_timer(timer); + metrics::inc_counter(&metrics::BEACON_STATE_WRITE_COUNT); + metrics::inc_counter_by(&metrics::BEACON_STATE_WRITE_BYTES, bytes.len() as i64); + + bytes } fn from_store_bytes(bytes: &mut [u8]) -> Result { + let timer = metrics::start_timer(&metrics::BEACON_STATE_READ_TIMES); + + let len = bytes.len(); let container = StorageContainer::from_ssz_bytes(bytes)?; - container.try_into() + let result = container.try_into(); + + metrics::stop_timer(timer); + metrics::inc_counter(&metrics::BEACON_STATE_READ_COUNT); + metrics::inc_counter_by(&metrics::BEACON_STATE_READ_BYTES, len as i64); + + result } } diff --git a/beacon_node/store/src/metrics.rs b/beacon_node/store/src/metrics.rs index 30cbb878b..90237824d 100644 --- a/beacon_node/store/src/metrics.rs +++ b/beacon_node/store/src/metrics.rs @@ -4,6 +4,9 @@ use std::fs; use std::path::PathBuf; lazy_static! { + /* + * General + */ pub static ref DISK_DB_SIZE: Result = try_create_int_gauge("store_disk_db_size", "Size of the on-disk database (bytes)"); pub static ref DISK_DB_WRITE_BYTES: Result = try_create_int_counter( @@ -30,6 +33,60 @@ lazy_static! { "store_disk_db_delete_count_total", "Total number of deletions from the on-disk DB" ); + /* + * Beacon State + */ + pub static ref BEACON_STATE_READ_TIMES: Result = try_create_histogram( + "store_beacon_state_read_overhead_seconds", + "Overhead on reading a beacon state from the DB (e.g., decoding)" + ); + pub static ref BEACON_STATE_READ_COUNT: Result = try_create_int_counter( + "store_beacon_state_read_total", + "Total number of beacon state reads from the DB" + ); + pub static ref BEACON_STATE_READ_BYTES: Result = try_create_int_counter( + "store_beacon_state_read_bytes_total", + "Total number of beacon state bytes read from the DB" + ); + pub static ref BEACON_STATE_WRITE_TIMES: Result = try_create_histogram( + "store_beacon_state_write_overhead_seconds", + "Overhead on writing a beacon state to the DB (e.g., encoding)" + ); + pub static ref BEACON_STATE_WRITE_COUNT: Result = try_create_int_counter( + "store_beacon_state_write_total", + "Total number of beacon state writes the DB" + ); + pub static ref BEACON_STATE_WRITE_BYTES: Result = try_create_int_counter( + "store_beacon_state_write_bytes_total", + "Total number of beacon state bytes written to the DB" + ); + /* + * Beacon Block + */ + pub static ref BEACON_BLOCK_READ_TIMES: Result = try_create_histogram( + "store_beacon_block_read_overhead_seconds", + "Overhead on reading a beacon block from the DB (e.g., decoding)" + ); + pub static ref BEACON_BLOCK_READ_COUNT: Result = try_create_int_counter( + "store_beacon_block_read_total", + "Total number of beacon block reads from the DB" + ); + pub static ref BEACON_BLOCK_READ_BYTES: Result = try_create_int_counter( + "store_beacon_block_read_bytes_total", + "Total number of beacon block bytes read from the DB" + ); + pub static ref BEACON_BLOCK_WRITE_TIMES: Result = try_create_histogram( + "store_beacon_block_write_overhead_seconds", + "Overhead on writing a beacon block to the DB (e.g., encoding)" + ); + pub static ref BEACON_BLOCK_WRITE_COUNT: Result = try_create_int_counter( + "store_beacon_block_write_total", + "Total number of beacon block writes the DB" + ); + pub static ref BEACON_BLOCK_WRITE_BYTES: Result = try_create_int_counter( + "store_beacon_block_write_bytes_total", + "Total number of beacon block bytes written to the DB" + ); } /// Updates the global metrics registry with store-related information. diff --git a/eth2/utils/slot_clock/src/metrics.rs b/eth2/utils/slot_clock/src/metrics.rs index a9153a10c..e0d3923e0 100644 --- a/eth2/utils/slot_clock/src/metrics.rs +++ b/eth2/utils/slot_clock/src/metrics.rs @@ -7,6 +7,8 @@ lazy_static! { try_create_int_gauge("slotclock_present_slot", "The present wall-clock slot"); pub static ref PRESENT_EPOCH: Result = try_create_int_gauge("slotclock_present_epoch", "The present wall-clock epoch"); + pub static ref SLOTS_PER_EPOCH: Result = + try_create_int_gauge("slotclock_slots_per_epoch", "Slots per epoch (constant)"); pub static ref MILLISECONDS_PER_SLOT: Result = try_create_int_gauge( "slotclock_slot_time_milliseconds", "The duration in milliseconds between each slot" @@ -25,5 +27,6 @@ pub fn scrape_for_metrics(clock: &U) { &PRESENT_EPOCH, present_slot.epoch(T::slots_per_epoch()).as_u64() as i64, ); + set_gauge(&SLOTS_PER_EPOCH, T::slots_per_epoch() as i64); set_gauge(&MILLISECONDS_PER_SLOT, clock.slot_duration_millis() as i64); } From a3e464078af39e10132bac3d1ac37dbebae8b41a Mon Sep 17 00:00:00 2001 From: Paul Hauner Date: Tue, 13 Aug 2019 13:00:01 +1000 Subject: [PATCH 3/4] Fix store block read metrics --- beacon_node/store/src/impls.rs | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/beacon_node/store/src/impls.rs b/beacon_node/store/src/impls.rs index 1c29c245b..ed724480c 100644 --- a/beacon_node/store/src/impls.rs +++ b/beacon_node/store/src/impls.rs @@ -9,25 +9,25 @@ impl StoreItem for BeaconBlock { } fn as_store_bytes(&self) -> Vec { - let timer = metrics::start_timer(&metrics::BEACON_STATE_WRITE_TIMES); + let timer = metrics::start_timer(&metrics::BEACON_BLOCK_WRITE_TIMES); let bytes = self.as_ssz_bytes(); metrics::stop_timer(timer); - metrics::inc_counter(&metrics::BEACON_STATE_WRITE_COUNT); - metrics::inc_counter_by(&metrics::BEACON_STATE_WRITE_BYTES, bytes.len() as i64); + metrics::inc_counter(&metrics::BEACON_BLOCK_WRITE_COUNT); + metrics::inc_counter_by(&metrics::BEACON_BLOCK_WRITE_BYTES, bytes.len() as i64); bytes } fn from_store_bytes(bytes: &mut [u8]) -> Result { - let timer = metrics::start_timer(&metrics::BEACON_STATE_READ_TIMES); + let timer = metrics::start_timer(&metrics::BEACON_BLOCK_READ_TIMES); let len = bytes.len(); let result = Self::from_ssz_bytes(bytes).map_err(Into::into); metrics::stop_timer(timer); - metrics::inc_counter(&metrics::BEACON_STATE_READ_COUNT); - metrics::inc_counter_by(&metrics::BEACON_STATE_READ_BYTES, len as i64); + metrics::inc_counter(&metrics::BEACON_BLOCK_READ_COUNT); + metrics::inc_counter_by(&metrics::BEACON_BLOCK_READ_BYTES, len as i64); result } From 341a83b9e8d5f3733b09ac9dae2e8aa6d5602ef5 Mon Sep 17 00:00:00 2001 From: Paul Hauner Date: Tue, 13 Aug 2019 16:17:11 +1000 Subject: [PATCH 4/4] Tidy attestation metrics --- beacon_node/beacon_chain/src/beacon_chain.rs | 28 +++++++++++++++----- beacon_node/beacon_chain/src/metrics.rs | 4 +++ 2 files changed, 26 insertions(+), 6 deletions(-) diff --git a/beacon_node/beacon_chain/src/beacon_chain.rs b/beacon_node/beacon_chain/src/beacon_chain.rs index faffa46f5..0cb6d5f98 100644 --- a/beacon_node/beacon_chain/src/beacon_chain.rs +++ b/beacon_node/beacon_chain/src/beacon_chain.rs @@ -547,11 +547,14 @@ impl BeaconChain { &self, attestation: Attestation, ) -> Result { + 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::>(&attestation.data.beacon_block_root)? { @@ -680,7 +683,15 @@ impl BeaconChain { 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 BeaconChain { state: &BeaconState, block: &BeaconBlock, ) -> Result { - 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 BeaconChain { 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 BeaconChain { Ok(AttestationProcessingOutcome::Processed) }; - timer.map(|t| t.observe_duration()); - result } diff --git a/beacon_node/beacon_chain/src/metrics.rs b/beacon_node/beacon_chain/src/metrics.rs index db213a0cf..6efa4b3f2 100644 --- a/beacon_node/beacon_chain/src/metrics.rs +++ b/beacon_node/beacon_chain/src/metrics.rs @@ -90,6 +90,10 @@ lazy_static! { "beacon_attestation_processing_seconds", "Full runtime of attestation processing" ); + pub static ref ATTESTATION_PROCESSING_CORE: Result = try_create_histogram( + "beacon_attestation_processing_core_seconds", + "Time spent on the core spec processing of attestation processing" + ); /* * Attestation Production