feat: track epoch transition steps time in metrics

packages/beacon-node/src/metrics/metrics/lodestar.ts

@@ -286,6 +286,12 @@ 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],
     }),
+    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({
       name: "lodestar_stfn_process_block_seconds",
       help: "Time to process a single block in seconds",

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,19 +65,31 @@ 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?.epochTransitionStepTime.startTimer({step: "processJustificationAndFinalization"});
   processJustificationAndFinalization(state, cache);
+  timer?.({step: "processJustificationAndFinalization"});
   if (fork >= ForkSeq.altair) {
+    timer = metrics?.epochTransitionStepTime.startTimer({step: "processInactivityUpdates"});
     processInactivityUpdates(state as CachedBeaconStateAltair, cache);
+    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?.epochTransitionStepTime.startTimer({step: "processRegistryUpdates"});
   processRegistryUpdates(state, cache);
+  timer?.({step: "processRegistryUpdates"});
   // accumulate slashing penalties and only update balances once in processRewardsAndPenalties()
+  timer = metrics?.epochTransitionStepTime.startTimer({step: "processSlashings"});
   const slashingPenalties = processSlashings(state, cache, false);
+  timer?.({step: "processSlashings"});
+  timer = metrics?.epochTransitionStepTime.startTimer({step: "processRewardsAndPenalties"});
   processRewardsAndPenalties(state, cache, slashingPenalties);
+  timer?.({step: "processRewardsAndPenalties"});
   processEth1DataReset(state, cache);
+  timer = metrics?.epochTransitionStepTime.startTimer({step: "processEffectiveBalanceUpdates"});
   processEffectiveBalanceUpdates(state, cache);
+  timer?.({step: "processEffectiveBalanceUpdates"});
   processSlashingsReset(state, cache);
   processRandaoMixesReset(state, cache);
 
@@ -84,7 +102,11 @@ export function processEpoch(fork: ForkSeq, state: CachedBeaconStateAllForks, ca
   if (fork === ForkSeq.phase0) {
     processParticipationRecordUpdates(state as CachedBeaconStatePhase0);
   } else {
+    timer = metrics?.epochTransitionStepTime.startTimer({step: "processParticipationFlagUpdates"});
     processParticipationFlagUpdates(state as CachedBeaconStateAltair);
+    timer?.({step: "processParticipationFlagUpdates"});
+    timer = metrics?.epochTransitionStepTime.startTimer({step: "processSyncCommitteeUpdates"});
     processSyncCommitteeUpdates(state as CachedBeaconStateAltair);
+    timer?.({step: "processSyncCommitteeUpdates"});
   }
 }

packages/state-transition/src/metrics.ts

@@ -5,6 +5,7 @@ import {AttesterStatus} from "./util/attesterStatus.js";
 export type BeaconStateTransitionMetrics = {
   epochTransitionTime: Histogram;
   epochTransitionCommitTime: Histogram;
+  epochTransitionStepTime: Histogram<"step">;
   processBlockTime: Histogram;
   processBlockCommitTime: Histogram;
   stateHashTreeRootTime: Histogram;
@@ -23,7 +24,7 @@ export type BeaconStateTransitionMetrics = {
 type LabelValues<T extends string> = Partial<Record<T, string | number>>;
 
 interface Histogram<T extends string = string> {
-  startTimer(): () => void;
+  startTimer(labels?: LabelValues<T>): (labels?: LabelValues<T>) => number;
 
   observe(value: number): void;
   observe(labels: LabelValues<T>, values: number): void;

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?.epochTransitionStepTime.startTimer({step: "beforeProcessEpoch"});
       const epochTransitionCache = beforeProcessEpoch(postState, epochTransitionCacheOpts);
-      processEpoch(fork, postState, epochTransitionCache);
+      beforeProcessEpochTimer?.({step: "beforeProcessEpoch"});
+      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"});
 
       // 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.