forks/go-ethereum
1
0
Fork 1
mirror of https://github.com/ethereum/go-ethereum.git synced 2026-07-24 13:46:43 +00:00
Code Issues Projects Releases Packages Wiki Activity Actions 1

feat: add more state_transition, worker, and tracing metrics (#700)

Browse source 
* feat: add transactions len metrics of block processer

* feat: (worker): add metrics

* feat: add commitTransaction loops

* feat: add metrics to rollup tracing

* feat: add metrics to getTxResult

* feat: bump version

* add state revert metric timer

* feat: add commitNewWrok metrics

* feat: fix comments

* feat: remove the consume part metrics

* feat: update

* Apply suggestions from code review

Co-authored-by: colin <102356659+colinlyguo@users.noreply.github.com>

* feat: update

* feat: address comments

* chore: auto version bump [bot]

* feat: bump version

* add tests

* Revert "add tests"

This reverts commit 175d544a68fc964dcc062b46c1a010ed821a0996.

---------

Co-authored-by: Ömer Faruk Irmak <omerfirmak@gmail.com>
Co-authored-by: colin <102356659+colinlyguo@users.noreply.github.com>
Co-authored-by: georgehao <georgehao@users.noreply.github.com>
Co-authored-by: colinlyguo <colinlyguo@scroll.io>
This commit is contained in:
georgehao 2024-04-16 16:05:21 +08:00 committed by GitHub
parent 5115f1342d
commit 678a9fcb69
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
5 changed files with 147 additions and 60 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

12
common/timer.go Normal file
View file

@ -0,0 +1,12 @@
package common
import "github.com/scroll-tech/go-ethereum/metrics"
// WithTimer calculates the interval of f
func WithTimer(timer metrics.Timer, f func()) {
if metrics.Enabled {
timer.Time(f)
} else {
f()
}
}

11
core/state_transition.go
View file

@ -34,7 +34,10 @@ import (
var emptyKeccakCodeHash = codehash.EmptyKeccakCodeHash
var evmCallExecutionTimer = metrics.NewRegisteredTimer("evm/call/execution", nil)
var (
stateTransitionEvmCallExecutionTimer = metrics.NewRegisteredTimer("state/transition/call_execution", nil)
stateTransitionApplyMessageTimer = metrics.NewRegisteredTimer("state/transition/apply_message", nil)
)
/*
The State Transitioning Model
@ -208,6 +211,10 @@ func NewStateTransition(evm *vm.EVM, msg Message, gp *GasPool, l1DataFee *big.In
// indicates a core error meaning that the message would always fail for that particular
// state and would never be accepted within a block.
func ApplyMessage(evm *vm.EVM, msg Message, gp *GasPool, l1DataFee *big.Int) (*ExecutionResult, error) {
defer func(t time.Time) {
stateTransitionApplyMessageTimer.Update(time.Since(t))
}(time.Now())
return NewStateTransition(evm, msg, gp, l1DataFee).TransitionDb()
}
@ -391,7 +398,7 @@ func (st *StateTransition) TransitionDb() (*ExecutionResult, error) {
st.state.SetNonce(msg.From(), st.state.GetNonce(sender.Address())+1)
evmCallStart := time.Now()
ret, st.gas, vmerr = st.evm.Call(sender, st.to(), st.data, st.gas, st.value)
evmCallExecutionTimer.Update(time.Since(evmCallStart))
stateTransitionEvmCallExecutionTimer.Update(time.Since(evmCallStart))
}
// no refunds for l1 messages

72
miner/worker.go
View file

@ -92,16 +92,28 @@ var (
l1TxCccUnknownErrCounter = metrics.NewRegisteredCounter("miner/skipped_txs/l1/ccc_unknown_err", nil)
l2TxCccUnknownErrCounter = metrics.NewRegisteredCounter("miner/skipped_txs/l2/ccc_unknown_err", nil)
l1TxStrangeErrCounter = metrics.NewRegisteredCounter("miner/skipped_txs/l1/strange_err", nil)
l2CommitTxsTimer = metrics.NewRegisteredTimer("miner/commit/txs_all", nil)
l2CommitTxTimer = metrics.NewRegisteredTimer("miner/commit/tx_all", nil)
l2CommitTxTraceTimer = metrics.NewRegisteredTimer("miner/commit/tx_trace", nil)
l2CommitTxTraceStateRevertTimer = metrics.NewRegisteredTimer("miner/commit/tx_trace_state_revert", nil)
l2CommitTxCCCTimer = metrics.NewRegisteredTimer("miner/commit/tx_ccc", nil)
l2CommitTxApplyTimer = metrics.NewRegisteredTimer("miner/commit/tx_apply", nil)
l2CommitNewWorkTimer = metrics.NewRegisteredTimer("miner/commit/new_work_all", nil)
l2CommitNewWorkL1CollectTimer = metrics.NewRegisteredTimer("miner/commit/new_work_collect_l1", nil)
l2CommitNewWorkPrepareTimer = metrics.NewRegisteredTimer("miner/commit/new_work_prepare", nil)
l2CommitNewWorkCommitUncleTimer = metrics.NewRegisteredTimer("miner/commit/new_work_uncle", nil)
l2CommitNewWorkTidyPendingTxTimer = metrics.NewRegisteredTimer("miner/commit/new_work_tidy_pending", nil)
l2CommitNewWorkCommitL1MsgTimer = metrics.NewRegisteredTimer("miner/commit/new_work_commit_l1_msg", nil)
l2CommitNewWorkPrioritizedTxCommitTimer = metrics.NewRegisteredTimer("miner/commit/new_work_prioritized", nil)
l2CommitNewWorkRemoteLocalCommitTimer = metrics.NewRegisteredTimer("miner/commit/new_work_remote_local", nil)
l2CommitNewWorkLocalPriceAndNonceTimer = metrics.NewRegisteredTimer("miner/commit/new_work_local_price_and_nonce", nil)
l2CommitNewWorkRemotePriceAndNonceTimer = metrics.NewRegisteredTimer("miner/commit/new_work_remote_price_and_nonce", nil)
l2CommitTimer = metrics.NewRegisteredTimer("miner/commit/all", nil)
l2CommitTraceTimer = metrics.NewRegisteredTimer("miner/commit/trace", nil)
l2CommitCCCTimer = metrics.NewRegisteredTimer("miner/commit/ccc", nil)
l2CommitNewWorkTimer = metrics.NewRegisteredTimer("miner/commit/new_work_all", nil)
l2CommitNewWorkL1CollectTimer = metrics.NewRegisteredTimer("miner/commit/new_work_collect_l1", nil)
l2ResultTimer = metrics.NewRegisteredTimer("miner/result/all", nil)
)
@ -937,18 +949,20 @@ func (w *worker) commitTransaction(tx *types.Transaction, coinbase common.Addres
// 2.1 when starting handling the first tx, `state.refund` is 0 by default,
// 2.2 after tracing, the state is either committed in `core.ApplyTransaction`, or reverted, so the `state.refund` can be cleared,
// 2.3 when starting handling the following txs, `state.refund` comes as 0
withTimer(l2CommitTxTraceTimer, func() {
common.WithTimer(l2CommitTxTraceTimer, func() {
traces, err = w.current.traceEnv.GetBlockTrace(
types.NewBlockWithHeader(w.current.header).WithBody([]*types.Transaction{tx}, nil),
)
})
common.WithTimer(l2CommitTxTraceStateRevertTimer, func() {
// `w.current.traceEnv.State` & `w.current.state` share a same pointer to the state, so only need to revert `w.current.state`
// revert to snapshot for calling `core.ApplyMessage` again, (both `traceEnv.GetBlockTrace` & `core.ApplyTransaction` will call `core.ApplyMessage`)
w.current.state.RevertToSnapshot(snap)
})
if err != nil {
return nil, nil, err
}
withTimer(l2CommitTxCCCTimer, func() {
common.WithTimer(l2CommitTxCCCTimer, func() {
accRows, err = w.circuitCapacityChecker.ApplyTransaction(traces)
})
if err != nil {
@ -966,7 +980,7 @@ func (w *worker) commitTransaction(tx *types.Transaction, coinbase common.Addres
snap := w.current.state.Snapshot()
var receipt *types.Receipt
withTimer(l2CommitTxApplyTimer, func() {
common.WithTimer(l2CommitTxApplyTimer, func() {
receipt, err = core.ApplyTransaction(w.chainConfig, w.chain, &coinbase, w.current.gasPool, w.current.state, w.current.header, tx, &w.current.header.GasUsed, *w.chain.GetVMConfig())
})
if err != nil {
@ -1013,9 +1027,10 @@ func (w *worker) commitTransactions(txs types.OrderedTransactionSet, coinbase co
}
var coalescedLogs []*types.Log
var loops int64
loop:
for {
loops++
// In the following three cases, we will interrupt the execution of the transaction.
// (1) new head block event arrival, the interrupt signal is 1
// (2) worker start or restart, the interrupt signal is 1
@ -1341,10 +1356,14 @@ func (w *worker) commitNewWork(interrupt *int32, noempty bool, timestamp int64)
}
header.Coinbase = w.coinbase
}
common.WithTimer(l2CommitNewWorkPrepareTimer, func() {
if err := w.engine.Prepare(w.chain, header); err != nil {
log.Error("Failed to prepare header for mining", "err", err)
return
}
})
// If we are care about TheDAO hard-fork check whether to override the extra-data or not
if daoBlock := w.chainConfig.DAOForkBlock; daoBlock != nil {
// Check whether the block is among the fork extra-override range
@ -1390,9 +1409,12 @@ func (w *worker) commitNewWork(interrupt *int32, noempty bool, timestamp int64)
}
}
}
common.WithTimer(l2CommitNewWorkCommitUncleTimer, func() {
// Prefer to locally generated uncle
commitUncles(w.localUncles)
commitUncles(w.remoteUncles)
})
// Create an empty block based on temporary copied state for
// sealing in advance without waiting block execution finished.
@ -1402,10 +1424,12 @@ func (w *worker) commitNewWork(interrupt *int32, noempty bool, timestamp int64)
// fetch l1Txs
var l1Messages []types.L1MessageTx
if w.chainConfig.Scroll.ShouldIncludeL1Messages() {
withTimer(l2CommitNewWorkL1CollectTimer, func() {
common.WithTimer(l2CommitNewWorkL1CollectTimer, func() {
l1Messages = w.collectPendingL1Messages(env.nextL1MsgIndex)
})
}
tidyPendingStart := time.Now()
// Fill the block with all available pending transactions.
pending := w.eth.TxPool().Pending(true)
// Short circuit if there is no available pending transactions.
@ -1413,6 +1437,7 @@ func (w *worker) commitNewWork(interrupt *int32, noempty bool, timestamp int64)
// empty block is necessary to keep the liveness of the network.
if len(pending) == 0 && len(l1Messages) == 0 && atomic.LoadUint32(&w.noempty) == 0 {
w.updateSnapshot()
l2CommitNewWorkTidyPendingTxTimer.UpdateSince(tidyPendingStart)
return
}
// Split the pending transactions into locals and remotes
@ -1423,7 +1448,10 @@ func (w *worker) commitNewWork(interrupt *int32, noempty bool, timestamp int64)
localTxs[account] = txs
}
}
l2CommitNewWorkTidyPendingTxTimer.UpdateSince(tidyPendingStart)
var skipCommit, circuitCapacityReached bool
commitL1MsgStart := time.Now()
if w.chainConfig.Scroll.ShouldIncludeL1Messages() && len(l1Messages) > 0 {
log.Trace("Processing L1 messages for inclusion", "count", len(l1Messages))
txs, err := types.NewL1MessagesByQueueIndex(l1Messages)
@ -1433,9 +1461,13 @@ func (w *worker) commitNewWork(interrupt *int32, noempty bool, timestamp int64)
}
skipCommit, circuitCapacityReached = w.commitTransactions(txs, w.coinbase, interrupt)
if skipCommit {
l2CommitNewWorkCommitL1MsgTimer.UpdateSince(commitL1MsgStart)
return
}
}
l2CommitNewWorkCommitL1MsgTimer.UpdateSince(commitL1MsgStart)
prioritizedTxStart := time.Now()
if w.prioritizedTx != nil && w.current.header.Number.Uint64() > w.prioritizedTx.blockNumber {
w.prioritizedTx = nil
}
@ -1446,25 +1478,39 @@ func (w *worker) commitNewWork(interrupt *int32, noempty bool, timestamp int64)
txs := types.NewTransactionsByPriceAndNonce(w.current.signer, txList, header.BaseFee)
skipCommit, circuitCapacityReached = w.commitTransactions(txs, w.coinbase, interrupt)
if skipCommit {
l2CommitNewWorkPrioritizedTxCommitTimer.UpdateSince(prioritizedTxStart)
return
}
}
l2CommitNewWorkPrioritizedTxCommitTimer.UpdateSince(prioritizedTxStart)
remoteLocalStart := time.Now()
if len(localTxs) > 0 && !circuitCapacityReached {
localTxPriceAndNonceStart := time.Now()
txs := types.NewTransactionsByPriceAndNonce(w.current.signer, localTxs, header.BaseFee)
l2CommitNewWorkLocalPriceAndNonceTimer.UpdateSince(localTxPriceAndNonceStart)
skipCommit, circuitCapacityReached = w.commitTransactions(txs, w.coinbase, interrupt)
if skipCommit {
l2CommitNewWorkRemoteLocalCommitTimer.UpdateSince(remoteLocalStart)
return
}
}
if len(remoteTxs) > 0 && !circuitCapacityReached {
remoteTxPriceAndNonceStart := time.Now()
txs := types.NewTransactionsByPriceAndNonce(w.current.signer, remoteTxs, header.BaseFee)
l2CommitNewWorkRemotePriceAndNonceTimer.UpdateSince(remoteTxPriceAndNonceStart)
// don't need to get `circuitCapacityReached` here because we don't have further `commitTransactions`
// after this one, and if we assign it won't take effect (`ineffassign`)
skipCommit, _ = w.commitTransactions(txs, w.coinbase, interrupt)
if skipCommit {
l2CommitNewWorkRemoteLocalCommitTimer.UpdateSince(remoteLocalStart)
return
}
}
l2CommitNewWorkRemoteLocalCommitTimer.UpdateSince(remoteLocalStart)
// do not produce empty blocks
if w.current.tcount == 0 {
@ -1492,7 +1538,7 @@ func (w *worker) commit(uncles []*types.Header, interval func(), update bool, st
)
var traces *types.BlockTrace
var err error
withTimer(l2CommitTraceTimer, func() {
common.WithTimer(l2CommitTraceTimer, func() {
traces, err = w.current.traceEnv.GetBlockTrace(types.NewBlockWithHeader(w.current.header))
})
if err != nil {
@ -1503,7 +1549,7 @@ func (w *worker) commit(uncles []*types.Header, interval func(), update bool, st
traces.ExecutionResults = traces.ExecutionResults[:0]
traces.TxStorageTraces = traces.TxStorageTraces[:0]
var accRows *types.RowConsumption
withTimer(l2CommitCCCTimer, func() {
common.WithTimer(l2CommitCCCTimer, func() {
accRows, err = w.circuitCapacityChecker.ApplyBlock(traces)
})
if err != nil {
@ -1575,11 +1621,3 @@ func totalFees(block *types.Block, receipts []*types.Receipt) *big.Float {
}
return new(big.Float).Quo(new(big.Float).SetInt(feesWei), new(big.Float).SetInt(big.NewInt(params.Ether)))
}
func withTimer(timer metrics.Timer, f func()) {
if metrics.Enabled {
timer.Time(f)
} else {
f()
}
}

2
params/version.go
View file

@ -24,7 +24,7 @@ import (
const (
VersionMajor = 5 // Major version component of the current release
VersionMinor = 2 // Minor version component of the current release
VersionPatch = 1 // Patch version component of the current release
VersionPatch = 3 // Patch version component of the current release
VersionMeta = "mainnet" // Version metadata to append to the version string
)

34
rollup/tracing/tracing.go
View file

@ -6,6 +6,7 @@ import (
"fmt"
"runtime"
"sync"
"time"
"github.com/scroll-tech/go-ethereum/common"
"github.com/scroll-tech/go-ethereum/common/hexutil"
@ -19,6 +20,7 @@ import (
_ "github.com/scroll-tech/go-ethereum/eth/tracers/native"
"github.com/scroll-tech/go-ethereum/ethdb"
"github.com/scroll-tech/go-ethereum/log"
"github.com/scroll-tech/go-ethereum/metrics"
"github.com/scroll-tech/go-ethereum/params"
"github.com/scroll-tech/go-ethereum/rollup/fees"
"github.com/scroll-tech/go-ethereum/rollup/rcfg"
@ -26,10 +28,19 @@ import (
"github.com/scroll-tech/go-ethereum/trie/zkproof"
)
var (
getTxResultTimer = metrics.NewRegisteredTimer("rollup/tracing/get_tx_result", nil)
getTxResultApplyMessageTimer = metrics.NewRegisteredTimer("rollup/tracing/get_tx_result/apply_message", nil)
getTxResultZkTrieBuildTimer = metrics.NewRegisteredTimer("rollup/tracing/get_tx_result/zk_trie_build", nil)
getTxResultTracerResultTimer = metrics.NewRegisteredTimer("rollup/tracing/get_tx_result/tracer_result", nil)
feedTxToTracerTimer = metrics.NewRegisteredTimer("rollup/tracing/feed_tx_to_tracer", nil)
fillBlockTraceTimer = metrics.NewRegisteredTimer("rollup/tracing/fill_block_trace", nil)
)
// TracerWrapper implements ScrollTracerWrapper interface
type TracerWrapper struct{}
// TracerWrapper creates a new TracerWrapper
// NewTracerWrapper TracerWrapper creates a new TracerWrapper
func NewTracerWrapper() *TracerWrapper {
return &TracerWrapper{}
}
@ -182,7 +193,11 @@ func (env *TraceEnv) GetBlockTrace(block *types.Block) (*types.BlockTrace, error
for th := 0; th < threads; th++ {
pend.Add(1)
go func() {
defer pend.Done()
defer func(t time.Time) {
pend.Done()
getTxResultTimer.Update(time.Since(t))
}(time.Now())
// Fetch and execute the next transaction trace tasks
for task := range jobs {
if err := env.getTxResult(task.statedb, task.index, block); err != nil {
@ -204,6 +219,7 @@ func (env *TraceEnv) GetBlockTrace(block *types.Block) (*types.BlockTrace, error
// Feed the transactions into the tracers and return
var failed error
common.WithTimer(feedTxToTracerTimer, func() {
for i, tx := range txs {
// Send the trace task over for execution
jobs <- &txTraceTask{statedb: env.state.Copy(), index: i}
@ -225,6 +241,7 @@ func (env *TraceEnv) GetBlockTrace(block *types.Block) (*types.BlockTrace, error
env.state.Finalise(vmenv.ChainConfig().IsEIP158(block.Number()))
}
}
})
close(jobs)
pend.Wait()
@ -306,6 +323,8 @@ func (env *TraceEnv) getTxResult(state *state.StateDB, index int, block *types.B
if err != nil {
return fmt.Errorf("failed to create prestateTracer: %w", err)
}
applyMessageStart := time.Now()
structLogger := vm.NewStructLogger(env.logConfig)
tracer := NewMuxTracer(structLogger, callTracer, prestateTracer)
// Run the transaction with tracing enabled.
@ -321,8 +340,11 @@ func (env *TraceEnv) getTxResult(state *state.StateDB, index int, block *types.B
}
result, err := core.ApplyMessage(vmenv, msg, new(core.GasPool).AddGas(msg.Gas()), l1DataFee)
if err != nil {
getTxResultApplyMessageTimer.UpdateSince(applyMessageStart)
return err
}
getTxResultApplyMessageTimer.UpdateSince(applyMessageStart)
// If the result contains a revert reason, return it.
returnVal := result.Return()
if len(result.Revert()) > 0 {
@ -388,6 +410,7 @@ func (env *TraceEnv) getTxResult(state *state.StateDB, index int, block *types.B
env.pMu.Unlock()
}
zkTrieBuildStart := time.Now()
proofStorages := structLogger.UpdatedStorages()
for addr, keys := range proofStorages {
if _, existed := txStorageTrace.StorageProofs[addr.String()]; !existed {
@ -456,7 +479,9 @@ func (env *TraceEnv) getTxResult(state *state.StateDB, index int, block *types.B
env.sMu.Unlock()
}
}
getTxResultZkTrieBuildTimer.UpdateSince(zkTrieBuildStart)
tracerResultTimer := time.Now()
callTrace, err := callTracer.GetResult()
if err != nil {
return fmt.Errorf("failed to get callTracer result: %w", err)
@ -465,6 +490,7 @@ func (env *TraceEnv) getTxResult(state *state.StateDB, index int, block *types.B
if err != nil {
return fmt.Errorf("failed to get prestateTracer result: %w", err)
}
getTxResultTracerResultTimer.UpdateSince(tracerResultTimer)
env.ExecutionResults[index] = &types.ExecutionResult{
From: sender,
@ -486,6 +512,10 @@ func (env *TraceEnv) getTxResult(state *state.StateDB, index int, block *types.B
// fillBlockTrace content after all the txs are finished running.
func (env *TraceEnv) fillBlockTrace(block *types.Block) (*types.BlockTrace, error) {
defer func(t time.Time) {
fillBlockTraceTimer.Update(time.Since(t))
}(time.Now())
statedb := env.state
txs := make([]*types.TransactionData, block.Transactions().Len())