core: add code read statistics

core/blockchain.go

@@ -75,6 +75,7 @@ var (
 	storageReadTimer   = metrics.NewRegisteredResettingTimer("chain/storage/reads", nil)
 	storageUpdateTimer = metrics.NewRegisteredResettingTimer("chain/storage/updates", nil)
 	storageCommitTimer = metrics.NewRegisteredResettingTimer("chain/storage/commits", nil)
+	codeReadTimer      = metrics.NewRegisteredResettingTimer("chain/code/reads", nil)
 
 	accountCacheHitMeter  = metrics.NewRegisteredMeter("chain/account/reads/cache/process/hit", nil)
 	accountCacheMissMeter = metrics.NewRegisteredMeter("chain/account/reads/cache/process/miss", nil)
@@ -88,6 +89,7 @@ var (
 
 	accountReadSingleTimer = metrics.NewRegisteredResettingTimer("chain/account/single/reads", nil)
 	storageReadSingleTimer = metrics.NewRegisteredResettingTimer("chain/storage/single/reads", nil)
+	codeReadSingleTimer    = metrics.NewRegisteredResettingTimer("chain/code/single/reads", nil)
 
 	snapshotCommitTimer = metrics.NewRegisteredResettingTimer("chain/snapshot/commits", nil)
 	triedbCommitTimer   = metrics.NewRegisteredResettingTimer("chain/triedb/commits", nil)
@@ -1602,13 +1604,17 @@ func (bc *BlockChain) writeBlockWithState(block *types.Block, receipts []*types.
 	//
 	// Note all the components of block(hash->number map, header, body, receipts)
 	// should be written atomically. BlockBatch is used for containing all components.
-	blockBatch := bc.db.NewBatch()
-	rawdb.WriteBlock(blockBatch, block)
-	rawdb.WriteReceipts(blockBatch, block.Hash(), block.NumberU64(), receipts)
-	rawdb.WritePreimages(blockBatch, statedb.Preimages())
-	if err := blockBatch.Write(); err != nil {
+	var (
+		batch = bc.db.NewBatch()
+		start = time.Now()
+	)
+	rawdb.WriteBlock(batch, block)
+	rawdb.WriteReceipts(batch, block.Hash(), block.NumberU64(), receipts)
+	rawdb.WritePreimages(batch, statedb.Preimages())
+	if err := batch.Write(); err != nil {
 		log.Crit("Failed to write block into disk", "err", err)
 	}
+	log.Debug("Committed block data", "size", common.StorageSize(batch.ValueSize()), "elapsed", common.PrettyDuration(time.Since(start)))
 
 	var (
 		err      error
@@ -2167,15 +2173,17 @@ func (bc *BlockChain) ProcessBlock(parentRoot common.Hash, block *types.Block, s
 	stats.AccountUpdates = statedb.AccountUpdates // Account updates are complete(in validation)
 	stats.StorageUpdates = statedb.StorageUpdates // Storage updates are complete(in validation)
 	stats.AccountHashes = statedb.AccountHashes   // Account hashes are complete(in validation)
+	stats.CodeReads = statedb.CodeReads
 
 	stats.AccountLoaded = statedb.AccountLoaded
 	stats.AccountUpdated = statedb.AccountUpdated
 	stats.AccountDeleted = statedb.AccountDeleted
 	stats.StorageLoaded = statedb.StorageLoaded
 	stats.StorageUpdated = int(statedb.StorageUpdated.Load())
 	stats.StorageDeleted = int(statedb.StorageDeleted.Load())
+	stats.CodeLoaded = statedb.CodeLoaded
 
-	stats.Execution = ptime - (statedb.AccountReads + statedb.StorageReads)                              // The time spent on EVM processing
+	stats.Execution = ptime - (statedb.AccountReads + statedb.StorageReads + statedb.CodeReads)          // The time spent on EVM processing
 	stats.Validation = vtime - (statedb.AccountHashes + statedb.AccountUpdates + statedb.StorageUpdates) // The time spent on block validation
 	stats.CrossValidation = xvtime                                                                       // The time spent on stateless cross validation
 

core/blockchain_stats.go

@@ -37,13 +37,15 @@ type ExecuteStats struct {
 	AccountCommits time.Duration // Time spent on the account trie commit
 	StorageUpdates time.Duration // Time spent on the storage trie update
 	StorageCommits time.Duration // Time spent on the storage trie commit
+	CodeReads      time.Duration // Time spent on the contract code read
 
 	AccountLoaded  int // Number of accounts loaded
 	AccountUpdated int // Number of accounts updated
 	AccountDeleted int // Number of accounts deleted
 	StorageLoaded  int // Number of storage slots loaded
 	StorageUpdated int // Number of storage slots updated
 	StorageDeleted int // Number of storage slots deleted
+	CodeLoaded     int // Number of contract code loaded
 
 	Execution       time.Duration // Time spent on the EVM execution
 	Validation      time.Duration // Time spent on the block validation
@@ -61,19 +63,21 @@ type ExecuteStats struct {
 
 // reportMetrics uploads execution statistics to the metrics system.
 func (s *ExecuteStats) reportMetrics() {
-	accountReadTimer.Update(s.AccountReads) // Account reads are complete(in processing)
-	storageReadTimer.Update(s.StorageReads) // Storage reads are complete(in processing)
 	if s.AccountLoaded != 0 {
+		accountReadTimer.Update(s.AccountReads)
 		accountReadSingleTimer.Update(s.AccountReads / time.Duration(s.AccountLoaded))
 	}
 	if s.StorageLoaded != 0 {
+		storageReadTimer.Update(s.StorageReads)
 		storageReadSingleTimer.Update(s.StorageReads / time.Duration(s.StorageLoaded))
 	}
-
+	if s.CodeLoaded != 0 {
+		codeReadTimer.Update(s.CodeReads)
+		codeReadSingleTimer.Update(s.CodeReads / time.Duration(s.CodeLoaded))
+	}
 	accountUpdateTimer.Update(s.AccountUpdates) // Account updates are complete(in validation)
 	storageUpdateTimer.Update(s.StorageUpdates) // Storage updates are complete(in validation)
 	accountHashTimer.Update(s.AccountHashes)    // Account hashes are complete(in validation)
-
 	accountCommitTimer.Update(s.AccountCommits) // Account commits are complete, we can mark them
 	storageCommitTimer.Update(s.StorageCommits) // Storage commits are complete, we can mark them
 
@@ -112,22 +116,44 @@ Block: %v (%#x) txs: %d, mgasps: %.2f, elapsed: %v
 
 EVM execution: %v
 Validation: %v
-Account read: %v(%d)
-Storage read: %v(%d)
-Account hash: %v
-Storage hash: %v
-DB commit: %v
-Block write: %v
+State read: %v
+    Account read: %v(%d)
+    Storage read: %v(%d)
+    Code read: %v(%d)
+
+State hash: %v
+    Account hash: %v
+    Storage hash: %v
+    Trie commit: %v
+
+DB write: %v
+    State write: %v
+    Block write: %v
 
 %s
 ##############################
 `, block.Number(), block.Hash(), len(block.Transactions()), s.MgasPerSecond, common.PrettyDuration(s.TotalTime),
-		common.PrettyDuration(s.Execution), common.PrettyDuration(s.Validation+s.CrossValidation),
+		common.PrettyDuration(s.Execution),
+		common.PrettyDuration(s.Validation+s.CrossValidation),
+
+		// State read
+		common.PrettyDuration(s.AccountReads+s.StorageReads+s.CodeReads),
 		common.PrettyDuration(s.AccountReads), s.AccountLoaded,
 		common.PrettyDuration(s.StorageReads), s.StorageLoaded,
-		common.PrettyDuration(s.AccountHashes+s.AccountCommits+s.AccountUpdates),
-		common.PrettyDuration(s.StorageCommits+s.StorageUpdates),
-		common.PrettyDuration(s.TrieDBCommit+s.SnapshotCommit), common.PrettyDuration(s.BlockWrite),
+		common.PrettyDuration(s.CodeReads), s.CodeLoaded,
+
+		// State hash
+		common.PrettyDuration(s.AccountHashes+s.AccountUpdates+s.StorageUpdates+max(s.AccountCommits, s.StorageCommits)),
+		common.PrettyDuration(s.AccountHashes+s.AccountUpdates),
+		common.PrettyDuration(s.StorageUpdates),
+		common.PrettyDuration(max(s.AccountCommits, s.StorageCommits)),
+
+		// Database commit
+		common.PrettyDuration(s.TrieDBCommit+s.SnapshotCommit+s.BlockWrite),
+		common.PrettyDuration(s.TrieDBCommit+s.SnapshotCommit),
+		common.PrettyDuration(s.BlockWrite),
+
+		// cache statistics
 		s.StateReadCacheStats)
 	for _, line := range strings.Split(msg, "\n") {
 		if line == "" {

core/state/state_object.go

@@ -531,6 +531,11 @@ func (s *stateObject) Code() []byte {
 	if bytes.Equal(s.CodeHash(), types.EmptyCodeHash.Bytes()) {
 		return nil
 	}
+	defer func(start time.Time) {
+		s.db.CodeLoaded += 1
+		s.db.CodeReads += time.Since(start)
+	}(time.Now())
+
 	code, err := s.db.reader.Code(s.address, common.BytesToHash(s.CodeHash()))
 	if err != nil {
 		s.db.setError(fmt.Errorf("can't load code hash %x: %v", s.CodeHash(), err))
@@ -552,6 +557,11 @@ func (s *stateObject) CodeSize() int {
 	if bytes.Equal(s.CodeHash(), types.EmptyCodeHash.Bytes()) {
 		return 0
 	}
+	defer func(start time.Time) {
+		s.db.CodeLoaded += 1
+		s.db.CodeReads += time.Since(start)
+	}(time.Now())
+
 	size, err := s.db.reader.CodeSize(s.address, common.BytesToHash(s.CodeHash()))
 	if err != nil {
 		s.db.setError(fmt.Errorf("can't load code size %x: %v", s.CodeHash(), err))

core/state/statedb.go

@@ -151,13 +151,15 @@ type StateDB struct {
 	StorageCommits  time.Duration
 	SnapshotCommits time.Duration
 	TrieDBCommits   time.Duration
+	CodeReads       time.Duration
 
 	AccountLoaded  int          // Number of accounts retrieved from the database during the state transition
 	AccountUpdated int          // Number of accounts updated during the state transition
 	AccountDeleted int          // Number of accounts deleted during the state transition
 	StorageLoaded  int          // Number of storage slots retrieved from the database during the state transition
 	StorageUpdated atomic.Int64 // Number of storage slots updated during the state transition
 	StorageDeleted atomic.Int64 // Number of storage slots deleted during the state transition
+	CodeLoaded     int          // Number of contract code loaded during the state transition
 }
 
 // New creates a new state from a given trie.