Add metrics

beacon_node/execution_layer/Cargo.toml

@@ -29,3 +29,8 @@ tree_hash = "0.4.1"
 tree_hash_derive = { path = "../../consensus/tree_hash_derive"}
 parking_lot = "0.11.0"
 slot_clock = { path = "../../common/slot_clock" }
+tempfile = "3.1.0"
+rand = "0.7.3"
+zeroize = { version = "1.4.2", features = ["zeroize_derive"] }
+lighthouse_metrics = { path = "../../common/lighthouse_metrics" }
+lazy_static = "1.4.0"

beacon_node/execution_layer/src/lib.rs

@@ -9,12 +9,12 @@ use engines::{Engine, EngineError, Engines, ForkChoiceState, Logging};
 use lru::LruCache;
 use payload_status::process_multiple_payload_statuses;
 use sensitive_url::SensitiveUrl;
-use slog::{crit, debug, error, info, Logger};
+use slog::{crit, debug, error, info, trace, Logger};
 use slot_clock::SlotClock;
 use std::collections::HashMap;
 use std::future::Future;
 use std::sync::Arc;
-use std::time::Duration;
+use std::time::{Duration, SystemTime, UNIX_EPOCH};
 use task_executor::TaskExecutor;
 use tokio::{
     sync::{Mutex, MutexGuard, RwLock},
@@ -29,6 +29,7 @@ pub use payload_status::PayloadStatus;
 
 mod engine_api;
 mod engines;
+mod metrics;
 mod payload_status;
 pub mod test_utils;
 
@@ -64,7 +65,7 @@ impl From<ApiError> for Error {
     }
 }
 
