Skip to content

Commit

Permalink
feat: track timings of various stages of block import (#6439)
Browse files Browse the repository at this point in the history 
* feat: minutely track timings of various stages of block import

* remove recvToValLatency metrics
  • Loading branch information
@g11tech
g11tech committed Feb 17, 2024
1 parent 290c301 commit c7c9941
Show file tree
Hide file tree
Showing 6 changed files with 150 additions and 65 deletions.
11 changes: 8 additions & 3 deletions packages/beacon-node/src/chain/blocks/importBlock.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -447,9 +448,13 @@ 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.recvToValidation.observe(recvToValidation);
this.metrics?.gossipBlock.blockImport.validationTime.observe(validationTime);

this.logger.debug("Imported block", {slot: blockSlot, recvToValLatency, recvToValidation, validationTime});
}

this.logger.verbose("Block processed", {
Expand Down
15 changes: 11 additions & 4 deletions packages/beacon-node/src/chain/blocks/verifyBlocksExecutionPayloads.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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) {
Expand Down Expand Up @@ -246,11 +247,17 @@ 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);
chain.logger.verbose("Verified execution payload", {
const recvToValidation = executionTime / 1000 - opts.seenTimestampSec;
const validationTime = recvToValidation - recvToValLatency;

chain.metrics?.gossipBlock.executionPayload.recvToValidation.observe(recvToValidation);
chain.metrics?.gossipBlock.executionPayload.validationTime.observe(validationTime);

chain.logger.debug("Verified execution payload", {
slot: blocks[0].message.slot,
recvToVerifiedExecPayload,
recvToValLatency,
recvToValidation,
validationTime,
});
}

Expand Down
16 changes: 13 additions & 3 deletions packages/beacon-node/src/chain/blocks/verifyBlocksSignatures.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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().
Expand Down Expand Up @@ -54,9 +55,18 @@ 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.recvToValidation.observe(recvToValidation);
metrics?.gossipBlock.signatureVerification.validationTime.observe(validationTime);

logger.debug("Verified block signatures", {
slot: blocks[0].message.slot,
recvToValLatency,
recvToValidation,
validationTime,
});
}

return {verifySignaturesTime};
Expand Down
11 changes: 8 additions & 3 deletions packages/beacon-node/src/chain/blocks/verifyBlocksStateTransitionOnly.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -96,9 +97,13 @@ 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.recvToValidation.observe(recvToValidation);
metrics?.gossipBlock.stateTransition.validationTime.observe(validationTime);

logger.debug("Verified block state transition", {slot, recvToValLatency, recvToValidation, validationTime});
}

return {postStates, proposerBalanceDeltas, verifyStateTime};
Expand Down
97 changes: 70 additions & 27 deletions packages/beacon-node/src/metrics/metrics/lodestar.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -668,26 +668,68 @@ 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: {
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: {
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: {
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: {
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: {
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",
Expand All @@ -705,21 +747,22 @@ 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({
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],
}),
},
Expand Down
65 changes: 40 additions & 25 deletions packages/beacon-node/src/network/processor/gossipHandlers.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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, {
Expand All @@ -133,19 +133,27 @@ 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.recvToValidation.observe(recvToValidation);
metrics?.gossipBlock.gossipValidation.validationTime.observe(validationTime);

logger.debug("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) {
Expand Down Expand Up @@ -177,28 +185,35 @@ 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.recvToValidation.observe(recvToValidation);
metrics?.gossipBlob.validationTime.observe(validationTime);

logger.debug("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) {
Expand Down

0 comments on commit c7c9941

Please sign in to comment.