From 069da318a625c9591ac4c3a9f9f7d7060cb6eb0e Mon Sep 17 00:00:00 2001
From: Nolan <33241113+nolanxyg@users.noreply.github.com>
Date: Wed, 13 Mar 2024 17:57:10 +0800
Subject: [PATCH 1/8] chore: add miner perf metrics

---
 core/blockchain.go        |  8 ++------
 eth/catalyst/api.go       | 10 ++++++++++
 miner/miner.go            | 21 +++++++++++++++++++++
 miner/payload_building.go |  2 ++
 miner/worker.go           | 18 ++++++++++++++++++
 5 files changed, 53 insertions(+), 6 deletions(-)

diff --git a/core/blockchain.go b/core/blockchain.go
index d3a7766bec..ad7e2f8eec 100644
--- a/core/blockchain.go
+++ b/core/blockchain.go
@@ -1882,12 +1882,8 @@ func (bc *BlockChain) insertChain(chain types.Blocks, setHead bool) (int, error)
 		storageUpdateTimer.Update(statedb.StorageUpdates)               // Storage updates are complete(in validation)
 		accountHashTimer.Update(statedb.AccountHashes)                  // Account hashes are complete(in validation)
 		storageHashTimer.Update(statedb.StorageHashes)                  // Storage hashes are complete(in validation)
-		triehash := statedb.AccountHashes + statedb.StorageHashes       // The time spent on tries hashing
-		trieUpdate := statedb.AccountUpdates + statedb.StorageUpdates   // The time spent on tries update
-		trieRead := statedb.SnapshotAccountReads + statedb.AccountReads // The time spent on account read
-		trieRead += statedb.SnapshotStorageReads + statedb.StorageReads // The time spent on storage read
-		blockExecutionTimer.Update(ptime - trieRead)                    // The time spent on EVM processing
-		blockValidationTimer.Update(vtime - (triehash + trieUpdate))    // The time spent on block validation
+		blockExecutionTimer.Update(ptime)                               // The time spent on block execution
+		blockValidationTimer.Update(vtime)                              // The time spent on block validation
 
 		// Write the block to the chain and get the status.
 		var (
diff --git a/eth/catalyst/api.go b/eth/catalyst/api.go
index 69599d8c6c..eeb60bd6dc 100644
--- a/eth/catalyst/api.go
+++ b/eth/catalyst/api.go
@@ -32,11 +32,17 @@ 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 (
+	forkchoiceUpdateAttributesTimer = metrics.NewRegisteredTimer("api/engine/forkchoiceUpdate/attributes", nil)
+	forkchoiceUpdateHeadsTimer = metrics.NewRegisteredTimer("api/engine/forkchoiceUpdate/heads", 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")
@@ -228,6 +234,8 @@ func checkAttribute(active func(*big.Int, uint64) bool, exists bool, block *big.
 }
 
 func (api *ConsensusAPI) forkchoiceUpdated(update engine.ForkchoiceStateV1, payloadAttributes *engine.PayloadAttributes) (engine.ForkChoiceResponse, error) {
+	start := time.Now()
+
 	api.forkchoiceLock.Lock()
 	defer api.forkchoiceLock.Unlock()
 
@@ -398,8 +406,10 @@ func (api *ConsensusAPI) forkchoiceUpdated(update engine.ForkchoiceStateV1, payl
 			return valid(nil), engine.InvalidPayloadAttributes.With(err)
 		}
 		api.localBlocks.put(id, payload)
+		forkchoiceUpdateAttributesTimer.UpdateSince(start)
 		return valid(&id), nil
 	}
+	forkchoiceUpdateHeadsTimer.UpdateSince(start)
 	return valid(nil), nil
 }
 
diff --git a/miner/miner.go b/miner/miner.go
index 82d353a336..6d058b4be2 100644
--- a/miner/miner.go
+++ b/miner/miner.go
@@ -35,9 +35,30 @@ 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 (
+	commitDepositTxsTimer = metrics.NewRegisteredTimer("miner/commit/deposit/txs", nil)
+	packFromTxpoolTimer = metrics.NewRegisteredTimer("miner/pack/txpool/txs", nil)
+	commitTxpoolTxsTimer = metrics.NewRegisteredTimer("miner/commit/txpool/txs", nil)
+	assembleBlockTimer = metrics.NewRegisteredTimer("miner/assemble/block", nil)
+
+	accountReadTimer   = metrics.NewRegisteredTimer("miner/account/reads", nil)
+	accountHashTimer   = metrics.NewRegisteredTimer("miner/account/hashes", nil)
+	accountUpdateTimer = metrics.NewRegisteredTimer("miner/account/updates", nil)
+
+	storageReadTimer   = metrics.NewRegisteredTimer("miner/storage/reads", nil)
+	storageHashTimer   = metrics.NewRegisteredTimer("miner/storage/hashes", nil)
+	storageUpdateTimer = metrics.NewRegisteredTimer("miner/storage/updates", nil)
+
+	snapshotAccountReadTimer = metrics.NewRegisteredTimer("miner/snapshot/account/reads", nil)
+	snapshotStorageReadTimer = metrics.NewRegisteredTimer("miner/snapshot/storage/reads", nil)
+
+	waitPayloadTimer = metrics.NewRegisteredTimer("miner/wait/payload", nil)
+)
+
 // Backend wraps all methods required for mining. Only full node is capable
 // to offer all the functions here.
 type Backend interface {
diff --git a/miner/payload_building.go b/miner/payload_building.go
index ed1916e3c0..73c2bb596b 100644
--- a/miner/payload_building.go
+++ b/miner/payload_building.go
@@ -211,7 +211,9 @@ func (payload *Payload) resolve(onlyFull bool) *engine.ExecutionPayloadEnvelope
 		// Wait the full payload construction. Note it might block
 		// forever if Resolve is called in the meantime which
 		// terminates the background construction process.
+		start := time.Now()
 		payload.cond.Wait()
+		waitPayloadTimer.UpdateSince(start)
 	}
 
 	// Now we can signal the building routine to stop.
diff --git a/miner/worker.go b/miner/worker.go
index 7b4b2a2676..be17ff10a2 100644
--- a/miner/worker.go
+++ b/miner/worker.go
@@ -1090,7 +1090,9 @@ func (w *worker) fillTransactions(interrupt *atomic.Int32, env *environment) err
 		}
 	}
 
+	start := time.Now()
 	pending := w.eth.TxPool().Pending(true)
+	packFromTxpoolTimer.UpdateSince(start)
 
 	// Split the pending transactions into locals and remotes.
 	localTxs, remoteTxs := make(map[common.Address][]*txpool.LazyTransaction), pending
@@ -1104,6 +1106,7 @@ func (w *worker) fillTransactions(interrupt *atomic.Int32, env *environment) err
 	// }
 
 	// Fill the block with all available pending transactions.
+	start = time.Now()
 	if len(localTxs) > 0 {
 		txs := newTransactionsByPriceAndNonce(env.signer, localTxs, env.header.BaseFee)
 		if err := w.commitTransactions(env, txs, interrupt); err != nil {
@@ -1116,6 +1119,7 @@ func (w *worker) fillTransactions(interrupt *atomic.Int32, env *environment) err
 			return err
 		}
 	}
+	commitTxpoolTxsTimer.UpdateSince(start)
 	return nil
 }
 
