From 678a9fcb69c98cade804629d7ddac1554e7d819b Mon Sep 17 00:00:00 2001 From: georgehao Date: Tue, 16 Apr 2024 16:05:21 +0800 Subject: [PATCH] feat: add more state_transition, worker, and tracing metrics (#700) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * 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 Co-authored-by: colin <102356659+colinlyguo@users.noreply.github.com> Co-authored-by: georgehao Co-authored-by: colinlyguo --- common/timer.go | 12 +++++ core/state_transition.go | 11 +++- miner/worker.go | 110 +++++++++++++++++++++++++------------- params/version.go | 2 +- rollup/tracing/tracing.go | 72 +++++++++++++++++-------- 5 files changed, 147 insertions(+), 60 deletions(-) create mode 100644 common/timer.go diff --git a/common/timer.go b/common/timer.go new file mode 100644 index 0000000000..a7bf3ced98 --- /dev/null +++ b/common/timer.go @@ -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() + } +} diff --git a/core/state_transition.go b/core/state_transition.go index daacc118d8..b9f514c853 100644 --- a/core/state_transition.go +++ b/core/state_transition.go @@ -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 diff --git a/miner/worker.go b/miner/worker.go index 62391c6853..56fa18e3fe 100644 --- a/miner/worker.go +++ b/miner/worker.go @@ -92,17 +92,29 @@ 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) - l2CommitTxCCCTimer = metrics.NewRegisteredTimer("miner/commit/tx_ccc", nil) - l2CommitTxApplyTimer = metrics.NewRegisteredTimer("miner/commit/tx_apply", 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) + + 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) + l2ResultTimer = metrics.NewRegisteredTimer("miner/result/all", nil) ) // environment is the worker's current environment and holds all of the current state information. @@ -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), ) }) - // `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) + 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 } - if err := w.engine.Prepare(w.chain, header); err != nil { - log.Error("Failed to prepare header for mining", "err", err) - return - } + + 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) } } } - // Prefer to locally generated uncle - commitUncles(w.localUncles) - commitUncles(w.remoteUncles) + + 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() - } -} diff --git a/params/version.go b/params/version.go index 248016d163..5bd5369dc0 100644 --- a/params/version.go +++ b/params/version.go @@ -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 ) diff --git a/rollup/tracing/tracing.go b/rollup/tracing/tracing.go index 2b87024a44..9c78445c6d 100644 --- a/rollup/tracing/tracing.go +++ b/rollup/tracing/tracing.go @@ -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,27 +219,29 @@ func (env *TraceEnv) GetBlockTrace(block *types.Block) (*types.BlockTrace, error // Feed the transactions into the tracers and return var failed error - for i, tx := range txs { - // Send the trace task over for execution - jobs <- &txTraceTask{statedb: env.state.Copy(), index: i} + common.WithTimer(feedTxToTracerTimer, func() { + for i, tx := range txs { + // Send the trace task over for execution + jobs <- &txTraceTask{statedb: env.state.Copy(), index: i} - // Generate the next state snapshot fast without tracing - msg, _ := tx.AsMessage(env.signer, block.BaseFee()) - env.state.Prepare(tx.Hash(), i) - vmenv := vm.NewEVM(env.blockCtx, core.NewEVMTxContext(msg), env.state, env.chainConfig, vm.Config{}) - l1DataFee, err := fees.CalculateL1DataFee(tx, env.state) - if err != nil { - failed = err - break + // Generate the next state snapshot fast without tracing + msg, _ := tx.AsMessage(env.signer, block.BaseFee()) + env.state.Prepare(tx.Hash(), i) + vmenv := vm.NewEVM(env.blockCtx, core.NewEVMTxContext(msg), env.state, env.chainConfig, vm.Config{}) + l1DataFee, err := fees.CalculateL1DataFee(tx, env.state) + if err != nil { + failed = err + break + } + if _, err = core.ApplyMessage(vmenv, msg, new(core.GasPool).AddGas(msg.Gas()), l1DataFee); err != nil { + failed = err + break + } + if env.commitAfterApply { + env.state.Finalise(vmenv.ChainConfig().IsEIP158(block.Number())) + } } - if _, err = core.ApplyMessage(vmenv, msg, new(core.GasPool).AddGas(msg.Gas()), l1DataFee); err != nil { - failed = err - break - } - if env.commitAfterApply { - 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())