From 4fc804b4e1623dba3a7b7cc70f59d7434f08a7ce Mon Sep 17 00:00:00 2001 From: CPerezz Date: Wed, 21 Jan 2026 10:30:27 +0100 Subject: [PATCH] core: standardize slow block JSON output for cross-client metrics 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 --- core/blockchain_stats.go | 232 +++++++++++++++++++++++++--------- core/blockchain_stats_test.go | 193 ++++++++++++++++++++++++++++ 2 files changed, 363 insertions(+), 62 deletions(-) create mode 100644 core/blockchain_stats_test.go diff --git a/core/blockchain_stats.go b/core/blockchain_stats.go index e8c5860294..5bd2e5bd1e 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" @@ -47,6 +46,12 @@ type ExecuteStats struct { 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) + CodeBytesWrite int // Total bytes of code written + + // EIP-7702 delegation tracking + Eip7702DelegationsSet int // Number of EIP-7702 delegations set + Eip7702DelegationsCleared int // Number of EIP-7702 delegations cleared Execution time.Duration // Time spent on the EVM execution Validation time.Duration // Time spent on the block validation @@ -104,64 +109,167 @@ 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"` + Eip7702DelegationsSet int `json:"eip7702_delegations_set"` + Eip7702DelegationsCleared int `json:"eip7702_delegations_cleared"` +} + +// 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.CodeBytesWrite, + Eip7702DelegationsSet: s.Eip7702DelegationsSet, + Eip7702DelegationsCleared: s.Eip7702DelegationsCleared, + }, + 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/blockchain_stats_test.go b/core/blockchain_stats_test.go new file mode 100644 index 0000000000..c6928e98e5 --- /dev/null +++ b/core/blockchain_stats_test.go @@ -0,0 +1,193 @@ +// Copyright 2025 The go-ethereum Authors +// This file is part of the go-ethereum library. +// +// The go-ethereum library is free software: you can redistribute it and/or modify +// it under the terms of the GNU Lesser General Public License as published by +// the Free Software Foundation, either version 3 of the License, or +// (at your option) any later version. +// +// The go-ethereum library is distributed in the hope that it will be useful, +// but WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +// GNU Lesser General Public License for more details. +// +// You should have received a copy of the GNU Lesser General Public License +// along with the go-ethereum library. If not, see . + +package core + +import ( + "bytes" + "encoding/json" + "testing" + "time" + + "github.com/ethereum/go-ethereum/common" + "github.com/ethereum/go-ethereum/core/state" + "github.com/ethereum/go-ethereum/core/types" + "github.com/ethereum/go-ethereum/log" +) + +// TestLogSlowBlockJSON tests that logSlow outputs valid JSON in the expected format. +func TestLogSlowBlockJSON(t *testing.T) { + // Create a buffer to capture log output + var buf bytes.Buffer + handler := log.NewTerminalHandler(&buf, false) + log.SetDefault(log.NewLogger(handler)) + + // Create a test block + header := &types.Header{ + Number: common.Big1, + GasUsed: 21000000, + GasLimit: 30000000, + } + block := types.NewBlockWithHeader(header) + + // Create test stats with cache data + stats := &ExecuteStats{ + Execution: 500 * time.Millisecond, + TotalTime: 1200 * time.Millisecond, // > 1s threshold + MgasPerSecond: 17.5, + AccountLoaded: 100, + StorageLoaded: 500, + CodeLoaded: 20, + AccountUpdated: 50, + StorageUpdated: 200, + StateReadCacheStats: state.ReaderStats{ + AccountCacheHit: 4, + AccountCacheMiss: 6, + StorageCacheHit: 0, + StorageCacheMiss: 11, + ContractCodeHit: 4, + ContractCodeMiss: 0, + }, + } + + // Log the slow block (threshold of 1s, so 1.2s total time should trigger) + stats.logSlow(block, 1*time.Second) + + // Get the log output + output := buf.String() + t.Logf("Log output:\n%s", output) + + // The output should contain the JSON + if len(output) == 0 { + t.Fatal("Expected log output, got empty string") + } + + // Try to extract and parse the JSON from the log line + // The log format is: WARN [...] {"level":"warn",...} + // We need to find the JSON part + jsonStart := bytes.Index(buf.Bytes(), []byte(`{"level"`)) + if jsonStart == -1 { + t.Logf("Full output: %s", output) + t.Fatal("Could not find JSON in log output") + } + + jsonBytes := buf.Bytes()[jsonStart:] + // Find the end of the JSON (newline or end of buffer) + jsonEnd := bytes.IndexByte(jsonBytes, '\n') + if jsonEnd != -1 { + jsonBytes = jsonBytes[:jsonEnd] + } + + // Parse the JSON + var logEntry slowBlockLog + if err := json.Unmarshal(jsonBytes, &logEntry); err != nil { + t.Fatalf("Failed to parse JSON: %v\nJSON: %s", err, string(jsonBytes)) + } + + // Verify the fields + if logEntry.Level != "warn" { + t.Errorf("Expected level 'warn', got '%s'", logEntry.Level) + } + if logEntry.Msg != "Slow block" { + t.Errorf("Expected msg 'Slow block', got '%s'", logEntry.Msg) + } + if logEntry.Block.Number != 1 { + t.Errorf("Expected block number 1, got %d", logEntry.Block.Number) + } + if logEntry.Block.GasUsed != 21000000 { + t.Errorf("Expected gas used 21000000, got %d", logEntry.Block.GasUsed) + } + if logEntry.Timing.ExecutionMs != 500 { + t.Errorf("Expected execution_ms 500, got %d", logEntry.Timing.ExecutionMs) + } + if logEntry.Timing.TotalMs != 1200 { + t.Errorf("Expected total_ms 1200, got %d", logEntry.Timing.TotalMs) + } + if logEntry.StateReads.Accounts != 100 { + t.Errorf("Expected accounts 100, got %d", logEntry.StateReads.Accounts) + } + if logEntry.StateReads.StorageSlots != 500 { + t.Errorf("Expected storage_slots 500, got %d", logEntry.StateReads.StorageSlots) + } + if logEntry.StateWrites.Accounts != 50 { + t.Errorf("Expected accounts updated 50, got %d", logEntry.StateWrites.Accounts) + } + + // Verify cache statistics + if logEntry.Cache.Account.Hits != 4 { + t.Errorf("Expected account cache hits 4, got %d", logEntry.Cache.Account.Hits) + } + if logEntry.Cache.Account.Misses != 6 { + t.Errorf("Expected account cache misses 6, got %d", logEntry.Cache.Account.Misses) + } + // 4/(4+6) = 0.4 = 40% + if logEntry.Cache.Account.HitRate != 40.0 { + t.Errorf("Expected account cache hit_rate 40.0, got %f", logEntry.Cache.Account.HitRate) + } + if logEntry.Cache.Storage.Hits != 0 { + t.Errorf("Expected storage cache hits 0, got %d", logEntry.Cache.Storage.Hits) + } + if logEntry.Cache.Storage.Misses != 11 { + t.Errorf("Expected storage cache misses 11, got %d", logEntry.Cache.Storage.Misses) + } + // 0/(0+11) = 0% + if logEntry.Cache.Storage.HitRate != 0.0 { + t.Errorf("Expected storage cache hit_rate 0.0, got %f", logEntry.Cache.Storage.HitRate) + } + if logEntry.Cache.Code.Hits != 4 { + t.Errorf("Expected code cache hits 4, got %d", logEntry.Cache.Code.Hits) + } + if logEntry.Cache.Code.Misses != 0 { + t.Errorf("Expected code cache misses 0, got %d", logEntry.Cache.Code.Misses) + } + // 4/(4+0) = 100% + if logEntry.Cache.Code.HitRate != 100.0 { + t.Errorf("Expected code cache hit_rate 100.0, got %f", logEntry.Cache.Code.HitRate) + } + + t.Logf("Parsed JSON:\n%+v", logEntry) +} + +// TestLogSlowBlockThreshold tests that logSlow respects the threshold. +func TestLogSlowBlockThreshold(t *testing.T) { + var buf bytes.Buffer + handler := log.NewTerminalHandler(&buf, false) + log.SetDefault(log.NewLogger(handler)) + + header := &types.Header{Number: common.Big1} + block := types.NewBlockWithHeader(header) + + stats := &ExecuteStats{ + TotalTime: 500 * time.Millisecond, // 0.5s, below 1s threshold + } + + // Should NOT log (below threshold) + stats.logSlow(block, 1*time.Second) + + if buf.Len() > 0 { + t.Errorf("Expected no output for fast block, got: %s", buf.String()) + } + + // Reset buffer + buf.Reset() + + // Test with zero threshold (disabled) + stats.logSlow(block, 0) + + if buf.Len() > 0 { + t.Errorf("Expected no output for zero threshold, got: %s", buf.String()) + } +}