@@ -1137,6 +1141,7 @@ func (w *worker) generateWork(genParams *generateParams) *newPayloadResult {
 	// opBNB no need to hard code this contract via hardfork
 	// misc.EnsureCreate2Deployer(w.chainConfig, work.header.Time, work.state)
 
+	start := time.Now()
 	for _, tx := range genParams.txs {
 		from, _ := types.Sender(work.signer, tx)
 		work.state.SetTxContext(tx.Hash(), work.tcount)
@@ -1146,6 +1151,7 @@ func (w *worker) generateWork(genParams *generateParams) *newPayloadResult {
 		}
 		work.tcount++
 	}
+	commitDepositTxsTimer.UpdateSince(start)
 
 	// forced transactions done, fill rest of block with transactions
 	if !genParams.noTxs {
@@ -1170,10 +1176,22 @@ func (w *worker) generateWork(genParams *generateParams) *newPayloadResult {
 		return &newPayloadResult{err: errInterruptedUpdate}
 	}
 
+	start = time.Now()
 	block, err := w.engine.FinalizeAndAssemble(w.chain, work.header, work.state, work.txs, nil, work.receipts, genParams.withdrawals)
 	if err != nil {
 		return &newPayloadResult{err: err}
 	}
+	assembleBlockTimer.UpdateSince(start)
+
+	accountReadTimer.Update(work.state.AccountReads)                   // Account reads are complete(in commit txs)
+	storageReadTimer.Update(work.state.StorageReads)                   // Storage reads are complete(in commit txs)
+	snapshotAccountReadTimer.Update(work.state.SnapshotAccountReads)   // Account reads are complete(in commit txs)
+	snapshotStorageReadTimer.Update(work.state.SnapshotStorageReads)   // Storage reads are complete(in commit txs)
+	accountUpdateTimer.Update(work.state.AccountUpdates)               // Account updates are complete(in FinalizeAndAssemble)
+	storageUpdateTimer.Update(work.state.StorageUpdates)               // Storage updates are complete(in FinalizeAndAssemble)
+	accountHashTimer.Update(work.state.AccountHashes)                  // Account hashes are complete(in FinalizeAndAssemble)
+	storageHashTimer.Update(work.state.StorageHashes)                  // Storage hashes are complete(in FinalizeAndAssemble)
+
 	return &newPayloadResult{
 		block:    block,
 		fees:     totalFees(block, work.receipts),

From 925e82591458d6ce7c26a55bf9f3457907aa3416 Mon Sep 17 00:00:00 2001
From: Nolan <33241113+nolanxyg@users.noreply.github.com>
Date: Thu, 21 Mar 2024 14:36:51 +0800
Subject: [PATCH 2/8] metric: add more metric and related logs

---
 core/blockchain.go        |  7 ++++++-
 eth/catalyst/api.go       | 15 +++++++++++++++
 miner/miner.go            |  3 +++
 miner/payload_building.go |  2 ++
 miner/worker.go           | 14 ++++++++++++--
 5 files changed, 38 insertions(+), 3 deletions(-)

diff --git a/core/blockchain.go b/core/blockchain.go
index ad7e2f8eec..cc5a0562a3 100644
--- a/core/blockchain.go
+++ b/core/blockchain.go
@@ -1885,6 +1885,8 @@ func (bc *BlockChain) insertChain(chain types.Blocks, setHead bool) (int, error)
 		blockExecutionTimer.Update(ptime)                               // The time spent on block execution
 		blockValidationTimer.Update(vtime)                              // The time spent on block validation
 
+		log.Info("New payload execution and validation metrics", "hash", block.Hash(), "execution", common.PrettyDuration(ptime), "validation", common.PrettyDuration(vtime), "accountReads", common.PrettyDuration(statedb.AccountReads), "storageReads", common.PrettyDuration(statedb.StorageReads), "snapshotAccountReads", common.PrettyDuration(statedb.SnapshotAccountReads), "snapshotStorageReads", common.PrettyDuration(statedb.SnapshotStorageReads), "accountUpdates", common.PrettyDuration(statedb.AccountUpdates), "storageUpdates", common.PrettyDuration(statedb.StorageUpdates), "accountHashes", common.PrettyDuration(statedb.AccountHashes), "storageHashes", common.PrettyDuration(statedb.StorageHashes))
+
 		// Write the block to the chain and get the status.
 		var (
 			wstart = time.Now()
@@ -1906,9 +1908,12 @@ func (bc *BlockChain) insertChain(chain types.Blocks, setHead bool) (int, error)
 		snapshotCommitTimer.Update(statedb.SnapshotCommits) // Snapshot commits are complete, we can mark them
 		triedbCommitTimer.Update(statedb.TrieDBCommits)     // Trie database commits are complete, we can mark them
 
-		blockWriteTimer.Update(time.Since(wstart) - statedb.AccountCommits - statedb.StorageCommits - statedb.SnapshotCommits - statedb.TrieDBCommits)
+		blockWriteDuration := time.Since(wstart) - statedb.AccountCommits - statedb.StorageCommits - statedb.SnapshotCommits - statedb.TrieDBCommits
+		blockWriteTimer.Update(blockWriteDuration)
 		blockInsertTimer.UpdateSince(start)
 
+		log.Info("New payload db write metrics", "hash", block.Hash(), "insert", common.PrettyDuration(time.Since(start)), "writeDB", common.PrettyDuration(time.Since(wstart)), "writeBlock", common.PrettyDuration(blockWriteDuration), "accountCommit", common.PrettyDuration(statedb.AccountCommits), "storageCommit", common.PrettyDuration(statedb.StorageCommits), "snapshotCommits", common.PrettyDuration(statedb.SnapshotCommits), "triedbCommit", common.PrettyDuration(statedb.TrieDBCommits))
+
 		// Report the import stats before returning the various results
 		stats.processed++
 		stats.usedGas += usedGas
diff --git a/eth/catalyst/api.go b/eth/catalyst/api.go
index eeb60bd6dc..9a0c5fd664 100644
--- a/eth/catalyst/api.go
+++ b/eth/catalyst/api.go
@@ -41,6 +41,8 @@ import (
 var (
 	forkchoiceUpdateAttributesTimer = metrics.NewRegisteredTimer("api/engine/forkchoiceUpdate/attributes", nil)
 	forkchoiceUpdateHeadsTimer = metrics.NewRegisteredTimer("api/engine/forkchoiceUpdate/heads", nil)
+	getPayloadTimer = metrics.NewRegisteredTimer("api/engine/get/payload", nil)
+	newPayloadTimer = metrics.NewRegisteredTimer("api/engine/new/payload", nil)
 )
 
 // Register adds the engine API to the full node.
@@ -407,9 +409,11 @@ func (api *ConsensusAPI) forkchoiceUpdated(update engine.ForkchoiceStateV1, payl
 		}
 		api.localBlocks.put(id, payload)
 		forkchoiceUpdateAttributesTimer.UpdateSince(start)
+		log.Info("forkchoiceUpdateAttributes", "duration", common.PrettyDuration(time.Since(start)), "id", id)
 		return valid(&id), nil
 	}
 	forkchoiceUpdateHeadsTimer.UpdateSince(start)
+	log.Info("forkchoiceUpdateHeads", "duration", common.PrettyDuration(time.Since(start)), "hash", update.HeadBlockHash)
 	return valid(nil), nil
 }
 
@@ -463,6 +467,11 @@ func (api *ConsensusAPI) GetPayloadV3(payloadID engine.PayloadID) (*engine.Execu
 }
 
 func (api *ConsensusAPI) getPayload(payloadID engine.PayloadID, full bool) (*engine.ExecutionPayloadEnvelope, error) {
+	start := time.Now()
+	defer func () {
+		getPayloadTimer.UpdateSince(start)
+		log.Info("getPayload", "duration", common.PrettyDuration(time.Since(start)), "id", payloadID)
+	} ()
 	log.Trace("Engine API request received", "method", "GetPayload", "id", payloadID)
 	data := api.localBlocks.get(payloadID, full)
 	if data == nil {
@@ -517,6 +526,12 @@ func (api *ConsensusAPI) NewPayloadV3(params engine.ExecutableData, versionedHas
 }
 
 func (api *ConsensusAPI) newPayload(params engine.ExecutableData, versionedHashes []common.Hash, beaconRoot *common.Hash) (engine.PayloadStatusV1, error) {
+	start := time.Now()
+	defer func () {
+		newPayloadTimer.UpdateSince(start)
+		log.Info("newPayload", "duration", common.PrettyDuration(time.Since(start)), "parentHash", params.ParentHash)
+	} ()
+
 	// The locking here is, strictly, not required. Without these locks, this can happen:
 	//
 	// 1. NewPayload( execdata-N ) is invoked from the CL. It goes all the way down to
diff --git a/miner/miner.go b/miner/miner.go
index 6d058b4be2..2fe25db984 100644
--- a/miner/miner.go
+++ b/miner/miner.go
@@ -44,6 +44,7 @@ var (
 	packFromTxpoolTimer = metrics.NewRegisteredTimer("miner/pack/txpool/txs", nil)
 	commitTxpoolTxsTimer = metrics.NewRegisteredTimer("miner/commit/txpool/txs", nil)
 	assembleBlockTimer = metrics.NewRegisteredTimer("miner/assemble/block", nil)
+	buildBlockTimer = metrics.NewRegisteredTimer("miner/build/block", nil)
 
 	accountReadTimer   = metrics.NewRegisteredTimer("miner/account/reads", nil)
 	accountHashTimer   = metrics.NewRegisteredTimer("miner/account/hashes", nil)
@@ -57,6 +58,8 @@ var (
 	snapshotStorageReadTimer = metrics.NewRegisteredTimer("miner/snapshot/storage/reads", nil)
 
 	waitPayloadTimer = metrics.NewRegisteredTimer("miner/wait/payload", nil)
+
+	isBuildBlockInterruptGauge = metrics.NewRegisteredGauge("miner/build/interrupt", nil)
 )
 
 // Backend wraps all methods required for mining. Only full node is capable
diff --git a/miner/payload_building.go b/miner/payload_building.go
index 73c2bb596b..48312928be 100644
--- a/miner/payload_building.go
+++ b/miner/payload_building.go
@@ -164,6 +164,7 @@ func (payload *Payload) update(r *newPayloadResult, elapsed time.Duration, postF
 				postFunc()
 			}
 		}
+		buildBlockTimer.Update(elapsed)
 	}
 }
 
@@ -214,6 +215,7 @@ func (payload *Payload) resolve(onlyFull bool) *engine.ExecutionPayloadEnvelope
 		start := time.Now()
 		payload.cond.Wait()
 		waitPayloadTimer.UpdateSince(start)
+		log.Info("Wait for background payload building end", "duration", common.PrettyDuration(time.Since(start)), "id", payload.id)
 	}
 
 	// Now we can signal the building routine to stop.
diff --git a/miner/worker.go b/miner/worker.go
index be17ff10a2..2948b9aca5 100644
--- a/miner/worker.go
+++ b/miner/worker.go
@@ -1093,6 +1093,7 @@ func (w *worker) fillTransactions(interrupt *atomic.Int32, env *environment) err
 	start := time.Now()
 	pending := w.eth.TxPool().Pending(true)
 	packFromTxpoolTimer.UpdateSince(start)
+	log.Info("packFromTxpool", "duration", common.PrettyDuration(time.Since(start)), "hash", env.header.Hash())
 
 	// Split the pending transactions into locals and remotes.
 	localTxs, remoteTxs := make(map[common.Address][]*txpool.LazyTransaction), pending
@@ -1120,6 +1121,7 @@ func (w *worker) fillTransactions(interrupt *atomic.Int32, env *environment) err
 		}
 	}
 	commitTxpoolTxsTimer.UpdateSince(start)
+	log.Info("commitTxpoolTxs", "duration", common.PrettyDuration(time.Since(start)), "hash", env.header.Hash())
 	return nil
 }
 
