New metric filtering missed blocks (#3927)

* Log block delay second

* Add elappsedTimeTillBecomeHead metric

* Add 'till become head' metric to dashboard

* chore: correct the metric name to elapsedTimeTillBecomeHead

* Add and use secFromSlot to clock

* Track block source

* Revert "Track block source"

This reverts commit 5fe62204e827e313fe6d081bb258e5306f3a734a.

* Update bucket values

* Limit how old blocks are tracked in elapsedTimeTillBecomeHead

* Simplify secFromSlot

Co-authored-by: dapplion <35266934+dapplion@users.noreply.github.com>

dashboards/lodestar_general.json

@@ -8632,6 +8632,18 @@
               "interval": "",
               "legendFormat": "till processed",
               "refId": "B"
+            },
+            {
+              "datasource": {
+                "type": "prometheus",
+                "uid": "${DS_PROMETHEUS}"
+              },
+              "exemplar": false,
+              "expr": "delta(lodestar_gossip_block_elapsed_time_till_become_head_sum[$__rate_interval])\n/\ndelta(lodestar_gossip_block_elapsed_time_till_become_head_count[$__rate_interval])",
+              "hide": false,
+              "interval": "",
+              "legendFormat": "till become head",
+              "refId": "C"
             }
           ],
           "title": "Gossip Block Received Delay",

packages/lodestar/src/chain/clock/LocalClock.ts

@@ -128,6 +128,10 @@ export class LocalClock implements IBeaconClock {
     });
   }
 
