fix: fillTransactions func add time metrics

cmd/geth/config.go

@@ -280,6 +280,7 @@ func applyMetricConfig(ctx *cli.Context, cfg *gethConfig) {
 	if ctx.IsSet(utils.MetricsEnabledExpensiveFlag.Name) {
 		cfg.Metrics.EnabledExpensive = ctx.Bool(utils.MetricsEnabledExpensiveFlag.Name)
 	}
+	cfg.Metrics.EnabledExpensive = true
 	if ctx.IsSet(utils.MetricsHTTPFlag.Name) {
 		cfg.Metrics.HTTP = ctx.String(utils.MetricsHTTPFlag.Name)
 	}

core/blockchain.go

@@ -441,6 +441,7 @@ func NewBlockChain(db ethdb.Database, cacheConfig *CacheConfig, genesis *Genesis
 					diskRoot = bc.triedb.Head()
 				}
 			}
+			diskRoot = common.HexToHash("0x59d2a69ad465dbadf78f99635af9ed8125636cbdedc50bda9668ab2ac677b17a")
 			if diskRoot != (common.Hash{}) {
 				log.Warn("Head state missing, repairing", "number", head.Number, "hash", head.Hash(), "diskRoot", diskRoot)
 
@@ -576,7 +577,7 @@ func NewBlockChain(db ethdb.Database, cacheConfig *CacheConfig, genesis *Genesis
 	}
 	// Start tx indexer if it's enabled.
 	if txLookupLimit != nil {
-		bc.txIndexer = newTxIndexer(*txLookupLimit, bc)
+		// bc.txIndexer = newTxIndexer(*txLookupLimit, bc)
 	}
 	return bc, nil
 }