@@ -1152,6 +1154,7 @@ func (w *worker) generateWork(genParams *generateParams) *newPayloadResult {
 		work.tcount++
 	}
 	commitDepositTxsTimer.UpdateSince(start)
+	log.Info("commitDepositTxs", "duration", common.PrettyDuration(time.Since(start)), "parentHash", genParams.parentHash)
 
 	// forced transactions done, fill rest of block with transactions
 	if !genParams.noTxs {
@@ -1167,9 +1170,13 @@ func (w *worker) generateWork(genParams *generateParams) *newPayloadResult {
 		err := w.fillTransactions(interrupt, work)
 		timer.Stop() // don't need timeout interruption any more
 		if errors.Is(err, errBlockInterruptedByTimeout) {
-			log.Warn("Block building is interrupted", "allowance", common.PrettyDuration(w.newpayloadTimeout))
+			log.Warn("Block building is interrupted", "allowance", common.PrettyDuration(w.newpayloadTimeout), "parentHash", genParams.parentHash)
+			isBuildBlockInterruptGauge.Update(2)
 		} else if errors.Is(err, errBlockInterruptedByResolve) {
-			log.Info("Block building got interrupted by payload resolution")
+			log.Info("Block building got interrupted by payload resolution", "parentHash", genParams.parentHash)
+			isBuildBlockInterruptGauge.Update(1)
+		} else {
+			isBuildBlockInterruptGauge.Update(0)
 		}
 	}
 	if intr := genParams.interrupt; intr != nil && genParams.isUpdate && intr.Load() != commitInterruptNone {
@@ -1182,6 +1189,7 @@ func (w *worker) generateWork(genParams *generateParams) *newPayloadResult {
 		return &newPayloadResult{err: err}
 	}
 	assembleBlockTimer.UpdateSince(start)
+	log.Info("FinalizeAndAssemble", "duration", common.PrettyDuration(time.Since(start)), "parentHash", genParams.parentHash)
 
 	accountReadTimer.Update(work.state.AccountReads)                   // Account reads are complete(in commit txs)
 	storageReadTimer.Update(work.state.StorageReads)                   // Storage reads are complete(in commit txs)
@@ -1192,6 +1200,8 @@ func (w *worker) generateWork(genParams *generateParams) *newPayloadResult {
 	accountHashTimer.Update(work.state.AccountHashes)                  // Account hashes are complete(in FinalizeAndAssemble)
 	storageHashTimer.Update(work.state.StorageHashes)                  // Storage hashes are complete(in FinalizeAndAssemble)
 
+	log.Info("build payload statedb metrics",  "parentHash", genParams.parentHash, "accountReads", common.PrettyDuration(work.state.AccountReads), "storageReads", common.PrettyDuration(work.state.StorageReads), "snapshotAccountReads", common.PrettyDuration(work.state.SnapshotAccountReads), "snapshotStorageReads", common.PrettyDuration(work.state.SnapshotStorageReads), "accountUpdates", common.PrettyDuration(work.state.AccountUpdates), "storageUpdates", common.PrettyDuration(work.state.StorageUpdates), "accountHashes", common.PrettyDuration(work.state.AccountHashes), "storageHashes", common.PrettyDuration(work.state.StorageHashes))
+
 	return &newPayloadResult{
 		block:    block,
 		fees:     totalFees(block, work.receipts),

From 8c78d605b3d88e781c41cfa9edf13eba62e30312 Mon Sep 17 00:00:00 2001
From: Nolan <33241113+nolanxyg@users.noreply.github.com>
Date: Tue, 26 Mar 2024 18:43:29 +0800
Subject: [PATCH 3/8] add more perf metrics

---
 core/blockchain.go       | 29 ++++++++++++++++++++++++++---
 core/state_transition.go |  6 ++++++
 miner/miner.go           |  4 +++-
 miner/worker.go          | 14 ++++++++++----
 4 files changed, 45 insertions(+), 8 deletions(-)

diff --git a/core/blockchain.go b/core/blockchain.go
index cc5a0562a3..5a07000efe 100644
--- a/core/blockchain.go
+++ b/core/blockchain.go
@@ -83,6 +83,11 @@ var (
 	blockExecutionTimer  = metrics.NewRegisteredTimer("chain/execution", nil)
 	blockWriteTimer      = metrics.NewRegisteredTimer("chain/write", nil)
 
+	blockWriteExternalTimer = metrics.NewRegisteredTimer("chain/block/write/external", nil)
+	stateCommitExternalTimer = metrics.NewRegisteredTimer("chain/state/commit/external", nil)
+	triedbCommitExternalTimer = metrics.NewRegisteredTimer("chain/triedb/commit/external", nil)
+	innerExecutionTimer = metrics.NewRegisteredTimer("chain/inner/execution", nil)
+
 	blockReorgMeter     = metrics.NewRegisteredMeter("chain/reorg/executes", nil)
 	blockReorgAddMeter  = metrics.NewRegisteredMeter("chain/reorg/add", nil)
 	blockReorgDropMeter = metrics.NewRegisteredMeter("chain/reorg/drop", nil)
@@ -1432,6 +1437,7 @@ func (bc *BlockChain) writeBlockWithState(block *types.Block, receipts []*types.
 	//
 	// Note all the components of block(td, hash->number map, header, body, receipts)
 	// should be written atomically. BlockBatch is used for containing all components.
+	start := time.Now()
 	blockBatch := bc.db.NewBatch()
 	rawdb.WriteTd(blockBatch, block.Hash(), block.NumberU64(), externTd)
 	rawdb.WriteBlock(blockBatch, block)
@@ -1440,17 +1446,29 @@ func (bc *BlockChain) writeBlockWithState(block *types.Block, receipts []*types.
 	if err := blockBatch.Write(); err != nil {
 		log.Crit("Failed to write block into disk", "err", err)
 	}
+	blockWriteExternalTimer.UpdateSince(start)
+	log.Info("blockWriteExternalTimer", "duration", common.PrettyDuration(time.Since(start)), "hash", block.Hash())
+	
 	// Commit all cached state changes into underlying memory database.
+	start = time.Now()
 	root, err := state.Commit(block.NumberU64(), bc.chainConfig.IsEIP158(block.Number()))
 	if err != nil {
 		return err
 	}
+	stateCommitExternalTimer.UpdateSince(start)
+	log.Info("stateCommitExternalTimer", "duration", common.PrettyDuration(time.Since(start)), "hash", block.Hash())
+
 	// If node is running in path mode, skip explicit gc operation
 	// which is unnecessary in this mode.
 	if bc.triedb.Scheme() == rawdb.PathScheme {
 		return nil
 	}
 	// If we're running an archive node, always flush
+	start = time.Now()
+	defer func () {
+		triedbCommitExternalTimer.UpdateSince(start)
+		log.Info("triedbCommitExternalTimer", "duration", common.PrettyDuration(time.Since(start)), "hash", block.Hash())
+	} ()
 	if bc.cacheConfig.TrieDirtyDisabled {
 		return bc.triedb.Commit(root, false)
 	}
@@ -1755,7 +1773,11 @@ func (bc *BlockChain) insertChain(chain types.Blocks, setHead bool) (int, error)
 		}
 	}()
 
+	defer func () {
+		DebugInnerExecutionDuration = 0
+	}()
 	for ; block != nil && err == nil || errors.Is(err, ErrKnownBlock); block, err = it.next() {
+		DebugInnerExecutionDuration = 0
 		// If the chain is terminating, stop processing blocks
 		if bc.insertStopped() {
 			log.Debug("Abort during block processing")
@@ -1885,6 +1907,8 @@ func (bc *BlockChain) insertChain(chain types.Blocks, setHead bool) (int, error)
 		blockExecutionTimer.Update(ptime)                               // The time spent on block execution
 		blockValidationTimer.Update(vtime)                              // The time spent on block validation
 
+		innerExecutionTimer.Update(DebugInnerExecutionDuration)
+
 		log.Info("New payload execution and validation metrics", "hash", block.Hash(), "execution", common.PrettyDuration(ptime), "validation", common.PrettyDuration(vtime), "accountReads", common.PrettyDuration(statedb.AccountReads), "storageReads", common.PrettyDuration(statedb.StorageReads), "snapshotAccountReads", common.PrettyDuration(statedb.SnapshotAccountReads), "snapshotStorageReads", common.PrettyDuration(statedb.SnapshotStorageReads), "accountUpdates", common.PrettyDuration(statedb.AccountUpdates), "storageUpdates", common.PrettyDuration(statedb.StorageUpdates), "accountHashes", common.PrettyDuration(statedb.AccountHashes), "storageHashes", common.PrettyDuration(statedb.StorageHashes))
 
 		// Write the block to the chain and get the status.
@@ -1908,11 +1932,10 @@ func (bc *BlockChain) insertChain(chain types.Blocks, setHead bool) (int, error)
 		snapshotCommitTimer.Update(statedb.SnapshotCommits) // Snapshot commits are complete, we can mark them
 		triedbCommitTimer.Update(statedb.TrieDBCommits)     // Trie database commits are complete, we can mark them
 
-		blockWriteDuration := time.Since(wstart) - statedb.AccountCommits - statedb.StorageCommits - statedb.SnapshotCommits - statedb.TrieDBCommits
-		blockWriteTimer.Update(blockWriteDuration)
+		blockWriteTimer.UpdateSince(wstart)
 		blockInsertTimer.UpdateSince(start)
 
-		log.Info("New payload db write metrics", "hash", block.Hash(), "insert", common.PrettyDuration(time.Since(start)), "writeDB", common.PrettyDuration(time.Since(wstart)), "writeBlock", common.PrettyDuration(blockWriteDuration), "accountCommit", common.PrettyDuration(statedb.AccountCommits), "storageCommit", common.PrettyDuration(statedb.StorageCommits), "snapshotCommits", common.PrettyDuration(statedb.SnapshotCommits), "triedbCommit", common.PrettyDuration(statedb.TrieDBCommits))
+		log.Info("New payload db write metrics", "hash", block.Hash(), "insert", common.PrettyDuration(time.Since(start)), "writeDB", common.PrettyDuration(time.Since(wstart)), "writeBlock", common.PrettyDuration(time.Since(wstart)), "accountCommit", common.PrettyDuration(statedb.AccountCommits), "storageCommit", common.PrettyDuration(statedb.StorageCommits), "snapshotCommits", common.PrettyDuration(statedb.SnapshotCommits), "triedbCommit", common.PrettyDuration(statedb.TrieDBCommits))
 
 		// Report the import stats before returning the various results
 		stats.processed++
diff --git a/core/state_transition.go b/core/state_transition.go
index f4a8e44e72..8e459d4eeb 100644
--- a/core/state_transition.go
+++ b/core/state_transition.go
@@ -21,6 +21,7 @@ import (
 	"fmt"
 	"math"
 	"math/big"
+	"time"
 
 	"github.com/ethereum/go-ethereum/common"
 	cmath "github.com/ethereum/go-ethereum/common/math"
@@ -29,6 +30,9 @@ import (
 	"github.com/ethereum/go-ethereum/params"
 )
 
+// TODO delete after debug performance metrics
+var DebugInnerExecutionDuration time.Duration
+
 // ExecutionResult includes all output after executing given evm
 // message no matter the execution itself is successful or not.
 type ExecutionResult struct {
@@ -473,6 +477,7 @@ func (st *StateTransition) innerTransitionDb() (*ExecutionResult, error) {
 		ret   []byte
 		vmerr error // vm errors do not effect consensus and are therefore not assigned to err
 	)
+	start := time.Now()
 	if contractCreation {
 		ret, _, st.gasRemaining, vmerr = st.evm.Create(sender, msg.Data, st.gasRemaining, msg.Value)
 	} else {
@@ -480,6 +485,7 @@ func (st *StateTransition) innerTransitionDb() (*ExecutionResult, error) {
 		st.state.SetNonce(msg.From, st.state.GetNonce(sender.Address())+1)
 		ret, st.gasRemaining, vmerr = st.evm.Call(sender, st.to(), msg.Data, st.gasRemaining, msg.Value)
 	}
+	DebugInnerExecutionDuration += time.Since(start)
 
 	// if deposit: skip refunds, skip tipping coinbase
 	// Regolith changes this behaviour to report the actual gasUsed instead of always reporting all gas used.
diff --git a/miner/miner.go b/miner/miner.go
index 2fe25db984..5c0ba3f815 100644
--- a/miner/miner.go
+++ b/miner/miner.go
@@ -54,12 +54,14 @@ var (
 	storageHashTimer   = metrics.NewRegisteredTimer("miner/storage/hashes", nil)
 	storageUpdateTimer = metrics.NewRegisteredTimer("miner/storage/updates", nil)
 
+	innerExecutionTimer = metrics.NewRegisteredTimer("miner/inner/execution", nil)
+
 	snapshotAccountReadTimer = metrics.NewRegisteredTimer("miner/snapshot/account/reads", nil)
 	snapshotStorageReadTimer = metrics.NewRegisteredTimer("miner/snapshot/storage/reads", nil)
 
 	waitPayloadTimer = metrics.NewRegisteredTimer("miner/wait/payload", nil)
 
-	isBuildBlockInterruptGauge = metrics.NewRegisteredGauge("miner/build/interrupt", nil)
+	isBuildBlockInterruptCounter = metrics.NewRegisteredCounter("miner/build/interrupt", nil)
 )
 
 // Backend wraps all methods required for mining. Only full node is capable
diff --git a/miner/worker.go b/miner/worker.go
index 2948b9aca5..88bf9097d6 100644
--- a/miner/worker.go
+++ b/miner/worker.go
@@ -1127,6 +1127,12 @@ func (w *worker) fillTransactions(interrupt *atomic.Int32, env *environment) err
 
 // generateWork generates a sealing block based on the given parameters.
 func (w *worker) generateWork(genParams *generateParams) *newPayloadResult {
+	// TODO delete after debug performance metrics
+	core.DebugInnerExecutionDuration = 0
+	defer func () {
+		core.DebugInnerExecutionDuration = 0
+	}()
+
 	work, err := w.prepareWork(genParams)
 	if err != nil {
 		return &newPayloadResult{err: err}
@@ -1171,12 +1177,10 @@ func (w *worker) generateWork(genParams *generateParams) *newPayloadResult {
 		timer.Stop() // don't need timeout interruption any more
 		if errors.Is(err, errBlockInterruptedByTimeout) {
 			log.Warn("Block building is interrupted", "allowance", common.PrettyDuration(w.newpayloadTimeout), "parentHash", genParams.parentHash)
-			isBuildBlockInterruptGauge.Update(2)
+			isBuildBlockInterruptCounter.Inc(1)
 		} else if errors.Is(err, errBlockInterruptedByResolve) {
 			log.Info("Block building got interrupted by payload resolution", "parentHash", genParams.parentHash)
-			isBuildBlockInterruptGauge.Update(1)
-		} else {
-			isBuildBlockInterruptGauge.Update(0)
+			isBuildBlockInterruptCounter.Inc(1)
 		}
 	}
 	if intr := genParams.interrupt; intr != nil && genParams.isUpdate && intr.Load() != commitInterruptNone {
@@ -1200,6 +1204,8 @@ func (w *worker) generateWork(genParams *generateParams) *newPayloadResult {
 	accountHashTimer.Update(work.state.AccountHashes)                  // Account hashes are complete(in FinalizeAndAssemble)
 	storageHashTimer.Update(work.state.StorageHashes)                  // Storage hashes are complete(in FinalizeAndAssemble)
 
+	innerExecutionTimer.Update(core.DebugInnerExecutionDuration)
+
 	log.Info("build payload statedb metrics",  "parentHash", genParams.parentHash, "accountReads", common.PrettyDuration(work.state.AccountReads), "storageReads", common.PrettyDuration(work.state.StorageReads), "snapshotAccountReads", common.PrettyDuration(work.state.SnapshotAccountReads), "snapshotStorageReads", common.PrettyDuration(work.state.SnapshotStorageReads), "accountUpdates", common.PrettyDuration(work.state.AccountUpdates), "storageUpdates", common.PrettyDuration(work.state.StorageUpdates), "accountHashes", common.PrettyDuration(work.state.AccountHashes), "storageHashes", common.PrettyDuration(work.state.StorageHashes))
 
 	return &newPayloadResult{

From 8d87b655a3007a4a69ab763c3e1d6bc5196a361f Mon Sep 17 00:00:00 2001
From: Nolan <33241113+nolanxyg@users.noreply.github.com>
Date: Tue, 26 Mar 2024 19:40:33 +0800
Subject: [PATCH 4/8] add storage metrics

---
 core/rawdb/accessors_snapshot.go | 10 ++++++++++
 core/rawdb/accessors_trie.go     | 10 ++++++++++
 core/rawdb/metrics.go            | 10 ++++++++++
 core/state_processor.go          |  8 ++++++++
 ethdb/metrics.go                 | 10 ++++++++++
 ethdb/pebble/pebble.go           | 18 ++++++++++++++++++
 trie/trie.go                     | 20 ++++++++++++++++++++
 7 files changed, 86 insertions(+)
 create mode 100644 core/rawdb/metrics.go
 create mode 100644 ethdb/metrics.go

diff --git a/core/rawdb/accessors_snapshot.go b/core/rawdb/accessors_snapshot.go
index 3c82b3f731..5e0d6b67c5 100644
--- a/core/rawdb/accessors_snapshot.go
+++ b/core/rawdb/accessors_snapshot.go
@@ -18,10 +18,12 @@ package rawdb
 
 import (
 	"encoding/binary"
+	"time"
 
 	"github.com/ethereum/go-ethereum/common"
 	"github.com/ethereum/go-ethereum/ethdb"
 	"github.com/ethereum/go-ethereum/log"
+	"github.com/ethereum/go-ethereum/metrics"
 )
 
 // ReadSnapshotDisabled retrieves if the snapshot maintenance is disabled.
@@ -74,6 +76,10 @@ func DeleteSnapshotRoot(db ethdb.KeyValueWriter) {
 
 // ReadAccountSnapshot retrieves the snapshot entry of an account trie leaf.
 func ReadAccountSnapshot(db ethdb.KeyValueReader, hash common.Hash) []byte {
+	if metrics.EnabledExpensive {
+		start := time.Now()
+		defer func() { rawdbGetAccountSnapNodeTimer.UpdateSince(start) }()
+	}
 	data, _ := db.Get(accountSnapshotKey(hash))
 	return data
 }
@@ -94,6 +100,10 @@ func DeleteAccountSnapshot(db ethdb.KeyValueWriter, hash common.Hash) {
 
 // ReadStorageSnapshot retrieves the snapshot entry of an storage trie leaf.
 func ReadStorageSnapshot(db ethdb.KeyValueReader, accountHash, storageHash common.Hash) []byte {
+	if metrics.EnabledExpensive {
+		start := time.Now()
+		defer func() { rawdbGetStorageSnapNodeTimer.UpdateSince(start) }()
+	}
 	data, _ := db.Get(storageSnapshotKey(accountHash, storageHash))
 	return data
 }
diff --git a/core/rawdb/accessors_trie.go b/core/rawdb/accessors_trie.go
index 78f1a70b1c..4284fb6ff7 100644
--- a/core/rawdb/accessors_trie.go
+++ b/core/rawdb/accessors_trie.go
@@ -19,11 +19,13 @@ package rawdb
 import (
 	"fmt"
 	"sync"
+	"time"
 
 	"github.com/ethereum/go-ethereum/common"
 	"github.com/ethereum/go-ethereum/crypto"
 	"github.com/ethereum/go-ethereum/ethdb"
 	"github.com/ethereum/go-ethereum/log"
+	"github.com/ethereum/go-ethereum/metrics"
 	"golang.org/x/crypto/sha3"
 )
 
@@ -68,6 +70,10 @@ func (h *hasher) release() {
 // ReadAccountTrieNode retrieves the account trie node and the associated node
 // hash with the specified node path.
 func ReadAccountTrieNode(db ethdb.KeyValueReader, path []byte) ([]byte, common.Hash) {
+	if metrics.EnabledExpensive {
+		start := time.Now()
+		defer func() { rawdbGetAccountTrieNodeTimer.UpdateSince(start) }()
+	}
 	data, err := db.Get(accountTrieNodeKey(path))
 	if err != nil {
 		return nil, common.Hash{}
@@ -116,6 +122,10 @@ func DeleteAccountTrieNode(db ethdb.KeyValueWriter, path []byte) {
 // ReadStorageTrieNode retrieves the storage trie node and the associated node
 // hash with the specified node path.
 func ReadStorageTrieNode(db ethdb.KeyValueReader, accountHash common.Hash, path []byte) ([]byte, common.Hash) {
+	if metrics.EnabledExpensive {
+		start := time.Now()
+		defer func() { rawdbGetStorageTrieNodeTimer.UpdateSince(start) }()
+	}
 	data, err := db.Get(storageTrieNodeKey(accountHash, path))
 	if err != nil {
 		return nil, common.Hash{}
diff --git a/core/rawdb/metrics.go b/core/rawdb/metrics.go
new file mode 100644
index 0000000000..b4c09f8689
--- /dev/null
+++ b/core/rawdb/metrics.go
@@ -0,0 +1,10 @@
+package rawdb
+
+import "github.com/ethereum/go-ethereum/metrics"
+
+var (
+	rawdbGetAccountTrieNodeTimer = metrics.NewRegisteredTimer("rawdb/get/account/trienode/time", nil)
+	rawdbGetStorageTrieNodeTimer = metrics.NewRegisteredTimer("rawdb/get/storage/trienode/time", nil)
+	rawdbGetAccountSnapNodeTimer = metrics.NewRegisteredTimer("rawdb/get/account/snapnode/time", nil)
+	rawdbGetStorageSnapNodeTimer = metrics.NewRegisteredTimer("rawdb/get/storage/snapnode/time", nil)
+)
diff --git a/core/state_processor.go b/core/state_processor.go
index 8b13aa0eb3..f84007cbbe 100644
--- a/core/state_processor.go
+++ b/core/state_processor.go
@@ -20,6 +20,7 @@ import (
 	"errors"
 	"fmt"
 	"math/big"
+	"time"
 
 	"github.com/ethereum/go-ethereum/common"
 	"github.com/ethereum/go-ethereum/consensus"
@@ -28,9 +29,12 @@ import (
 	"github.com/ethereum/go-ethereum/core/types"
 	"github.com/ethereum/go-ethereum/core/vm"
 	"github.com/ethereum/go-ethereum/crypto"
+	"github.com/ethereum/go-ethereum/metrics"
 	"github.com/ethereum/go-ethereum/params"
 )
 
+var processTxTimer = metrics.NewRegisteredTimer("process/tx/time", nil)
+
 // StateProcessor is a basic Processor, which takes care of transitioning
 // state from one point to another.
 //
@@ -88,6 +92,7 @@ func (p *StateProcessor) Process(block *types.Block, statedb *state.StateDB, cfg
 	}
 	// Iterate over and process the individual transactions
 	for i, tx := range block.Transactions() {
+		start := time.Now()
 		msg, err := TransactionToMessage(tx, signer, header.BaseFee)
 		if err != nil {
 			return nil, nil, 0, fmt.Errorf("could not apply tx %d [%v]: %w", i, tx.Hash().Hex(), err)
@@ -99,6 +104,9 @@ func (p *StateProcessor) Process(block *types.Block, statedb *state.StateDB, cfg
 		}
 		receipts = append(receipts, receipt)
 		allLogs = append(allLogs, receipt.Logs...)
+		if metrics.EnabledExpensive {
+			processTxTimer.UpdateSince(start)
+		}
 	}
 	// Fail if Shanghai not enabled and len(withdrawals) is non-zero.
 	withdrawals := block.Withdrawals()
diff --git a/ethdb/metrics.go b/ethdb/metrics.go
new file mode 100644
index 0000000000..39133a7243
--- /dev/null
+++ b/ethdb/metrics.go
@@ -0,0 +1,10 @@
+package ethdb
+
+import "github.com/ethereum/go-ethereum/metrics"
+
+var (
+	EthdbGetTimer        = metrics.NewRegisteredTimer("ethdb/get/time", nil)
+	EthdbPutTimer        = metrics.NewRegisteredTimer("ethdb/put/time", nil)
+	EthdbDeleteTimer     = metrics.NewRegisteredTimer("ethdb/delete/time", nil)
+	EthdbBatchWriteTimer = metrics.NewRegisteredTimer("ethdb/batch/write/time", nil)
+)
diff --git a/ethdb/pebble/pebble.go b/ethdb/pebble/pebble.go
index ae0039f41e..28aa115229 100644
--- a/ethdb/pebble/pebble.go
+++ b/ethdb/pebble/pebble.go
@@ -299,6 +299,10 @@ func (d *Database) Has(key []byte) (bool, error) {
 
 // Get retrieves the given key if it's present in the key-value store.
 func (d *Database) Get(key []byte) ([]byte, error) {
+	if metrics.EnabledExpensive {
+		start := time.Now()
+		defer func() { ethdb.EthdbGetTimer.UpdateSince(start) }()
+	}
 	d.quitLock.RLock()
 	defer d.quitLock.RUnlock()
 	if d.closed {
@@ -316,6 +320,10 @@ func (d *Database) Get(key []byte) ([]byte, error) {
 
 // Put inserts the given value into the key-value store.
 func (d *Database) Put(key []byte, value []byte) error {
+	if metrics.EnabledExpensive {
+		start := time.Now()
+		defer func() { ethdb.EthdbPutTimer.UpdateSince(start) }()
+	}
 	d.quitLock.RLock()
 	defer d.quitLock.RUnlock()
 	if d.closed {
@@ -326,6 +334,10 @@ func (d *Database) Put(key []byte, value []byte) error {
 
 // Delete removes the key from the key-value store.
 func (d *Database) Delete(key []byte) error {
+	if metrics.EnabledExpensive {
+		start := time.Now()
+		defer func() { ethdb.EthdbDeleteTimer.UpdateSince(start) }()
+	}
 	d.quitLock.RLock()
 	defer d.quitLock.RUnlock()
 	if d.closed {
@@ -482,6 +494,8 @@ func (d *Database) meter(refresh time.Duration, namespace string) {
 			nonLevel0CompCount = int64(d.nonLevel0Comp.Load())
 			level0CompCount    = int64(d.level0Comp.Load())
 		)
+		fmt.Printf("loop print db stats db_metrics=\n%v\n", stats)
+		d.log.Info("loop print db stats", "comp_time", compTime, "write_delay_count", writeDelayCount, "write_delay_time", writeDelayTime, "non_level0_comp_count", nonLevel0CompCount, "level0_comp_count", level0CompCount)
 		writeDelayTimes[i%2] = writeDelayTime
 		writeDelayCounts[i%2] = writeDelayCount
 		compTimes[i%2] = compTime
@@ -580,6 +594,10 @@ func (b *batch) ValueSize() int {
 
 // Write flushes any accumulated data to disk.
 func (b *batch) Write() error {
+	if metrics.EnabledExpensive {
+		start := time.Now()
+		defer func() { ethdb.EthdbBatchWriteTimer.UpdateSince(start) }()
+	}
 	b.db.quitLock.RLock()
 	defer b.db.quitLock.RUnlock()
 	if b.db.closed {
diff --git a/trie/trie.go b/trie/trie.go
index 07467ac69c..f4d4d9963c 100644
--- a/trie/trie.go
+++ b/trie/trie.go
@@ -21,13 +21,21 @@ import (
 	"bytes"
 	"errors"
 	"fmt"
+	"time"
 
 	"github.com/ethereum/go-ethereum/common"
 	"github.com/ethereum/go-ethereum/core/types"
 	"github.com/ethereum/go-ethereum/log"
+	"github.com/ethereum/go-ethereum/metrics"
 	"github.com/ethereum/go-ethereum/trie/trienode"
 )
 
+var (
+	trieGetTimer         = metrics.NewRegisteredTimer("trie/get/time", nil)
+	trieReaderGetTimer   = metrics.NewRegisteredTimer("trie/reader/get/time", nil)
+	trieReaderTotalTimer = metrics.NewRegisteredTimer("trie/reader/total/time", nil)
+)
+
 // Trie is a Merkle Patricia Trie. Use New to create a trie that sits on
 // top of a database. Whenever trie performs a commit operation, the generated
 // nodes will be gathered and returned in a set. Once the trie is committed,
@@ -145,6 +153,10 @@ func (t *Trie) Get(key []byte) ([]byte, error) {
 	if t.committed {
 		return nil, ErrCommitted
 	}
+	if metrics.EnabledExpensive {
+		start := time.Now()
+		defer func() { trieGetTimer.UpdateSince(start) }()
+	}
 	value, newroot, didResolve, err := t.get(t.root, keybytesToHex(key), 0)
 	if err == nil && didResolve {
 		t.root = newroot
@@ -177,7 +189,11 @@ func (t *Trie) get(origNode node, key []byte, pos int) (value []byte, newnode no
 		}
 		return value, n, didResolve, err
 	case hashNode:
+		start := time.Now()
 		child, err := t.resolveAndTrack(n, key[:pos])
+		if metrics.EnabledExpensive {
+			trieReaderGetTimer.UpdateSince(start)
+		}
 		if err != nil {
 			return nil, n, true, err
 		}
@@ -585,6 +601,10 @@ func (t *Trie) resolve(n node, prefix []byte) (node, error) {
 // node's original value. The rlp-encoded blob is preferred to be loaded from
 // database because it's easy to decode node while complex to encode node to blob.
 func (t *Trie) resolveAndTrack(n hashNode, prefix []byte) (node, error) {
+	if metrics.EnabledExpensive {
+		start := time.Now()
+		defer func() { trieReaderTotalTimer.UpdateSince(start) }()
+	}
 	blob, err := t.reader.node(prefix, common.BytesToHash(n))
 	if err != nil {
 		return nil, err

From 614210b1f2d0f4d968edf7944fa016e17113c277 Mon Sep 17 00:00:00 2001
From: Nolan <33241113+nolanxyg@users.noreply.github.com>
Date: Wed, 27 Mar 2024 16:09:18 +0800
Subject: [PATCH 5/8] add metric mgasps gauge

---
 core/blockchain.go        | 4 ++++
 core/blockchain_insert.go | 1 +
 2 files changed, 5 insertions(+)

diff --git a/core/blockchain.go b/core/blockchain.go
index 5a07000efe..87d7bfb63b 100644
--- a/core/blockchain.go
+++ b/core/blockchain.go
@@ -88,6 +88,9 @@ var (
 	triedbCommitExternalTimer = metrics.NewRegisteredTimer("chain/triedb/commit/external", nil)
 	innerExecutionTimer = metrics.NewRegisteredTimer("chain/inner/execution", nil)
 
+	blockGasUsedGauge = metrics.NewRegisteredGauge("chain/block/gas/used", nil)
+	mgaspsGauge = metrics.NewRegisteredGauge("chain/mgas/ps", nil)
+
 	blockReorgMeter     = metrics.NewRegisteredMeter("chain/reorg/executes", nil)
 	blockReorgAddMeter  = metrics.NewRegisteredMeter("chain/reorg/add", nil)
 	blockReorgDropMeter = metrics.NewRegisteredMeter("chain/reorg/drop", nil)
@@ -1947,6 +1950,7 @@ func (bc *BlockChain) insertChain(chain types.Blocks, setHead bool) (int, error)
 		}
 		trieDiffNodes, trieBufNodes, _ := bc.triedb.Size()
 		stats.report(chain, it.index, snapDiffItems, snapBufItems, trieDiffNodes, trieBufNodes, setHead)
+		blockGasUsedGauge.Update(int64(block.GasUsed())/1000000)
 
 		if !setHead {
 			// After merge we expect few side chains. Simply count
diff --git a/core/blockchain_insert.go b/core/blockchain_insert.go
index 9bf662b6b7..436d681482 100644
--- a/core/blockchain_insert.go
+++ b/core/blockchain_insert.go
@@ -60,6 +60,7 @@ func (st *insertStats) report(chain []*types.Block, index int, snapDiffItems, sn
 			"blocks", st.processed, "txs", txs, "mgas", float64(st.usedGas) / 1000000,
 			"elapsed", common.PrettyDuration(elapsed), "mgasps", float64(st.usedGas) * 1000 / float64(elapsed),
 		}
+		mgaspsGauge.Update(int64(st.usedGas)*1000/int64(elapsed))
 		if timestamp := time.Unix(int64(end.Time()), 0); time.Since(timestamp) > time.Minute {
 			context = append(context, []interface{}{"age", common.PrettyAge(timestamp)}...)
 		}

From 53b8a2a78fef05d32cbafdaaf44db35395e85ec9 Mon Sep 17 00:00:00 2001
From: Nolan <33241113+nolanxyg@users.noreply.github.com>
Date: Wed, 3 Apr 2024 17:18:47 +0800
Subject: [PATCH 6/8] chore: adjust log level

---
 core/blockchain.go        | 12 ++++++------
 eth/catalyst/api.go       |  8 ++++----
 miner/payload_building.go |  2 +-
 miner/worker.go           | 10 +++++-----
 4 files changed, 16 insertions(+), 16 deletions(-)

diff --git a/core/blockchain.go b/core/blockchain.go
index dd69d45fdd..b42db6368b 100644
--- a/core/blockchain.go
+++ b/core/blockchain.go
@@ -1458,7 +1458,7 @@ func (bc *BlockChain) writeBlockWithState(block *types.Block, receipts []*types.
 		log.Crit("Failed to write block into disk", "err", err)
 	}
 	blockWriteExternalTimer.UpdateSince(start)
-	log.Info("blockWriteExternalTimer", "duration", common.PrettyDuration(time.Since(start)), "hash", block.Hash())
+	log.Debug("blockWriteExternalTimer", "duration", common.PrettyDuration(time.Since(start)), "hash", block.Hash())
 	
 	// Commit all cached state changes into underlying memory database.
 	start = time.Now()
@@ -1467,7 +1467,7 @@ func (bc *BlockChain) writeBlockWithState(block *types.Block, receipts []*types.
 		return err
 	}
 	stateCommitExternalTimer.UpdateSince(start)
-	log.Info("stateCommitExternalTimer", "duration", common.PrettyDuration(time.Since(start)), "hash", block.Hash())
+	log.Debug("stateCommitExternalTimer", "duration", common.PrettyDuration(time.Since(start)), "hash", block.Hash())
 
 	// If node is running in path mode, skip explicit gc operation
 	// which is unnecessary in this mode.
@@ -1478,7 +1478,7 @@ func (bc *BlockChain) writeBlockWithState(block *types.Block, receipts []*types.
 	start = time.Now()
 	defer func () {
 		triedbCommitExternalTimer.UpdateSince(start)
-		log.Info("triedbCommitExternalTimer", "duration", common.PrettyDuration(time.Since(start)), "hash", block.Hash())
+		log.Debug("triedbCommitExternalTimer", "duration", common.PrettyDuration(time.Since(start)), "hash", block.Hash())
 	} ()
 	if bc.cacheConfig.TrieDirtyDisabled {
 		return bc.triedb.Commit(root, false)
@@ -1920,7 +1920,7 @@ func (bc *BlockChain) insertChain(chain types.Blocks, setHead bool) (int, error)
 
 		innerExecutionTimer.Update(DebugInnerExecutionDuration)
 
-		log.Info("New payload execution and validation metrics", "hash", block.Hash(), "execution", common.PrettyDuration(ptime), "validation", common.PrettyDuration(vtime), "accountReads", common.PrettyDuration(statedb.AccountReads), "storageReads", common.PrettyDuration(statedb.StorageReads), "snapshotAccountReads", common.PrettyDuration(statedb.SnapshotAccountReads), "snapshotStorageReads", common.PrettyDuration(statedb.SnapshotStorageReads), "accountUpdates", common.PrettyDuration(statedb.AccountUpdates), "storageUpdates", common.PrettyDuration(statedb.StorageUpdates), "accountHashes", common.PrettyDuration(statedb.AccountHashes), "storageHashes", common.PrettyDuration(statedb.StorageHashes))
+		log.Debug("New payload execution and validation metrics", "hash", block.Hash(), "execution", common.PrettyDuration(ptime), "validation", common.PrettyDuration(vtime), "accountReads", common.PrettyDuration(statedb.AccountReads), "storageReads", common.PrettyDuration(statedb.StorageReads), "snapshotAccountReads", common.PrettyDuration(statedb.SnapshotAccountReads), "snapshotStorageReads", common.PrettyDuration(statedb.SnapshotStorageReads), "accountUpdates", common.PrettyDuration(statedb.AccountUpdates), "storageUpdates", common.PrettyDuration(statedb.StorageUpdates), "accountHashes", common.PrettyDuration(statedb.AccountHashes), "storageHashes", common.PrettyDuration(statedb.StorageHashes))
 
 		// Write the block to the chain and get the status.
 		var (
@@ -1946,7 +1946,7 @@ func (bc *BlockChain) insertChain(chain types.Blocks, setHead bool) (int, error)
 		blockWriteTimer.UpdateSince(wstart)
 		blockInsertTimer.UpdateSince(start)
 
-		log.Info("New payload db write metrics", "hash", block.Hash(), "insert", common.PrettyDuration(time.Since(start)), "writeDB", common.PrettyDuration(time.Since(wstart)), "writeBlock", common.PrettyDuration(time.Since(wstart)), "accountCommit", common.PrettyDuration(statedb.AccountCommits), "storageCommit", common.PrettyDuration(statedb.StorageCommits), "snapshotCommits", common.PrettyDuration(statedb.SnapshotCommits), "triedbCommit", common.PrettyDuration(statedb.TrieDBCommits))
+		log.Debug("New payload db write metrics", "hash", block.Hash(), "insert", common.PrettyDuration(time.Since(start)), "writeDB", common.PrettyDuration(time.Since(wstart)), "writeBlock", common.PrettyDuration(time.Since(wstart)), "accountCommit", common.PrettyDuration(statedb.AccountCommits), "storageCommit", common.PrettyDuration(statedb.StorageCommits), "snapshotCommits", common.PrettyDuration(statedb.SnapshotCommits), "triedbCommit", common.PrettyDuration(statedb.TrieDBCommits))
 
 		// Report the import stats before returning the various results
 		stats.processed++
@@ -1959,7 +1959,7 @@ func (bc *BlockChain) insertChain(chain types.Blocks, setHead bool) (int, error)
 		trieDiffNodes, trieBufNodes, trieImmutableBufNodes, _ := bc.triedb.Size()
 		stats.report(chain, it.index, snapDiffItems, snapBufItems, trieDiffNodes, trieBufNodes, trieImmutableBufNodes, setHead)
 		blockGasUsedGauge.Update(int64(block.GasUsed())/1000000)
-		
+
 		if !setHead {
 			// After merge we expect few side chains. Simply count
 			// all blocks the CL gives us for GC processing time
diff --git a/eth/catalyst/api.go b/eth/catalyst/api.go
index 9a0c5fd664..60858b8230 100644
--- a/eth/catalyst/api.go
+++ b/eth/catalyst/api.go
@@ -409,11 +409,11 @@ func (api *ConsensusAPI) forkchoiceUpdated(update engine.ForkchoiceStateV1, payl
 		}
 		api.localBlocks.put(id, payload)
 		forkchoiceUpdateAttributesTimer.UpdateSince(start)
-		log.Info("forkchoiceUpdateAttributes", "duration", common.PrettyDuration(time.Since(start)), "id", id)
+		log.Debug("forkchoiceUpdateAttributesTimer", "duration", common.PrettyDuration(time.Since(start)), "id", id)
 		return valid(&id), nil
 	}
 	forkchoiceUpdateHeadsTimer.UpdateSince(start)
-	log.Info("forkchoiceUpdateHeads", "duration", common.PrettyDuration(time.Since(start)), "hash", update.HeadBlockHash)
+	log.Debug("forkchoiceUpdateAttributesTimer", "duration", common.PrettyDuration(time.Since(start)), "hash", update.HeadBlockHash)
 	return valid(nil), nil
 }
 
@@ -470,7 +470,7 @@ func (api *ConsensusAPI) getPayload(payloadID engine.PayloadID, full bool) (*eng
 	start := time.Now()
 	defer func () {
 		getPayloadTimer.UpdateSince(start)
-		log.Info("getPayload", "duration", common.PrettyDuration(time.Since(start)), "id", payloadID)
+		log.Debug("getPayloadTimer", "duration", common.PrettyDuration(time.Since(start)), "id", payloadID)
 	} ()
 	log.Trace("Engine API request received", "method", "GetPayload", "id", payloadID)
 	data := api.localBlocks.get(payloadID, full)
@@ -529,7 +529,7 @@ func (api *ConsensusAPI) newPayload(params engine.ExecutableData, versionedHashe
 	start := time.Now()
 	defer func () {
 		newPayloadTimer.UpdateSince(start)
-		log.Info("newPayload", "duration", common.PrettyDuration(time.Since(start)), "parentHash", params.ParentHash)
+		log.Debug("newPayloadTimer", "duration", common.PrettyDuration(time.Since(start)), "parentHash", params.ParentHash)
 	} ()
 
 	// The locking here is, strictly, not required. Without these locks, this can happen:
diff --git a/miner/payload_building.go b/miner/payload_building.go
index 48312928be..f3b8382783 100644
--- a/miner/payload_building.go
+++ b/miner/payload_building.go
@@ -215,7 +215,7 @@ func (payload *Payload) resolve(onlyFull bool) *engine.ExecutionPayloadEnvelope
 		start := time.Now()
 		payload.cond.Wait()
 		waitPayloadTimer.UpdateSince(start)
-		log.Info("Wait for background payload building end", "duration", common.PrettyDuration(time.Since(start)), "id", payload.id)
+		log.Debug("waitPayloadTimer", "duration", common.PrettyDuration(time.Since(start)), "id", payload.id)
 	}
 
 	// Now we can signal the building routine to stop.
diff --git a/miner/worker.go b/miner/worker.go
index 88bf9097d6..8b03825cbf 100644
--- a/miner/worker.go
+++ b/miner/worker.go
@@ -1093,7 +1093,7 @@ func (w *worker) fillTransactions(interrupt *atomic.Int32, env *environment) err
 	start := time.Now()
 	pending := w.eth.TxPool().Pending(true)
 	packFromTxpoolTimer.UpdateSince(start)
-	log.Info("packFromTxpool", "duration", common.PrettyDuration(time.Since(start)), "hash", env.header.Hash())
+	log.Debug("packFromTxpoolTimer", "duration", common.PrettyDuration(time.Since(start)), "hash", env.header.Hash())
 
 	// Split the pending transactions into locals and remotes.
 	localTxs, remoteTxs := make(map[common.Address][]*txpool.LazyTransaction), pending
@@ -1121,7 +1121,7 @@ func (w *worker) fillTransactions(interrupt *atomic.Int32, env *environment) err
 		}
 	}
 	commitTxpoolTxsTimer.UpdateSince(start)
-	log.Info("commitTxpoolTxs", "duration", common.PrettyDuration(time.Since(start)), "hash", env.header.Hash())
+	log.Debug("commitTxpoolTxsTimer", "duration", common.PrettyDuration(time.Since(start)), "hash", env.header.Hash())
 	return nil
 }
 
@@ -1160,7 +1160,7 @@ func (w *worker) generateWork(genParams *generateParams) *newPayloadResult {
 		work.tcount++
 	}
 	commitDepositTxsTimer.UpdateSince(start)
-	log.Info("commitDepositTxs", "duration", common.PrettyDuration(time.Since(start)), "parentHash", genParams.parentHash)
+	log.Debug("commitDepositTxsTimer", "duration", common.PrettyDuration(time.Since(start)), "parentHash", genParams.parentHash)
 
 	// forced transactions done, fill rest of block with transactions
 	if !genParams.noTxs {
@@ -1193,7 +1193,7 @@ func (w *worker) generateWork(genParams *generateParams) *newPayloadResult {
 		return &newPayloadResult{err: err}
 	}
 	assembleBlockTimer.UpdateSince(start)
-	log.Info("FinalizeAndAssemble", "duration", common.PrettyDuration(time.Since(start)), "parentHash", genParams.parentHash)
+	log.Debug("assembleBlockTimer", "duration", common.PrettyDuration(time.Since(start)), "parentHash", genParams.parentHash)
 
 	accountReadTimer.Update(work.state.AccountReads)                   // Account reads are complete(in commit txs)
 	storageReadTimer.Update(work.state.StorageReads)                   // Storage reads are complete(in commit txs)
@@ -1206,7 +1206,7 @@ func (w *worker) generateWork(genParams *generateParams) *newPayloadResult {
 
 	innerExecutionTimer.Update(core.DebugInnerExecutionDuration)
 
-	log.Info("build payload statedb metrics",  "parentHash", genParams.parentHash, "accountReads", common.PrettyDuration(work.state.AccountReads), "storageReads", common.PrettyDuration(work.state.StorageReads), "snapshotAccountReads", common.PrettyDuration(work.state.SnapshotAccountReads), "snapshotStorageReads", common.PrettyDuration(work.state.SnapshotStorageReads), "accountUpdates", common.PrettyDuration(work.state.AccountUpdates), "storageUpdates", common.PrettyDuration(work.state.StorageUpdates), "accountHashes", common.PrettyDuration(work.state.AccountHashes), "storageHashes", common.PrettyDuration(work.state.StorageHashes))
+	log.Debug("build payload statedb metrics",  "parentHash", genParams.parentHash, "accountReads", common.PrettyDuration(work.state.AccountReads), "storageReads", common.PrettyDuration(work.state.StorageReads), "snapshotAccountReads", common.PrettyDuration(work.state.SnapshotAccountReads), "snapshotStorageReads", common.PrettyDuration(work.state.SnapshotStorageReads), "accountUpdates", common.PrettyDuration(work.state.AccountUpdates), "storageUpdates", common.PrettyDuration(work.state.StorageUpdates), "accountHashes", common.PrettyDuration(work.state.AccountHashes), "storageHashes", common.PrettyDuration(work.state.StorageHashes))
 
 	return &newPayloadResult{
 		block:    block,

From cd9859aff2949ec61bd36ebf0672cd3be27052b6 Mon Sep 17 00:00:00 2001
From: Nolan <33241113+nolanxyg@users.noreply.github.com>
Date: Wed, 3 Apr 2024 17:54:56 +0800
Subject: [PATCH 7/8] chore: fix ci

---
 ethdb/pebble/pebble.go | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/ethdb/pebble/pebble.go b/ethdb/pebble/pebble.go
index 28aa115229..52f6ad36a5 100644
--- a/ethdb/pebble/pebble.go
+++ b/ethdb/pebble/pebble.go
@@ -494,7 +494,7 @@ func (d *Database) meter(refresh time.Duration, namespace string) {
 			nonLevel0CompCount = int64(d.nonLevel0Comp.Load())
 			level0CompCount    = int64(d.level0Comp.Load())
 		)
-		fmt.Printf("loop print db stats db_metrics=\n%v\n", stats)
+		// fmt.Printf("loop print db stats db_metrics=\n%v\n", stats)
 		d.log.Info("loop print db stats", "comp_time", compTime, "write_delay_count", writeDelayCount, "write_delay_time", writeDelayTime, "non_level0_comp_count", nonLevel0CompCount, "level0_comp_count", level0CompCount)
 		writeDelayTimes[i%2] = writeDelayTime
 		writeDelayCounts[i%2] = writeDelayCount

From 0a003b71e8795ef932226f065dbe46a9bfd911c1 Mon Sep 17 00:00:00 2001
From: bnoieh <135800952+bnoieh@users.noreply.github.com>
Date: Mon, 8 Apr 2024 11:25:59 +0800
Subject: [PATCH 8/8] Update ethdb/pebble/pebble.go

Co-authored-by: Owen <103096885+owen-reorg@users.noreply.github.com>
---
 ethdb/pebble/pebble.go | 1 -
 1 file changed, 1 deletion(-)

diff --git a/ethdb/pebble/pebble.go b/ethdb/pebble/pebble.go
index 52f6ad36a5..56e1aa92d8 100644
--- a/ethdb/pebble/pebble.go
+++ b/ethdb/pebble/pebble.go
@@ -494,7 +494,6 @@ func (d *Database) meter(refresh time.Duration, namespace string) {
 			nonLevel0CompCount = int64(d.nonLevel0Comp.Load())
 			level0CompCount    = int64(d.level0Comp.Load())
 		)
-		// fmt.Printf("loop print db stats db_metrics=\n%v\n", stats)
 		d.log.Info("loop print db stats", "comp_time", compTime, "write_delay_count", writeDelayCount, "write_delay_time", writeDelayTime, "non_level0_comp_count", nonLevel0CompCount, "level0_comp_count", level0CompCount)
 		writeDelayTimes[i%2] = writeDelayTime
 		writeDelayCounts[i%2] = writeDelayCount