add separate metrics for block insertion and chain validation (#13446)

NewPayload function when processing a new block spends time on two main
sub-functions - `InsertBlockAndWait` and `ValidateChain`.

I want to see how the time we are spending there is distributed among
them and see how specific optimisation affects them.

Co-authored-by: shota.silagadze <[email protected]>

cl/monitor/metrics.go

@@ -28,6 +28,8 @@ var (
 	batchVerificationThroughput    = metrics.GetOrCreateGauge("aggregation_per_signature")
 	blobVerificationTime           = metrics.GetOrCreateGauge("blob_verification_time")
 	executionTime                  = metrics.GetOrCreateGauge("execution_time")
+	executionClientInsertingBlocks = metrics.GetOrCreateGauge("execution_client_insert_blocks_time")
+	executionClientValidateChain   = metrics.GetOrCreateGauge("execution_client_validate_chain_time")
 
 	// Epoch processing metrics
 	EpochProcessingTime                     = metrics.GetOrCreateGauge("epoch_processing_time")
@@ -223,6 +225,14 @@ func ObserveBlobVerificationTime(startTime time.Time) {
 	blobVerificationTime.Set(microToMilli(time.Since(startTime).Microseconds()))
 }
 
-func ObserveExecutionTime(startTime time.Time) {
+func ObserveNewPayloadTime(startTime time.Time) {
 	executionTime.Set(microToMilli(time.Since(startTime).Microseconds()))
 }
+
+func ObserveExecutionClientInsertingBlocks(startTime time.Time) {
+	executionClientInsertingBlocks.Set(microToMilli(time.Since(startTime).Microseconds()))
+}
+
+func ObserveExecutionClientValidateChain(startTime time.Time) {
+	executionClientValidateChain.Set(microToMilli(time.Since(startTime).Microseconds()))
+}

cl/phase1/execution_client/execution_client_direct.go

@@ -22,11 +22,13 @@ import (
 	"errors"
 	"fmt"
 	"math/big"
+	"time"
 
 	libcommon "github.com/erigontech/erigon-lib/common"
 	"github.com/erigontech/erigon-lib/common/hexutility"
 	execution "github.com/erigontech/erigon-lib/gointerfaces/executionproto"
 	"github.com/erigontech/erigon/cl/cltypes"
+	"github.com/erigontech/erigon/cl/monitor"
 	"github.com/erigontech/erigon/core/types"
 	"github.com/erigontech/erigon/turbo/engineapi/engine_types"
 	"github.com/erigontech/erigon/turbo/execution/eth1/eth1_chain_reader"
@@ -66,20 +68,24 @@ func (cc *ExecutionClientDirect) NewPayload(
 		return PayloadStatusInvalidated, err
 	}
 
+	startInsertBlockAndWait := time.Now()
 	if err := cc.chainRW.InsertBlockAndWait(ctx, types.NewBlockFromStorage(payload.BlockHash, header, txs, nil, body.Withdrawals)); err != nil {
 		return PayloadStatusNone, err
 	}
+	monitor.ObserveExecutionClientInsertingBlocks(startInsertBlockAndWait)
 
 	headHeader := cc.chainRW.CurrentHeader(ctx)
 	if headHeader == nil || header.Number.Uint64() > headHeader.Number.Uint64()+1 {
 		// can't validate yet
 		return PayloadStatusNotValidated, nil
 	}
 
+	startValidateChain := time.Now()
 	status, _, _, err := cc.chainRW.ValidateChain(ctx, payload.BlockHash, payload.BlockNumber)
 	if err != nil {
 		return PayloadStatusNone, err
 	}
+	monitor.ObserveExecutionClientValidateChain(startValidateChain)
 	// check status
 	switch status {
 	case execution.ExecutionStatus_BadBlock, execution.ExecutionStatus_InvalidForkchoice:

cl/phase1/forkchoice/on_block.go

@@ -115,6 +115,7 @@ func (f *ForkChoiceStore) ProcessBlockExecution(ctx context.Context, block *clty
 
 	timeStartExec := time.Now()
 	payloadStatus, err := f.engine.NewPayload(ctx, block.Block.Body.ExecutionPayload, &block.Block.ParentRoot, versionedHashes, executionRequestsList)
+	monitor.ObserveNewPayloadTime(timeStartExec)
 	switch payloadStatus {
 	case execution_client.PayloadStatusInvalidated:
 		log.Warn("OnBlock: block is invalid", "block", libcommon.Hash(blockRoot), "err", err)
@@ -135,7 +136,6 @@ func (f *ForkChoiceStore) ProcessBlockExecution(ctx context.Context, block *clty
 	if err != nil {
 		return fmt.Errorf("newPayload failed: %v", err)
 	}
-	monitor.ObserveExecutionTime(timeStartExec)
 	return nil
 }
 
@@ -213,6 +213,7 @@ func (f *ForkChoiceStore) OnBlock(ctx context.Context, block *cltypes.SignedBeac
 		}
 		timeStartExec := time.Now()
 		payloadStatus, err := f.engine.NewPayload(ctx, block.Block.Body.ExecutionPayload, &block.Block.ParentRoot, versionedHashes, executionRequestsList)
+		monitor.ObserveNewPayloadTime(timeStartExec)
 		switch payloadStatus {
 		case execution_client.PayloadStatusNotValidated:
 			log.Debug("OnBlock: block is not validated yet", "block", libcommon.Hash(blockRoot))
@@ -239,7 +240,6 @@ func (f *ForkChoiceStore) OnBlock(ctx context.Context, block *cltypes.SignedBeac
 		if err != nil {
 			return fmt.Errorf("newPayload failed: %v", err)
 		}
-		monitor.ObserveExecutionTime(timeStartExec)
 	}
 	log.Trace("OnBlock: engine", "elapsed", time.Since(startEngine))
 	startStateProcess := time.Now()

cmd/prometheus/dashboards/erigon_internals.json

@@ -1582,7 +1582,7 @@
               }
             }
           ],
-          "title": "ValidateChain: time spent",
+          "title": "NewPayload: time spent",
           "type": "timeseries"
         },
         {

dashboards/erigon_custom_metrics/erigon_custom_metrics.internal.json

@@ -1473,7 +1473,7 @@
               "refId": "A"
             }
           ],
-          "title": "ValidateChain: time spent",
+          "title": "NewPayload: time spent",
           "type": "timeseries"
         },
         {