+  secFromSlot(slot: Slot, toSec = Date.now() / 1000): number {
+    return toSec - (this.genesisTime + slot * this.config.SECONDS_PER_SLOT);
+  }
+
   private onNextSlot = (slot?: Slot): void => {
     const clockSlot = slot ?? getCurrentSlot(this.config, this.genesisTime);
     // process multiple clock slots in the case the main thread has been saturated for > SECONDS_PER_SLOT

packages/lodestar/src/chain/clock/interface.ts

@@ -29,4 +29,8 @@ export interface IBeaconClock {
    * Rejects if the clock is aborted
    */
   waitForSlot(slot: Slot): Promise<void>;
+  /**
+   * Return second from a slot to either toSec or now.
+   */
+  secFromSlot(slot: Slot, toSec?: number): number;
 }

packages/lodestar/src/chain/eventHandlers.ts

@@ -151,13 +151,23 @@ export async function onForkChoiceFinalized(this: BeaconChain, cp: CheckpointWit
 }
 
 export function onForkChoiceHead(this: BeaconChain, head: IProtoBlock): void {
+  const delaySec = this.clock.secFromSlot(head.slot);
   this.logger.verbose("New chain head", {
     headSlot: head.slot,
     headRoot: head.blockRoot,
+    delaySec,
   });
   this.syncContributionAndProofPool.prune(head.slot);
   this.seenContributionAndProof.prune(head.slot);
-  this.metrics?.headSlot.set(head.slot);
+
+  if (this.metrics) {
+    this.metrics.headSlot.set(head.slot);
+    // Only track "recent" blocks. Otherwise sync can distort this metrics heavily.
+    // We want to track recent blocks coming from gossip, unknown block sync, and API.
+    if (delaySec < 64 * this.config.SECONDS_PER_SLOT) {
+      this.metrics.elapsedTimeTillBecomeHead.observe(delaySec);
+    }
+  }
 }
 
 export function onForkChoiceReorg(this: BeaconChain, head: IProtoBlock, oldHead: IProtoBlock, depth: number): void {
@@ -186,6 +196,7 @@ export async function onBlock(
   this.logger.verbose("Block processed", {
     slot: block.message.slot,
     root: blockRoot,
+    delaySec: this.clock.secFromSlot(block.message.slot),
   });
 }
 

packages/lodestar/src/metrics/metrics/lodestar.ts

@@ -523,17 +523,22 @@ export function createLodestarMetrics(
 
     // Gossip block
     gossipBlock: {
-      elappsedTimeTillReceived: register.histogram({
+      elapsedTimeTillReceived: register.histogram({
         name: "lodestar_gossip_block_elappsed_time_till_received",
         help: "Time elappsed between block slot time and the time block received via gossip",
-        buckets: [0.1, 1, 10],
+        buckets: [0.5, 1, 2, 4, 6, 12],
       }),
-      elappsedTimeTillProcessed: register.histogram({
+      elapsedTimeTillProcessed: register.histogram({
         name: "lodestar_gossip_block_elappsed_time_till_processed",
         help: "Time elappsed between block slot time and the time block processed",
-        buckets: [0.1, 1, 10],
+        buckets: [0.5, 1, 2, 4, 6, 12],
       }),
     },
+    elapsedTimeTillBecomeHead: register.histogram({
+      name: "lodestar_gossip_block_elapsed_time_till_become_head",
+      help: "Time elappsed between block slot time and the time block becomes head",
+      buckets: [0.5, 1, 2, 4, 6, 12],
+    }),
 
     backfillSync: {
       backfilledTillSlot: register.gauge({

packages/lodestar/src/metrics/validatorMonitor.ts

@@ -277,7 +277,7 @@ export function createValidatorMonitor(
       const validator = validators.get(index);
       // Returns the delay between the start of `block.slot` and `seenTimestamp`.
       const delaySec = seenTimestampSec - (genesisTime + block.slot * config.SECONDS_PER_SLOT);
-      metrics.gossipBlock.elappsedTimeTillReceived.observe(delaySec);
+      metrics.gossipBlock.elapsedTimeTillReceived.observe(delaySec);
       if (validator) {
         metrics.validatorMonitor.beaconBlockTotal.inc({src, index});
         metrics.validatorMonitor.beaconBlockDelaySeconds.observe({src, index}, delaySec);

packages/lodestar/src/network/gossip/handlers/index.ts

@@ -76,11 +76,13 @@ export function getGossipHandlers(modules: ValidatorFnsModules, options: GossipH
     [GossipType.beacon_block]: async (signedBlock, topic, peerIdStr, seenTimestampSec) => {
       const slot = signedBlock.message.slot;
       const blockHex = prettyBytes(config.getForkTypes(slot).BeaconBlock.hashTreeRoot(signedBlock.message));
+      const delaySec = chain.clock.secFromSlot(slot, seenTimestampSec);
       logger.verbose("Received gossip block", {
         slot: slot,
         root: blockHex,
         curentSlot: chain.clock.currentSlot,
         peerId: peerIdStr,
+        delaySec,
       });
 
       try {
@@ -120,8 +122,8 @@ export function getGossipHandlers(modules: ValidatorFnsModules, options: GossipH
         .processBlock(signedBlock, {validProposerSignature: true, blsVerifyOnMainThread: true})
         .then(() => {
           // Returns the delay between the start of `block.slot` and `current time`
-          const delaySec = Date.now() / 1000 - (chain.genesisTime + slot * config.SECONDS_PER_SLOT);
-          metrics?.gossipBlock.elappsedTimeTillProcessed.observe(delaySec);
+          const delaySec = chain.clock.secFromSlot(slot);
+          metrics?.gossipBlock.elapsedTimeTillProcessed.observe(delaySec);
         })
         .catch((e) => {
           if (e instanceof BlockError) {

packages/lodestar/test/utils/clock.ts

@@ -28,4 +28,9 @@ export class ClockStatic implements IBeaconClock {
   async waitForSlot(): Promise<void> {
     //
   }
+
+  secFromSlot(slot: number, toSec?: number): number {
+    // SECONDS_PER_SLOT = 6 in minimal config
+    return (toSec ?? Date.now() / 1000) - slot * 6;
+  }
 }