chore: add miner perf metrics

eth/catalyst/api.go

@@ -32,11 +32,18 @@ import (
 	"github.com/ethereum/go-ethereum/eth"
 	"github.com/ethereum/go-ethereum/eth/downloader"
 	"github.com/ethereum/go-ethereum/log"
+	"github.com/ethereum/go-ethereum/metrics"
 	"github.com/ethereum/go-ethereum/miner"
 	"github.com/ethereum/go-ethereum/node"
 	"github.com/ethereum/go-ethereum/rpc"
 )
 
+var (
+	forkChoiceUnsafeTimer = metrics.NewRegisteredTimer("engine/fork/unsafe", nil)
+	forkChoiceSafeTimer = metrics.NewRegisteredTimer("engine/fork/safe", nil)
+	forkChoiceFinalTimer = metrics.NewRegisteredTimer("engine/fork/final", nil)
+)
+
 // Register adds the engine API to the full node.
 func Register(stack *node.Node, backend *eth.Ethereum) error {
 	log.Warn("Engine API enabled", "protocol", "eth")
@@ -313,9 +320,11 @@ func (api *ConsensusAPI) forkchoiceUpdated(update engine.ForkchoiceStateV1, payl
 	}
 	if rawdb.ReadCanonicalHash(api.eth.ChainDb(), block.NumberU64()) != update.HeadBlockHash {
 		// Block is not canonical, set head.
+		start := time.Now()
 		if latestValid, err := api.eth.BlockChain().SetCanonical(block); err != nil {
 			return engine.ForkChoiceResponse{PayloadStatus: engine.PayloadStatusV1{Status: engine.INVALID, LatestValidHash: &latestValid}}, err
 		}
+		forkChoiceUnsafeTimer.Update(time.Since(start))
 	} else if api.eth.BlockChain().CurrentBlock().Hash() == update.HeadBlockHash {
 		// If the specified head matches with our local head, do nothing and keep
 		// generating the payload. It's a special corner case that a few slots are
@@ -344,7 +353,9 @@ func (api *ConsensusAPI) forkchoiceUpdated(update engine.ForkchoiceStateV1, payl
 			return engine.STATUS_INVALID, engine.InvalidForkChoiceState.With(errors.New("final block not in canonical chain"))
 		}
 		// Set the finalized block
+		start := time.Now()
 		api.eth.BlockChain().SetFinalized(finalBlock.Header())
+		forkChoiceFinalTimer.Update(time.Since(start))
 	}
 	// Check if the safe block hash is in our canonical tree, if not somethings wrong
 	if update.SafeBlockHash != (common.Hash{}) {
@@ -358,7 +369,9 @@ func (api *ConsensusAPI) forkchoiceUpdated(update engine.ForkchoiceStateV1, payl
 			return engine.STATUS_INVALID, engine.InvalidForkChoiceState.With(errors.New("safe block not in canonical chain"))
 		}
 		// Set the safe block
+		start := time.Now()
 		api.eth.BlockChain().SetSafe(safeBlock.Header())
+		forkChoiceSafeTimer.Update(time.Since(start))
 	}
 	// If payload generation was requested, create a new block to be potentially
 	// sealed by the beacon client. The payload will be requested later, and we

miner/miner.go

@@ -35,9 +35,21 @@ import (
 	"github.com/ethereum/go-ethereum/eth/tracers"
 	"github.com/ethereum/go-ethereum/event"
 	"github.com/ethereum/go-ethereum/log"
+	"github.com/ethereum/go-ethereum/metrics"
 	"github.com/ethereum/go-ethereum/params"
 )
 
+var (
+	sendBuildReqTimer = metrics.NewRegisteredTimer("miner/build/request", nil)
+	buildEmptyPayloadTimer = metrics.NewRegisteredTimer("miner/build/empty", nil)
+	buildFullPayloadTimer = metrics.NewRegisteredTimer("miner/build/full", nil)
+	prepareWorkTimer = metrics.NewRegisteredTimer("miner/build/prepare", nil)
+	achieveTxTimer = metrics.NewRegisteredTimer("miner/build/txpool", nil)
+	commitDepositTxTimer = metrics.NewRegisteredTimer("miner/build/commit/deposit", nil)
+	commitPoolTxTimer = metrics.NewRegisteredTimer("miner/build/commit/pool", nil)
+	assembleWorkTimer = metrics.NewRegisteredTimer("miner/build/assemble", nil)
+)
+
 // Backend wraps all methods required for mining. Only full node is capable
 // to offer all the functions here.
 type Backend interface {

miner/payload_building.go

@@ -221,6 +221,7 @@ func (w *worker) buildPayload(args *BuildPayloadArgs) (*Payload, error) {
 		log.Error("Built initial payload error", "id", args.Id(), "error", empty.err)
 		return nil, empty.err
 	}
+	buildEmptyPayloadTimer.Update(time.Since(start))
 	log.Info("Built initial payload", "id", args.Id(), "number", empty.block.NumberU64(), "hash", empty.block.Hash(), "elapsed", common.PrettyDuration(time.Since(start)))
 
 	// Construct a payload object for return.
@@ -267,6 +268,7 @@ func (w *worker) buildPayload(args *BuildPayloadArgs) (*Payload, error) {
 					log.Error("Failed to build updated payload", "id", payload.id, "err", r.err)
 					return
 				}
+				buildFullPayloadTimer.Update(time.Since(start))
 				log.Info("Built updated payload", "id", payload.id, "number", r.block.NumberU64(), "hash", r.block.Hash(), "elapsed", common.PrettyDuration(time.Since(start)))
 				payload.update(r, time.Since(start), func() {
 					w.cacheMiningBlock(r.block, r.env)

miner/worker.go

@@ -1050,57 +1050,63 @@ func (w *worker) prepareWork(genParams *generateParams) (*environment, error) {
 // be customized with the plugin in the future.
 func (w *worker) fillTransactions(interrupt *atomic.Int32, env *environment) error {
 	start := time.Now()
+	var commitDuration time.Duration
+
 	pending := w.eth.TxPool().Pending(true)
 	log.Info("got pending from pool", "parent hash", env.header.ParentHash, "duration", common.PrettyDuration(time.Since(start)))
 
 	// Split the pending transactions into locals and remotes.
-	start = time.Now()
+	start1 := time.Now()
 	localTxs, remoteTxs := make(map[common.Address][]*txpool.LazyTransaction), pending
 	for _, account := range w.eth.TxPool().Locals() {
 		if txs := remoteTxs[account]; len(txs) > 0 {
 			delete(remoteTxs, account)
 			localTxs[account] = txs
 		}
 	}
-	log.Info("got locals from pool", "parent hash", env.header.ParentHash, "duration", common.PrettyDuration(time.Since(start)))
+	log.Info("got locals from pool", "parent hash", env.header.ParentHash, "duration", common.PrettyDuration(time.Since(start1)))
 
 
 	// Fill the block with all available pending transactions.
 	if len(localTxs) > 0 {
-		start = time.Now()
+		start2 := time.Now()
 		txs := newTransactionsByPriceAndNonce(env.signer, localTxs, env.header.BaseFee)
-		log.Info("local newTransactionsByPriceAndNonce", "parent hash", env.header.ParentHash, "duration", common.PrettyDuration(time.Since(start)))
+		log.Info("local newTransactionsByPriceAndNonce", "parent hash", env.header.ParentHash, "duration", common.PrettyDuration(time.Since(start2)))
 
-		start = time.Now()
+		start3 := time.Now()
 		if err := w.commitTransactions(env, txs, interrupt); err != nil {
 			return err
 		}
-		log.Info("local commitTransactions", "parent hash", env.header.ParentHash, "duration", common.PrettyDuration(time.Since(start)))
+		commitDuration += time.Since(start3)
+		log.Info("local commitTransactions", "parent hash", env.header.ParentHash, "duration", common.PrettyDuration(time.Since(start3)))
 
 	}
 	if len(remoteTxs) > 0 {
-		start = time.Now()
+		start4 := time.Now()
 		txs := newTransactionsByPriceAndNonce(env.signer, remoteTxs, env.header.BaseFee)
-		log.Info("remote newTransactionsByPriceAndNonce", "parent hash", env.header.ParentHash, "duration", common.PrettyDuration(time.Since(start)))
+		log.Info("remote newTransactionsByPriceAndNonce", "parent hash", env.header.ParentHash, "duration", common.PrettyDuration(time.Since(start4)))
 
-		start = time.Now()
+		start5 := time.Now()
 		if err := w.commitTransactions(env, txs, interrupt); err != nil {
 			return err
 		}
-		log.Info("remote commitTransactions", "parent hash", env.header.ParentHash, "duration", common.PrettyDuration(time.Since(start)))
-
+		commitDuration += time.Since(start5)
+		log.Info("remote commitTransactions", "parent hash", env.header.ParentHash, "duration", common.PrettyDuration(time.Since(start5)))
 	}
+	achieveTxTimer.Update(time.Since(start) - commitDuration)
+	commitPoolTxTimer.Update(commitDuration)
 	return nil
 }
 
 // generateWork generates a sealing block based on the given parameters.
 func (w *worker) generateWork(genParams *generateParams) *newPayloadResult {
 	start := time.Now()
 	work, err := w.prepareWork(genParams)
-	log.Info("prepared work", "parent hash", genParams.parentHash, "isEmpty", genParams.noTxs, "duration", common.PrettyDuration(time.Since(start)))
 	if err != nil {
 		return &newPayloadResult{err: err}
 	}
+	prepareWorkTimer.Update(time.Since(start))
+	log.Info("prepared work", "parent hash", genParams.parentHash, "isEmpty", genParams.noTxs, "duration", common.PrettyDuration(time.Since(start)))
 	defer work.discard()
 	if work.gasPool == nil {
 		work.gasPool = new(core.GasPool).AddGas(work.header.GasLimit)
@@ -1123,6 +1129,7 @@ func (w *worker) generateWork(genParams *generateParams) *newPayloadResult {
 		}
 		work.tcount++
 	}
+	commitDepositTxTimer.Update(time.Since(start))
 	log.Info("committed deposit txs", "parent hash", genParams.parentHash, "isEmpty", genParams.noTxs, "duration", common.PrettyDuration(time.Since(start)))
 
 	// forced transactions done, fill rest of block with transactions
@@ -1141,11 +1148,12 @@ func (w *worker) generateWork(genParams *generateParams) *newPayloadResult {
 
 	start = time.Now()
 	block, err := w.engine.FinalizeAndAssemble(w.chain, work.header, work.state, work.txs, nil, work.receipts, genParams.withdrawals)
-	log.Info("FinalizeAndAssembled", "parent hash", genParams.parentHash, "block number", block.NumberU64(), "isEmpty", genParams.noTxs, "duration", common.PrettyDuration(time.Since(start)))
-
 	if err != nil {
 		return &newPayloadResult{err: err}
 	}
+	assembleWorkTimer.Update(time.Since(start))
+	log.Info("FinalizeAndAssembled", "parent hash", genParams.parentHash, "block number", block.NumberU64(), "isEmpty", genParams.noTxs, "duration", common.PrettyDuration(time.Since(start)))
+
 	return &newPayloadResult{
 		block:    block,
 		fees:     totalFees(block, work.receipts),
@@ -1269,6 +1277,7 @@ func (w *worker) getSealingBlock(params *generateParams) *newPayloadResult {
 	select {
 	case w.getWorkCh <- req:
 		log.Info("sent build req", "parent hash", params.parentHash, "isEmpty", params.noTxs, "duration", common.PrettyDuration(time.Since(start)))
+		sendBuildReqTimer.Update(time.Since(start))
 		return <-req.result
 	case <-w.exitCh:
 		return &newPayloadResult{err: errors.New("miner closed")}