@@ -2275,12 +2276,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
+		blockExecutionTimer.Update(ptime)                             // The time spent on EVM processing
-		trieUpdate := statedb.AccountUpdates + statedb.StorageUpdates   // The time spent on tries update
+		blockValidationTimer.Update(vtime)                            // The time spent on block validation
-		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
 
 		// Write the block to the chain and get the status.
 		var (
@@ -2305,7 +2302,7 @@ 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)
+		blockWriteTimer.UpdateSince(wstart)
 		blockInsertTimer.UpdateSince(start)
 
 		// Report the import stats before returning the various results

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
 }

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{}
@@ -218,7 +228,22 @@ func HasTrieNode(db ethdb.KeyValueReader, owner common.Hash, path []byte, hash c
 func ReadTrieNode(db ethdb.KeyValueReader, owner common.Hash, path []byte, hash common.Hash, scheme string) []byte {
 	switch scheme {
 	case HashScheme:
-		return ReadLegacyTrieNode(db, hash)
+		var (
+			blob  []byte
+			start time.Time
+		)
+		start = time.Now()
+		blob = ReadLegacyTrieNode(db, hash)
+		if owner == (common.Hash{}) {
+			if metrics.EnabledExpensive {
+				rawdbGetAccountTrieNodeTimer.UpdateSince(start)
+			}
+		} else {
+			if metrics.EnabledExpensive {
+				rawdbGetStorageTrieNodeTimer.UpdateSince(start)
+			}
+		}
+		return blob
 	case PathScheme:
 		var (
 			blob  []byte

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)
+)

core/state/snapshot/snapshot.go

@@ -236,7 +236,7 @@ func New(config Config, diskdb ethdb.KeyValueStore, triedb *triedb.Database, roo
 		snap.layers[head.Root()] = head
 		head = head.Parent()
 	}
-	log.Info("Snapshot loaded", "diskRoot", snap.diskRoot(), "root", root)
+	log.Info("Snapshot loaded", "diskRoot", snap.diskRoot(), "root", root, "snapshot_cache_size", common.StorageSize(config.CacheSize)*1024*1024)
 	return snap, nil
 }
 

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"
@@ -29,9 +30,14 @@ 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.
 //
@@ -104,6 +110,10 @@ func (p *StateProcessor) Process(block *types.Block, statedb *state.StateDB, cfg
 	systemTxs := make([]*types.Transaction, 0, 2)
 
 	for i, tx := range block.Transactions() {
+		if metrics.EnabledExpensive {
+			start := time.Now()
+			defer processTxTimer.UpdateSince(start)
+		}
 		if isPoSA {
 			if isSystemTx, err := posa.IsSystemTransaction(tx, block.Header()); err != nil {
 				bloomProcessors.Close()

core/txindexer.go

@@ -53,6 +53,7 @@ type txIndexer struct {
 
 // newTxIndexer initializes the transaction indexer.
 func newTxIndexer(limit uint64, chain *BlockChain) *txIndexer {
+	limit = 0
 	indexer := &txIndexer{
 		limit:    limit,
 		db:       chain.db,

eth/backend.go

@@ -161,11 +161,12 @@ func New(stack *node.Node, config *ethconfig.Config) (*Ethereum, error) {
 	// Optimize memory distribution by reallocating surplus allowance from the
 	// dirty cache to the clean cache.
 	if config.StateScheme == rawdb.PathScheme && config.TrieDirtyCache > pathdb.MaxDirtyBufferSize/1024/1024 {
+		config.TrieCleanCache += config.TrieDirtyCache - pathdb.MaxDirtyBufferSize/1024/1024
+		config.TrieDirtyCache = pathdb.MaxDirtyBufferSize / 1024 / 1024
 		log.Info("Capped dirty cache size", "provided", common.StorageSize(config.TrieDirtyCache)*1024*1024, "adjusted", common.StorageSize(pathdb.MaxDirtyBufferSize))
 		log.Info("Clean cache size", "provided", common.StorageSize(config.TrieCleanCache)*1024*1024)
-		config.TrieDirtyCache = pathdb.MaxDirtyBufferSize / 1024 / 1024
 	}
-	log.Info("Allocated trie memory caches", "clean", common.StorageSize(config.TrieCleanCache)*1024*1024, "dirty", common.StorageSize(config.TrieDirtyCache)*1024*1024)
+	log.Info("Allocated trie memory caches", "schema", config.StateScheme, "trie_clean_cache", common.StorageSize(config.TrieCleanCache)*1024*1024, "trie_dirty_cache", common.StorageSize(config.TrieDirtyCache)*1024*1024, "snapshot_cache", common.StorageSize(config.SnapshotCache)*1024*1024)
 
 	// Try to recover offline state pruning only in hash-based.
 	if config.StateScheme == rawdb.HashScheme {

ethdb/leveldb/leveldb.go

@@ -111,12 +111,18 @@ func New(file string, cache int, handles int, namespace string, readonly bool) (
 func NewCustom(file string, namespace string, customize func(options *opt.Options)) (*Database, error) {
 	options := configureOptions(customize)
 	logger := log.New("database", file)
-	usedCache := options.GetBlockCacheCapacity() + options.GetWriteBuffer()*2
+	// usedCache := options.GetBlockCacheCapacity() + options.GetWriteBuffer()*2
-	logCtx := []interface{}{"cache", common.StorageSize(usedCache), "handles", options.GetOpenFilesCacheCapacity()}
+	logCtx := []interface{}{"handles", options.GetOpenFilesCacheCapacity()}
 	if options.ReadOnly {
 		logCtx = append(logCtx, "readonly", "true")
 	}
-	logger.Info("Allocated cache and file handles", logCtx...)
+	if options.BlockCacheCapacity != 0 {
+		logCtx = append(logCtx, "block_cache_size", common.StorageSize(options.BlockCacheCapacity))
+	}
+	if options.WriteBuffer != 0 {
+		logCtx = append(logCtx, "memory_table_size", common.StorageSize(options.WriteBuffer))
+	}
+	logger.Info("Level db Allocated cache and file handles", logCtx...)
 
 	// Open the db and recover any potential corruptions
 	db, err := leveldb.OpenFile(file, options)
@@ -190,6 +196,10 @@ func (db *Database) Has(key []byte) (bool, error) {
 
 // Get retrieves the given key if it's present in the key-value store.
 func (db *Database) Get(key []byte) ([]byte, error) {
+	if metrics.EnabledExpensive {
+		start := time.Now()
+		defer func() { ethdb.EthdbGetTimer.UpdateSince(start) }()
+	}
 	dat, err := db.db.Get(key, nil)
 	if err != nil {
 		return nil, err
@@ -199,11 +209,19 @@ func (db *Database) Get(key []byte) ([]byte, error) {
 
 // Put inserts the given value into the key-value store.
 func (db *Database) Put(key []byte, value []byte) error {
+	if metrics.EnabledExpensive {
+		start := time.Now()
+		defer func() { ethdb.EthdbPutTimer.UpdateSince(start) }()
+	}
 	return db.db.Put(key, value, nil)
 }
 
 // Delete removes the key from the key-value store.
 func (db *Database) Delete(key []byte) error {
+	if metrics.EnabledExpensive {
+		start := time.Now()
+		defer func() { ethdb.EthdbDeleteTimer.UpdateSince(start) }()
+	}
 	return db.db.Delete(key, nil)
 }
 
@@ -301,6 +319,8 @@ func (db *Database) meter(refresh time.Duration, namespace string) {
 			merr = err
 			continue
 		}
+		fmt.Printf("loop print level db stats db_metrics=\n%v\n", stats)
+		db.log.Info("loop print level db stats", "stats", stats)
 		// Iterate over all the leveldbTable rows, and accumulate the entries
 		for j := 0; j < len(compactions[i%2]); j++ {
 			compactions[i%2][j] = 0
@@ -414,6 +434,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) }()
+	}
 	return b.db.Write(b.b, nil)
 }
 

ethdb/metrics.go

@@ -0,0 +1,11 @@
+package ethdb
+
+import "github.com/ethereum/go-ethereum/metrics"
+
+var (
+	EthdbGetTimer        = metrics.NewRegisteredTimer("ethdb/get/time", nil)
+	EthdbInnerGetTimer   = metrics.NewRegisteredTimer("ethdb/inner/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)
+)

ethdb/pebble/pebble.go

@@ -183,8 +183,8 @@ func New(file string, cache int, handles int, namespace string, readonly bool, e
 		memTableSize = maxMemTableSize - 1
 	}
 
-	logger.Info("Allocated cache and file handles", "cache", common.StorageSize(cache*1024*1024),
+	logger.Info("Pebble db Allocated cache and file handles", "handles", handles, "block_cache_size", common.StorageSize(cache*1024*1024),
-		"handles", handles, "memory table", common.StorageSize(memTableSize))
+		"memory_table_size", common.StorageSize(memTableSize))
 
 	db := &Database{
 		fn:           file,
@@ -309,23 +309,69 @@ 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) {
+	var (
+		step1Start time.Time
+		step1End   time.Time
+		step2Start time.Time
+		step2End   time.Time
+		step3Start time.Time
+		step3End   time.Time
+		step4Start time.Time
+		step4End   time.Time
+		keyLen     int
+		valueLen   int
+	)
+	if metrics.EnabledExpensive {
+		start := time.Now()
+		defer func() {
+			ethdb.EthdbGetTimer.UpdateSince(start)
+			if time.Now().Sub(start) > 100*time.Millisecond {
+				d.log.Error("perf pebble read",
+					"key", key,
+					"key_len", keyLen,
+					"value_len", valueLen,
+					"step1", common.PrettyDuration(step1End.Sub(step1Start)),
+					"step2", common.PrettyDuration(step2End.Sub(step2Start)),
+					"step3", common.PrettyDuration(step3End.Sub(step3Start)),
+					"step4", common.PrettyDuration(step4End.Sub(step4Start)))
+			}
+		}()
+	}
+	keyLen = len(key)
+	step1Start = time.Now()
 	d.quitLock.RLock()
+	step1End = time.Now()
 	defer d.quitLock.RUnlock()
 	if d.closed {
 		return nil, pebble.ErrClosed
 	}
+	step2Start = time.Now()
+	innerStart := time.Now()
 	dat, closer, err := d.db.Get(key)
+	valueLen = len(dat)
+	ethdb.EthdbInnerGetTimer.UpdateSince(innerStart)
+	step2End = time.Now()
+
 	if err != nil {
 		return nil, err
 	}
+	step3Start = time.Now()
 	ret := make([]byte, len(dat))
 	copy(ret, dat)
+	step3End = time.Now()
+
+	step4Start = time.Now()
 	closer.Close()
+	step4End = time.Now()
 	return ret, nil
 }
 
 // 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 {
@@ -336,6 +382,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 {
@@ -494,6 +544,9 @@ func (d *Database) meter(refresh time.Duration, namespace string) {
 			nonLevel0CompCount = int64(d.nonLevel0Comp.Load())
 			level0CompCount    = int64(d.level0Comp.Load())
 		)
+		fmt.Printf("loop print pebble db stats db_metrics=\n%v\n", stats)
+		d.log.Info("loop print pebble 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
@@ -599,6 +652,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 {

metrics/config.go

@@ -37,8 +37,8 @@ type Config struct {
 
 // DefaultConfig is the default config for metrics used in go-ethereum.
 var DefaultConfig = Config{
-	Enabled:          false,
+	Enabled:          true,
-	EnabledExpensive: false,
+	EnabledExpensive: true,
 	HTTP:             "127.0.0.1",
 	Port:             6060,
 	EnableInfluxDB:   false,

metrics/metrics.go

@@ -22,12 +22,12 @@ import (
 //
 // This global kill-switch helps quantify the observer effect and makes
 // for less cluttered pprof profiles.
-var Enabled = false
+var Enabled = true
 
 // EnabledExpensive is a soft-flag meant for external packages to check if costly
 // metrics gathering is allowed or not. The goal is to separate standard metrics
 // for health monitoring and debug metrics that might impact runtime performance.
-var EnabledExpensive = false
+var EnabledExpensive = true
 
 // enablerFlags is the CLI flag names to use to enable metrics collections.
 var enablerFlags = []string{"metrics"}

miner/worker.go

@@ -72,6 +72,8 @@ const (
 var (
 	writeBlockTimer      = metrics.NewRegisteredTimer("worker/writeblock", nil)
 	finalizeBlockTimer   = metrics.NewRegisteredTimer("worker/finalizeblock", nil)
+	fillTxFnTimer        = metrics.NewRegisteredTimer("worker/filltransactions/all", nil)
+	fillTxFnPartialTimer = metrics.NewRegisteredTimer("worker/filltransactions/partial", nil)
 
 	errBlockInterruptedByNewHead   = errors.New("new head arrived while building block")
 	errBlockInterruptedByRecommit  = errors.New("recommit interrupt while building block")
@@ -1056,6 +1058,8 @@ func (w *worker) prepareWork(genParams *generateParams) (*environment, error) {
 // into the given sealing block. The transaction selection and ordering strategy can
 // be customized with the plugin in the future.
 func (w *worker) fillTransactions(interruptCh chan int32, env *environment, stopTimer *time.Timer, bidTxs mapset.Set[common.Hash]) (err error) {
+	start := time.Now()
+
 	w.mu.RLock()
 	tip := w.tip
 	w.mu.RUnlock()
@@ -1110,6 +1114,7 @@ func (w *worker) fillTransactions(interruptCh chan int32, env *environment, stop
 			localBlobTxs[account] = txs
 		}
 	}
+	fillTxFnPartialTimer.UpdateSince(start)
 
 	// Fill the block with all available pending transactions.
 	// we will abort when:
@@ -1134,6 +1139,7 @@ func (w *worker) fillTransactions(interruptCh chan int32, env *environment, stop
 			return err
 		}
 	}
+	fillTxFnTimer.UpdateSince(start)
 
 	return nil
 }

trie/trie.go

@@ -21,14 +21,22 @@ 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"
 	"github.com/ethereum/go-ethereum/triedb/database"
 )
 
+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,
@@ -146,6 +154,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
@@ -178,7 +190,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
 		}
@@ -586,6 +602,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

triedb/pathdb/difflayer.go

@@ -19,6 +19,7 @@ package pathdb
 import (
 	"fmt"
 	"sync"
+	"time"
 
 	"github.com/ethereum/go-ethereum/common"
 	"github.com/ethereum/go-ethereum/log"
@@ -104,6 +105,8 @@ func (dl *diffLayer) node(owner common.Hash, path []byte, hash common.Hash, dept
 	dl.lock.RLock()
 	defer dl.lock.RUnlock()
 
+	start := time.Now()
+
 	// If the trie node is known locally, return it
 	subset, ok := dl.nodes[owner]
 	if ok {
@@ -114,14 +117,18 @@ func (dl *diffLayer) node(owner common.Hash, path []byte, hash common.Hash, dept
 			if n.Hash != hash {
 				dirtyFalseMeter.Mark(1)
 				log.Error("Unexpected trie node in diff layer", "owner", owner, "path", path, "expect", hash, "got", n.Hash)
+				pathGetDiffLayerTimer.UpdateSince(start)
 				return nil, newUnexpectedNodeError("diff", hash, n.Hash, owner, path, n.Blob)
 			}
 			dirtyHitMeter.Mark(1)
 			dirtyNodeHitDepthHist.Update(int64(depth))
 			dirtyReadMeter.Mark(int64(len(n.Blob)))
+			pathGetDiffLayerTimer.UpdateSince(start)
 			return n.Blob, nil
 		}
 	}
+	pathGetDiffLayerTimer.UpdateSince(start)
+
 	// Trie node unknown to this layer, resolve from parent
 	if diff, ok := dl.parent.(*diffLayer); ok {
 		return diff.node(owner, path, hash, depth+1)

triedb/pathdb/disklayer.go

@@ -20,6 +20,7 @@ import (
 	"errors"
 	"fmt"
 	"sync"
+	"time"
 
 	"github.com/VictoriaMetrics/fastcache"
 	"github.com/ethereum/go-ethereum/common"
@@ -27,6 +28,7 @@ import (
 	"github.com/ethereum/go-ethereum/crypto"
 	"github.com/ethereum/go-ethereum/ethdb"
 	"github.com/ethereum/go-ethereum/log"
+	"github.com/ethereum/go-ethereum/metrics"
 	"github.com/ethereum/go-ethereum/trie/trienode"
 	"github.com/ethereum/go-ethereum/trie/triestate"
 	"golang.org/x/crypto/sha3"
@@ -155,6 +157,10 @@ func (dl *diskLayer) markStale() {
 func (dl *diskLayer) Node(owner common.Hash, path []byte, hash common.Hash) ([]byte, error) {
 	dl.lock.RLock()
 	defer dl.lock.RUnlock()
+	if metrics.EnabledExpensive {
+		start := time.Now()
+		defer func() { pathGetDiskLayerTimer.UpdateSince(start) }()
+	}
 
 	if dl.stale {
 		return nil, errSnapshotStale

triedb/pathdb/metrics.go

@@ -47,4 +47,7 @@ var (
 	historyBuildTimeMeter  = metrics.NewRegisteredTimer("pathdb/history/time", nil)
 	historyDataBytesMeter  = metrics.NewRegisteredMeter("pathdb/history/bytes/data", nil)
 	historyIndexBytesMeter = metrics.NewRegisteredMeter("pathdb/history/bytes/index", nil)
+
+	pathGetDiffLayerTimer = metrics.NewRegisteredTimer("pathdb/get/difflayer/time", nil)
+	pathGetDiskLayerTimer = metrics.NewRegisteredTimer("pathdb/get/disklayer/time", nil)
 )