diff --git a/cmd/utils/flags.go b/cmd/utils/flags.go index 844397b734..91448c520c 100644 --- a/cmd/utils/flags.go +++ b/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 - SlowBlockThreshold: ctx.Duration(LogSlowBlockFlag.Name), + // Configure the slow block statistic logger (disabled by default) + 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 diff --git a/core/blockchain.go b/core/blockchain.go index db3f71c44d..6f1db96463 100644 --- a/core/blockchain.go +++ b/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.StateReadCacheStats = rStat + result.stats.StatePrefetchCacheStats = prefetch.GetStats() + 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 diff --git a/core/blockchain_stats.go b/core/blockchain_stats.go index e8c5860294..adc66266c4 100644 --- a/core/blockchain_stats.go +++ b/core/blockchain_stats.go @@ -17,8 +17,7 @@ package core import ( - "fmt" - "strings" + "encoding/json" "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 - 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 - CodeLoadBytes int // Number of bytes read from contract code + 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 + 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. -func (s *ExecuteStats) logSlow(block *types.Block, slowBlockThreshold time.Duration) { - if slowBlockThreshold == 0 { - return - } - if s.TotalTime < slowBlockThreshold { - return - } - msg := fmt.Sprintf(` -########## SLOW BLOCK ######### -Block: %v (%#x) txs: %d, mgasps: %.2f, elapsed: %v - -EVM execution: %v - -Validation: %v - Account hash: %v - Storage hash: %v - -State read: %v - Account read: %v(%d) - Storage read: %v(%d) - Code read: %v(%d %v) - -State write: %v - Trie commit: %v - State write: %v - Block write: %v - -%s -############################## -`, block.Number(), block.Hash(), len(block.Transactions()), s.MgasPerSecond, common.PrettyDuration(s.TotalTime), - // EVM execution - common.PrettyDuration(s.Execution), - - // Block validation - common.PrettyDuration(s.Validation+s.CrossValidation+s.AccountHashes+s.AccountUpdates+s.StorageUpdates), - common.PrettyDuration(s.AccountHashes+s.AccountUpdates), - common.PrettyDuration(s.StorageUpdates), - - // 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.CodeReads), s.CodeLoaded, common.StorageSize(s.CodeLoadBytes), - - // State write - common.PrettyDuration(max(s.AccountCommits, s.StorageCommits)+s.TrieDBCommit+s.SnapshotCommit+s.BlockWrite), - common.PrettyDuration(max(s.AccountCommits, s.StorageCommits)), - common.PrettyDuration(s.TrieDBCommit+s.SnapshotCommit), - common.PrettyDuration(s.BlockWrite), - - // cache statistics - s.StateReadCacheStats, - ) - for _, line := range strings.Split(msg, "\n") { - if line == "" { - continue - } - log.Info(line) - } +// slowBlockLog represents the JSON structure for slow block logging. +// This format is designed for cross-client compatibility with other +// Ethereum execution clients (reth, Besu, Nethermind). +type slowBlockLog struct { + Level string `json:"level"` + Msg string `json:"msg"` + Block slowBlockInfo `json:"block"` + Timing slowBlockTime `json:"timing"` + Throughput slowBlockThru `json:"throughput"` + StateReads slowBlockReads `json:"state_reads"` + StateWrites slowBlockWrites `json:"state_writes"` + Cache slowBlockCache `json:"cache"` +} + +type slowBlockInfo struct { + Number uint64 `json:"number"` + Hash common.Hash `json:"hash"` + GasUsed uint64 `json:"gas_used"` + TxCount int `json:"tx_count"` +} + +type slowBlockTime struct { + ExecutionMs float64 `json:"execution_ms"` + StateReadMs float64 `json:"state_read_ms"` + StateHashMs float64 `json:"state_hash_ms"` + CommitMs float64 `json:"commit_ms"` + TotalMs float64 `json:"total_ms"` +} + +type slowBlockThru struct { + MgasPerSec float64 `json:"mgas_per_sec"` +} + +type slowBlockReads struct { + Accounts int `json:"accounts"` + StorageSlots int `json:"storage_slots"` + Code int `json:"code"` + CodeBytes int `json:"code_bytes"` +} + +type slowBlockWrites struct { + Accounts int `json:"accounts"` + AccountsDeleted int `json:"accounts_deleted"` + StorageSlots int `json:"storage_slots"` + StorageSlotsDeleted int `json:"storage_slots_deleted"` + Code int `json:"code"` + CodeBytes int `json:"code_bytes"` +} + +// slowBlockCache represents cache hit/miss statistics for cross-client analysis. +type slowBlockCache struct { + Account slowBlockCacheEntry `json:"account"` + Storage slowBlockCacheEntry `json:"storage"` + Code slowBlockCodeCacheEntry `json:"code"` +} + +// slowBlockCacheEntry represents cache statistics for account/storage caches. +type slowBlockCacheEntry struct { + 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)) } diff --git a/core/state/statedb.go b/core/state/statedb.go index 610e7173cf..3d329bab64 100644 --- a/core/state/statedb.go +++ b/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 } diff --git a/eth/ethconfig/config.go b/eth/ethconfig/config.go index e58c4b884a..8aa6e4ef09 100644 --- a/eth/ethconfig/config.go +++ b/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) - // below which detailed statistics are logged. + // SlowBlockThreshold is the block execution time threshold beyond which + // detailed statistics are logged. Negative means disabled (default), zero + // logs all blocks, positive filters by execution time. SlowBlockThreshold time.Duration `toml:",omitempty"` // Database options