From ca528a868198023605205c74439047086327f4d0 Mon Sep 17 00:00:00 2001 From: Tuyen Nguyen Date: Wed, 6 Apr 2022 11:20:36 +0700 Subject: [PATCH 1/8] Log attestation journey --- .../src/api/impl/beacon/pool/index.ts | 11 +-- .../lodestar/src/api/impl/validator/index.ts | 22 ++---- packages/lodestar/src/metrics/metrics.ts | 6 +- .../lodestar/src/metrics/metrics/lodestar.ts | 6 ++ .../lodestar/src/metrics/validatorMonitor.ts | 67 ++++++++++++++++++- .../lodestar/src/network/gossip/gossipsub.ts | 11 +-- packages/lodestar/src/node/nodejs.ts | 4 +- packages/lodestar/test/unit/metrics/utils.ts | 4 +- 8 files changed, 97 insertions(+), 34 deletions(-) diff --git a/packages/lodestar/src/api/impl/beacon/pool/index.ts b/packages/lodestar/src/api/impl/beacon/pool/index.ts index d51a771695b8..2805f785d15e 100644 --- a/packages/lodestar/src/api/impl/beacon/pool/index.ts +++ b/packages/lodestar/src/api/impl/beacon/pool/index.ts @@ -8,7 +8,6 @@ import {validateGossipProposerSlashing} from "../../../../chain/validation/propo import {validateGossipVoluntaryExit} from "../../../../chain/validation/voluntaryExit"; import {validateSyncCommitteeSigOnly} from "../../../../chain/validation/syncCommittee"; import {ApiModules} from "../../types"; -import {OpSource} from "../../../../metrics/validatorMonitor"; import {toHexString} from "@chainsafe/ssz"; import {AttestationError, GossipAction, SyncCommitteeError} from "../../../../chain/errors"; @@ -43,7 +42,6 @@ export function getBeaconPoolApi({ }, async submitPoolAttestations(attestations) { - const seenTimestampSec = Date.now() / 1000; const errors: Error[] = []; await Promise.all( @@ -51,12 +49,9 @@ export function getBeaconPoolApi({ try { const {indexedAttestation, subnet} = await validateGossipAttestation(chain, attestation, null); - metrics?.registerUnaggregatedAttestation(OpSource.api, seenTimestampSec, indexedAttestation); - - await Promise.all([ - network.gossip.publishBeaconAttestation(attestation, subnet), - chain.attestationPool.add(attestation), - ]); + chain.attestationPool.add(attestation); + const sentPeers = await network.gossip.publishBeaconAttestation(attestation, subnet); + metrics?.submitUnaggregatedAttestation(indexedAttestation, subnet, sentPeers); } catch (e) { errors.push(e as Error); logger.error( diff --git a/packages/lodestar/src/api/impl/validator/index.ts b/packages/lodestar/src/api/impl/validator/index.ts index 0d9dff34ea8c..e06f5e833620 100644 --- a/packages/lodestar/src/api/impl/validator/index.ts +++ b/packages/lodestar/src/api/impl/validator/index.ts @@ -25,7 +25,6 @@ import {toGraffitiBuffer} from "../../../util/graffiti"; import {ApiError, NodeIsSyncing} from "../errors"; import {validateSyncCommitteeGossipContributionAndProof} from "../../../chain/validation/syncCommitteeContributionAndProof"; import {CommitteeSubscription} from "../../../network/subnets"; -import {OpSource} from "../../../metrics/validatorMonitor"; import {computeSubnetForCommitteesAtSlot, getPubkeysForIndices} from "./utils"; import {ApiModules} from "../types"; import {RegenCaller} from "../../../chain/regen"; @@ -424,7 +423,6 @@ export function getValidatorApi({chain, config, logger, metrics, network, sync}: async publishAggregateAndProofs(signedAggregateAndProofs) { notWhileSyncing(); - const seenTimestampSec = Date.now() / 1000; const errors: Error[] = []; await Promise.all( @@ -436,21 +434,13 @@ export function getValidatorApi({chain, config, logger, metrics, network, sync}: signedAggregateAndProof ); - metrics?.registerAggregatedAttestation( - OpSource.api, - seenTimestampSec, - signedAggregateAndProof, - indexedAttestation + chain.aggregatedAttestationPool.add( + signedAggregateAndProof.message.aggregate, + indexedAttestation.attestingIndices, + committeeIndices ); - - await Promise.all([ - chain.aggregatedAttestationPool.add( - signedAggregateAndProof.message.aggregate, - indexedAttestation.attestingIndices, - committeeIndices - ), - network.gossip.publishBeaconAggregateAndProof(signedAggregateAndProof), - ]); + const sentPeers = await network.gossip.publishBeaconAggregateAndProof(signedAggregateAndProof); + metrics?.submitAggregatedAttestation(indexedAttestation, sentPeers); } catch (e) { if (e instanceof AttestationError && e.type.code === AttestationErrorCode.AGGREGATOR_ALREADY_KNOWN) { logger.debug("Ignoring known signedAggregateAndProof"); diff --git a/packages/lodestar/src/metrics/metrics.ts b/packages/lodestar/src/metrics/metrics.ts index f4ec0e2ce2d1..c6f7889913a1 100644 --- a/packages/lodestar/src/metrics/metrics.ts +++ b/packages/lodestar/src/metrics/metrics.ts @@ -1,6 +1,7 @@ /** * @module metrics */ +import {ILogger} from "@chainsafe/lodestar-utils"; import {BeaconStateAllForks, getCurrentSlot} from "@chainsafe/lodestar-beacon-state-transition"; import {IChainForkConfig} from "@chainsafe/lodestar-config"; import {collectDefaultMetrics, Counter, Metric, Registry} from "prom-client"; @@ -18,14 +19,15 @@ export function createMetrics( opts: IMetricsOptions, config: IChainForkConfig, anchorState: BeaconStateAllForks, - externalRegistries: Registry[] = [] + logger: ILogger, + externalRegistries: Registry[] = [], ): IMetrics { const register = new RegistryMetricCreator(); const beacon = createBeaconMetrics(register); const lodestar = createLodestarMetrics(register, opts.metadata, anchorState); const genesisTime = anchorState.genesisTime; - const validatorMonitor = createValidatorMonitor(lodestar, config, genesisTime); + const validatorMonitor = createValidatorMonitor(lodestar, config, genesisTime, logger); // Register a single collect() function to run all validatorMonitor metrics lodestar.validatorMonitor.validatorsTotal.addCollect(() => { const clockSlot = getCurrentSlot(config, genesisTime); diff --git a/packages/lodestar/src/metrics/metrics/lodestar.ts b/packages/lodestar/src/metrics/metrics/lodestar.ts index 5455f2a33ae3..f01135d76558 100644 --- a/packages/lodestar/src/metrics/metrics/lodestar.ts +++ b/packages/lodestar/src/metrics/metrics/lodestar.ts @@ -644,6 +644,12 @@ export function createLodestarMetrics( labelNames: ["index", "src"], buckets: [0.1, 1], }), + unaggregatedAttestationSubmittedSentPeers: register.histogram<"index">({ + name: "validator_monitor_unaggregated_attestation_submited_sent_peers_total", + help: "Number of unaggregated attestations submitted by local validator that has no subnet peers", + labelNames: ["index"], + buckets: [0, 2, 5, 10], + }), aggregatedAttestationTotal: register.gauge<"index" | "src">({ name: "validator_monitor_aggregated_attestation_total", help: "Number of aggregated attestations seen", diff --git a/packages/lodestar/src/metrics/validatorMonitor.ts b/packages/lodestar/src/metrics/validatorMonitor.ts index f7348fb9ee37..527389b04023 100644 --- a/packages/lodestar/src/metrics/validatorMonitor.ts +++ b/packages/lodestar/src/metrics/validatorMonitor.ts @@ -4,6 +4,7 @@ import { IAttesterStatus, parseAttesterFlags, } from "@chainsafe/lodestar-beacon-state-transition"; +import {ILogger} from "@chainsafe/lodestar-utils"; import {allForks} from "@chainsafe/lodestar-beacon-state-transition"; import {IChainForkConfig} from "@chainsafe/lodestar-config"; import {MIN_ATTESTATION_INCLUSION_DELAY, SLOTS_PER_EPOCH} from "@chainsafe/lodestar-params"; @@ -26,11 +27,13 @@ export interface IValidatorMonitor { registerLocalValidator(index: number): void; registerValidatorStatuses(currentEpoch: Epoch, statuses: IAttesterStatus[], balances?: number[]): void; registerBeaconBlock(src: OpSource, seenTimestampSec: Seconds, block: allForks.BeaconBlock): void; + submitUnaggregatedAttestation(indexedAttestation: IndexedAttestation, subnet: number, sentPeers: number): void; registerUnaggregatedAttestation( src: OpSource, seenTimestampSec: Seconds, indexedAttestation: IndexedAttestation ): void; + submitAggregatedAttestation(indexedAttestation: IndexedAttestation, sentPeers: number): void; registerAggregatedAttestation( src: OpSource, seenTimestampSec: Seconds, @@ -166,7 +169,8 @@ type MonitoredValidator = { export function createValidatorMonitor( metrics: ILodestarMetrics, config: IChainForkConfig, - genesisTime: number + genesisTime: number, + logger: ILogger ): IValidatorMonitor { /** The validators that require additional monitoring. */ const validators = new Map(); @@ -201,23 +205,37 @@ export function createValidatorMonitor( } const summary = statusToSummary(status); + let failedAttestation = false; if (summary.isPrevSourceAttester) { metrics.validatorMonitor.prevEpochOnChainAttesterHit.inc({index}); } else { + failedAttestation = true; metrics.validatorMonitor.prevEpochOnChainAttesterMiss.inc({index}); } if (summary.isPrevHeadAttester) { metrics.validatorMonitor.prevEpochOnChainHeadAttesterHit.inc({index}); } else { + failedAttestation = true; metrics.validatorMonitor.prevEpochOnChainHeadAttesterMiss.inc({index}); } if (summary.isPrevTargetAttester) { metrics.validatorMonitor.prevEpochOnChainTargetAttesterHit.inc({index}); } else { + failedAttestation = true; metrics.validatorMonitor.prevEpochOnChainTargetAttesterMiss.inc({index}); } + if (failedAttestation) { + logger.verbose("Failed attestation in previous epoch", { + validatorIndex: index, + currentEpoch, + isPrevSourceAttester: summary.isPrevSourceAttester, + isPrevHeadAttester: summary.isPrevHeadAttester, + isPrevTargetAttester: summary.isPrevTargetAttester, + }); + } + const prevEpochSummary = monitoredValidator.summaries.get(previousEpoch); const attestationCorrectHead = prevEpochSummary?.attestationCorrectHead; if (attestationCorrectHead !== null && attestationCorrectHead !== undefined) { @@ -257,6 +275,25 @@ export function createValidatorMonitor( } }, + submitUnaggregatedAttestation(indexedAttestation, subnet, sentPeers) { + const data = indexedAttestation.data; + for (const index of indexedAttestation.attestingIndices) { + const validator = validators.get(index); + if (validator) { + if (sentPeers <= 0) { + metrics.validatorMonitor.unaggregatedAttestationSubmittedSentPeers.observe({index}, sentPeers); + } + logger.verbose("Local validator published unaggregated attestation", { + validatorIndex: validator.index, + slot: data.slot, + committeeIndex: data.index, + subnet, + sentPeers, + }); + } + } + }, + registerUnaggregatedAttestation(src, seenTimestampSec, indexedAttestation) { const data = indexedAttestation.data; const epoch = computeEpochAtSlot(data.slot); @@ -276,6 +313,21 @@ export function createValidatorMonitor( } }, + submitAggregatedAttestation(indexedAttestation, sentPeers) { + const data = indexedAttestation.data; + for (const index of indexedAttestation.attestingIndices) { + const validator = validators.get(index); + if (validator) { + logger.verbose("Local validator published aggregated attestation", { + validatorIndex: validator.index, + slot: data.slot, + committeeIndex: data.index, + sentPeers, + }); + } + } + }, + registerAggregatedAttestation(src, seenTimestampSec, signedAggregateAndProof, indexedAttestation) { const data = indexedAttestation.data; const epoch = computeEpochAtSlot(data.slot); @@ -302,6 +354,11 @@ export function createValidatorMonitor( withEpochSummary(validator, epoch, (summary) => { summary.attestationAggregateIncusions += 1; }); + logger.verbose("Local validator attestation is included in AggregatedAndProof", { + validatorIndex: validator.index, + slot: data.slot, + committeeIndex: data.index, + }); } } }, @@ -336,6 +393,14 @@ export function createValidatorMonitor( } summary.attestationCorrectHead = correctHead; }); + + logger.verbose("Local validator attestation is included in block", { + validatorIndex: validator.index, + slot: data.slot, + committeeIndex: data.index, + inclusionDistance, + correctHead, + }); } } }, diff --git a/packages/lodestar/src/network/gossip/gossipsub.ts b/packages/lodestar/src/network/gossip/gossipsub.ts index a0ec23266f5d..b26f743f3511 100644 --- a/packages/lodestar/src/network/gossip/gossipsub.ts +++ b/packages/lodestar/src/network/gossip/gossipsub.ts @@ -148,12 +148,13 @@ export class Eth2Gossipsub extends Gossipsub { /** * Publish a `GossipObject` on a `GossipTopic` */ - async publishObject(topic: GossipTopicMap[K], object: GossipTypeMap[K]): Promise { + async publishObject(topic: GossipTopicMap[K], object: GossipTypeMap[K]): Promise { const topicStr = this.getGossipTopicString(topic); const sszType = getGossipSSZType(topic); const messageData = (sszType.serialize as (object: GossipTypeMap[GossipType]) => Uint8Array)(object); const sentPeers = await this.publish(topicStr, messageData); this.logger.verbose("Publish to topic", {topic: topicStr, sentPeers}); + return sentPeers; } /** @@ -182,17 +183,17 @@ export class Eth2Gossipsub extends Gossipsub { await this.publishObject({type: GossipType.beacon_block, fork}, signedBlock); } - async publishBeaconAggregateAndProof(aggregateAndProof: phase0.SignedAggregateAndProof): Promise { + async publishBeaconAggregateAndProof(aggregateAndProof: phase0.SignedAggregateAndProof): Promise { const fork = this.config.getForkName(aggregateAndProof.message.aggregate.data.slot); - await this.publishObject( + return await this.publishObject( {type: GossipType.beacon_aggregate_and_proof, fork}, aggregateAndProof ); } - async publishBeaconAttestation(attestation: phase0.Attestation, subnet: number): Promise { + async publishBeaconAttestation(attestation: phase0.Attestation, subnet: number): Promise { const fork = this.config.getForkName(attestation.data.slot); - await this.publishObject( + return await this.publishObject( {type: GossipType.beacon_attestation, fork, subnet}, attestation ); diff --git a/packages/lodestar/src/node/nodejs.ts b/packages/lodestar/src/node/nodejs.ts index 66e1f524eade..15f970e57dfa 100644 --- a/packages/lodestar/src/node/nodejs.ts +++ b/packages/lodestar/src/node/nodejs.ts @@ -128,7 +128,9 @@ export class BeaconNode { // start db if not already started await db.start(); - const metrics = opts.metrics.enabled ? createMetrics(opts.metrics, config, anchorState, metricsRegistries) : null; + const metrics = opts.metrics.enabled + ? createMetrics(opts.metrics, config, anchorState, logger.child({module: "VMON"}), metricsRegistries) + : null; if (metrics) { initBeaconMetrics(metrics, anchorState); } diff --git a/packages/lodestar/test/unit/metrics/utils.ts b/packages/lodestar/test/unit/metrics/utils.ts index d13f132850ba..616822014583 100644 --- a/packages/lodestar/test/unit/metrics/utils.ts +++ b/packages/lodestar/test/unit/metrics/utils.ts @@ -1,8 +1,10 @@ import {config} from "@chainsafe/lodestar-config/default"; import {ssz} from "@chainsafe/lodestar-types"; +import {WinstonLogger} from "@chainsafe/lodestar-utils"; import {createMetrics, IMetrics} from "../../../src/metrics"; export function createMetricsTest(): IMetrics { const state = ssz.phase0.BeaconState.defaultViewDU(); - return createMetrics({enabled: true, timeout: 12000}, config, state); + const logger = new WinstonLogger(); + return createMetrics({enabled: true, timeout: 12000}, config, state, logger); } From d4a770e3844f5887761014e64f6076fc830cf76b Mon Sep 17 00:00:00 2001 From: Tuyen Nguyen Date: Thu, 7 Apr 2022 14:51:29 +0700 Subject: [PATCH 2/8] Fix lint and log --- packages/lodestar/src/metrics/metrics.ts | 2 +- packages/lodestar/src/metrics/validatorMonitor.ts | 3 ++- 2 files changed, 3 insertions(+), 2 deletions(-) diff --git a/packages/lodestar/src/metrics/metrics.ts b/packages/lodestar/src/metrics/metrics.ts index c6f7889913a1..3cfdb661cca0 100644 --- a/packages/lodestar/src/metrics/metrics.ts +++ b/packages/lodestar/src/metrics/metrics.ts @@ -20,7 +20,7 @@ export function createMetrics( config: IChainForkConfig, anchorState: BeaconStateAllForks, logger: ILogger, - externalRegistries: Registry[] = [], + externalRegistries: Registry[] = [] ): IMetrics { const register = new RegistryMetricCreator(); const beacon = createBeaconMetrics(register); diff --git a/packages/lodestar/src/metrics/validatorMonitor.ts b/packages/lodestar/src/metrics/validatorMonitor.ts index 527389b04023..1399c9ad15f7 100644 --- a/packages/lodestar/src/metrics/validatorMonitor.ts +++ b/packages/lodestar/src/metrics/validatorMonitor.ts @@ -229,10 +229,11 @@ export function createValidatorMonitor( if (failedAttestation) { logger.verbose("Failed attestation in previous epoch", { validatorIndex: index, - currentEpoch, + prevEpoch: currentEpoch - 1, isPrevSourceAttester: summary.isPrevSourceAttester, isPrevHeadAttester: summary.isPrevHeadAttester, isPrevTargetAttester: summary.isPrevTargetAttester, + inclusionDistance: summary.inclusionDistance, }); } From d494aab9d1cdb751a2d1053b62e4a0c43e1ecac2 Mon Sep 17 00:00:00 2001 From: Tuyen Nguyen Date: Thu, 7 Apr 2022 16:16:00 +0700 Subject: [PATCH 3/8] New metric: missed attestations vs big inclusion distance --- packages/lodestar/src/metrics/metrics/lodestar.ts | 15 +++++++++++++-- packages/lodestar/src/metrics/validatorMonitor.ts | 7 +++++-- 2 files changed, 18 insertions(+), 4 deletions(-) diff --git a/packages/lodestar/src/metrics/metrics/lodestar.ts b/packages/lodestar/src/metrics/metrics/lodestar.ts index f01135d76558..5cca99ab360e 100644 --- a/packages/lodestar/src/metrics/metrics/lodestar.ts +++ b/packages/lodestar/src/metrics/metrics/lodestar.ts @@ -542,12 +542,23 @@ export function createLodestarMetrics( }), prevEpochOnChainAttesterHit: register.gauge<"index">({ name: "validator_monitor_prev_epoch_on_chain_attester_hit_total", - help: "Incremented if the validator is flagged as a previous epoch attester during per epoch processing", + help: "Incremented if validator's submitted attestation is included in some blocks", labelNames: ["index"], }), prevEpochOnChainAttesterMiss: register.gauge<"index">({ name: "validator_monitor_prev_epoch_on_chain_attester_miss_total", - help: "Incremented if the validator is not flagged as a previous epoch attester during per epoch processing", + help: "Incremented if validator's submitted attestation is not included in any blocks", + labelNames: ["index"], + }), + prevEpochOnChainSourceAttesterHit: register.gauge<"index">({ + name: "validator_monitor_prev_epoch_on_chain_source_attester_hit_total", + help: "Incremented if the validator is flagged as a previous epoch source attester during per epoch processing", + labelNames: ["index"], + }), + prevEpochOnChainSourceAttesterMiss: register.gauge<"index">({ + name: "validator_monitor_prev_epoch_on_chain_source_attester_miss_total", + help: + "Incremented if the validator is not flagged as a previous epoch source attester during per epoch processing", labelNames: ["index"], }), prevEpochOnChainHeadAttesterHit: register.gauge<"index">({ diff --git a/packages/lodestar/src/metrics/validatorMonitor.ts b/packages/lodestar/src/metrics/validatorMonitor.ts index 1399c9ad15f7..00dc51627b92 100644 --- a/packages/lodestar/src/metrics/validatorMonitor.ts +++ b/packages/lodestar/src/metrics/validatorMonitor.ts @@ -208,10 +208,10 @@ export function createValidatorMonitor( let failedAttestation = false; if (summary.isPrevSourceAttester) { - metrics.validatorMonitor.prevEpochOnChainAttesterHit.inc({index}); + metrics.validatorMonitor.prevEpochOnChainSourceAttesterHit.inc({index}); } else { failedAttestation = true; - metrics.validatorMonitor.prevEpochOnChainAttesterMiss.inc({index}); + metrics.validatorMonitor.prevEpochOnChainSourceAttesterMiss.inc({index}); } if (summary.isPrevHeadAttester) { metrics.validatorMonitor.prevEpochOnChainHeadAttesterHit.inc({index}); @@ -255,6 +255,9 @@ export function createValidatorMonitor( if (inclusionDistance !== null) { metrics.validatorMonitor.prevEpochOnChainInclusionDistance.set({index}, inclusionDistance); + metrics.validatorMonitor.prevEpochOnChainAttesterHit.inc({index}); + } else { + metrics.validatorMonitor.prevEpochOnChainAttesterMiss.inc({index}); } const balance = balances && balances[index]; From a4850151e8b57fa901a073f34267e8fa42630a82 Mon Sep 17 00:00:00 2001 From: Tuyen Nguyen Date: Fri, 8 Apr 2022 09:14:00 +0700 Subject: [PATCH 4/8] Correct inclusionDistance in failed attestation log --- .../lodestar/src/metrics/validatorMonitor.ts | 23 ++++++++++--------- 1 file changed, 12 insertions(+), 11 deletions(-) diff --git a/packages/lodestar/src/metrics/validatorMonitor.ts b/packages/lodestar/src/metrics/validatorMonitor.ts index 00dc51627b92..21b8924c798d 100644 --- a/packages/lodestar/src/metrics/validatorMonitor.ts +++ b/packages/lodestar/src/metrics/validatorMonitor.ts @@ -226,17 +226,6 @@ export function createValidatorMonitor( metrics.validatorMonitor.prevEpochOnChainTargetAttesterMiss.inc({index}); } - if (failedAttestation) { - logger.verbose("Failed attestation in previous epoch", { - validatorIndex: index, - prevEpoch: currentEpoch - 1, - isPrevSourceAttester: summary.isPrevSourceAttester, - isPrevHeadAttester: summary.isPrevHeadAttester, - isPrevTargetAttester: summary.isPrevTargetAttester, - inclusionDistance: summary.inclusionDistance, - }); - } - const prevEpochSummary = monitoredValidator.summaries.get(previousEpoch); const attestationCorrectHead = prevEpochSummary?.attestationCorrectHead; if (attestationCorrectHead !== null && attestationCorrectHead !== undefined) { @@ -264,6 +253,18 @@ export function createValidatorMonitor( if (balance !== undefined) { metrics.validatorMonitor.prevEpochOnChainBalance.set({index}, balance); } + + if (failedAttestation) { + logger.verbose("Failed attestation in previous epoch", { + validatorIndex: index, + prevEpoch: currentEpoch - 1, + isPrevSourceAttester: summary.isPrevSourceAttester, + isPrevHeadAttester: summary.isPrevHeadAttester, + isPrevTargetAttester: summary.isPrevTargetAttester, + // inclusionDistance is not available in summary since altair + inclusionDistance, + }); + } } }, From 757863bcce58c9bdd605c825f977d12b1b7a901b Mon Sep 17 00:00:00 2001 From: Tuyen Nguyen Date: Sun, 10 Apr 2022 14:38:48 +0700 Subject: [PATCH 5/8] Track attestation publish delay second in metric and log --- .../lodestar/src/metrics/validatorMonitor.ts | 24 ++++++++++++------- .../src/network/gossip/handlers/index.ts | 9 ++----- 2 files changed, 17 insertions(+), 16 deletions(-) diff --git a/packages/lodestar/src/metrics/validatorMonitor.ts b/packages/lodestar/src/metrics/validatorMonitor.ts index 21b8924c798d..91e430206709 100644 --- a/packages/lodestar/src/metrics/validatorMonitor.ts +++ b/packages/lodestar/src/metrics/validatorMonitor.ts @@ -28,14 +28,9 @@ export interface IValidatorMonitor { registerValidatorStatuses(currentEpoch: Epoch, statuses: IAttesterStatus[], balances?: number[]): void; registerBeaconBlock(src: OpSource, seenTimestampSec: Seconds, block: allForks.BeaconBlock): void; submitUnaggregatedAttestation(indexedAttestation: IndexedAttestation, subnet: number, sentPeers: number): void; - registerUnaggregatedAttestation( - src: OpSource, - seenTimestampSec: Seconds, - indexedAttestation: IndexedAttestation - ): void; + registerGossipUnaggregatedAttestation(seenTimestampSec: Seconds, indexedAttestation: IndexedAttestation): void; submitAggregatedAttestation(indexedAttestation: IndexedAttestation, sentPeers: number): void; - registerAggregatedAttestation( - src: OpSource, + registerGossipAggregatedAttestation( seenTimestampSec: Seconds, signedAggregateAndProof: SignedAggregateAndProof, indexedAttestation: IndexedAttestation @@ -282,24 +277,29 @@ export function createValidatorMonitor( submitUnaggregatedAttestation(indexedAttestation, subnet, sentPeers) { const data = indexedAttestation.data; + // Returns the duration between when the attestation `data` could be produced (1/3rd through the slot) and `seenTimestamp`. + const delaySec = Math.floor(Date.now() / 1000) - (genesisTime + (data.slot + 1 / 3) * config.SECONDS_PER_SLOT); for (const index of indexedAttestation.attestingIndices) { const validator = validators.get(index); if (validator) { if (sentPeers <= 0) { metrics.validatorMonitor.unaggregatedAttestationSubmittedSentPeers.observe({index}, sentPeers); } + metrics.validatorMonitor.unaggregatedAttestationDelaySeconds.observe({src: OpSource.api, index}, delaySec); logger.verbose("Local validator published unaggregated attestation", { validatorIndex: validator.index, slot: data.slot, committeeIndex: data.index, subnet, sentPeers, + delaySec, }); } } }, - registerUnaggregatedAttestation(src, seenTimestampSec, indexedAttestation) { + registerGossipUnaggregatedAttestation(seenTimestampSec, indexedAttestation) { + const src = OpSource.gossip; const data = indexedAttestation.data; const epoch = computeEpochAtSlot(data.slot); // Returns the duration between when the attestation `data` could be produced (1/3rd through the slot) and `seenTimestamp`. @@ -320,20 +320,26 @@ export function createValidatorMonitor( submitAggregatedAttestation(indexedAttestation, sentPeers) { const data = indexedAttestation.data; + // Returns the duration between when a `AggregateAndproof` with `data` could be produced (2/3rd through the slot) and `seenTimestamp`. + const delaySec = Math.floor(Date.now() / 1000) - (genesisTime + (data.slot + 2 / 3) * config.SECONDS_PER_SLOT); + for (const index of indexedAttestation.attestingIndices) { const validator = validators.get(index); if (validator) { + metrics.validatorMonitor.aggregatedAttestationDelaySeconds.observe({src: OpSource.api, index}, delaySec); logger.verbose("Local validator published aggregated attestation", { validatorIndex: validator.index, slot: data.slot, committeeIndex: data.index, sentPeers, + delaySec, }); } } }, - registerAggregatedAttestation(src, seenTimestampSec, signedAggregateAndProof, indexedAttestation) { + registerGossipAggregatedAttestation(seenTimestampSec, signedAggregateAndProof, indexedAttestation) { + const src = OpSource.gossip; const data = indexedAttestation.data; const epoch = computeEpochAtSlot(data.slot); // Returns the duration between when a `AggregateAndproof` with `data` could be produced (2/3rd through the slot) and `seenTimestamp`. diff --git a/packages/lodestar/src/network/gossip/handlers/index.ts b/packages/lodestar/src/network/gossip/handlers/index.ts index ce2e3e7aed00..50667a8645b7 100644 --- a/packages/lodestar/src/network/gossip/handlers/index.ts +++ b/packages/lodestar/src/network/gossip/handlers/index.ts @@ -161,12 +161,7 @@ export function getGossipHandlers(modules: ValidatorFnsModules, options: GossipH // Handler const {indexedAttestation, committeeIndices} = validationResult; - metrics?.registerAggregatedAttestation( - OpSource.gossip, - seenTimestampSec, - signedAggregateAndProof, - indexedAttestation - ); + metrics?.registerGossipAggregatedAttestation(seenTimestampSec, signedAggregateAndProof, indexedAttestation); const aggregatedAttestation = signedAggregateAndProof.message.aggregate; chain.aggregatedAttestationPool.add( @@ -206,7 +201,7 @@ export function getGossipHandlers(modules: ValidatorFnsModules, options: GossipH // Handler const {indexedAttestation} = validationResult; - metrics?.registerUnaggregatedAttestation(OpSource.gossip, seenTimestampSec, indexedAttestation); + metrics?.registerGossipUnaggregatedAttestation(seenTimestampSec, indexedAttestation); // Node may be subscribe to extra subnets (long-lived random subnets). For those, validate the messages // but don't import them, to save CPU and RAM From 7d701310fe98ce48c14e80c009ead812d04b9b97 Mon Sep 17 00:00:00 2001 From: Tuyen Nguyen Date: Sun, 10 Apr 2022 15:05:44 +0700 Subject: [PATCH 6/8] Remove Math.floor() to calculate metric exactly --- packages/lodestar/src/metrics/validatorMonitor.ts | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/packages/lodestar/src/metrics/validatorMonitor.ts b/packages/lodestar/src/metrics/validatorMonitor.ts index 91e430206709..6be3ef72788b 100644 --- a/packages/lodestar/src/metrics/validatorMonitor.ts +++ b/packages/lodestar/src/metrics/validatorMonitor.ts @@ -278,7 +278,7 @@ export function createValidatorMonitor( submitUnaggregatedAttestation(indexedAttestation, subnet, sentPeers) { const data = indexedAttestation.data; // Returns the duration between when the attestation `data` could be produced (1/3rd through the slot) and `seenTimestamp`. - const delaySec = Math.floor(Date.now() / 1000) - (genesisTime + (data.slot + 1 / 3) * config.SECONDS_PER_SLOT); + const delaySec = Date.now() / 1000 - (genesisTime + (data.slot + 1 / 3) * config.SECONDS_PER_SLOT); for (const index of indexedAttestation.attestingIndices) { const validator = validators.get(index); if (validator) { @@ -321,7 +321,7 @@ export function createValidatorMonitor( submitAggregatedAttestation(indexedAttestation, sentPeers) { const data = indexedAttestation.data; // Returns the duration between when a `AggregateAndproof` with `data` could be produced (2/3rd through the slot) and `seenTimestamp`. - const delaySec = Math.floor(Date.now() / 1000) - (genesisTime + (data.slot + 2 / 3) * config.SECONDS_PER_SLOT); + const delaySec = Date.now() / 1000 - (genesisTime + (data.slot + 2 / 3) * config.SECONDS_PER_SLOT); for (const index of indexedAttestation.attestingIndices) { const validator = validators.get(index); From 702c4d558b118ad415ca4915a1707e6ace5cd560 Mon Sep 17 00:00:00 2001 From: Tuyen Nguyen Date: Wed, 13 Apr 2022 16:00:30 +0700 Subject: [PATCH 7/8] Track seen time at the api side --- .../src/api/impl/beacon/pool/index.ts | 3 +- .../lodestar/src/api/impl/validator/index.ts | 3 +- .../lodestar/src/metrics/metrics/lodestar.ts | 6 ++-- .../lodestar/src/metrics/validatorMonitor.ts | 35 +++++++++++-------- 4 files changed, 28 insertions(+), 19 deletions(-) diff --git a/packages/lodestar/src/api/impl/beacon/pool/index.ts b/packages/lodestar/src/api/impl/beacon/pool/index.ts index 2805f785d15e..206bb793d3ef 100644 --- a/packages/lodestar/src/api/impl/beacon/pool/index.ts +++ b/packages/lodestar/src/api/impl/beacon/pool/index.ts @@ -42,6 +42,7 @@ export function getBeaconPoolApi({ }, async submitPoolAttestations(attestations) { + const seenTimestampSec = Date.now() / 1000; const errors: Error[] = []; await Promise.all( @@ -51,7 +52,7 @@ export function getBeaconPoolApi({ chain.attestationPool.add(attestation); const sentPeers = await network.gossip.publishBeaconAttestation(attestation, subnet); - metrics?.submitUnaggregatedAttestation(indexedAttestation, subnet, sentPeers); + metrics?.submitUnaggregatedAttestation(seenTimestampSec, indexedAttestation, subnet, sentPeers); } catch (e) { errors.push(e as Error); logger.error( diff --git a/packages/lodestar/src/api/impl/validator/index.ts b/packages/lodestar/src/api/impl/validator/index.ts index e06f5e833620..5d065ebb1f11 100644 --- a/packages/lodestar/src/api/impl/validator/index.ts +++ b/packages/lodestar/src/api/impl/validator/index.ts @@ -423,6 +423,7 @@ export function getValidatorApi({chain, config, logger, metrics, network, sync}: async publishAggregateAndProofs(signedAggregateAndProofs) { notWhileSyncing(); + const seenTimestampSec = Date.now() / 1000; const errors: Error[] = []; await Promise.all( @@ -440,7 +441,7 @@ export function getValidatorApi({chain, config, logger, metrics, network, sync}: committeeIndices ); const sentPeers = await network.gossip.publishBeaconAggregateAndProof(signedAggregateAndProof); - metrics?.submitAggregatedAttestation(indexedAttestation, sentPeers); + metrics?.submitAggregatedAttestation(seenTimestampSec, indexedAttestation, sentPeers); } catch (e) { if (e instanceof AttestationError && e.type.code === AttestationErrorCode.AGGREGATOR_ALREADY_KNOWN) { logger.debug("Ignoring known signedAggregateAndProof"); diff --git a/packages/lodestar/src/metrics/metrics/lodestar.ts b/packages/lodestar/src/metrics/metrics/lodestar.ts index 5cca99ab360e..dcae04f2d06f 100644 --- a/packages/lodestar/src/metrics/metrics/lodestar.ts +++ b/packages/lodestar/src/metrics/metrics/lodestar.ts @@ -656,10 +656,10 @@ export function createLodestarMetrics( buckets: [0.1, 1], }), unaggregatedAttestationSubmittedSentPeers: register.histogram<"index">({ - name: "validator_monitor_unaggregated_attestation_submited_sent_peers_total", - help: "Number of unaggregated attestations submitted by local validator that has no subnet peers", + name: "validator_monitor_unaggregated_attestation_submited_sent_peers_count", + help: "Number of peers that an unaggregated attestation sent to", labelNames: ["index"], - buckets: [0, 2, 5, 10], + buckets: [0, 10, 20, 30], }), aggregatedAttestationTotal: register.gauge<"index" | "src">({ name: "validator_monitor_aggregated_attestation_total", diff --git a/packages/lodestar/src/metrics/validatorMonitor.ts b/packages/lodestar/src/metrics/validatorMonitor.ts index 6be3ef72788b..942d38c8b31b 100644 --- a/packages/lodestar/src/metrics/validatorMonitor.ts +++ b/packages/lodestar/src/metrics/validatorMonitor.ts @@ -27,9 +27,18 @@ export interface IValidatorMonitor { registerLocalValidator(index: number): void; registerValidatorStatuses(currentEpoch: Epoch, statuses: IAttesterStatus[], balances?: number[]): void; registerBeaconBlock(src: OpSource, seenTimestampSec: Seconds, block: allForks.BeaconBlock): void; - submitUnaggregatedAttestation(indexedAttestation: IndexedAttestation, subnet: number, sentPeers: number): void; + submitUnaggregatedAttestation( + seenTimestampSec: number, + indexedAttestation: IndexedAttestation, + subnet: number, + sentPeers: number + ): void; registerGossipUnaggregatedAttestation(seenTimestampSec: Seconds, indexedAttestation: IndexedAttestation): void; - submitAggregatedAttestation(indexedAttestation: IndexedAttestation, sentPeers: number): void; + submitAggregatedAttestation( + seenTimestampSec: number, + indexedAttestation: IndexedAttestation, + sentPeers: number + ): void; registerGossipAggregatedAttestation( seenTimestampSec: Seconds, signedAggregateAndProof: SignedAggregateAndProof, @@ -250,7 +259,7 @@ export function createValidatorMonitor( } if (failedAttestation) { - logger.verbose("Failed attestation in previous epoch", { + logger.debug("Failed attestation in previous epoch", { validatorIndex: index, prevEpoch: currentEpoch - 1, isPrevSourceAttester: summary.isPrevSourceAttester, @@ -275,18 +284,16 @@ export function createValidatorMonitor( } }, - submitUnaggregatedAttestation(indexedAttestation, subnet, sentPeers) { + submitUnaggregatedAttestation(seenTimestampSec, indexedAttestation, subnet, sentPeers) { const data = indexedAttestation.data; // Returns the duration between when the attestation `data` could be produced (1/3rd through the slot) and `seenTimestamp`. - const delaySec = Date.now() / 1000 - (genesisTime + (data.slot + 1 / 3) * config.SECONDS_PER_SLOT); + const delaySec = seenTimestampSec - (genesisTime + (data.slot + 1 / 3) * config.SECONDS_PER_SLOT); for (const index of indexedAttestation.attestingIndices) { const validator = validators.get(index); if (validator) { - if (sentPeers <= 0) { - metrics.validatorMonitor.unaggregatedAttestationSubmittedSentPeers.observe({index}, sentPeers); - } + metrics.validatorMonitor.unaggregatedAttestationSubmittedSentPeers.observe({index}, sentPeers); metrics.validatorMonitor.unaggregatedAttestationDelaySeconds.observe({src: OpSource.api, index}, delaySec); - logger.verbose("Local validator published unaggregated attestation", { + logger.debug("Local validator published unaggregated attestation", { validatorIndex: validator.index, slot: data.slot, committeeIndex: data.index, @@ -318,16 +325,16 @@ export function createValidatorMonitor( } }, - submitAggregatedAttestation(indexedAttestation, sentPeers) { + submitAggregatedAttestation(seenTimestampSec, indexedAttestation, sentPeers) { const data = indexedAttestation.data; // Returns the duration between when a `AggregateAndproof` with `data` could be produced (2/3rd through the slot) and `seenTimestamp`. - const delaySec = Date.now() / 1000 - (genesisTime + (data.slot + 2 / 3) * config.SECONDS_PER_SLOT); + const delaySec = seenTimestampSec - (genesisTime + (data.slot + 2 / 3) * config.SECONDS_PER_SLOT); for (const index of indexedAttestation.attestingIndices) { const validator = validators.get(index); if (validator) { metrics.validatorMonitor.aggregatedAttestationDelaySeconds.observe({src: OpSource.api, index}, delaySec); - logger.verbose("Local validator published aggregated attestation", { + logger.debug("Local validator published aggregated attestation", { validatorIndex: validator.index, slot: data.slot, committeeIndex: data.index, @@ -365,7 +372,7 @@ export function createValidatorMonitor( withEpochSummary(validator, epoch, (summary) => { summary.attestationAggregateIncusions += 1; }); - logger.verbose("Local validator attestation is included in AggregatedAndProof", { + logger.debug("Local validator attestation is included in AggregatedAndProof", { validatorIndex: validator.index, slot: data.slot, committeeIndex: data.index, @@ -405,7 +412,7 @@ export function createValidatorMonitor( summary.attestationCorrectHead = correctHead; }); - logger.verbose("Local validator attestation is included in block", { + logger.debug("Local validator attestation is included in block", { validatorIndex: validator.index, slot: data.slot, committeeIndex: data.index, From caebb63e78ee1db88b9ff1c9cc535fa8aefdda37 Mon Sep 17 00:00:00 2001 From: Tuyen Nguyen Date: Wed, 13 Apr 2022 16:25:12 +0700 Subject: [PATCH 8/8] Add comments for sent peers bucket values --- packages/lodestar/src/metrics/metrics/lodestar.ts | 3 +++ 1 file changed, 3 insertions(+) diff --git a/packages/lodestar/src/metrics/metrics/lodestar.ts b/packages/lodestar/src/metrics/metrics/lodestar.ts index dcae04f2d06f..1a4f8c38b311 100644 --- a/packages/lodestar/src/metrics/metrics/lodestar.ts +++ b/packages/lodestar/src/metrics/metrics/lodestar.ts @@ -659,6 +659,9 @@ export function createLodestarMetrics( name: "validator_monitor_unaggregated_attestation_submited_sent_peers_count", help: "Number of peers that an unaggregated attestation sent to", labelNames: ["index"], + // as of Apr 2022, most of the time we sent to >30 peers per attestations + // these bucket values just base on that fact to get equal range + // refine if we want more reasonable values buckets: [0, 10, 20, 30], }), aggregatedAttestationTotal: register.gauge<"index" | "src">({