diff --git a/beacon_chain/gossip_processing/eth2_processor.nim b/beacon_chain/gossip_processing/eth2_processor.nim index 728986fff4..0462686194 100644 --- a/beacon_chain/gossip_processing/eth2_processor.nim +++ b/beacon_chain/gossip_processing/eth2_processor.nim @@ -100,6 +100,20 @@ declareHistogram data_column_sidecar_delay, "Time(s) betweeen slot start and data column sidecar reception", buckets = delayBuckets +declareHistogram beacon_data_column_sidecar_computation_seconds, + "Time taken to compute data column sidecar, including cells and inclusion proof", + buckets = [0.005, 0.01, 0.025, 0.05, 0.075, 0.1, 0.25, 0.5, 0.75, 1.0, 2.5, 5.0, Inf] + +declareCounter beacon_engine_getBlobsV2_requests, + "Total number of engine_getBlobsV2 requests sent" + +declareCounter beacon_engine_getBlobsV2_responses, + "Total number of engine_getBlobsV2 successful responses received" + +declareHistogram beacon_engine_getBlobsV2_request_duration_seconds, + "Duration of engine_getBlobsV2 requests", + buckets = [0.01, 0.05, 0.1, 0.5, 1, 2.5, 5, 10] + type DoppelgangerProtection = object broadcastStartEpoch*: Epoch ##\ @@ -362,12 +376,17 @@ proc validateDataColumnSidecarFromEL*( let columnless = o.unsafeGet() withBlck(columnless): when consensusFork >= ConsensusFork.Fulu: + beacon_engine_getBlobsV2_requests.inc() let start_time = Moment.now() - let blobsFromElOpt = - await elManager.sendGetBlobsV2(forkyBlck) + blobsFromElOpt = + await elManager.sendGetBlobsV2(forkyBlck) + getBlobsV2_end_time = Moment.now() + getBlobsV2_dur = getBlobsV2_end_time - start_time + beacon_engine_getBlobsV2_request_duration_seconds.observe(getBlobsV2_dur.toFloatSeconds()) if blobsFromElOpt.isSome(): let blobsEl = blobsFromElOpt.get() + beacon_engine_getBlobsV2_responses.inc() # check lengths of array[BlobAndProofV2 with blobs # kzg commitments of the signed block @@ -381,11 +400,15 @@ proc validateDataColumnSidecarFromEL*( flat_proof.add(kzg.KzgProof(bytes: proof.data)) let + recover_start_time = Moment.now() recovered_columns = assemble_data_column_sidecars( forkyBlck, blobsEl.mapIt(kzg.KzgBlob(bytes: it.blob.data)), flat_proof) + recover_end_time = Moment.now() + recover_dur = recover_end_time - recover_start_time + beacon_data_column_sidecar_computation_seconds.observe(recover_dur.toFloatSeconds()) # Pop out the column sidecars as we have all columns from the EL discard self.dataColumnQuarantine[].popSidecars(block_root, diff --git a/beacon_chain/gossip_processing/gossip_validation.nim b/beacon_chain/gossip_processing/gossip_validation.nim index d61a7144f9..4ea651aa33 100644 --- a/beacon_chain/gossip_processing/gossip_validation.nim +++ b/beacon_chain/gossip_processing/gossip_validation.nim @@ -44,6 +44,24 @@ declareCounter beacon_sync_messages_dropped_queue_full, declareCounter beacon_contributions_dropped_queue_full, "Number of sync committee contributions dropped because queue is full" +declareCounter beacon_data_column_sidecar_processing_requests, + "Number of data column sidecars submitted for processing" + +declareCounter beacon_data_column_sidecar_processing_successes, + "Number of data column sidecars verified for gossip" + +declareHistogram beacon_data_column_sidecar_gossip_verification_seconds, + "Full runtime of data column sidecars gossip verification", + buckets = [0.005, 0.01, 0.025, 0.05, 0.075, 0.1, 0.25, 0.5, 0.75, 1.0, 2.5, 5.0, 7.5, 10.0, Inf] + +declareHistogram beacon_data_column_sidecar_inclusion_proof_verification_seconds, + "Time taken to verify data column sidecar inclusion proof", + buckets = [0.005, 0.01, 0.025, 0.05, 0.075, 0.1, 0.25, 0.5, 0.75, 1.0, 2.5, 5.0, 7.5, 10.0, Inf] + +declareHistogram beacon_kzg_verification_data_column_batch_seconds, + "Runtime of batched data column kzg verification", + buckets = [0.005, 0.01, 0.025, 0.05, 0.075, 0.1, 0.25, 0.5, 0.75, 1.0, 2.5, 5.0, 7.5, 10.0, Inf] + # This result is a little messy in that it returns Result.ok for # ValidationResult.Accept and an err for the others - this helps transport # an error message to callers but could arguably be done in an cleaner way. @@ -596,6 +614,11 @@ proc validateDataColumnSidecar*( template block_header: untyped = data_column_sidecar.signed_block_header.message + beacon_data_column_sidecar_processing_requests.inc() + + let + startTick = Moment.now() + # [REJECT] The sidecar's index is consistent with `NUMBER_OF_COLUMNS` # -- i.e. `data_column_sidecar.index < NUMBER_OF_COLUMNS` if not (data_column_sidecar.index < dag.cfg.NUMBER_OF_COLUMNS): @@ -631,7 +654,12 @@ proc validateDataColumnSidecar*( # [REJECT] The sidecar's `kzg_commitments` inclusion proof is valid as verified by # `verify_data_column_sidecar_inclusion_proof(sidecar)`. block: - let v = check_data_column_sidecar_inclusion_proof(data_column_sidecar) + let + inclusionProofStartTick = Moment.now() + v = check_data_column_sidecar_inclusion_proof(data_column_sidecar) + inclusionProofValidationTick = Moment.now() + inclusionProofValidationDur = inclusionProofValidationTick - inclusionProofStartTick + beacon_data_column_sidecar_inclusion_proof_verification_seconds.observe(inclusionProofValidationDur.toFloatSeconds()) if v.isErr: return dag.checkedReject(v.error) @@ -702,10 +730,23 @@ proc validateDataColumnSidecar*( # [REJECT] The sidecar's column data is valid as # verified by `verify_data_column_kzg_proofs(sidecar)` block: - let r = check_data_column_sidecar_kzg_proofs(data_column_sidecar) + let + kzgStartTick = Moment.now() + r = check_data_column_sidecar_kzg_proofs(data_column_sidecar) + kzgValidationTick = Moment.now() + kzgValidationDur = kzgValidationTick - kzgStartTick + beacon_kzg_verification_data_column_batch_seconds.observe(kzgValidationDur.toFloatSeconds()) if r.isErr: return dag.checkedReject(r.error) + let + validationTick = Moment.now() + validationDur = validationTick - startTick + + beacon_data_column_sidecar_gossip_verification_seconds.observe(validationDur.toFloatSeconds()) + + beacon_data_column_sidecar_processing_successes.inc() + # Send notification about new data column sidecar via callback let onDataColumnSidecarCallback = dataColumnQuarantine[].onDataColumnSidecarCallback()