From 2a7846274a3e93822bba7c8091324672d331b4c7 Mon Sep 17 00:00:00 2001 From: Tuyen Nguyen Date: Thu, 30 Nov 2023 11:29:22 +0700 Subject: [PATCH 1/7] feat: track epoch transition steps time in metrics --- .../src/metrics/metrics/lodestar.ts | 70 +++++++++++++++++++ packages/state-transition/src/epoch/index.ts | 36 +++++++++- packages/state-transition/src/metrics.ts | 14 ++++ 3 files changed, 119 insertions(+), 1 deletion(-) diff --git a/packages/beacon-node/src/metrics/metrics/lodestar.ts b/packages/beacon-node/src/metrics/metrics/lodestar.ts index a68fdae0551f..6fd5facb4307 100644 --- a/packages/beacon-node/src/metrics/metrics/lodestar.ts +++ b/packages/beacon-node/src/metrics/metrics/lodestar.ts @@ -286,6 +286,76 @@ export function createLodestarMetrics( help: "Time to call commit after process a single epoch transition in seconds", buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], }), + epochTransitionJustificationAndFinalizationTime: register.histogram({ + name: "lodestar_stfn_epoch_transition_justification_and_finalization_seconds", + help: "Time to process justification and finalization in seconds", + buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], + }), + epochTransitionInactivityUpdatesTime: register.histogram({ + name: "lodestar_stfn_epoch_transition_inactivity_updates_seconds", + help: "Time to process inactivity updates in seconds", + buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], + }), + epochTransitionRewardsAndPenaltiesTime: register.histogram({ + name: "lodestar_stfn_epoch_transition_rewards_and_penalties_seconds", + help: "Time to process rewards and penalties in seconds", + buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], + }), + epochTransitionRegistryUpdatesTime: register.histogram({ + name: "lodestar_stfn_epoch_transition_registry_updates_seconds", + help: "Time to process registry updates in seconds", + buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], + }), + epochTransitionSlashingsTime: register.histogram({ + name: "lodestar_stfn_epoch_transition_slashings_seconds", + help: "Time to process slashings in seconds", + buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], + }), + epochTransitionEth1DataResetTime: register.histogram({ + name: "lodestar_stfn_epoch_transition_eth1_data_reset_seconds", + help: "Time to process eth1 data reset in seconds", + buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], + }), + epochTransitionEffectiveBalanceUpdatesTime: register.histogram({ + name: "lodestar_stfn_epoch_transition_effective_balance_updates_seconds", + help: "Time to process effective balance updates in seconds", + buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], + }), + epochTransitionSlashingsResetTime: register.histogram({ + name: "lodestar_stfn_epoch_transition_slashings_reset_seconds", + help: "Time to process slashings reset in seconds", + buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], + }), + epochTransitionRandaoMixesResetTime: register.histogram({ + name: "lodestar_stfn_epoch_transition_randao_mixes_reset_seconds", + help: "Time to process randao mixes reset in seconds", + buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], + }), + epochTransitionHistoricalSummariesUpdateTime: register.histogram({ + name: "lodestar_stfn_epoch_transition_historical_summaries_update_seconds", + help: "Time to process historical summaries update in seconds", + buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], + }), + epochTransitionHistoricalRootsUpdateTime: register.histogram({ + name: "lodestar_stfn_epoch_transition_historical_roots_update_seconds", + help: "Time to process historical roots update in seconds", + buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], + }), + epochTransitionParticipationRecordUpdatesTime: register.histogram({ + name: "lodestar_stfn_epoch_transition_participation_record_updates_seconds", + help: "Time to process participation record updates in seconds", + buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], + }), + epochTransitionParticipationFlagUpdatesTime: register.histogram({ + name: "lodestar_stfn_epoch_transition_participation_flag_updates_seconds", + help: "Time to process participation flag updates in seconds", + buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], + }), + epochTransitionSyncCommitteeUpdatesTime: register.histogram({ + name: "lodestar_stfn_epoch_transition_sync_committee_updates_seconds", + help: "Time to process sync committee updates in seconds", + buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], + }), processBlockTime: register.histogram({ name: "lodestar_stfn_process_block_seconds", help: "Time to process a single block in seconds", diff --git a/packages/state-transition/src/epoch/index.ts b/packages/state-transition/src/epoch/index.ts index bb37ed17f4e1..641b1eea0535 100644 --- a/packages/state-transition/src/epoch/index.ts +++ b/packages/state-transition/src/epoch/index.ts @@ -12,6 +12,7 @@ import { CachedBeaconStatePhase0, EpochTransitionCache, } from "../types.js"; +import {BeaconStateTransitionMetrics} from "../metrics.js"; import {processEffectiveBalanceUpdates} from "./processEffectiveBalanceUpdates.js"; import {processEth1DataReset} from "./processEth1DataReset.js"; import {processHistoricalRootsUpdate} from "./processHistoricalRootsUpdate.js"; @@ -50,7 +51,12 @@ export {computeUnrealizedCheckpoints} from "./computeUnrealizedCheckpoints.js"; const maxValidatorsPerStateSlashing = SLOTS_PER_EPOCH * MAX_ATTESTER_SLASHINGS * MAX_VALIDATORS_PER_COMMITTEE; const maxSafeValidators = Math.floor(Number.MAX_SAFE_INTEGER / MAX_EFFECTIVE_BALANCE); -export function processEpoch(fork: ForkSeq, state: CachedBeaconStateAllForks, cache: EpochTransitionCache): void { +export function processEpoch( + fork: ForkSeq, + state: CachedBeaconStateAllForks, + cache: EpochTransitionCache, + metrics?: BeaconStateTransitionMetrics | null +): void { // state.slashings is initially a Gwei (BigInt) vector, however since Nov 2023 it's converted to UintNum64 (number) vector in the state transition because: // - state.slashings[nextEpoch % EPOCHS_PER_SLASHINGS_VECTOR] is reset per epoch in processSlashingsReset() // - max slashed validators per epoch is SLOTS_PER_EPOCH * MAX_ATTESTER_SLASHINGS * MAX_VALIDATORS_PER_COMMITTEE which is 32 * 2 * 2048 = 131072 on mainnet @@ -59,32 +65,60 @@ export function processEpoch(fork: ForkSeq, state: CachedBeaconStateAllForks, ca throw new Error("Lodestar does not support this network, parameters don't fit number value inside state.slashings"); } + let timer = metrics?.epochTransitionJustificationAndFinalizationTime.startTimer(); + processJustificationAndFinalization(state, cache); + timer?.(); if (fork >= ForkSeq.altair) { + timer = metrics?.epochTransitionInactivityUpdatesTime.startTimer(); processInactivityUpdates(state as CachedBeaconStateAltair, cache); + timer?.(); } // processRewardsAndPenalties() is 2nd step in the specs, we optimize to do it // after processSlashings() to update balances only once // processRewardsAndPenalties(state, cache); + timer = metrics?.epochTransitionRegistryUpdatesTime.startTimer(); processRegistryUpdates(state, cache); + timer?.(); // accumulate slashing penalties and only update balances once in processRewardsAndPenalties() + timer = metrics?.epochTransitionSlashingsTime.startTimer(); const slashingPenalties = processSlashings(state, cache, false); + timer?.(); + timer = metrics?.epochTransitionRewardsAndPenaltiesTime.startTimer(); processRewardsAndPenalties(state, cache, slashingPenalties); + timer?.(); processEth1DataReset(state, cache); + timer?.(); + timer = metrics?.epochTransitionEffectiveBalanceUpdatesTime.startTimer(); processEffectiveBalanceUpdates(state, cache); + timer?.(); + timer = metrics?.epochTransitionSlashingsResetTime.startTimer(); processSlashingsReset(state, cache); + timer?.(); + timer = metrics?.epochTransitionRandaoMixesResetTime.startTimer(); processRandaoMixesReset(state, cache); + timer?.(); if (fork >= ForkSeq.capella) { + timer = metrics?.epochTransitionHistoricalSummariesUpdateTime.startTimer(); processHistoricalSummariesUpdate(state as CachedBeaconStateCapella, cache); + timer?.(); } else { + timer = metrics?.epochTransitionHistoricalRootsUpdateTime.startTimer(); processHistoricalRootsUpdate(state, cache); + timer?.(); } if (fork === ForkSeq.phase0) { + timer = metrics?.epochTransitionParticipationRecordUpdatesTime.startTimer(); processParticipationRecordUpdates(state as CachedBeaconStatePhase0); + timer?.(); } else { + timer = metrics?.epochTransitionParticipationFlagUpdatesTime.startTimer(); processParticipationFlagUpdates(state as CachedBeaconStateAltair); + timer?.(); + timer = metrics?.epochTransitionSyncCommitteeUpdatesTime.startTimer(); processSyncCommitteeUpdates(state as CachedBeaconStateAltair); + timer?.(); } } diff --git a/packages/state-transition/src/metrics.ts b/packages/state-transition/src/metrics.ts index c5179a1df5b3..1d560cffdde6 100644 --- a/packages/state-transition/src/metrics.ts +++ b/packages/state-transition/src/metrics.ts @@ -5,6 +5,20 @@ import {AttesterStatus} from "./util/attesterStatus.js"; export type BeaconStateTransitionMetrics = { epochTransitionTime: Histogram; epochTransitionCommitTime: Histogram; + epochTransitionJustificationAndFinalizationTime: Histogram; + epochTransitionInactivityUpdatesTime: Histogram; + epochTransitionRewardsAndPenaltiesTime: Histogram; + epochTransitionRegistryUpdatesTime: Histogram; + epochTransitionSlashingsTime: Histogram; + epochTransitionEth1DataResetTime: Histogram; + epochTransitionEffectiveBalanceUpdatesTime: Histogram; + epochTransitionSlashingsResetTime: Histogram; + epochTransitionRandaoMixesResetTime: Histogram; + epochTransitionHistoricalSummariesUpdateTime: Histogram; + epochTransitionHistoricalRootsUpdateTime: Histogram; + epochTransitionParticipationRecordUpdatesTime: Histogram; + epochTransitionParticipationFlagUpdatesTime: Histogram; + epochTransitionSyncCommitteeUpdatesTime: Histogram; processBlockTime: Histogram; processBlockCommitTime: Histogram; stateHashTreeRootTime: Histogram; From cf2da82881bfa06444e715d871268f8b18b49b0d Mon Sep 17 00:00:00 2001 From: Tuyen Nguyen Date: Tue, 5 Dec 2023 09:16:48 +0700 Subject: [PATCH 2/7] feat: also track beforeProcessEpoch and afterProcessEpoch --- packages/beacon-node/src/metrics/metrics/lodestar.ts | 10 ++++++++++ packages/state-transition/src/metrics.ts | 2 ++ packages/state-transition/src/stateTransition.ts | 5 ++++- 3 files changed, 16 insertions(+), 1 deletion(-) diff --git a/packages/beacon-node/src/metrics/metrics/lodestar.ts b/packages/beacon-node/src/metrics/metrics/lodestar.ts index 6fd5facb4307..6e1d5705b6ca 100644 --- a/packages/beacon-node/src/metrics/metrics/lodestar.ts +++ b/packages/beacon-node/src/metrics/metrics/lodestar.ts @@ -286,6 +286,16 @@ export function createLodestarMetrics( help: "Time to call commit after process a single epoch transition in seconds", buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], }), + epochTransitionBeforeProcessEpochTime: register.histogram({ + name: "lodestar_stfn_epoch_transition_before_process_epoch_seconds", + help: "Time to call beforeProcessEpoch before process a single epoch transition in seconds", + buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], + }), + epochTransitionAfterProcessEpochTime: register.histogram({ + name: "lodestar_stfn_epoch_transition_after_process_epoch_seconds", + help: "Time to call afterProcessEpoch after process a single epoch transition in seconds", + buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], + }), epochTransitionJustificationAndFinalizationTime: register.histogram({ name: "lodestar_stfn_epoch_transition_justification_and_finalization_seconds", help: "Time to process justification and finalization in seconds", diff --git a/packages/state-transition/src/metrics.ts b/packages/state-transition/src/metrics.ts index 1d560cffdde6..f6dba5477136 100644 --- a/packages/state-transition/src/metrics.ts +++ b/packages/state-transition/src/metrics.ts @@ -5,6 +5,8 @@ import {AttesterStatus} from "./util/attesterStatus.js"; export type BeaconStateTransitionMetrics = { epochTransitionTime: Histogram; epochTransitionCommitTime: Histogram; + epochTransitionBeforeProcessEpochTime: Histogram; + epochTransitionAfterProcessEpochTime: Histogram; epochTransitionJustificationAndFinalizationTime: Histogram; epochTransitionInactivityUpdatesTime: Histogram; epochTransitionRewardsAndPenaltiesTime: Histogram; diff --git a/packages/state-transition/src/stateTransition.ts b/packages/state-transition/src/stateTransition.ts index 8fd98f4df03e..cf9b032f3e2f 100644 --- a/packages/state-transition/src/stateTransition.ts +++ b/packages/state-transition/src/stateTransition.ts @@ -164,14 +164,17 @@ function processSlotsWithTransientCache( const fork = postState.config.getForkSeq(postState.slot); const epochTransitionTimer = metrics?.epochTransitionTime.startTimer(); - + const beforeProcessEpochTimer = metrics?.epochTransitionBeforeProcessEpochTime.startTimer(); const epochTransitionCache = beforeProcessEpoch(postState, epochTransitionCacheOpts); + beforeProcessEpochTimer?.(); processEpoch(fork, postState, epochTransitionCache); const {currentEpoch, statuses, balances} = epochTransitionCache; metrics?.registerValidatorStatuses(currentEpoch, statuses, balances); postState.slot++; + const afterProcessEpochTimer = metrics?.epochTransitionAfterProcessEpochTime.startTimer(); postState.epochCtx.afterProcessEpoch(postState, epochTransitionCache); + afterProcessEpochTimer?.(); // Running commit here is not strictly necessary. The cost of running commit twice (here + after process block) // Should be negligible but gives better metrics to differentiate the cost of it for block and epoch proc. From bc3481829d7f4106e7ad83ff13641a3337dce0f4 Mon Sep 17 00:00:00 2001 From: Tuyen Nguyen Date: Tue, 5 Dec 2023 09:35:17 +0700 Subject: [PATCH 3/7] fix: do not need to time simple steps in processEpoch --- .../src/metrics/metrics/lodestar.ts | 30 ------------------- packages/state-transition/src/epoch/index.ts | 12 -------- packages/state-transition/src/metrics.ts | 6 ---- 3 files changed, 48 deletions(-) diff --git a/packages/beacon-node/src/metrics/metrics/lodestar.ts b/packages/beacon-node/src/metrics/metrics/lodestar.ts index 6e1d5705b6ca..3654c919f192 100644 --- a/packages/beacon-node/src/metrics/metrics/lodestar.ts +++ b/packages/beacon-node/src/metrics/metrics/lodestar.ts @@ -321,41 +321,11 @@ export function createLodestarMetrics( help: "Time to process slashings in seconds", buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], }), - epochTransitionEth1DataResetTime: register.histogram({ - name: "lodestar_stfn_epoch_transition_eth1_data_reset_seconds", - help: "Time to process eth1 data reset in seconds", - buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], - }), epochTransitionEffectiveBalanceUpdatesTime: register.histogram({ name: "lodestar_stfn_epoch_transition_effective_balance_updates_seconds", help: "Time to process effective balance updates in seconds", buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], }), - epochTransitionSlashingsResetTime: register.histogram({ - name: "lodestar_stfn_epoch_transition_slashings_reset_seconds", - help: "Time to process slashings reset in seconds", - buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], - }), - epochTransitionRandaoMixesResetTime: register.histogram({ - name: "lodestar_stfn_epoch_transition_randao_mixes_reset_seconds", - help: "Time to process randao mixes reset in seconds", - buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], - }), - epochTransitionHistoricalSummariesUpdateTime: register.histogram({ - name: "lodestar_stfn_epoch_transition_historical_summaries_update_seconds", - help: "Time to process historical summaries update in seconds", - buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], - }), - epochTransitionHistoricalRootsUpdateTime: register.histogram({ - name: "lodestar_stfn_epoch_transition_historical_roots_update_seconds", - help: "Time to process historical roots update in seconds", - buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], - }), - epochTransitionParticipationRecordUpdatesTime: register.histogram({ - name: "lodestar_stfn_epoch_transition_participation_record_updates_seconds", - help: "Time to process participation record updates in seconds", - buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], - }), epochTransitionParticipationFlagUpdatesTime: register.histogram({ name: "lodestar_stfn_epoch_transition_participation_flag_updates_seconds", help: "Time to process participation flag updates in seconds", diff --git a/packages/state-transition/src/epoch/index.ts b/packages/state-transition/src/epoch/index.ts index 641b1eea0535..cf215da4276e 100644 --- a/packages/state-transition/src/epoch/index.ts +++ b/packages/state-transition/src/epoch/index.ts @@ -66,7 +66,6 @@ export function processEpoch( } let timer = metrics?.epochTransitionJustificationAndFinalizationTime.startTimer(); - processJustificationAndFinalization(state, cache); timer?.(); if (fork >= ForkSeq.altair) { @@ -88,31 +87,20 @@ export function processEpoch( processRewardsAndPenalties(state, cache, slashingPenalties); timer?.(); processEth1DataReset(state, cache); - timer?.(); timer = metrics?.epochTransitionEffectiveBalanceUpdatesTime.startTimer(); processEffectiveBalanceUpdates(state, cache); timer?.(); - timer = metrics?.epochTransitionSlashingsResetTime.startTimer(); processSlashingsReset(state, cache); - timer?.(); - timer = metrics?.epochTransitionRandaoMixesResetTime.startTimer(); processRandaoMixesReset(state, cache); - timer?.(); if (fork >= ForkSeq.capella) { - timer = metrics?.epochTransitionHistoricalSummariesUpdateTime.startTimer(); processHistoricalSummariesUpdate(state as CachedBeaconStateCapella, cache); - timer?.(); } else { - timer = metrics?.epochTransitionHistoricalRootsUpdateTime.startTimer(); processHistoricalRootsUpdate(state, cache); - timer?.(); } if (fork === ForkSeq.phase0) { - timer = metrics?.epochTransitionParticipationRecordUpdatesTime.startTimer(); processParticipationRecordUpdates(state as CachedBeaconStatePhase0); - timer?.(); } else { timer = metrics?.epochTransitionParticipationFlagUpdatesTime.startTimer(); processParticipationFlagUpdates(state as CachedBeaconStateAltair); diff --git a/packages/state-transition/src/metrics.ts b/packages/state-transition/src/metrics.ts index f6dba5477136..d31c0de4fa5c 100644 --- a/packages/state-transition/src/metrics.ts +++ b/packages/state-transition/src/metrics.ts @@ -12,13 +12,7 @@ export type BeaconStateTransitionMetrics = { epochTransitionRewardsAndPenaltiesTime: Histogram; epochTransitionRegistryUpdatesTime: Histogram; epochTransitionSlashingsTime: Histogram; - epochTransitionEth1DataResetTime: Histogram; epochTransitionEffectiveBalanceUpdatesTime: Histogram; - epochTransitionSlashingsResetTime: Histogram; - epochTransitionRandaoMixesResetTime: Histogram; - epochTransitionHistoricalSummariesUpdateTime: Histogram; - epochTransitionHistoricalRootsUpdateTime: Histogram; - epochTransitionParticipationRecordUpdatesTime: Histogram; epochTransitionParticipationFlagUpdatesTime: Histogram; epochTransitionSyncCommitteeUpdatesTime: Histogram; processBlockTime: Histogram; From a3b0449a3f53cc007d2aa1e16f374153971c046f Mon Sep 17 00:00:00 2001 From: Tuyen Nguyen Date: Wed, 6 Dec 2023 09:29:42 +0700 Subject: [PATCH 4/7] fix: incorporate to single metric with step label --- .../src/metrics/metrics/lodestar.ts | 52 ++----------------- packages/state-transition/src/epoch/index.ts | 32 ++++++------ packages/state-transition/src/metrics.ts | 13 +---- .../state-transition/src/stateTransition.ts | 8 +-- 4 files changed, 26 insertions(+), 79 deletions(-) diff --git a/packages/beacon-node/src/metrics/metrics/lodestar.ts b/packages/beacon-node/src/metrics/metrics/lodestar.ts index 3654c919f192..64d43af9001d 100644 --- a/packages/beacon-node/src/metrics/metrics/lodestar.ts +++ b/packages/beacon-node/src/metrics/metrics/lodestar.ts @@ -286,54 +286,10 @@ export function createLodestarMetrics( help: "Time to call commit after process a single epoch transition in seconds", buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], }), - epochTransitionBeforeProcessEpochTime: register.histogram({ - name: "lodestar_stfn_epoch_transition_before_process_epoch_seconds", - help: "Time to call beforeProcessEpoch before process a single epoch transition in seconds", - buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], - }), - epochTransitionAfterProcessEpochTime: register.histogram({ - name: "lodestar_stfn_epoch_transition_after_process_epoch_seconds", - help: "Time to call afterProcessEpoch after process a single epoch transition in seconds", - buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], - }), - epochTransitionJustificationAndFinalizationTime: register.histogram({ - name: "lodestar_stfn_epoch_transition_justification_and_finalization_seconds", - help: "Time to process justification and finalization in seconds", - buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], - }), - epochTransitionInactivityUpdatesTime: register.histogram({ - name: "lodestar_stfn_epoch_transition_inactivity_updates_seconds", - help: "Time to process inactivity updates in seconds", - buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], - }), - epochTransitionRewardsAndPenaltiesTime: register.histogram({ - name: "lodestar_stfn_epoch_transition_rewards_and_penalties_seconds", - help: "Time to process rewards and penalties in seconds", - buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], - }), - epochTransitionRegistryUpdatesTime: register.histogram({ - name: "lodestar_stfn_epoch_transition_registry_updates_seconds", - help: "Time to process registry updates in seconds", - buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], - }), - epochTransitionSlashingsTime: register.histogram({ - name: "lodestar_stfn_epoch_transition_slashings_seconds", - help: "Time to process slashings in seconds", - buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], - }), - epochTransitionEffectiveBalanceUpdatesTime: register.histogram({ - name: "lodestar_stfn_epoch_transition_effective_balance_updates_seconds", - help: "Time to process effective balance updates in seconds", - buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], - }), - epochTransitionParticipationFlagUpdatesTime: register.histogram({ - name: "lodestar_stfn_epoch_transition_participation_flag_updates_seconds", - help: "Time to process participation flag updates in seconds", - buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], - }), - epochTransitionSyncCommitteeUpdatesTime: register.histogram({ - name: "lodestar_stfn_epoch_transition_sync_committee_updates_seconds", - help: "Time to process sync committee updates in seconds", + epochTransitionStepTime: register.histogram<"step">({ + name: "lodestar_stfn_epoch_transition_step_seconds", + help: "Time to call each step of epoch transition in seconds", + labelNames: ["step"], buckets: [0.01, 0.05, 0.1, 0.2, 0.5, 0.75, 1], }), processBlockTime: register.histogram({ diff --git a/packages/state-transition/src/epoch/index.ts b/packages/state-transition/src/epoch/index.ts index cf215da4276e..c8a95ada1663 100644 --- a/packages/state-transition/src/epoch/index.ts +++ b/packages/state-transition/src/epoch/index.ts @@ -65,31 +65,31 @@ export function processEpoch( throw new Error("Lodestar does not support this network, parameters don't fit number value inside state.slashings"); } - let timer = metrics?.epochTransitionJustificationAndFinalizationTime.startTimer(); + let timer = metrics?.epochTransitionStepTime.startTimer({step: "processJustificationAndFinalization"}); processJustificationAndFinalization(state, cache); - timer?.(); + timer?.({step: "processJustificationAndFinalization"}); if (fork >= ForkSeq.altair) { - timer = metrics?.epochTransitionInactivityUpdatesTime.startTimer(); + timer = metrics?.epochTransitionStepTime.startTimer({step: "processInactivityUpdates"}); processInactivityUpdates(state as CachedBeaconStateAltair, cache); - timer?.(); + timer?.({step: "processInactivityUpdates"}); } // processRewardsAndPenalties() is 2nd step in the specs, we optimize to do it // after processSlashings() to update balances only once // processRewardsAndPenalties(state, cache); - timer = metrics?.epochTransitionRegistryUpdatesTime.startTimer(); + timer = metrics?.epochTransitionStepTime.startTimer({step: "processRegistryUpdates"}); processRegistryUpdates(state, cache); - timer?.(); + timer?.({step: "processRegistryUpdates"}); // accumulate slashing penalties and only update balances once in processRewardsAndPenalties() - timer = metrics?.epochTransitionSlashingsTime.startTimer(); + timer = metrics?.epochTransitionStepTime.startTimer({step: "processSlashings"}); const slashingPenalties = processSlashings(state, cache, false); - timer?.(); - timer = metrics?.epochTransitionRewardsAndPenaltiesTime.startTimer(); + timer?.({step: "processSlashings"}); + timer = metrics?.epochTransitionStepTime.startTimer({step: "processRewardsAndPenalties"}); processRewardsAndPenalties(state, cache, slashingPenalties); - timer?.(); + timer?.({step: "processRewardsAndPenalties"}); processEth1DataReset(state, cache); - timer = metrics?.epochTransitionEffectiveBalanceUpdatesTime.startTimer(); + timer = metrics?.epochTransitionStepTime.startTimer({step: "processEffectiveBalanceUpdates"}); processEffectiveBalanceUpdates(state, cache); - timer?.(); + timer?.({step: "processEffectiveBalanceUpdates"}); processSlashingsReset(state, cache); processRandaoMixesReset(state, cache); @@ -102,11 +102,11 @@ export function processEpoch( if (fork === ForkSeq.phase0) { processParticipationRecordUpdates(state as CachedBeaconStatePhase0); } else { - timer = metrics?.epochTransitionParticipationFlagUpdatesTime.startTimer(); + timer = metrics?.epochTransitionStepTime.startTimer({step: "processParticipationFlagUpdates"}); processParticipationFlagUpdates(state as CachedBeaconStateAltair); - timer?.(); - timer = metrics?.epochTransitionSyncCommitteeUpdatesTime.startTimer(); + timer?.({step: "processParticipationFlagUpdates"}); + timer = metrics?.epochTransitionStepTime.startTimer({step: "processSyncCommitteeUpdates"}); processSyncCommitteeUpdates(state as CachedBeaconStateAltair); - timer?.(); + timer?.({step: "processSyncCommitteeUpdates"}); } } diff --git a/packages/state-transition/src/metrics.ts b/packages/state-transition/src/metrics.ts index d31c0de4fa5c..681bb2b910cf 100644 --- a/packages/state-transition/src/metrics.ts +++ b/packages/state-transition/src/metrics.ts @@ -5,16 +5,7 @@ import {AttesterStatus} from "./util/attesterStatus.js"; export type BeaconStateTransitionMetrics = { epochTransitionTime: Histogram; epochTransitionCommitTime: Histogram; - epochTransitionBeforeProcessEpochTime: Histogram; - epochTransitionAfterProcessEpochTime: Histogram; - epochTransitionJustificationAndFinalizationTime: Histogram; - epochTransitionInactivityUpdatesTime: Histogram; - epochTransitionRewardsAndPenaltiesTime: Histogram; - epochTransitionRegistryUpdatesTime: Histogram; - epochTransitionSlashingsTime: Histogram; - epochTransitionEffectiveBalanceUpdatesTime: Histogram; - epochTransitionParticipationFlagUpdatesTime: Histogram; - epochTransitionSyncCommitteeUpdatesTime: Histogram; + epochTransitionStepTime: Histogram<"step">; processBlockTime: Histogram; processBlockCommitTime: Histogram; stateHashTreeRootTime: Histogram; @@ -33,7 +24,7 @@ export type BeaconStateTransitionMetrics = { type LabelValues = Partial>; interface Histogram { - startTimer(): () => void; + startTimer(labels?: LabelValues): (labels?: LabelValues) => number; observe(value: number): void; observe(labels: LabelValues, values: number): void; diff --git a/packages/state-transition/src/stateTransition.ts b/packages/state-transition/src/stateTransition.ts index cf9b032f3e2f..51bc7d0802e9 100644 --- a/packages/state-transition/src/stateTransition.ts +++ b/packages/state-transition/src/stateTransition.ts @@ -164,17 +164,17 @@ function processSlotsWithTransientCache( const fork = postState.config.getForkSeq(postState.slot); const epochTransitionTimer = metrics?.epochTransitionTime.startTimer(); - const beforeProcessEpochTimer = metrics?.epochTransitionBeforeProcessEpochTime.startTimer(); + const beforeProcessEpochTimer = metrics?.epochTransitionStepTime.startTimer({step: "beforeProcessEpoch"}); const epochTransitionCache = beforeProcessEpoch(postState, epochTransitionCacheOpts); - beforeProcessEpochTimer?.(); + beforeProcessEpochTimer?.({step: "beforeProcessEpoch"}); processEpoch(fork, postState, epochTransitionCache); const {currentEpoch, statuses, balances} = epochTransitionCache; metrics?.registerValidatorStatuses(currentEpoch, statuses, balances); postState.slot++; - const afterProcessEpochTimer = metrics?.epochTransitionAfterProcessEpochTime.startTimer(); + const afterProcessEpochTimer = metrics?.epochTransitionStepTime.startTimer({step: "afterProcessEpoch"}); postState.epochCtx.afterProcessEpoch(postState, epochTransitionCache); - afterProcessEpochTimer?.(); + afterProcessEpochTimer?.({step: "afterProcessEpoch"}); // Running commit here is not strictly necessary. The cost of running commit twice (here + after process block) // Should be negligible but gives better metrics to differentiate the cost of it for block and epoch proc. From efa3fbc26d9998f8aed76a466505180846487e37 Mon Sep 17 00:00:00 2001 From: Tuyen Nguyen Date: Wed, 6 Dec 2023 09:46:15 +0700 Subject: [PATCH 5/7] fix: pass metrics to processEpoch() --- packages/state-transition/src/stateTransition.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/state-transition/src/stateTransition.ts b/packages/state-transition/src/stateTransition.ts index 51bc7d0802e9..f4f8efda31cb 100644 --- a/packages/state-transition/src/stateTransition.ts +++ b/packages/state-transition/src/stateTransition.ts @@ -167,7 +167,7 @@ function processSlotsWithTransientCache( const beforeProcessEpochTimer = metrics?.epochTransitionStepTime.startTimer({step: "beforeProcessEpoch"}); const epochTransitionCache = beforeProcessEpoch(postState, epochTransitionCacheOpts); beforeProcessEpochTimer?.({step: "beforeProcessEpoch"}); - processEpoch(fork, postState, epochTransitionCache); + processEpoch(fork, postState, epochTransitionCache, metrics); const {currentEpoch, statuses, balances} = epochTransitionCache; metrics?.registerValidatorStatuses(currentEpoch, statuses, balances); From d863360b0aeef7492ae9ba287684e98892944888 Mon Sep 17 00:00:00 2001 From: Tuyen Nguyen Date: Tue, 12 Dec 2023 13:46:42 +0700 Subject: [PATCH 6/7] chore: use separate timer for each epoch transition step --- packages/state-transition/src/epoch/index.ts | 48 +++++++++++++------- 1 file changed, 32 insertions(+), 16 deletions(-) diff --git a/packages/state-transition/src/epoch/index.ts b/packages/state-transition/src/epoch/index.ts index c8a95ada1663..f5252670c51b 100644 --- a/packages/state-transition/src/epoch/index.ts +++ b/packages/state-transition/src/epoch/index.ts @@ -65,31 +65,42 @@ export function processEpoch( throw new Error("Lodestar does not support this network, parameters don't fit number value inside state.slashings"); } - let timer = metrics?.epochTransitionStepTime.startTimer({step: "processJustificationAndFinalization"}); + const justificationAndFinalizationTimer = metrics?.epochTransitionStepTime.startTimer({ + step: "processJustificationAndFinalization", + }); processJustificationAndFinalization(state, cache); - timer?.({step: "processJustificationAndFinalization"}); + justificationAndFinalizationTimer?.(); + if (fork >= ForkSeq.altair) { - timer = metrics?.epochTransitionStepTime.startTimer({step: "processInactivityUpdates"}); + const inactivityUpdatesTimer = metrics?.epochTransitionStepTime.startTimer({step: "processInactivityUpdates"}); processInactivityUpdates(state as CachedBeaconStateAltair, cache); - timer?.({step: "processInactivityUpdates"}); + inactivityUpdatesTimer?.(); } + // processRewardsAndPenalties() is 2nd step in the specs, we optimize to do it // after processSlashings() to update balances only once // processRewardsAndPenalties(state, cache); - timer = metrics?.epochTransitionStepTime.startTimer({step: "processRegistryUpdates"}); + const registryUpdatesTimer = metrics?.epochTransitionStepTime.startTimer({step: "processRegistryUpdates"}); processRegistryUpdates(state, cache); - timer?.({step: "processRegistryUpdates"}); + registryUpdatesTimer?.(); + // accumulate slashing penalties and only update balances once in processRewardsAndPenalties() - timer = metrics?.epochTransitionStepTime.startTimer({step: "processSlashings"}); + const slashingsTimer = metrics?.epochTransitionStepTime.startTimer({step: "processSlashings"}); const slashingPenalties = processSlashings(state, cache, false); - timer?.({step: "processSlashings"}); - timer = metrics?.epochTransitionStepTime.startTimer({step: "processRewardsAndPenalties"}); + slashingsTimer?.(); + + const rewardsAndPenaltiesTimer = metrics?.epochTransitionStepTime.startTimer({step: "processRewardsAndPenalties"}); processRewardsAndPenalties(state, cache, slashingPenalties); - timer?.({step: "processRewardsAndPenalties"}); + rewardsAndPenaltiesTimer?.(); + processEth1DataReset(state, cache); - timer = metrics?.epochTransitionStepTime.startTimer({step: "processEffectiveBalanceUpdates"}); + + const effectiveBalanceUpdatesTimer = metrics?.epochTransitionStepTime.startTimer({ + step: "processEffectiveBalanceUpdates", + }); processEffectiveBalanceUpdates(state, cache); - timer?.({step: "processEffectiveBalanceUpdates"}); + effectiveBalanceUpdatesTimer?.(); + processSlashingsReset(state, cache); processRandaoMixesReset(state, cache); @@ -102,11 +113,16 @@ export function processEpoch( if (fork === ForkSeq.phase0) { processParticipationRecordUpdates(state as CachedBeaconStatePhase0); } else { - timer = metrics?.epochTransitionStepTime.startTimer({step: "processParticipationFlagUpdates"}); + const participationFlagUpdatesTimer = metrics?.epochTransitionStepTime.startTimer({ + step: "processParticipationFlagUpdates", + }); processParticipationFlagUpdates(state as CachedBeaconStateAltair); - timer?.({step: "processParticipationFlagUpdates"}); - timer = metrics?.epochTransitionStepTime.startTimer({step: "processSyncCommitteeUpdates"}); + participationFlagUpdatesTimer?.(); + + const syncCommitteeUpdatesTimer = metrics?.epochTransitionStepTime.startTimer({ + step: "processSyncCommitteeUpdates", + }); processSyncCommitteeUpdates(state as CachedBeaconStateAltair); - timer?.({step: "processSyncCommitteeUpdates"}); + syncCommitteeUpdatesTimer?.(); } } From 172da6afe65070729d915ebc790b3f0db9528260 Mon Sep 17 00:00:00 2001 From: Cayman Date: Tue, 12 Dec 2023 11:06:22 -0500 Subject: [PATCH 7/7] chore: use blocks to separate timers --- packages/state-transition/src/epoch/index.ts | 77 +++++++++++-------- .../state-transition/src/stateTransition.ts | 31 +++++--- 2 files changed, 67 insertions(+), 41 deletions(-) diff --git a/packages/state-transition/src/epoch/index.ts b/packages/state-transition/src/epoch/index.ts index f5252670c51b..05c8b55d0435 100644 --- a/packages/state-transition/src/epoch/index.ts +++ b/packages/state-transition/src/epoch/index.ts @@ -65,41 +65,52 @@ export function processEpoch( throw new Error("Lodestar does not support this network, parameters don't fit number value inside state.slashings"); } - const justificationAndFinalizationTimer = metrics?.epochTransitionStepTime.startTimer({ - step: "processJustificationAndFinalization", - }); - processJustificationAndFinalization(state, cache); - justificationAndFinalizationTimer?.(); + { + const timer = metrics?.epochTransitionStepTime.startTimer({ + step: "processJustificationAndFinalization", + }); + processJustificationAndFinalization(state, cache); + timer?.(); + } if (fork >= ForkSeq.altair) { - const inactivityUpdatesTimer = metrics?.epochTransitionStepTime.startTimer({step: "processInactivityUpdates"}); + const timer = metrics?.epochTransitionStepTime.startTimer({step: "processInactivityUpdates"}); processInactivityUpdates(state as CachedBeaconStateAltair, cache); - inactivityUpdatesTimer?.(); + timer?.(); } // processRewardsAndPenalties() is 2nd step in the specs, we optimize to do it // after processSlashings() to update balances only once // processRewardsAndPenalties(state, cache); - const registryUpdatesTimer = metrics?.epochTransitionStepTime.startTimer({step: "processRegistryUpdates"}); - processRegistryUpdates(state, cache); - registryUpdatesTimer?.(); + { + const timer = metrics?.epochTransitionStepTime.startTimer({step: "processRegistryUpdates"}); + processRegistryUpdates(state, cache); + timer?.(); + } // accumulate slashing penalties and only update balances once in processRewardsAndPenalties() - const slashingsTimer = metrics?.epochTransitionStepTime.startTimer({step: "processSlashings"}); - const slashingPenalties = processSlashings(state, cache, false); - slashingsTimer?.(); + let slashingPenalties: number[]; + { + const timer = metrics?.epochTransitionStepTime.startTimer({step: "processSlashings"}); + slashingPenalties = processSlashings(state, cache, false); + timer?.(); + } - const rewardsAndPenaltiesTimer = metrics?.epochTransitionStepTime.startTimer({step: "processRewardsAndPenalties"}); - processRewardsAndPenalties(state, cache, slashingPenalties); - rewardsAndPenaltiesTimer?.(); + { + const timer = metrics?.epochTransitionStepTime.startTimer({step: "processRewardsAndPenalties"}); + processRewardsAndPenalties(state, cache, slashingPenalties); + timer?.(); + } processEth1DataReset(state, cache); - const effectiveBalanceUpdatesTimer = metrics?.epochTransitionStepTime.startTimer({ - step: "processEffectiveBalanceUpdates", - }); - processEffectiveBalanceUpdates(state, cache); - effectiveBalanceUpdatesTimer?.(); + { + const timer = metrics?.epochTransitionStepTime.startTimer({ + step: "processEffectiveBalanceUpdates", + }); + processEffectiveBalanceUpdates(state, cache); + timer?.(); + } processSlashingsReset(state, cache); processRandaoMixesReset(state, cache); @@ -113,16 +124,20 @@ export function processEpoch( if (fork === ForkSeq.phase0) { processParticipationRecordUpdates(state as CachedBeaconStatePhase0); } else { - const participationFlagUpdatesTimer = metrics?.epochTransitionStepTime.startTimer({ - step: "processParticipationFlagUpdates", - }); - processParticipationFlagUpdates(state as CachedBeaconStateAltair); - participationFlagUpdatesTimer?.(); + { + const timer = metrics?.epochTransitionStepTime.startTimer({ + step: "processParticipationFlagUpdates", + }); + processParticipationFlagUpdates(state as CachedBeaconStateAltair); + timer?.(); + } - const syncCommitteeUpdatesTimer = metrics?.epochTransitionStepTime.startTimer({ - step: "processSyncCommitteeUpdates", - }); - processSyncCommitteeUpdates(state as CachedBeaconStateAltair); - syncCommitteeUpdatesTimer?.(); + { + const timer = metrics?.epochTransitionStepTime.startTimer({ + step: "processSyncCommitteeUpdates", + }); + processSyncCommitteeUpdates(state as CachedBeaconStateAltair); + timer?.(); + } } } diff --git a/packages/state-transition/src/stateTransition.ts b/packages/state-transition/src/stateTransition.ts index f4f8efda31cb..cdb8878c87fa 100644 --- a/packages/state-transition/src/stateTransition.ts +++ b/packages/state-transition/src/stateTransition.ts @@ -2,7 +2,7 @@ import {toHexString} from "@chainsafe/ssz"; import {allForks, Slot, ssz} from "@lodestar/types"; import {SLOTS_PER_EPOCH} from "@lodestar/params"; import {BeaconStateTransitionMetrics, onPostStateMetrics, onStateCloneMetrics} from "./metrics.js"; -import {beforeProcessEpoch, EpochTransitionCacheOpts} from "./cache/epochTransitionCache.js"; +import {beforeProcessEpoch, EpochTransitionCache, EpochTransitionCacheOpts} from "./cache/epochTransitionCache.js"; import { CachedBeaconStateAllForks, CachedBeaconStatePhase0, @@ -164,23 +164,34 @@ function processSlotsWithTransientCache( const fork = postState.config.getForkSeq(postState.slot); const epochTransitionTimer = metrics?.epochTransitionTime.startTimer(); - const beforeProcessEpochTimer = metrics?.epochTransitionStepTime.startTimer({step: "beforeProcessEpoch"}); - const epochTransitionCache = beforeProcessEpoch(postState, epochTransitionCacheOpts); - beforeProcessEpochTimer?.({step: "beforeProcessEpoch"}); + + let epochTransitionCache: EpochTransitionCache; + { + const timer = metrics?.epochTransitionStepTime.startTimer({step: "beforeProcessEpoch"}); + epochTransitionCache = beforeProcessEpoch(postState, epochTransitionCacheOpts); + timer?.(); + } + processEpoch(fork, postState, epochTransitionCache, metrics); + const {currentEpoch, statuses, balances} = epochTransitionCache; metrics?.registerValidatorStatuses(currentEpoch, statuses, balances); postState.slot++; - const afterProcessEpochTimer = metrics?.epochTransitionStepTime.startTimer({step: "afterProcessEpoch"}); - postState.epochCtx.afterProcessEpoch(postState, epochTransitionCache); - afterProcessEpochTimer?.({step: "afterProcessEpoch"}); + + { + const timer = metrics?.epochTransitionStepTime.startTimer({step: "afterProcessEpoch"}); + postState.epochCtx.afterProcessEpoch(postState, epochTransitionCache); + timer?.(); + } // Running commit here is not strictly necessary. The cost of running commit twice (here + after process block) // Should be negligible but gives better metrics to differentiate the cost of it for block and epoch proc. - const epochTransitionCommitTimer = metrics?.epochTransitionCommitTime.startTimer(); - postState.commit(); - epochTransitionCommitTimer?.(); + { + const timer = metrics?.epochTransitionCommitTime.startTimer(); + postState.commit(); + timer?.(); + } // Note: time only on success. Include beforeProcessEpoch, processEpoch, afterProcessEpoch, commit epochTransitionTimer?.();