core: standardize slow block JSON output for cross-client metrics (#33655)

Implement standardized JSON format for slow block logging to enable
cross-client performance analysis and protocol research.

This change is part of the Cross-Client Execution Metrics initiative
proposed by Gary Rong: https://hackmd.io/dg7rizTyTXuCf2LSa2LsyQ

The standardized metrics enabled data-driven analysis like the EIP-7907
research: https://ethresear.ch/t/data-driven-analysis-on-eip-7907/23850

JSON format includes:
- block: number, hash, gas_used, tx_count
- timing: execution_ms, total_ms
- throughput: mgas_per_sec
- state_reads: accounts, storage_slots, bytecodes, code_bytes
- state_writes: accounts, storage_slots, bytecodes
- cache: account/storage/code hits, misses, hit_rate


This should come after merging #33522

---------

Co-authored-by: Gary Rong <garyrong0905@gmail.com>

cmd/utils/flags.go

@@ -692,7 +692,7 @@ var (
 	}
 	LogSlowBlockFlag = &cli.DurationFlag{
 		Name:     "debug.logslowblock",
-		Usage:    "Block execution time threshold beyond which detailed statistics will be logged (0 means disable)",
+		Usage:    "Block execution time threshold beyond which detailed statistics will be logged (0 logs all blocks, negative means disable)",
 		Value:    ethconfig.Defaults.SlowBlockThreshold,
 		Category: flags.LoggingCategory,
 	}
@@ -2351,8 +2351,12 @@ func MakeChain(ctx *cli.Context, stack *node.Node, readonly bool) (*core.BlockCh
 		// Enable state size tracking if enabled
 		StateSizeTracking: ctx.Bool(StateSizeTrackingFlag.Name),
 
-		// Configure the slow block statistic logger
+		// Configure the slow block statistic logger (disabled by default)
-		SlowBlockThreshold: ctx.Duration(LogSlowBlockFlag.Name),
+		SlowBlockThreshold: ethconfig.Defaults.SlowBlockThreshold,
+	}
+	// Only enable slow block logging if the flag was explicitly set
+	if ctx.IsSet(LogSlowBlockFlag.Name) {
+		options.SlowBlockThreshold = ctx.Duration(LogSlowBlockFlag.Name)
 	}
 	if options.ArchiveMode && !options.Preimages {
 		options.Preimages = true

core/blockchain.go

@@ -214,7 +214,8 @@ type BlockChainConfig struct {
 	StateSizeTracking bool
 
 	// SlowBlockThreshold is the block execution time threshold beyond which
-	// detailed statistics will be logged.
+	// detailed statistics will be logged. Negative value means disabled (default),
+	// zero logs all blocks, positive value filters blocks by execution time.
 	SlowBlockThreshold time.Duration
 }
 
@@ -2106,24 +2107,11 @@ func (bc *BlockChain) ProcessBlock(parentRoot common.Hash, block *types.Block, s
 		}
 		// Upload the statistics of reader at the end
 		defer func() {
-			pStat := prefetch.GetStats()
-			accountCacheHitPrefetchMeter.Mark(pStat.AccountCacheHit)
-			accountCacheMissPrefetchMeter.Mark(pStat.AccountCacheMiss)
-			storageCacheHitPrefetchMeter.Mark(pStat.StorageCacheHit)
-			storageCacheMissPrefetchMeter.Mark(pStat.StorageCacheMiss)
-
-			rStat := process.GetStats()
-			accountCacheHitMeter.Mark(rStat.AccountCacheHit)
-			accountCacheMissMeter.Mark(rStat.AccountCacheMiss)
-			storageCacheHitMeter.Mark(rStat.StorageCacheHit)
-			storageCacheMissMeter.Mark(rStat.StorageCacheMiss)
-
 			if result != nil {
-				result.stats.StatePrefetchCacheStats = pStat
+				result.stats.StatePrefetchCacheStats = prefetch.GetStats()
-				result.stats.StateReadCacheStats = rStat
+				result.stats.StateReadCacheStats = process.GetStats()
 			}
 		}()
-
 		go func(start time.Time, throwaway *state.StateDB, block *types.Block) {
 			// Disable tracing for prefetcher executions.
 			vmCfg := bc.cfg.VmConfig
@@ -2238,8 +2226,11 @@ func (bc *BlockChain) ProcessBlock(parentRoot common.Hash, block *types.Block, s
 	stats.StorageLoaded = statedb.StorageLoaded
 	stats.StorageUpdated = int(statedb.StorageUpdated.Load())
 	stats.StorageDeleted = int(statedb.StorageDeleted.Load())
+
 	stats.CodeLoaded = statedb.CodeLoaded
 	stats.CodeLoadBytes = statedb.CodeLoadBytes
+	stats.CodeUpdated = statedb.CodeUpdated
+	stats.CodeUpdateBytes = statedb.CodeUpdateBytes
 
 	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

core/blockchain_stats.go

@@ -17,8 +17,7 @@
 package core
 
 import (
-	"fmt"
+	"encoding/json"
-	"strings"
 	"time"
 
 	"github.com/ethereum/go-ethereum/common"
@@ -39,14 +38,16 @@ type ExecuteStats struct {
 	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
+	AccountLoaded   int // Number of accounts loaded
-	AccountUpdated int // Number of accounts updated
+	AccountUpdated  int // Number of accounts updated
-	AccountDeleted int // Number of accounts deleted
+	AccountDeleted  int // Number of accounts deleted
-	StorageLoaded  int // Number of storage slots loaded
+	StorageLoaded   int // Number of storage slots loaded
-	StorageUpdated int // Number of storage slots updated
+	StorageUpdated  int // Number of storage slots updated
-	StorageDeleted int // Number of storage slots deleted
+	StorageDeleted  int // Number of storage slots deleted
-	CodeLoaded     int // Number of contract code loaded
+	CodeLoaded      int // Number of contract code loaded
-	CodeLoadBytes  int // Number of bytes read from contract code
+	CodeLoadBytes   int // Number of bytes read from contract code
+	CodeUpdated     int // Number of contract code written (CREATE/CREATE2 + EIP-7702)
+	CodeUpdateBytes int // Total bytes of code written
 
 	Execution       time.Duration // Time spent on the EVM execution
 	Validation      time.Duration // Time spent on the block validation
@@ -104,64 +105,161 @@ func (s *ExecuteStats) reportMetrics() {
 	storageCacheMissMeter.Mark(s.StateReadCacheStats.StorageCacheMiss)
 }
 
-// logSlow prints the detailed execution statistics if the block is regarded as slow.
+// slowBlockLog represents the JSON structure for slow block logging.
-func (s *ExecuteStats) logSlow(block *types.Block, slowBlockThreshold time.Duration) {
+// This format is designed for cross-client compatibility with other
-	if slowBlockThreshold == 0 {
+// Ethereum execution clients (reth, Besu, Nethermind).
-		return
+type slowBlockLog struct {
-	}
+	Level       string          `json:"level"`
-	if s.TotalTime < slowBlockThreshold {
+	Msg         string          `json:"msg"`
-		return
+	Block       slowBlockInfo   `json:"block"`
-	}
+	Timing      slowBlockTime   `json:"timing"`
-	msg := fmt.Sprintf(`
+	Throughput  slowBlockThru   `json:"throughput"`
-########## SLOW BLOCK #########
+	StateReads  slowBlockReads  `json:"state_reads"`
-Block: %v (%#x) txs: %d, mgasps: %.2f, elapsed: %v
+	StateWrites slowBlockWrites `json:"state_writes"`
-
+	Cache       slowBlockCache  `json:"cache"`
-EVM execution: %v
+}
-
+
-Validation: %v
+type slowBlockInfo struct {
-    Account hash: %v
+	Number  uint64      `json:"number"`
-    Storage hash: %v
+	Hash    common.Hash `json:"hash"`
-
+	GasUsed uint64      `json:"gas_used"`
-State read: %v
+	TxCount int         `json:"tx_count"`
-    Account read: %v(%d)
+}
-    Storage read: %v(%d)
+
-    Code read: %v(%d %v)
+type slowBlockTime struct {
-
+	ExecutionMs float64 `json:"execution_ms"`
-State write: %v
+	StateReadMs float64 `json:"state_read_ms"`
-    Trie commit: %v
+	StateHashMs float64 `json:"state_hash_ms"`
-    State write: %v
+	CommitMs    float64 `json:"commit_ms"`
-    Block write: %v
+	TotalMs     float64 `json:"total_ms"`
-
+}
-%s
+
-##############################
+type slowBlockThru struct {
-`, block.Number(), block.Hash(), len(block.Transactions()), s.MgasPerSecond, common.PrettyDuration(s.TotalTime),
+	MgasPerSec float64 `json:"mgas_per_sec"`
-		// EVM execution
+}
-		common.PrettyDuration(s.Execution),
+
-
+type slowBlockReads struct {
-		// Block validation
+	Accounts     int `json:"accounts"`
-		common.PrettyDuration(s.Validation+s.CrossValidation+s.AccountHashes+s.AccountUpdates+s.StorageUpdates),
+	StorageSlots int `json:"storage_slots"`
-		common.PrettyDuration(s.AccountHashes+s.AccountUpdates),
+	Code         int `json:"code"`
-		common.PrettyDuration(s.StorageUpdates),
+	CodeBytes    int `json:"code_bytes"`
-
+}
-		// State read
+
-		common.PrettyDuration(s.AccountReads+s.StorageReads+s.CodeReads),
+type slowBlockWrites struct {
-		common.PrettyDuration(s.AccountReads), s.AccountLoaded,
+	Accounts            int `json:"accounts"`
-		common.PrettyDuration(s.StorageReads), s.StorageLoaded,
+	AccountsDeleted     int `json:"accounts_deleted"`
-		common.PrettyDuration(s.CodeReads), s.CodeLoaded, common.StorageSize(s.CodeLoadBytes),
+	StorageSlots        int `json:"storage_slots"`
-
+	StorageSlotsDeleted int `json:"storage_slots_deleted"`
-		// State write
+	Code                int `json:"code"`
-		common.PrettyDuration(max(s.AccountCommits, s.StorageCommits)+s.TrieDBCommit+s.SnapshotCommit+s.BlockWrite),
+	CodeBytes           int `json:"code_bytes"`
-		common.PrettyDuration(max(s.AccountCommits, s.StorageCommits)),
+}
-		common.PrettyDuration(s.TrieDBCommit+s.SnapshotCommit),
+
-		common.PrettyDuration(s.BlockWrite),
+// slowBlockCache represents cache hit/miss statistics for cross-client analysis.
-
+type slowBlockCache struct {
-		// cache statistics
+	Account slowBlockCacheEntry     `json:"account"`
-		s.StateReadCacheStats,
+	Storage slowBlockCacheEntry     `json:"storage"`
-	)
+	Code    slowBlockCodeCacheEntry `json:"code"`
-	for _, line := range strings.Split(msg, "\n") {
+}
-		if line == "" {
+
-			continue
+// slowBlockCacheEntry represents cache statistics for account/storage caches.
-		}
+type slowBlockCacheEntry struct {
-		log.Info(line)
+	Hits    int64   `json:"hits"`
-	}
+	Misses  int64   `json:"misses"`
+	HitRate float64 `json:"hit_rate"`
+}
+
+// slowBlockCodeCacheEntry represents cache statistics for code cache with byte-level granularity.
+type slowBlockCodeCacheEntry struct {
+	Hits      int64   `json:"hits"`
+	Misses    int64   `json:"misses"`
+	HitRate   float64 `json:"hit_rate"`
+	HitBytes  int64   `json:"hit_bytes"`
+	MissBytes int64   `json:"miss_bytes"`
+}
+
+// calculateHitRate computes the cache hit rate as a percentage (0-100).
+func calculateHitRate(hits, misses int64) float64 {
+	if total := hits + misses; total > 0 {
+		return float64(hits) / float64(total) * 100.0
+	}
+	return 0.0
+}
+
+// durationToMs converts a time.Duration to milliseconds as a float64
+// with sub-millisecond precision for accurate cross-client metrics.
+func durationToMs(d time.Duration) float64 {
+	return float64(d.Nanoseconds()) / 1e6
+}
+
+// logSlow prints the detailed execution statistics in JSON format if the block
+// is regarded as slow. The JSON format is designed for cross-client compatibility
+// with other Ethereum execution clients.
+func (s *ExecuteStats) logSlow(block *types.Block, slowBlockThreshold time.Duration) {
+	// Negative threshold means disabled (default when flag not set)
+	if slowBlockThreshold < 0 {
+		return
+	}
+	// Threshold of 0 logs all blocks; positive threshold filters
+	if slowBlockThreshold > 0 && s.TotalTime < slowBlockThreshold {
+		return
+	}
+	logEntry := slowBlockLog{
+		Level: "warn",
+		Msg:   "Slow block",
+		Block: slowBlockInfo{
+			Number:  block.NumberU64(),
+			Hash:    block.Hash(),
+			GasUsed: block.GasUsed(),
+			TxCount: len(block.Transactions()),
+		},
+		Timing: slowBlockTime{
+			ExecutionMs: durationToMs(s.Execution),
+			StateReadMs: durationToMs(s.AccountReads + s.StorageReads + s.CodeReads),
+			StateHashMs: durationToMs(s.AccountHashes + s.AccountUpdates + s.StorageUpdates),
+			CommitMs:    durationToMs(max(s.AccountCommits, s.StorageCommits) + s.TrieDBCommit + s.SnapshotCommit + s.BlockWrite),
+			TotalMs:     durationToMs(s.TotalTime),
+		},
+		Throughput: slowBlockThru{
+			MgasPerSec: s.MgasPerSecond,
+		},
+		StateReads: slowBlockReads{
+			Accounts:     s.AccountLoaded,
+			StorageSlots: s.StorageLoaded,
+			Code:         s.CodeLoaded,
+			CodeBytes:    s.CodeLoadBytes,
+		},
+		StateWrites: slowBlockWrites{
+			Accounts:            s.AccountUpdated,
+			AccountsDeleted:     s.AccountDeleted,
+			StorageSlots:        s.StorageUpdated,
+			StorageSlotsDeleted: s.StorageDeleted,
+			Code:                s.CodeUpdated,
+			CodeBytes:           s.CodeUpdateBytes,
+		},
+		Cache: slowBlockCache{
+			Account: slowBlockCacheEntry{
+				Hits:    s.StateReadCacheStats.AccountCacheHit,
+				Misses:  s.StateReadCacheStats.AccountCacheMiss,
+				HitRate: calculateHitRate(s.StateReadCacheStats.AccountCacheHit, s.StateReadCacheStats.AccountCacheMiss),
+			},
+			Storage: slowBlockCacheEntry{
+				Hits:    s.StateReadCacheStats.StorageCacheHit,
+				Misses:  s.StateReadCacheStats.StorageCacheMiss,
+				HitRate: calculateHitRate(s.StateReadCacheStats.StorageCacheHit, s.StateReadCacheStats.StorageCacheMiss),
+			},
+			Code: slowBlockCodeCacheEntry{
+				Hits:      s.StateReadCacheStats.CodeStats.CacheHit,
+				Misses:    s.StateReadCacheStats.CodeStats.CacheMiss,
+				HitRate:   calculateHitRate(s.StateReadCacheStats.CodeStats.CacheHit, s.StateReadCacheStats.CodeStats.CacheMiss),
+				HitBytes:  s.StateReadCacheStats.CodeStats.CacheHitBytes,
+				MissBytes: s.StateReadCacheStats.CodeStats.CacheMissBytes,
+			},
+		},
+	}
+	jsonBytes, err := json.Marshal(logEntry)
+	if err != nil {
+		log.Error("Failed to marshal slow block log", "error", err)
+		return
+	}
+	log.Warn(string(jsonBytes))
 }

core/state/statedb.go

@@ -158,13 +158,15 @@ type StateDB struct {
 	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
 
 	// CodeLoadBytes is the total number of bytes read from contract code.
 	// This value may be smaller than the actual number of bytes read, since
 	// some APIs (e.g. CodeSize) may load the entire code from either the
 	// cache or the database when the size is not available in the cache.
-	CodeLoadBytes int
+	CodeLoaded      int // Number of contract code loaded during the state transition
+	CodeLoadBytes   int // Total bytes of resolved code
+	CodeUpdated     int // Number of contracts with code changes that persisted
+	CodeUpdateBytes int // Total bytes of persisted code written
 }
 
 // New creates a new state from a given trie.
@@ -941,8 +943,15 @@ func (s *StateDB) IntermediateRoot(deleteEmptyObjects bool) common.Hash {
 		if op.isDelete() {
 			deletedAddrs = append(deletedAddrs, addr)
 		} else {
-			s.updateStateObject(s.stateObjects[addr])
+			obj := s.stateObjects[addr]
+			s.updateStateObject(obj)
 			s.AccountUpdated += 1
+
+			// Count code writes post-Finalise so reverted CREATEs are excluded.
+			if obj.dirtyCode {
+				s.CodeUpdated += 1
+				s.CodeUpdateBytes += len(obj.code)
+			}
 		}
 		usedAddrs = append(usedAddrs, addr) // Copy needed for closure
 	}

eth/ethconfig/config.go

@@ -75,7 +75,7 @@ var Defaults = Config{
 	RPCTxFeeCap:             1, // 1 ether
 	TxSyncDefaultTimeout:    20 * time.Second,
 	TxSyncMaxTimeout:        1 * time.Minute,
-	SlowBlockThreshold:      time.Second * 2,
+	SlowBlockThreshold:      -1, // Disabled by default; set via --debug.logslowblock flag
 	RangeLimit:              0,
 }
 
@@ -130,8 +130,9 @@ type Config struct {
 	// presence of these blocks for every new peer connection.
 	RequiredBlocks map[uint64]common.Hash `toml:"-"`
 
-	// SlowBlockThreshold is the block execution speed threshold (Mgas/s)
+	// SlowBlockThreshold is the block execution time threshold beyond which
-	// below which detailed statistics are logged.
+	// detailed statistics are logged. Negative means disabled (default), zero
+	// logs all blocks, positive filters by execution time.
 	SlowBlockThreshold time.Duration `toml:",omitempty"`
 
 	// Database options