mirror of
https://github.com/ethereum/go-ethereum.git
synced 2026-07-19 11:20:45 +00:00
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
This commit is contained in:
CPerezz
parent
c2595381bf
commit
4fc804b4e1
2 changed files with 363 additions and 62 deletions
|
|
@ -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))
|
||||
}
|
||||
|
|
|
|||
193
core/blockchain_stats_test.go
Normal file
193
core/blockchain_stats_test.go
Normal file
|
|
@ -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 <http://www.gnu.org/licenses/>.
|
||||
|
||||
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())
|
||||
}
|
||||
}
|
||||
Loading…
Reference in a new issue