cosmetic: refactor log

cmd/geth/chaincmd.go

@@ -48,7 +48,6 @@ import (
 	"github.com/ethereum/go-ethereum/metrics"
 	"github.com/ethereum/go-ethereum/node"
 	"github.com/ethereum/go-ethereum/params"
-	"github.com/ethereum/go-ethereum/trie"
 	"github.com/urfave/cli/v2"
 )
 
@@ -447,9 +446,19 @@ func showMetrics() {
 	fmt.Println("blockCrossValidationTimer", blockCrossValidationTimer.Total())
 
 	// execution
-	fmt.Println("prefetchTimer", blockPrefetchExecuteTimer.Total())
+	fmt.Println("prefetchTimer    :", blockPrefetchExecuteTimer.Total())
+	fmt.Println("prefetchBALtime:  ", core.PrefetchBALTime)
+
+	// execution: parallel merging post state for deriving the new stateRoot
+	fmt.Println("postStateMergeTime:", core.PostMergeTime)
+	fmt.Println("prefetchTrieWallT:", core.PrefetchTrieTimer)
+	// execution: parallel execution for validation
+	fmt.Println("prestateMergeTime:", core.PrefetchMergeBALTime)
+	fmt.Println("parallelExeTime:  ", core.ParallelExeTime)
+	// Other:Sync state time
+	fmt.Println("prefetchChTime:   ", core.PrefetchChTime)
+
 	fmt.Println("accountReadTimer", accountReadTimer.Total())
-	fmt.Println("ResolveTimer", trie.ResolveTime)
 	fmt.Println("storageReadTimer", storageReadTimer.Total())
 	fmt.Println("blockExecutionTimer", blockExecutionTimer.Total())
 
@@ -465,27 +474,19 @@ func showMetrics() {
 	fmt.Println("triedbCommitTimer", triedbCommitTimer.Total())
 	fmt.Println("blockWriteTimer", blockWriteTimer.Total())
 
-	// Parallel
+	// Others
 	fmt.Println("StateSetTime:     ", state.StateSetTime)
 	fmt.Println("StateLoadTime:    ", state.StateLoadTime)
 	fmt.Println("StateFinaliTime:  ", state.StateFinalizeTime)
 	fmt.Println("StateCopyTime:    ", state.StateCopyTime)
 	fmt.Println("StateCopyNewTime: ", state.StateNewTime)
 	fmt.Println("StateDeepCpTime:  ", state.StateDeepCpTime)
-	fmt.Println("PrefetchBALtime:  ", core.PrefetchBALTime)
-	fmt.Println("PrefetchMergeTime:", core.PrefetchMergeBALTime)
-	fmt.Println("ParallelExeTime: ", core.ParallelExeTime)
-	fmt.Println("PrefetchTrieWallTime: ", core.PrefetchTrieTimer)
-	// fmt.Println("PrefetchTrieCPUtime:  ", state.PrefetchTrieCPUTime)
-
-	// Sync state time
-	fmt.Println("PrefetchChTime: ", core.PrefetchChTime)
 
 	// total
-	fmt.Println("blockInsertTimer", blockInsertTimer.Total())
+	fmt.Println("blockInsertTimer: ", blockInsertTimer.Total())
 
 	mgasps := chainMgaspsMeter.Snapshot()
-	fmt.Println("mgasps,mean,max,min:", int64(mgasps.Mean()), mgasps.Max(), mgasps.Min())
+	fmt.Println("mgasps min,mean,max:", mgasps.Min(), int64(mgasps.Mean()), mgasps.Max())
 }
 
 func exportChain(ctx *cli.Context) error {

core/blockchainN.go

@@ -305,11 +305,19 @@ func (bc *BlockChain) insertChainN(chain types.Blocks, setHead bool, makeWitness
 
 	// Validate stateRoot for N-blocks at once.
 	xvtime := time.Now()
+	statedb.AccountUpdates = time.Duration(0)
+	statedb.StorageUpdates = time.Duration(0)
+	statedb.AccountHashes = time.Duration(0)
 	header := endBlock.Header()
 	if root := statedb.IntermediateRoot(true); header.Root != root {
 		log.Crit("invalid merkle root (remote: %x local: %x) dberr: %w", header.Root, root, statedb.Error())
 	}
-	blockCrossValidationTimer.Update(time.Since(xvtime))
+	accountUpdateTimer.Update(statedb.AccountUpdates)                         // Account updates are complete(in validation)
+	storageUpdateTimer.Update(statedb.StorageUpdates)                         // Storage updates are complete(in validation)
+	accountHashTimer.Update(statedb.AccountHashes)                            // Account hashes are complete(in validation)
+	triehash := statedb.AccountHashes                                         // The time spent on tries hashing
+	trieUpdate := statedb.AccountUpdates + statedb.StorageUpdates             // The time spent on tries update
+	blockValidationTimer.Update(time.Since(xvtime) - (triehash + trieUpdate)) // The time spent on block validation
 
 	// Commit N-blocks together to the chain and get the status.
 	var (

trie/trie.go

@@ -21,7 +21,6 @@ import (
 	"bytes"
 	"errors"
 	"fmt"
-	"time"
 
 	"github.com/ethereum/go-ethereum/common"
 	"github.com/ethereum/go-ethereum/core/types"
@@ -325,8 +324,6 @@ func (t *Trie) update(key, value []byte) error {
 	return nil
 }
 
-var ResolveTime = time.Duration(0)
-
 func (t *Trie) insert(n node, prefix, key []byte, value node) (bool, node, error) {
 	if len(key) == 0 {
 		if v, ok := n.(valueNode); ok {
@@ -390,9 +387,7 @@ func (t *Trie) insert(n node, prefix, key []byte, value node) (bool, node, error
 		// We've hit a part of the trie that isn't loaded yet. Load
 		// the node and insert into it. This leaves all child nodes on
 		// the path to the value in the trie.
-		start := time.Now()
 		rn, err := t.resolveAndTrack(n, prefix)
-		ResolveTime += time.Since(start)
 		if err != nil {
 			return false, nil, err
 		}
@@ -522,9 +517,7 @@ func (t *Trie) delete(n node, prefix, key []byte) (bool, node, error) {
 				// shortNode{..., shortNode{...}}.  Since the entry
 				// might not be loaded yet, resolve it just for this
 				// check.
-				start := time.Now()
 				cnode, err := t.resolve(n.Children[pos], append(prefix, byte(pos)))
-				ResolveTime += time.Since(start)
 
 				if err != nil {
 					return false, nil, err
@@ -556,9 +549,7 @@ func (t *Trie) delete(n node, prefix, key []byte) (bool, node, error) {
 		// We've hit a part of the trie that isn't loaded yet. Load
 		// the node and delete from it. This leaves all child nodes on
 		// the path to the value in the trie.
-		start := time.Now()
 		rn, err := t.resolveAndTrack(n, prefix)
-		ResolveTime += time.Since(start)
 		if err != nil {
 			return false, nil, err
 		}