Add BlockTimesCache to allow additional block delay metrics (#2546)

## Issue Addressed

Closes #2528

## Proposed Changes

- Add `BlockTimesCache` to provide block timing information to `BeaconChain`. This allows additional metrics to be calculated for blocks that are set as head too late.
- Thread the `seen_timestamp` of blocks received from RPC responses (except blocks from syncing) through to the sync manager, similar to what is done for blocks from gossip.

## Additional Info

This provides the following additional metrics:
- `BEACON_BLOCK_OBSERVED_SLOT_START_DELAY_TIME`
  - The delay between the start of the slot and when the block was first observed.
- `BEACON_BLOCK_IMPORTED_OBSERVED_DELAY_TIME`
   - The delay between when the block was first observed and when the block was imported.
- `BEACON_BLOCK_HEAD_IMPORTED_DELAY_TIME`
  - The delay between when the block was imported and when the block was set as head.

The metric `BEACON_BLOCK_IMPORTED_SLOT_START_DELAY_TIME` was removed.

A log is produced when a block is set as head too late, e.g.:
```
Aug 27 03:46:39.006 DEBG Delayed head block                      set_as_head_delay: Some(21.731066ms), imported_delay: Some(119.929934ms), observed_delay: Some(3.864596988s), block_delay: 4.006257988s, slot: 1931331, proposer_index: 24294, block_root: 0x937602c89d3143afa89088a44bdf4b4d0d760dad082abacb229495c048648a9e, service: beacon
```

beacon_node/network/src/beacon_processor/mod.rs

@@ -42,7 +42,7 @@ use crate::{metrics, service::NetworkMessage, sync::SyncMessage};
 use beacon_chain::{BeaconChain, BeaconChainTypes, BlockError, GossipVerifiedBlock};
 use eth2_libp2p::{
     rpc::{BlocksByRangeRequest, BlocksByRootRequest, StatusMessage},
-    MessageId, NetworkGlobals, PeerId, PeerRequestId,
+    Client, MessageId, NetworkGlobals, PeerId, PeerRequestId,
 };
 use futures::stream::{Stream, StreamExt};
 use futures::task::Poll;
@@ -341,6 +341,7 @@ impl<T: BeaconChainTypes> WorkEvent<T> {
     pub fn gossip_beacon_block(
         message_id: MessageId,
         peer_id: PeerId,
+        peer_client: Client,
         block: Box<SignedBeaconBlock<T::EthSpec>>,
         seen_timestamp: Duration,
     ) -> Self {
@@ -349,6 +350,7 @@ impl<T: BeaconChainTypes> WorkEvent<T> {
             work: Work::GossipBlock {
                 message_id,
                 peer_id,
+                peer_client,
                 block,
                 seen_timestamp,
             },
@@ -602,6 +604,7 @@ pub enum Work<T: BeaconChainTypes> {
     GossipBlock {
         message_id: MessageId,
         peer_id: PeerId,
+        peer_client: Client,
         block: Box<SignedBeaconBlock<T::EthSpec>>,
         seen_timestamp: Duration,
     },
@@ -1362,11 +1365,13 @@ impl<T: BeaconChainTypes> BeaconProcessor<T> {
                     Work::GossipBlock {
                         message_id,
                         peer_id,
+                        peer_client,
                         block,
                         seen_timestamp,
                     } => worker.process_gossip_block(
                         message_id,
                         peer_id,
+                        peer_client,
                         *block,
                         work_reprocessing_tx,
                         seen_timestamp,

beacon_node/network/src/beacon_processor/tests.rs

@@ -231,6 +231,7 @@ impl TestRig {
             .try_send(WorkEvent::gossip_beacon_block(
                 junk_message_id(),
                 junk_peer_id(),
+                Client::default(),
                 Box::new(self.next_block.clone()),
                 Duration::from_secs(0),
             ))

beacon_node/network/src/beacon_processor/worker/gossip_methods.rs

@@ -7,7 +7,7 @@ use beacon_chain::{
     validator_monitor::get_block_delay_ms,
     BeaconChainError, BeaconChainTypes, BlockError, ForkChoiceError, GossipVerifiedBlock,
 };
-use eth2_libp2p::{MessageAcceptance, MessageId, PeerAction, PeerId, ReportSource};
+use eth2_libp2p::{Client, MessageAcceptance, MessageId, PeerAction, PeerId, ReportSource};
 use slog::{crit, debug, error, info, trace, warn};
 use slot_clock::SlotClock;
 use ssz::Encode;
@@ -622,6 +622,7 @@ impl<T: BeaconChainTypes> Worker<T> {
         self,
         message_id: MessageId,
         peer_id: PeerId,
+        peer_client: Client,
         block: SignedBeaconBlock<T::EthSpec>,
         reprocess_tx: mpsc::Sender<ReprocessQueueMessage<T>>,
         seen_duration: Duration,
@@ -634,6 +635,15 @@ impl<T: BeaconChainTypes> Worker<T> {
             block_delay,
         );
 
+        // Write the time the block was observed into delay cache.
+        self.chain.block_times_cache.write().set_time_observed(
+            block.canonical_root(),
+            block.slot(),
+            seen_duration,
+            Some(peer_id.to_string()),
+            Some(peer_client.to_string()),
+        );
+
         let verified_block = match self.chain.verify_block_for_gossip(block) {
             Ok(verified_block) => {
                 if block_delay >= self.chain.slot_clock.unagg_attestation_production_delay() {

beacon_node/network/src/router/mod.rs

@@ -223,7 +223,12 @@ impl<T: BeaconChainTypes> Router<T> {
                 );
             }
             PubsubMessage::BeaconBlock(block) => {
-                self.processor.on_block_gossip(id, peer_id, block);
+                self.processor.on_block_gossip(
+                    id,
+                    peer_id,
+                    self.network_globals.client(&peer_id),
+                    block,
+                );
             }
             PubsubMessage::VoluntaryExit(exit) => {
                 debug!(self.log, "Received a voluntary exit"; "peer_id" => %peer_id);

beacon_node/network/src/router/processor.rs

@@ -5,7 +5,7 @@ use crate::service::NetworkMessage;
 use crate::sync::SyncMessage;
 use beacon_chain::{BeaconChain, BeaconChainError, BeaconChainTypes};
 use eth2_libp2p::rpc::*;
-use eth2_libp2p::{MessageId, NetworkGlobals, PeerId, PeerRequestId, Request, Response};
+use eth2_libp2p::{Client, MessageId, NetworkGlobals, PeerId, PeerRequestId, Request, Response};
 use slog::{debug, error, o, trace, warn};
 use std::cmp;
 use std::sync::Arc;
@@ -211,6 +211,7 @@ impl<T: BeaconChainTypes> Processor<T> {
                 peer_id,
                 request_id: id,
                 beacon_block,
+                seen_timestamp: timestamp_now(),
             });
         } else {
             debug!(
@@ -229,11 +230,13 @@ impl<T: BeaconChainTypes> Processor<T> {
         &mut self,
         message_id: MessageId,
         peer_id: PeerId,
+        peer_client: Client,
         block: Box<SignedBeaconBlock<T::EthSpec>>,
     ) {
         self.send_beacon_processor_work(BeaconWorkEvent::gossip_beacon_block(
             message_id,
             peer_id,
+            peer_client,
             block,
             timestamp_now(),
         ))

beacon_node/network/src/sync/manager.rs

@@ -54,6 +54,7 @@ use ssz_types::VariableList;
 use std::boxed::Box;
 use std::ops::Sub;
 use std::sync::Arc;
+use std::time::Duration;
 use tokio::sync::mpsc;
 use types::{Epoch, EthSpec, Hash256, SignedBeaconBlock, Slot};
 
@@ -90,6 +91,7 @@ pub enum SyncMessage<T: EthSpec> {
         peer_id: PeerId,
         request_id: RequestId,
         beacon_block: Option<Box<SignedBeaconBlock<T>>>,
+        seen_timestamp: Duration,
     },
 
     /// A block with an unknown parent has been received.
@@ -313,6 +315,7 @@ impl<T: BeaconChainTypes> SyncManager<T> {
         peer_id: PeerId,
         request_id: RequestId,
         block: Option<SignedBeaconBlock<T::EthSpec>>,
+        seen_timestamp: Duration,
     ) {
         match block {
             Some(block) => {
@@ -326,7 +329,7 @@ impl<T: BeaconChainTypes> SyncManager<T> {
                     single_block_hash = Some(block_request.hash);
                 }
                 if let Some(block_hash) = single_block_hash {
-                    self.single_block_lookup_response(peer_id, block, block_hash)
+                    self.single_block_lookup_response(peer_id, block, block_hash, seen_timestamp)
                         .await;
                     return;
                 }
@@ -449,6 +452,7 @@ impl<T: BeaconChainTypes> SyncManager<T> {
         peer_id: PeerId,
         block: SignedBeaconBlock<T::EthSpec>,
         expected_block_hash: Hash256,
+        seen_timestamp: Duration,
     ) {
         // verify the hash is correct and try and process the block
         if expected_block_hash != block.canonical_root() {
@@ -467,6 +471,14 @@ impl<T: BeaconChainTypes> SyncManager<T> {
         // we have the correct block, try and process it
         match block_result {
             Ok(block_root) => {
+                // Block has been processed, so write the block time to the cache.
+                self.chain.block_times_cache.write().set_time_observed(
+                    block_root,
+                    block.slot(),
+                    seen_timestamp,
+                    None,
+                    None,
+                );
                 info!(self.log, "Processed block"; "block" => %block_root);
 
                 match self.chain.fork_choice() {
@@ -1007,9 +1019,15 @@ impl<T: BeaconChainTypes> SyncManager<T> {
                         peer_id,
                         request_id,
                         beacon_block,
+                        seen_timestamp,
                     } => {
-                        self.blocks_by_root_response(peer_id, request_id, beacon_block.map(|b| *b))
-                            .await;
+                        self.blocks_by_root_response(
+                            peer_id,
+                            request_id,
+                            beacon_block.map(|b| *b),
+                            seen_timestamp,
+                        )
+                        .await;
                     }
                     SyncMessage::UnknownBlock(peer_id, block) => {
                         self.add_unknown_block(peer_id, *block);