-#[derive(Clone)]
+#[derive(Clone, PartialEq)]
 pub struct ProposerPreparationDataEntry {
     update_epoch: Epoch,
     preparation_data: ProposerPreparationData,
@@ -354,13 +355,17 @@ impl ExecutionLayer {
     ) {
         let mut proposer_preparation_data = self.proposer_preparation_data().await;
         for preparation_entry in preparation_data {
-            proposer_preparation_data.insert(
-                preparation_entry.validator_index,
-                ProposerPreparationDataEntry {
-                    update_epoch,
-                    preparation_data: preparation_entry.clone(),
-                },
-            );
+            let new = ProposerPreparationDataEntry {
+                update_epoch,
+                preparation_data: preparation_entry.clone(),
+            };
+
+            let existing =
+                proposer_preparation_data.insert(preparation_entry.validator_index, new.clone());
+
+            if existing != Some(new) {
+                metrics::inc_counter(&metrics::EXECUTION_LAYER_PROPOSER_DATA_UPDATED);
+            }
         }
     }
 
@@ -434,6 +439,11 @@ impl ExecutionLayer {
         finalized_block_hash: ExecutionBlockHash,
         proposer_index: u64,
     ) -> Result<ExecutionPayload<T>, Error> {
+        let _timer = metrics::start_timer_vec(
+            &metrics::EXECUTION_LAYER_REQUEST_TIMES,
+            &[metrics::GET_PAYLOAD],
+        );
+
         let suggested_fee_recipient = self.get_suggested_fee_recipient(proposer_index).await;
 
         debug!(
@@ -513,7 +523,12 @@ impl ExecutionLayer {
         &self,
         execution_payload: &ExecutionPayload<T>,
     ) -> Result<PayloadStatus, Error> {
-        debug!(
+        let _timer = metrics::start_timer_vec(
+            &metrics::EXECUTION_LAYER_REQUEST_TIMES,
+            &[metrics::NEW_PAYLOAD],
+        );
+
+        trace!(
             self.log(),
             "Issuing engine_newPayload";
             "parent_hash" => ?execution_payload.parent_hash,
@@ -549,17 +564,19 @@ impl ExecutionLayer {
             head_block_root,
         };
 
-        self.proposers()
-            .write()
-            .await
-            .insert(
-                proposers_key,
-                Proposer {
-                    validator_index,
-                    payload_attributes,
-                },
-            )
-            .is_some()
+        let existing = self.proposers().write().await.insert(
+            proposers_key,
+            Proposer {
+                validator_index,
+                payload_attributes,
+            },
+        );
+
+        if existing.is_none() {
+            metrics::inc_counter(&metrics::EXECUTION_LAYER_PROPOSER_INSERTED);
+        }
+
+        existing.is_some()
     }
 
     /// If there has been a proposer registered via `Self::insert_proposer` with a matching `slot`
@@ -609,7 +626,12 @@ impl ExecutionLayer {
         current_slot: Slot,
         head_block_root: Hash256,
     ) -> Result<PayloadStatus, Error> {
-        debug!(
+        let _timer = metrics::start_timer_vec(
+            &metrics::EXECUTION_LAYER_REQUEST_TIMES,
+            &[metrics::FORKCHOICE_UPDATED],
+        );
+
+        trace!(
             self.log(),
             "Issuing engine_forkchoiceUpdated";
             "finalized_block_hash" => ?finalized_block_hash,
@@ -619,6 +641,26 @@ impl ExecutionLayer {
         let next_slot = current_slot + 1;
         let payload_attributes = self.payload_attributes(next_slot, head_block_root).await;
 
+        // Compute the "lookahead", the time between when the payload will be produced and now.
+        if let Some(payload_attributes) = payload_attributes {
+            if let Ok(now) = SystemTime::now().duration_since(UNIX_EPOCH) {
+                let timestamp = Duration::from_secs(payload_attributes.timestamp);
+                if let Some(lookahead) = timestamp.checked_sub(now) {
+                    metrics::observe_duration(
+                        &metrics::EXECUTION_LAYER_PAYLOAD_ATTRIBUTES_LOOKAHEAD,
+                        lookahead,
+                    );
+                } else {
+                    debug!(
+                        self.log(),
+                        "Late payload attributes";
+                        "timestamp" => ?timestamp,
+                        "now" => ?now,
+                    )
+                }
+            }
+        }
+
         // see https://hackmd.io/@n0ble/kintsugi-spec#Engine-API
         // for now, we must set safe_block_hash = head_block_hash
         let forkchoice_state = ForkChoiceState {
@@ -660,6 +702,11 @@ impl ExecutionLayer {
         &self,
         spec: &ChainSpec,
     ) -> Result<Option<ExecutionBlockHash>, Error> {
+        let _timer = metrics::start_timer_vec(
+            &metrics::EXECUTION_LAYER_REQUEST_TIMES,
+            &[metrics::GET_TERMINAL_POW_BLOCK_HASH],
+        );
+
         let hash_opt = self
             .engines()
             .first_success(|engine| async move {
@@ -771,6 +818,11 @@ impl ExecutionLayer {
         block_hash: ExecutionBlockHash,
         spec: &ChainSpec,
     ) -> Result<Option<bool>, Error> {
+        let _timer = metrics::start_timer_vec(
+            &metrics::EXECUTION_LAYER_REQUEST_TIMES,
+            &[metrics::IS_VALID_TERMINAL_POW_BLOCK_HASH],
+        );
+
         let broadcast_results = self
             .engines()
             .broadcast(|engine| async move {

beacon_node/execution_layer/src/metrics.rs

@@ -0,0 +1,27 @@
+pub use lighthouse_metrics::*;
+
+pub const GET_PAYLOAD: &str = "get_payload";
+pub const NEW_PAYLOAD: &str = "new_payload";
+pub const FORKCHOICE_UPDATED: &str = "forkchoice_updated";
+pub const GET_TERMINAL_POW_BLOCK_HASH: &str = "get_terminal_pow_block_hash";
+pub const IS_VALID_TERMINAL_POW_BLOCK_HASH: &str = "is_valid_terminal_pow_block_hash";
+
+lazy_static::lazy_static! {
+    pub static ref EXECUTION_LAYER_PROPOSER_INSERTED: Result<IntCounter> = try_create_int_counter(
+        "execution_layer_proposer_inserted",
+        "Count of times a new proposer is known",
+    );
+    pub static ref EXECUTION_LAYER_PROPOSER_DATA_UPDATED: Result<IntCounter> = try_create_int_counter(
+        "execution_layer_proposer_data_updated",
+        "Count of times new proposer data is supplied",
+    );
+    pub static ref EXECUTION_LAYER_REQUEST_TIMES: Result<HistogramVec> = try_create_histogram_vec(
+        "execution_layer_request_times",
+        "Duration of calls to ELs",
+        &["method"]
+    );
+    pub static ref EXECUTION_LAYER_PAYLOAD_ATTRIBUTES_LOOKAHEAD: Result<Histogram> = try_create_histogram(
+        "execution_layer_payload_attributes_lookahead",
+        "Duration between a fcU call with PayloadAttributes and when the block should be produced",
+    );
+}