diff --git a/dashboards/lodestar_general.json b/dashboards/lodestar_general.json index 6f2d45f27974..24d201056bc4 100644 --- a/dashboards/lodestar_general.json +++ b/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", diff --git a/packages/lodestar/src/chain/clock/LocalClock.ts b/packages/lodestar/src/chain/clock/LocalClock.ts index e6c94294ca07..7ae4ab0652a2 100644 --- a/packages/lodestar/src/chain/clock/LocalClock.ts +++ b/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 diff --git a/packages/lodestar/src/chain/clock/interface.ts b/packages/lodestar/src/chain/clock/interface.ts index 202f7720e900..691ddf530870 100644 --- a/packages/lodestar/src/chain/clock/interface.ts +++ b/packages/lodestar/src/chain/clock/interface.ts @@ -29,4 +29,8 @@ export interface IBeaconClock { * Rejects if the clock is aborted */ waitForSlot(slot: Slot): Promise; + /** + * Return second from a slot to either toSec or now. + */ + secFromSlot(slot: Slot, toSec?: number): number; } diff --git a/packages/lodestar/src/chain/eventHandlers.ts b/packages/lodestar/src/chain/eventHandlers.ts index 9fae7140a265..5161809cc266 100644 --- a/packages/lodestar/src/chain/eventHandlers.ts +++ b/packages/lodestar/src/chain/eventHandlers.ts @@ -149,13 +149,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 { @@ -184,6 +194,7 @@ export async function onBlock( this.logger.verbose("Block processed", { slot: block.message.slot, root: blockRoot, + delaySec: this.clock.secFromSlot(block.message.slot), }); } diff --git a/packages/lodestar/src/metrics/metrics/lodestar.ts b/packages/lodestar/src/metrics/metrics/lodestar.ts index b655736d5afc..49a56dbfe19d 100644 --- a/packages/lodestar/src/metrics/metrics/lodestar.ts +++ b/packages/lodestar/src/metrics/metrics/lodestar.ts @@ -514,17 +514,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({ diff --git a/packages/lodestar/src/metrics/validatorMonitor.ts b/packages/lodestar/src/metrics/validatorMonitor.ts index 942d38c8b31b..7c4b76d87689 100644 --- a/packages/lodestar/src/metrics/validatorMonitor.ts +++ b/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); diff --git a/packages/lodestar/src/network/gossip/handlers/index.ts b/packages/lodestar/src/network/gossip/handlers/index.ts index 08a0f0c77f59..51c15bf5dc60 100644 --- a/packages/lodestar/src/network/gossip/handlers/index.ts +++ b/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) { diff --git a/packages/lodestar/test/utils/clock.ts b/packages/lodestar/test/utils/clock.ts index db1cd8a451c0..d65c19fa7185 100644 --- a/packages/lodestar/test/utils/clock.ts +++ b/packages/lodestar/test/utils/clock.ts @@ -28,4 +28,9 @@ export class ClockStatic implements IBeaconClock { async waitForSlot(): Promise { // } + + secFromSlot(slot: number, toSec?: number): number { + // SECONDS_PER_SLOT = 6 in minimal config + return (toSec ?? Date.now() / 1000) - slot * 6; + } }