From 4278dab1457e9599f6dd32d1cf57506343419759 Mon Sep 17 00:00:00 2001 From: Sina Mahmoodi Date: Fri, 25 Apr 2025 11:28:45 +0200 Subject: [PATCH 1/7] eth/tracers: add perf tracking live tracer --- eth/tracers/live/perf.go | 166 +++++++++++++++++++++++++++++++++++++++ 1 file changed, 166 insertions(+) create mode 100644 eth/tracers/live/perf.go diff --git a/eth/tracers/live/perf.go b/eth/tracers/live/perf.go new file mode 100644 index 000000000000..19072d944822 --- /dev/null +++ b/eth/tracers/live/perf.go @@ -0,0 +1,166 @@ +// Copyright 2025 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 live + +import ( + "encoding/csv" + "encoding/json" + "errors" + "fmt" + "os" + "time" + + "github.com/ethereum/go-ethereum/common" + "github.com/ethereum/go-ethereum/core/tracing" + "github.com/ethereum/go-ethereum/core/types" + "github.com/ethereum/go-ethereum/eth/tracers" +) + +func init() { + tracers.LiveDirectory.Register("perfTracer", newPerfTracer) +} + +type perfTracerConfig struct { + CSVPath string `json:"csvPath"` +} + +// perfTracer is a live tracer that measures and records transaction processing performance metrics. +// It tracks total processing time, IO time (account and storage reads), and EVM execution time for +// each transaction. The metrics are written to a CSV file. +type perfTracer struct { + csvPath string + writer *csv.Writer + file *os.File + + // Block context + currentBlock *types.Block + currentBlockHash common.Hash + + // Transaction tracking + txStartTime time.Time + txIndex int + + // IO measurements + prevAccountReads time.Duration + prevStorageReads time.Duration + + statedb tracing.StateDB +} + +func newPerfTracer(cfg json.RawMessage) (*tracing.Hooks, error) { + var config perfTracerConfig + if err := json.Unmarshal(cfg, &config); err != nil { + return nil, fmt.Errorf("failed to parse config: %v", err) + } + if config.CSVPath == "" { + return nil, errors.New("csv path is required") + } + + // Open CSV file + file, err := os.OpenFile(config.CSVPath, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644) + if err != nil { + return nil, fmt.Errorf("failed to open CSV file: %v", err) + } + writer := csv.NewWriter(file) + + // Write header if file is empty + info, err := file.Stat() + if err != nil { + file.Close() + return nil, fmt.Errorf("failed to get file info: %v", err) + } + if info.Size() == 0 { + header := []string{"block_number", "block_hash", "tx_index", "tx_hash", "total_time_ns", "io_time_ns", "evm_time_ns", "gas_used"} + if err := writer.Write(header); err != nil { + file.Close() + return nil, fmt.Errorf("failed to write CSV header: %v", err) + } + writer.Flush() + } + + t := &perfTracer{ + csvPath: config.CSVPath, + writer: writer, + file: file, + } + + return &tracing.Hooks{ + OnBlockStart: t.OnBlockStart, + OnTxStart: t.OnTxStart, + OnTxEnd: t.OnTxEnd, + OnBlockEnd: t.OnBlockEnd, + OnClose: t.OnClose, + }, nil +} + +func (t *perfTracer) OnBlockStart(event tracing.BlockEvent) { + t.currentBlock = event.Block + t.currentBlockHash = event.Block.Hash() + t.txIndex = 0 + // Reset previous IO measurements for the new block + t.prevAccountReads = 0 + t.prevStorageReads = 0 +} + +func (t *perfTracer) OnTxStart(vm *tracing.VMContext, tx *types.Transaction, from common.Address) { + t.txStartTime = time.Now() + t.statedb = vm.StateDB +} + +func (t *perfTracer) OnTxEnd(receipt *types.Receipt, err error) { + var ( + totalTime = time.Since(t.txStartTime) + accumulatedIO = t.statedb.GetAccumulatedIOMeasurements() + ioTime = (accumulatedIO.AccountReads - t.prevAccountReads) + + (accumulatedIO.StorageReads - t.prevStorageReads) + evmTime = totalTime - ioTime + ) + + row := []string{ + t.currentBlock.Number().String(), + t.currentBlockHash.Hex(), + fmt.Sprintf("%d", t.txIndex), + receipt.TxHash.Hex(), + fmt.Sprintf("%d", totalTime.Nanoseconds()), + fmt.Sprintf("%d", ioTime.Nanoseconds()), + fmt.Sprintf("%d", evmTime.Nanoseconds()), + fmt.Sprintf("%d", receipt.GasUsed), + } + if err := t.writer.Write(row); err != nil { + fmt.Printf("Failed to write CSV row: %v\n", err) + } + + t.prevAccountReads = accumulatedIO.AccountReads + t.prevStorageReads = accumulatedIO.StorageReads + t.txIndex++ +} + +// OnBlockEnd implements tracing.BlockEndHook +func (t *perfTracer) OnBlockEnd(err error) { + if t.writer != nil { + t.writer.Flush() + } +} + +func (t *perfTracer) OnClose() { + if t.writer != nil { + t.writer.Flush() + } + if t.file != nil { + t.file.Close() + } +} From 0fc0b407f72987ef03cc43763a254d038f05bf8b Mon Sep 17 00:00:00 2001 From: Sina Mahmoodi Date: Fri, 25 Apr 2025 11:29:45 +0200 Subject: [PATCH 2/7] Expose IO measurements from statedb --- core/state/statedb.go | 14 ++++++++++++++ core/state/statedb_hooked.go | 4 ++++ core/tracing/hooks.go | 16 ++++++++++++++++ core/vm/interface.go | 4 ++++ 4 files changed, 38 insertions(+) diff --git a/core/state/statedb.go b/core/state/statedb.go index e3f5b9e1a0a8..ac04c87fb802 100644 --- a/core/state/statedb.go +++ b/core/state/statedb.go @@ -1434,3 +1434,17 @@ func (s *StateDB) Witness() *stateless.Witness { func (s *StateDB) AccessEvents() *AccessEvents { return s.accessEvents } + +func (s *StateDB) GetAccumulatedIOMeasurements() *tracing.IOMeasurements { + return &tracing.IOMeasurements{ + AccountReads: s.AccountReads, + AccountHashes: s.AccountHashes, + AccountUpdates: s.AccountUpdates, + AccountCommits: s.AccountCommits, + StorageReads: s.StorageReads, + StorageUpdates: s.StorageUpdates, + StorageCommits: s.StorageCommits, + SnapshotCommits: s.SnapshotCommits, + TrieDBCommits: s.TrieDBCommits, + } +} diff --git a/core/state/statedb_hooked.go b/core/state/statedb_hooked.go index a2fdfe9a217a..feaa51dd2c2b 100644 --- a/core/state/statedb_hooked.go +++ b/core/state/statedb_hooked.go @@ -276,3 +276,7 @@ func (s *hookedStateDB) Finalise(deleteEmptyObjects bool) { } } } + +func (s *hookedStateDB) GetAccumulatedIOMeasurements() *tracing.IOMeasurements { + return s.inner.GetAccumulatedIOMeasurements() +} diff --git a/core/tracing/hooks.go b/core/tracing/hooks.go index 0485f7a3eb29..f550b3f807e0 100644 --- a/core/tracing/hooks.go +++ b/core/tracing/hooks.go @@ -26,6 +26,7 @@ package tracing import ( "math/big" + "time" "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/core/types" @@ -55,6 +56,21 @@ type StateDB interface { GetTransientState(common.Address, common.Hash) common.Hash Exist(common.Address) bool GetRefund() uint64 + GetAccumulatedIOMeasurements() *IOMeasurements +} + +// IOMeasurements is a struct that contains the measurements of +// the I/O operations performed by the statedb. +type IOMeasurements struct { + AccountReads time.Duration + AccountHashes time.Duration + AccountUpdates time.Duration + AccountCommits time.Duration + StorageReads time.Duration + StorageUpdates time.Duration + StorageCommits time.Duration + SnapshotCommits time.Duration + TrieDBCommits time.Duration } // VMContext provides the context for the EVM execution. diff --git a/core/vm/interface.go b/core/vm/interface.go index 57f35cb2492d..2451f8e29e30 100644 --- a/core/vm/interface.go +++ b/core/vm/interface.go @@ -101,4 +101,8 @@ type StateDB interface { // Finalise must be invoked at the end of a transaction Finalise(bool) + + // GetAccumulatedGasMeasurements returns measurements of IO operations that have + // been accumulated since the execution of the block started. + GetAccumulatedIOMeasurements() *tracing.IOMeasurements } From 01649de12eb917b9a7556fbd35132dbecbe04ec3 Mon Sep 17 00:00:00 2001 From: Sina Mahmoodi Date: Fri, 25 Apr 2025 11:37:20 +0200 Subject: [PATCH 3/7] error on minus evm time --- eth/tracers/live/perf.go | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/eth/tracers/live/perf.go b/eth/tracers/live/perf.go index 19072d944822..7535e890bc13 100644 --- a/eth/tracers/live/perf.go +++ b/eth/tracers/live/perf.go @@ -28,10 +28,11 @@ import ( "github.com/ethereum/go-ethereum/core/tracing" "github.com/ethereum/go-ethereum/core/types" "github.com/ethereum/go-ethereum/eth/tracers" + "github.com/ethereum/go-ethereum/log" ) func init() { - tracers.LiveDirectory.Register("perfTracer", newPerfTracer) + tracers.LiveDirectory.Register("perf", newPerfTracer) } type perfTracerConfig struct { @@ -127,8 +128,13 @@ func (t *perfTracer) OnTxEnd(receipt *types.Receipt, err error) { accumulatedIO = t.statedb.GetAccumulatedIOMeasurements() ioTime = (accumulatedIO.AccountReads - t.prevAccountReads) + (accumulatedIO.StorageReads - t.prevStorageReads) - evmTime = totalTime - ioTime + evmTime time.Duration ) + if ioTime > totalTime { + log.Error("PerfTracer: IO time exceeds total time", "ioTime", ioTime, "totalTime", totalTime) + } else { + evmTime = totalTime - ioTime + } row := []string{ t.currentBlock.Number().String(), From c8592a42a8f2f5e99c0befca8e0f82cf129503e9 Mon Sep 17 00:00:00 2001 From: Sina Mahmoodi Date: Fri, 25 Apr 2025 11:49:58 +0200 Subject: [PATCH 4/7] fix negative evm --- eth/tracers/live/perf.go | 9 ++++++++- 1 file changed, 8 insertions(+), 1 deletion(-) diff --git a/eth/tracers/live/perf.go b/eth/tracers/live/perf.go index 7535e890bc13..51c686198786 100644 --- a/eth/tracers/live/perf.go +++ b/eth/tracers/live/perf.go @@ -120,6 +120,13 @@ func (t *perfTracer) OnBlockStart(event tracing.BlockEvent) { func (t *perfTracer) OnTxStart(vm *tracing.VMContext, tx *types.Transaction, from common.Address) { t.txStartTime = time.Now() t.statedb = vm.StateDB + + // The accumulated measurements include IO performed before any txs were executed. + if t.txIndex == 0 { + initialIO := t.statedb.GetAccumulatedIOMeasurements() + t.prevAccountReads = initialIO.AccountReads + t.prevStorageReads = initialIO.StorageReads + } } func (t *perfTracer) OnTxEnd(receipt *types.Receipt, err error) { @@ -131,7 +138,7 @@ func (t *perfTracer) OnTxEnd(receipt *types.Receipt, err error) { evmTime time.Duration ) if ioTime > totalTime { - log.Error("PerfTracer: IO time exceeds total time", "ioTime", ioTime, "totalTime", totalTime) + log.Error("PerfTracer: IO time exceeds total time", "ioTime", ioTime, "totalTime", totalTime, "txIdx", t.txIndex) } else { evmTime = totalTime - ioTime } From 23bb0c49de813f00b2c9621354092b3c3237709f Mon Sep 17 00:00:00 2001 From: Sina Mahmoodi Date: Fri, 25 Apr 2025 15:40:44 +0200 Subject: [PATCH 5/7] collect block level times --- eth/tracers/live/perf.go | 94 ++++++++++++++++++++-------------------- 1 file changed, 48 insertions(+), 46 deletions(-) diff --git a/eth/tracers/live/perf.go b/eth/tracers/live/perf.go index 51c686198786..bda674d34fff 100644 --- a/eth/tracers/live/perf.go +++ b/eth/tracers/live/perf.go @@ -17,7 +17,6 @@ package live import ( - "encoding/csv" "encoding/json" "errors" "fmt" @@ -36,20 +35,21 @@ func init() { } type perfTracerConfig struct { - CSVPath string `json:"csvPath"` + Path string `json:"path"` } // perfTracer is a live tracer that measures and records transaction processing performance metrics. // It tracks total processing time, IO time (account and storage reads), and EVM execution time for -// each transaction. The metrics are written to a CSV file. +// each transaction. The metrics are written to a JSONL file. type perfTracer struct { - csvPath string - writer *csv.Writer + path string file *os.File + encoder *json.Encoder // Block context currentBlock *types.Block currentBlockHash common.Hash + blockStartTime time.Time // Transaction tracking txStartTime time.Time @@ -59,6 +59,9 @@ type perfTracer struct { prevAccountReads time.Duration prevStorageReads time.Duration + // Transaction data collection + txData []map[string]interface{} + statedb tracing.StateDB } @@ -67,36 +70,20 @@ func newPerfTracer(cfg json.RawMessage) (*tracing.Hooks, error) { if err := json.Unmarshal(cfg, &config); err != nil { return nil, fmt.Errorf("failed to parse config: %v", err) } - if config.CSVPath == "" { - return nil, errors.New("csv path is required") + if config.Path == "" { + return nil, errors.New("path is required") } - // Open CSV file - file, err := os.OpenFile(config.CSVPath, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644) + // Open JSONL file + file, err := os.OpenFile(config.Path, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0644) if err != nil { - return nil, fmt.Errorf("failed to open CSV file: %v", err) - } - writer := csv.NewWriter(file) - - // Write header if file is empty - info, err := file.Stat() - if err != nil { - file.Close() - return nil, fmt.Errorf("failed to get file info: %v", err) - } - if info.Size() == 0 { - header := []string{"block_number", "block_hash", "tx_index", "tx_hash", "total_time_ns", "io_time_ns", "evm_time_ns", "gas_used"} - if err := writer.Write(header); err != nil { - file.Close() - return nil, fmt.Errorf("failed to write CSV header: %v", err) - } - writer.Flush() + return nil, fmt.Errorf("failed to open JSONL file: %v", err) } t := &perfTracer{ - csvPath: config.CSVPath, - writer: writer, + path: config.Path, file: file, + encoder: json.NewEncoder(file), } return &tracing.Hooks{ @@ -112,6 +99,8 @@ func (t *perfTracer) OnBlockStart(event tracing.BlockEvent) { t.currentBlock = event.Block t.currentBlockHash = event.Block.Hash() t.txIndex = 0 + t.txData = make([]map[string]interface{}, 0) + t.blockStartTime = time.Now() // Reset previous IO measurements for the new block t.prevAccountReads = 0 t.prevStorageReads = 0 @@ -143,36 +132,49 @@ func (t *perfTracer) OnTxEnd(receipt *types.Receipt, err error) { evmTime = totalTime - ioTime } - row := []string{ - t.currentBlock.Number().String(), - t.currentBlockHash.Hex(), - fmt.Sprintf("%d", t.txIndex), - receipt.TxHash.Hex(), - fmt.Sprintf("%d", totalTime.Nanoseconds()), - fmt.Sprintf("%d", ioTime.Nanoseconds()), - fmt.Sprintf("%d", evmTime.Nanoseconds()), - fmt.Sprintf("%d", receipt.GasUsed), - } - if err := t.writer.Write(row); err != nil { - fmt.Printf("Failed to write CSV row: %v\n", err) + txRecord := map[string]interface{}{ + "txIndex": fmt.Sprintf("0x%x", t.txIndex), + "txHash": receipt.TxHash.Hex(), + "gasUsed": fmt.Sprintf("0x%x", receipt.GasUsed), + "totalTime": fmt.Sprintf("0x%x", totalTime.Nanoseconds()), + "ioTime": fmt.Sprintf("0x%x", ioTime.Nanoseconds()), + "evmTime": fmt.Sprintf("0x%x", evmTime.Nanoseconds()), } + t.txData = append(t.txData, txRecord) + t.prevAccountReads = accumulatedIO.AccountReads t.prevStorageReads = accumulatedIO.StorageReads t.txIndex++ } -// OnBlockEnd implements tracing.BlockEndHook func (t *perfTracer) OnBlockEnd(err error) { - if t.writer != nil { - t.writer.Flush() + // Calculate block-level timings + totalTime := time.Since(t.blockStartTime) + blockEndIO := t.statedb.GetAccumulatedIOMeasurements() + ioTime := blockEndIO.AccountReads + blockEndIO.StorageReads + evmTime := totalTime - ioTime + + blockRecord := map[string]interface{}{ + "blockNumber": fmt.Sprintf("0x%x", t.currentBlock.Number()), + "blockHash": t.currentBlockHash.Hex(), + "gasUsed": fmt.Sprintf("0x%x", t.currentBlock.GasUsed()), + "totalTime": fmt.Sprintf("0x%x", totalTime.Nanoseconds()), + "ioTime": fmt.Sprintf("0x%x", ioTime.Nanoseconds()), + "evmTime": fmt.Sprintf("0x%x", evmTime.Nanoseconds()), + "transactions": t.txData, + } + + if err := t.encoder.Encode(blockRecord); err != nil { + fmt.Printf("Failed to write block record: %v\n", err) + } + + if t.file != nil { + t.file.Sync() } } func (t *perfTracer) OnClose() { - if t.writer != nil { - t.writer.Flush() - } if t.file != nil { t.file.Close() } From f04436728810cf0f790a422b92b37c9f427722ba Mon Sep 17 00:00:00 2001 From: Sina Mahmoodi Date: Fri, 25 Apr 2025 16:47:47 +0200 Subject: [PATCH 6/7] add triedb metrics to block io --- eth/tracers/live/perf.go | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/eth/tracers/live/perf.go b/eth/tracers/live/perf.go index bda674d34fff..dc8dcc1e7610 100644 --- a/eth/tracers/live/perf.go +++ b/eth/tracers/live/perf.go @@ -152,7 +152,9 @@ func (t *perfTracer) OnBlockEnd(err error) { // Calculate block-level timings totalTime := time.Since(t.blockStartTime) blockEndIO := t.statedb.GetAccumulatedIOMeasurements() - ioTime := blockEndIO.AccountReads + blockEndIO.StorageReads + ioTime := blockEndIO.AccountReads + blockEndIO.AccountHashes + blockEndIO.AccountUpdates + blockEndIO.AccountCommits + + blockEndIO.StorageReads + blockEndIO.StorageUpdates + blockEndIO.StorageCommits + + blockEndIO.SnapshotCommits + blockEndIO.TrieDBCommits evmTime := totalTime - ioTime blockRecord := map[string]interface{}{ From 232bafe6fbb32d6cafd10bfd1979fd6b48a008cd Mon Sep 17 00:00:00 2001 From: Sina Mahmoodi Date: Fri, 25 Apr 2025 16:53:54 +0200 Subject: [PATCH 7/7] sanity check --- eth/tracers/live/perf.go | 24 ++++++++++++++++++++++++ 1 file changed, 24 insertions(+) diff --git a/eth/tracers/live/perf.go b/eth/tracers/live/perf.go index dc8dcc1e7610..46c4abd7b349 100644 --- a/eth/tracers/live/perf.go +++ b/eth/tracers/live/perf.go @@ -21,6 +21,7 @@ import ( "errors" "fmt" "os" + "strconv" "time" "github.com/ethereum/go-ethereum/common" @@ -157,6 +158,29 @@ func (t *perfTracer) OnBlockEnd(err error) { blockEndIO.SnapshotCommits + blockEndIO.TrieDBCommits evmTime := totalTime - ioTime + // Sanity check: IO time should not exceed total time + if ioTime > totalTime { + log.Error("PerfTracer: Block IO time exceeds total time", + "blockNumber", t.currentBlock.Number(), + "ioTime", ioTime, + "totalTime", totalTime) + return + } + + // Calculate sum of transaction times and gas + var totalTxTime time.Duration + for _, tx := range t.txData { + txTime, _ := strconv.ParseUint(tx["totalTime"].(string)[2:], 16, 64) + totalTxTime += time.Duration(txTime) + } + if totalTxTime > totalTime { + log.Error("PerfTracer: Sum of transaction times exceeds block total time", + "blockNumber", t.currentBlock.Number(), + "totalTxTime", totalTxTime, + "blockTotalTime", totalTime) + return + } + blockRecord := map[string]interface{}{ "blockNumber": fmt.Sprintf("0x%x", t.currentBlock.Number()), "blockHash": t.currentBlockHash.Hex(),