feat: track timings of various stages of block import

packages/beacon-node/src/chain/blocks/importBlock.ts

@@ -67,6 +67,7 @@ export async function importBlock(
   const parentEpoch = computeEpochAtSlot(parentBlockSlot);
   const prevFinalizedEpoch = this.forkChoice.getFinalizedCheckpoint().epoch;
   const blockDelaySec = (fullyVerifiedBlock.seenTimestampSec - postState.genesisTime) % this.config.SECONDS_PER_SLOT;
+  const recvToValLatency = Date.now() / 1000 - (opts.seenTimestampSec ?? Date.now() / 1000);
 
   // 1. Persist block to hot DB (pre-emptively)
   // If eagerPersistBlock = true we do that in verifyBlocksInEpoch to batch all I/O operations to save block time to head
@@ -447,9 +448,14 @@ export async function importBlock(
   }, 0);
 
   if (opts.seenTimestampSec !== undefined) {
-    const recvToImportedBlock = Date.now() / 1000 - opts.seenTimestampSec;
-    this.metrics?.gossipBlock.receivedToBlockImport.observe(recvToImportedBlock);
-    this.logger.verbose("Imported block", {slot: blockSlot, recvToImportedBlock});
+    const recvToValidation = Date.now() / 1000 - opts.seenTimestampSec;
+    const validationTime = recvToValidation - recvToValLatency;
+
+    this.metrics?.gossipBlock.blockImport.recvToValLatency.observe(recvToValLatency);
+    this.metrics?.gossipBlock.blockImport.recvToValidation.observe(recvToValidation);
+    this.metrics?.gossipBlock.blockImport.validationTime.observe(validationTime);
+
+    this.logger.verbose("Imported block", {slot: blockSlot, recvToValLatency, recvToValidation, validationTime});
   }
 
   this.logger.verbose("Block processed", {

packages/beacon-node/src/chain/blocks/verifyBlocksExecutionPayloads.ts

@@ -75,6 +75,7 @@ export async function verifyBlocksExecutionPayload(
 ): Promise<SegmentExecStatus> {
   const executionStatuses: MaybeValidExecutionStatus[] = [];
   let mergeBlockFound: bellatrix.BeaconBlock | null = null;
+  const recvToValLatency = Date.now() / 1000 - (opts.seenTimestampSec ?? Date.now() / 1000);
 
   // Error in the same way as verifyBlocksSanityChecks if empty blocks
   if (blocks.length === 0) {
@@ -246,11 +247,18 @@ export async function verifyBlocksExecutionPayload(
 
   const executionTime = Date.now();
   if (blocks.length === 1 && opts.seenTimestampSec !== undefined && executionStatuses[0] === ExecutionStatus.Valid) {
-    const recvToVerifiedExecPayload = executionTime / 1000 - opts.seenTimestampSec;
-    chain.metrics?.gossipBlock.receivedToExecutionPayloadVerification.observe(recvToVerifiedExecPayload);
+    const recvToValidation = executionTime / 1000 - opts.seenTimestampSec;
+    const validationTime = recvToValidation - recvToValLatency;
+
+    chain.metrics?.gossipBlock.executionPayload.recvToValLatency.observe(recvToValLatency);
+    chain.metrics?.gossipBlock.executionPayload.recvToValidation.observe(recvToValidation);
+    chain.metrics?.gossipBlock.executionPayload.validationTime.observe(validationTime);
+
     chain.logger.verbose("Verified execution payload", {
       slot: blocks[0].message.slot,
-      recvToVerifiedExecPayload,
+      recvToValLatency,
+      recvToValidation,
+      validationTime,
     });
   }
 

packages/beacon-node/src/chain/blocks/verifyBlocksSignatures.ts

@@ -22,6 +22,7 @@ export async function verifyBlocksSignatures(
   opts: ImportBlockOpts
 ): Promise<{verifySignaturesTime: number}> {
   const isValidPromises: Promise<boolean>[] = [];
+  const recvToValLatency = Date.now() / 1000 - (opts.seenTimestampSec ?? Date.now() / 1000);
 
   // Verifies signatures after running state transition, so all SyncCommittee signed roots are known at this point.
   // We must ensure block.slot <= state.slot before running getAllBlockSignatureSets().
@@ -54,9 +55,19 @@ export async function verifyBlocksSignatures(
 
   const verifySignaturesTime = Date.now();
   if (blocks.length === 1 && opts.seenTimestampSec !== undefined) {
-    const recvToSigVer = verifySignaturesTime / 1000 - opts.seenTimestampSec;
-    metrics?.gossipBlock.receivedToSignaturesVerification.observe(recvToSigVer);
-    logger.verbose("Verified block signatures", {slot: blocks[0].message.slot, recvToSigVer});
+    const recvToValidation = verifySignaturesTime / 1000 - opts.seenTimestampSec;
+    const validationTime = recvToValidation - recvToValLatency;
+
+    metrics?.gossipBlock.signatureVerification.recvToValLatency.observe(recvToValLatency);
+    metrics?.gossipBlock.signatureVerification.recvToValidation.observe(recvToValidation);
+    metrics?.gossipBlock.signatureVerification.validationTime.observe(validationTime);
+
+    logger.verbose("Verified block signatures", {
+      slot: blocks[0].message.slot,
+      recvToValLatency,
+      recvToValidation,
+      validationTime,
+    });
   }
 
   return {verifySignaturesTime};

packages/beacon-node/src/chain/blocks/verifyBlocksStateTransitionOnly.ts

@@ -31,6 +31,7 @@ export async function verifyBlocksStateTransitionOnly(
 ): Promise<{postStates: CachedBeaconStateAllForks[]; proposerBalanceDeltas: number[]; verifyStateTime: number}> {
   const postStates: CachedBeaconStateAllForks[] = [];
   const proposerBalanceDeltas: number[] = [];
+  const recvToValLatency = Date.now() / 1000 - (opts.seenTimestampSec ?? Date.now() / 1000);
 
   for (let i = 0; i < blocks.length; i++) {
     const {validProposerSignature, validSignatures} = opts;
@@ -96,9 +97,14 @@ export async function verifyBlocksStateTransitionOnly(
   const verifyStateTime = Date.now();
   if (blocks.length === 1 && opts.seenTimestampSec !== undefined) {
     const slot = blocks[0].block.message.slot;
-    const recvToTransition = verifyStateTime / 1000 - opts.seenTimestampSec;
-    metrics?.gossipBlock.receivedToStateTransition.observe(recvToTransition);
-    logger.verbose("Verified block state transition", {slot, recvToTransition});
+    const recvToValidation = verifyStateTime / 1000 - opts.seenTimestampSec;
+    const validationTime = recvToValidation - recvToValLatency;
+
+    metrics?.gossipBlock.stateTransition.recvToValLatency.observe(recvToValLatency);
+    metrics?.gossipBlock.stateTransition.recvToValidation.observe(recvToValidation);
+    metrics?.gossipBlock.stateTransition.validationTime.observe(validationTime);
+
+    logger.verbose("Verified block state transition", {slot, recvToValLatency, recvToValidation, validationTime});
   }
 
   return {postStates, proposerBalanceDeltas, verifyStateTime};

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

@@ -668,26 +668,93 @@ export function createLodestarMetrics(
         help: "Time elapsed between block slot time and the time block processed",
         buckets: [0.5, 1, 2, 4, 6, 12],
       }),
-      receivedToGossipValidate: register.histogram({
-        name: "lodestar_gossip_block_received_to_gossip_validate",
-        help: "Time elapsed between block received and block validated",
-        buckets: [0.05, 0.1, 0.3, 0.5, 0.7, 1, 1.3, 1.6, 2, 2.5, 3, 3.5, 4],
-      }),
-      receivedToStateTransition: register.histogram({
-        name: "lodestar_gossip_block_received_to_state_transition",
-        help: "Time elapsed between block received and block state transition",
-        buckets: [0.05, 0.1, 0.3, 0.5, 0.7, 1, 1.3, 1.6, 2, 2.5, 3, 3.5, 4],
-      }),
-      receivedToSignaturesVerification: register.histogram({
-        name: "lodestar_gossip_block_received_to_signatures_verification",
-        help: "Time elapsed between block received and block signatures verification",
-        buckets: [0.05, 0.1, 0.3, 0.5, 0.7, 1, 1.3, 1.6, 2, 2.5, 3, 3.5, 4],
-      }),
-      receivedToExecutionPayloadVerification: register.histogram({
-        name: "lodestar_gossip_block_received_to_execution_payload_verification",
-        help: "Time elapsed between block received and execution payload verification",
-        buckets: [0.05, 0.1, 0.3, 0.5, 0.7, 1, 1.3, 1.6, 2, 2.5, 3, 3.5, 4],
-      }),
+
+      gossipValidation: {
+        recvToValLatency: register.histogram({
+          name: "lodestar_gossip_block_received_to_gossip_validate_latency",
+          help: "Time elapsed between block received and gossip validation start",
+          buckets: [0.05, 0.1, 0.3, 0.5, 0.7, 1, 1.3, 1.6, 2, 2.5, 3, 3.5, 4],
+        }),
+        recvToValidation: register.histogram({
+          name: "lodestar_gossip_block_received_to_gossip_validate",
+          help: "Time elapsed between block received and block validated",
+          buckets: [0.05, 0.1, 0.3, 0.5, 0.7, 1, 1.3, 1.6, 2, 2.5, 3, 3.5, 4],
+        }),
+        validationTime: register.histogram({
+          name: "lodestar_gossip_block_gossip_validate_time",
+          help: "Time to apply gossip validations",
+          buckets: [0.05, 0.1, 0.3, 0.5, 0.7, 1, 1.3, 1.6, 2, 2.5, 3, 3.5, 4],
+        }),
+      },
+      stateTransition: {
+        recvToValLatency: register.histogram({
+          name: "lodestar_gossip_block_received_to_state_transition_latency",
+          help: "Time elapsed between block received and block state transition start",
+          buckets: [0.05, 0.1, 0.3, 0.5, 0.7, 1, 1.3, 1.6, 2, 2.5, 3, 3.5, 4],
+        }),
+        recvToValidation: register.histogram({
+          name: "lodestar_gossip_block_received_to_state_transition",
+          help: "Time elapsed between block received and block state transition",
+          buckets: [0.05, 0.1, 0.3, 0.5, 0.7, 1, 1.3, 1.6, 2, 2.5, 3, 3.5, 4],
+        }),
+        validationTime: register.histogram({
+          name: "lodestar_gossip_block_state_transition_time",
+          help: "Time to validate block state transition",
+          buckets: [0.05, 0.1, 0.3, 0.5, 0.7, 1, 1.3, 1.6, 2, 2.5, 3, 3.5, 4],
+        }),
+      },
+      signatureVerification: {
+        recvToValLatency: register.histogram({
+          name: "lodestar_gossip_block_received_to_signatures_verification_latency",
+          help: "Time elapsed between block recieved and the block signatures verification start",
+          buckets: [0.05, 0.1, 0.3, 0.5, 0.7, 1, 1.3, 1.6, 2, 2.5, 3, 3.5, 4],
+        }),
+        recvToValidation: register.histogram({
+          name: "lodestar_gossip_block_received_to_signatures_verification",
+          help: "Time elapsed between block received and block signatures verification",
+          buckets: [0.05, 0.1, 0.3, 0.5, 0.7, 1, 1.3, 1.6, 2, 2.5, 3, 3.5, 4],
+        }),
+        validationTime: register.histogram({
+          name: "lodestar_gossip_block_signatures_verification_time",
+          help: "Time elapsed for block signatures verification",
+          buckets: [0.05, 0.1, 0.3, 0.5, 0.7, 1, 1.3, 1.6, 2, 2.5, 3, 3.5, 4],
+        }),
+      },
+      executionPayload: {
+        recvToValLatency: register.histogram({
+          name: "lodestar_gossip_block_received_to_execution_payload_verification_latench",
+          help: "Time elapsed between block received and execution payload verification start",
+          buckets: [0.05, 0.1, 0.3, 0.5, 0.7, 1, 1.3, 1.6, 2, 2.5, 3, 3.5, 4],
+        }),
+        recvToValidation: register.histogram({
+          name: "lodestar_gossip_block_received_to_execution_payload_verification",
+          help: "Time elapsed between block received and execution payload verification",
+          buckets: [0.05, 0.1, 0.3, 0.5, 0.7, 1, 1.3, 1.6, 2, 2.5, 3, 3.5, 4],
+        }),
+        validationTime: register.histogram({
+          name: "lodestar_gossip_execution_payload_verification_time",
+          help: "Time elapsed for execution payload verification",
+          buckets: [0.05, 0.1, 0.3, 0.5, 0.7, 1, 1.3, 1.6, 2, 2.5, 3, 3.5, 4],
+        }),
+      },
+      blockImport: {
+        recvToValLatency: register.histogram({
+          name: "lodestar_gossip_block_received_to_block_import_latency",
+          help: "Time elapsed between block received and block import start",
+          buckets: [0.05, 0.1, 0.3, 0.5, 0.7, 1, 1.3, 1.6, 2, 2.5, 3, 3.5, 4],
+        }),
+        recvToValidation: register.histogram({
+          name: "lodestar_gossip_block_received_to_block_import",
+          help: "Time elapsed between block received and block import",
+          buckets: [0.05, 0.1, 0.3, 0.5, 0.7, 1, 1.3, 1.6, 2, 2.5, 3, 3.5, 4],
+        }),
+        validationTime: register.histogram({
+          name: "lodestar_gossip_block_block_import_time",
+          help: "Time elapsed for block import",
+          buckets: [0.05, 0.1, 0.3, 0.5, 0.7, 1, 1.3, 1.6, 2, 2.5, 3, 3.5, 4],
+        }),
+      },
+
       receivedToBlobsAvailabilityTime: register.histogram<{numBlobs: number}>({
         name: "lodestar_gossip_block_received_to_blobs_availability_time",
         help: "Time elapsed between block received and blobs became available",
@@ -705,21 +772,27 @@ export function createLodestarMetrics(
         buckets: [0.05, 0.1, 0.3, 0.5, 0.7, 1, 1.3, 1.6, 2, 2.5, 3, 3.5, 4],
         labelNames: ["numBlobs"],
       }),
-      receivedToBlockImport: register.histogram({
-        name: "lodestar_gossip_block_received_to_block_import",
-        help: "Time elapsed between block received and block import",
-        buckets: [0.05, 0.1, 0.3, 0.5, 0.7, 1, 1.3, 1.6, 2, 2.5, 3, 3.5, 4],
-      }),
+
       processBlockErrors: register.gauge<{error: BlockErrorCode | "NOT_BLOCK_ERROR"}>({
         name: "lodestar_gossip_block_process_block_errors",
         help: "Count of errors, by error type, while processing blocks",
         labelNames: ["error"],
       }),
     },
     gossipBlob: {
-      receivedToGossipValidate: register.histogram({
+      recvToValLatency: register.histogram({
+        name: "lodestar_gossip_blob_received_to_gossip_validate_latency",
+        help: "Time elapsed between blob received and blob validation start",
+        buckets: [0.05, 0.1, 0.2, 0.5, 1, 1.5, 2, 4],
+      }),
+      recvToValidation: register.histogram({
         name: "lodestar_gossip_blob_received_to_gossip_validate",
-        help: "Time elapsed between blob received and blob validated",
+        help: "Time elapsed between blob received and blob validation",
+        buckets: [0.05, 0.1, 0.2, 0.5, 1, 1.5, 2, 4],
+      }),
+      validationTime: register.histogram({
+        name: "lodestar_gossip_blob_gossip_validate_time",
+        help: "Time elapsed for blob validation",
         buckets: [0.05, 0.1, 0.2, 0.5, 1, 1.5, 2, 4],
       }),
     },

packages/beacon-node/src/network/processor/gossipHandlers.ts

@@ -115,7 +115,7 @@ function getDefaultHandlers(modules: ValidatorFnsModules, options: GossipHandler
     const forkTypes = config.getForkTypes(slot);
     const blockHex = prettyBytes(forkTypes.BeaconBlock.hashTreeRoot(signedBlock.message));
     const delaySec = chain.clock.secFromSlot(slot, seenTimestampSec);
-    const recvToVal = Date.now() / 1000 - seenTimestampSec;
+    const recvToValLatency = Date.now() / 1000 - seenTimestampSec;
 
     // always set block to seen cache for all forks so that we don't need to download it
     const blockInputRes = chain.seenGossipBlockInput.getGossipBlockInput(config, {
@@ -133,19 +133,28 @@ function getDefaultHandlers(modules: ValidatorFnsModules, options: GossipHandler
     const blockInputMeta =
       config.getForkSeq(signedBlock.message.slot) >= ForkSeq.deneb ? blockInputRes.blockInputMeta : {};
 
-    metrics?.gossipBlock.receivedToGossipValidate.observe(recvToVal);
-    logger.verbose("Received gossip block", {
-      slot: slot,
-      root: blockHex,
-      curentSlot: chain.clock.currentSlot,
-      peerId: peerIdStr,
-      delaySec,
-      recvToVal,
-      ...blockInputMeta,
-    });
-
     try {
       await validateGossipBlock(config, chain, signedBlock, fork);
+
+      const recvToValidation = Date.now() / 1000 - seenTimestampSec;
+      const validationTime = recvToValidation - recvToValLatency;
+
+      metrics?.gossipBlock.gossipValidation.recvToValLatency.observe(recvToValLatency);
+      metrics?.gossipBlock.gossipValidation.recvToValidation.observe(recvToValidation);
+      metrics?.gossipBlock.gossipValidation.validationTime.observe(validationTime);
+
+      logger.verbose("Received gossip block", {
+        slot: slot,
+        root: blockHex,
+        curentSlot: chain.clock.currentSlot,
+        peerId: peerIdStr,
+        delaySec,
+        ...blockInputMeta,
+        recvToValLatency,
+        recvToValidation,
+        validationTime,
+      });
+
       return blockInput;
     } catch (e) {
       if (e instanceof BlockGossipError) {
@@ -177,28 +186,36 @@ function getDefaultHandlers(modules: ValidatorFnsModules, options: GossipHandler
     const blockHex = prettyBytes(blockRoot);
 
     const delaySec = chain.clock.secFromSlot(slot, seenTimestampSec);
-    const recvToVal = Date.now() / 1000 - seenTimestampSec;
+    const recvToValLatency = Date.now() / 1000 - seenTimestampSec;
 
     const {blockInput, blockInputMeta} = chain.seenGossipBlockInput.getGossipBlockInput(config, {
       type: GossipedInputType.blob,
       blobSidecar,
       blobBytes,
     });
 
-    metrics?.gossipBlob.receivedToGossipValidate.observe(recvToVal);
-    logger.verbose("Received gossip blob", {
-      slot: slot,
-      root: blockHex,
-      curentSlot: chain.clock.currentSlot,
-      peerId: peerIdStr,
-      delaySec,
-      recvToVal,
-      gossipIndex,
-      ...blockInputMeta,
-    });
-
     try {
       await validateGossipBlobSidecar(chain, blobSidecar, gossipIndex);
+      const recvToValidation = Date.now() / 1000 - seenTimestampSec;
+      const validationTime = recvToValidation - recvToValLatency;
+
+      metrics?.gossipBlob.recvToValLatency.observe(recvToValLatency);
+      metrics?.gossipBlob.recvToValidation.observe(recvToValidation);
+      metrics?.gossipBlob.validationTime.observe(validationTime);
+
+      logger.verbose("Received gossip blob", {
+        slot: slot,
+        root: blockHex,
+        curentSlot: chain.clock.currentSlot,
+        peerId: peerIdStr,
+        delaySec,
+        gossipIndex,
+        ...blockInputMeta,
+        recvToValLatency,
+        recvToValidation,
+        validationTime,
+      });
+
       return blockInput;
     } catch (e) {
       if (e instanceof BlobSidecarGossipError) {