From c86a215b048c0a4388cd70a25bd84b99bcd15078 Mon Sep 17 00:00:00 2001 From: Mengran Lan Date: Mon, 29 Jul 2024 16:07:31 +0800 Subject: [PATCH] feat(metrics):migrate metrics from develop branch (#910) migrate metrics from develop Co-authored-by: HAOYUatHZ <37070449+HAOYUatHZ@users.noreply.github.com> --- core/block_validator.go | 24 ++++++++++ core/blockchain.go | 16 +++++++ core/state_processor.go | 26 +++++++++++ core/state_transition.go | 13 ++++++ rollup/sync_service/sync_service.go | 6 +++ rollup/tracing/tracing.go | 68 ++++++++++++++++++++--------- 6 files changed, 133 insertions(+), 20 deletions(-) diff --git a/core/block_validator.go b/core/block_validator.go index 0b69c586f5..3f6ee5c7b3 100644 --- a/core/block_validator.go +++ b/core/block_validator.go @@ -20,6 +20,7 @@ import ( "errors" "fmt" "sync" + "time" "github.com/scroll-tech/go-ethereum/consensus" "github.com/scroll-tech/go-ethereum/core/rawdb" @@ -27,11 +28,20 @@ import ( "github.com/scroll-tech/go-ethereum/core/types" "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/circuitcapacitychecker" "github.com/scroll-tech/go-ethereum/trie" ) +var ( + validateL1MessagesTimer = metrics.NewRegisteredTimer("validator/l1msg", nil) + validateRowConsumptionTimer = metrics.NewRegisteredTimer("validator/rowconsumption", nil) + validateTraceTimer = metrics.NewRegisteredTimer("validator/trace", nil) + validateLockTimer = metrics.NewRegisteredTimer("validator/lock", nil) + validateCccTimer = metrics.NewRegisteredTimer("validator/ccc", nil) +) + // BlockValidator is responsible for validating block headers, uncles and // processed state. // @@ -182,6 +192,10 @@ func (v *BlockValidator) ValidateBody(block *types.Block) error { // - L1 messages follow the QueueIndex order. // - The L1 messages included in the block match the node's view of the L1 ledger. func (v *BlockValidator) ValidateL1Messages(block *types.Block) error { + defer func(t0 time.Time) { + validateL1MessagesTimer.Update(time.Since(t0)) + }(time.Now()) + // skip DB read if the block contains no L1 messages if !block.ContainsL1Messages() { return nil @@ -334,6 +348,10 @@ func (v *BlockValidator) createTraceEnvAndGetBlockTrace(block *types.Block) (*ty } func (v *BlockValidator) validateCircuitRowConsumption(block *types.Block) (*types.RowConsumption, error) { + defer func(t0 time.Time) { + validateRowConsumptionTimer.Update(time.Since(t0)) + }(time.Now()) + log.Trace( "Validator apply ccc for block", "id", v.circuitCapacityChecker.ID, @@ -342,17 +360,23 @@ func (v *BlockValidator) validateCircuitRowConsumption(block *types.Block) (*typ "len(txs)", block.Transactions().Len(), ) + traceStartTime := time.Now() traces, err := v.createTraceEnvAndGetBlockTrace(block) if err != nil { return nil, err } + validateTraceTimer.Update(time.Since(traceStartTime)) + lockStartTime := time.Now() v.cMu.Lock() defer v.cMu.Unlock() + validateLockTimer.Update(time.Since(lockStartTime)) + cccStartTime := time.Now() v.circuitCapacityChecker.Reset() log.Trace("Validator reset ccc", "id", v.circuitCapacityChecker.ID) rc, err := v.circuitCapacityChecker.ApplyBlock(traces) + validateCccTimer.Update(time.Since(cccStartTime)) log.Trace( "Validator apply ccc for block result", diff --git a/core/blockchain.go b/core/blockchain.go index 92de9aa35b..6db2b45d35 100644 --- a/core/blockchain.go +++ b/core/blockchain.go @@ -59,6 +59,9 @@ var ( headFastBlockGauge = metrics.NewRegisteredGauge("chain/head/receipt", nil) headFinalizedBlockGauge = metrics.NewRegisteredGauge("chain/head/finalized", nil) headSafeBlockGauge = metrics.NewRegisteredGauge("chain/head/safe", nil) + headTimeGapGauge = metrics.NewRegisteredGauge("chain/head/timegap", nil) + + l2BaseFeeGauge = metrics.NewRegisteredGauge("chain/fees/l2basefee", nil) chainInfoGauge = metrics.NewRegisteredGaugeInfo("chain/info", nil) @@ -1434,6 +1437,19 @@ func (bc *BlockChain) writeKnownBlock(block *types.Block) error { // writeBlockWithState writes block, metadata and corresponding state data to the // database. func (bc *BlockChain) writeBlockWithState(block *types.Block, receipts []*types.Receipt, state *state.StateDB) error { + // Note latest seen L2 base fee + if block.BaseFee() != nil { + l2BaseFeeGauge.Update(block.BaseFee().Int64()) + } else { + l2BaseFeeGauge.Update(0) + } + + parent := bc.GetHeaderByHash(block.ParentHash()) + // block.Time is guaranteed to be larger than parent.Time, + // and the time gap should fit into int64. + gap := int64(block.Time() - parent.Time) + headTimeGapGauge.Update(gap) + // Calculate the total difficulty of the block ptd := bc.GetTd(block.ParentHash(), block.NumberU64()-1) if ptd == nil { diff --git a/core/state_processor.go b/core/state_processor.go index d74ca7baee..9468055d21 100644 --- a/core/state_processor.go +++ b/core/state_processor.go @@ -20,6 +20,7 @@ import ( "errors" "fmt" "math/big" + "time" "github.com/scroll-tech/go-ethereum/common" "github.com/scroll-tech/go-ethereum/consensus" @@ -28,10 +29,20 @@ import ( "github.com/scroll-tech/go-ethereum/core/types" "github.com/scroll-tech/go-ethereum/core/vm" "github.com/scroll-tech/go-ethereum/crypto" + "github.com/scroll-tech/go-ethereum/metrics" "github.com/scroll-tech/go-ethereum/params" "github.com/scroll-tech/go-ethereum/rollup/fees" ) +var ( + processorBlockTransactionGauge = metrics.NewRegisteredGauge("processor/block/transactions", nil) + processBlockTimer = metrics.NewRegisteredTimer("processor/block/process", nil) + finalizeBlockTimer = metrics.NewRegisteredTimer("processor/block/finalize", nil) + applyTransactionTimer = metrics.NewRegisteredTimer("processor/tx/apply", nil) + applyMessageTimer = metrics.NewRegisteredTimer("processor/tx/msg/apply", nil) + updateStatedbTimer = metrics.NewRegisteredTimer("processor/tx/statedb/update", nil) +) + // StateProcessor is a basic Processor, which takes care of transitioning // state from one point to another. // @@ -59,6 +70,10 @@ func NewStateProcessor(config *params.ChainConfig, bc *BlockChain, engine consen // returns the amount of gas that was used in the process. If any of the // transactions failed to execute due to insufficient gas it will return an error. func (p *StateProcessor) Process(block *types.Block, statedb *state.StateDB, cfg vm.Config) (types.Receipts, []*types.Log, uint64, error) { + defer func(t0 time.Time) { + processBlockTimer.Update(time.Since(t0)) + }(time.Now()) + var ( receipts types.Receipts usedGas = new(uint64) @@ -84,6 +99,7 @@ func (p *StateProcessor) Process(block *types.Block, statedb *state.StateDB, cfg if beaconRoot := block.BeaconRoot(); beaconRoot != nil { ProcessBeaconBlockRoot(*beaconRoot, vmenv, statedb) } + processorBlockTransactionGauge.Update(int64(block.Transactions().Len())) // Iterate over and process the individual transactions for i, tx := range block.Transactions() { msg, err := TransactionToMessage(tx, signer, header.BaseFee) @@ -104,12 +120,18 @@ func (p *StateProcessor) Process(block *types.Block, statedb *state.StateDB, cfg return nil, nil, 0, errors.New("withdrawals before shanghai") } // Finalize the block, applying any consensus engine specific extras (e.g. block rewards) + finalizeBlockStartTime := time.Now() p.engine.Finalize(p.bc, header, statedb, block.Transactions(), block.Uncles(), withdrawals) + finalizeBlockTimer.Update(time.Since(finalizeBlockStartTime)) return receipts, allLogs, *usedGas, nil } func applyTransaction(msg *Message, config *params.ChainConfig, gp *GasPool, statedb *state.StateDB, blockNumber *big.Int, blockHash common.Hash, tx *types.Transaction, usedGas *uint64, evm *vm.EVM) (*types.Receipt, error) { + defer func(t0 time.Time) { + applyTransactionTimer.Update(time.Since(t0)) + }(time.Now()) + // Create a new context to be used in the EVM environment. txContext := NewEVMTxContext(msg) evm.Reset(txContext, statedb) @@ -120,18 +142,22 @@ func applyTransaction(msg *Message, config *params.ChainConfig, gp *GasPool, sta } // Apply the transaction to the current state (included in the env). + applyMessageStartTime := time.Now() result, err := ApplyMessage(evm, msg, gp, l1DataFee) + applyMessageTimer.Update(time.Since(applyMessageStartTime)) if err != nil { return nil, err } // Update the state with pending changes. var root []byte + updateStatedbStartTime := time.Now() if config.IsByzantium(blockNumber) { statedb.Finalise(true) } else { root = statedb.IntermediateRoot(config.IsEIP158(blockNumber)).Bytes() } + updateStatedbTimer.Update(time.Since(updateStatedbStartTime)) *usedGas += result.UsedGas // Create a new receipt for the transaction, storing the intermediate root and gas used diff --git a/core/state_transition.go b/core/state_transition.go index 916c49230d..9c84aaaf2a 100644 --- a/core/state_transition.go +++ b/core/state_transition.go @@ -21,15 +21,22 @@ import ( "fmt" "math" "math/big" + "time" "github.com/scroll-tech/go-ethereum/common" cmath "github.com/scroll-tech/go-ethereum/common/math" "github.com/scroll-tech/go-ethereum/core/types" "github.com/scroll-tech/go-ethereum/core/vm" "github.com/scroll-tech/go-ethereum/log" + "github.com/scroll-tech/go-ethereum/metrics" "github.com/scroll-tech/go-ethereum/params" ) +var ( + stateTransitionEvmCallExecutionTimer = metrics.NewRegisteredTimer("state/transition/call_execution", nil) + stateTransitionApplyMessageTimer = metrics.NewRegisteredTimer("state/transition/apply_message", nil) +) + // ExecutionResult includes all output after executing given evm // message no matter the execution itself is successful or not. type ExecutionResult struct { @@ -196,6 +203,10 @@ func TransactionToMessage(tx *types.Transaction, s types.Signer, baseFee *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() } @@ -463,7 +474,9 @@ func (st *StateTransition) TransitionDb() (*ExecutionResult, error) { } else { // Increment the nonce for the next transaction st.state.SetNonce(msg.From, st.state.GetNonce(sender.Address())+1) + evmCallStart := time.Now() ret, st.gasRemaining, vmerr = st.evm.Call(sender, st.to(), msg.Data, st.gasRemaining, msg.Value) + stateTransitionEvmCallExecutionTimer.Update(time.Since(evmCallStart)) } // no refunds for l1 messages diff --git a/rollup/sync_service/sync_service.go b/rollup/sync_service/sync_service.go index 05f95c47ab..091f2d1969 100644 --- a/rollup/sync_service/sync_service.go +++ b/rollup/sync_service/sync_service.go @@ -11,6 +11,7 @@ import ( "github.com/scroll-tech/go-ethereum/ethdb" "github.com/scroll-tech/go-ethereum/event" "github.com/scroll-tech/go-ethereum/log" + "github.com/scroll-tech/go-ethereum/metrics" "github.com/scroll-tech/go-ethereum/node" "github.com/scroll-tech/go-ethereum/params" ) @@ -35,6 +36,10 @@ const ( DbWriteThresholdBlocks = 1000 ) +var ( + l1MessageTotalCounter = metrics.NewRegisteredCounter("rollup/l1/message", nil) +) + // SyncService collects all L1 messages and stores them in a local database. type SyncService struct { ctx context.Context @@ -172,6 +177,7 @@ func (s *SyncService) fetchMessages() { numBlocksPendingDbWrite = 0 if numMessagesPendingDbWrite > 0 { + l1MessageTotalCounter.Inc(int64(numMessagesPendingDbWrite)) s.msgCountFeed.Send(core.NewL1MsgsEvent{Count: numMessagesPendingDbWrite}) numMessagesPendingDbWrite = 0 } diff --git a/rollup/tracing/tracing.go b/rollup/tracing/tracing.go index a906461b39..6ddd3c5ea9 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" @@ -21,12 +22,22 @@ 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" "github.com/scroll-tech/go-ethereum/rollup/withdrawtrie" ) +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{} @@ -191,7 +202,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 { @@ -213,27 +228,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, _ := core.TransactionToMessage(tx, env.signer, block.BaseFee()) - env.state.SetTxContext(tx.Hash(), i) - vmenv := vm.NewEVM(env.blockCtx, core.NewEVMTxContext(msg), env.state, env.chainConfig, vm.Config{}) - l1DataFee, err := fees.CalculateL1DataFee(tx, env.state, env.chainConfig, block.Number()) - if err != nil { - failed = err - break + // Generate the next state snapshot fast without tracing + msg, _ := core.TransactionToMessage(tx, env.signer, block.BaseFee()) + env.state.SetTxContext(tx.Hash(), i) + vmenv := vm.NewEVM(env.blockCtx, core.NewEVMTxContext(msg), env.state, env.chainConfig, vm.Config{}) + l1DataFee, err := fees.CalculateL1DataFee(tx, env.state, env.chainConfig, block.Number()) + if err != nil { + failed = err + break + } + if _, err = core.ApplyMessage(vmenv, msg, new(core.GasPool).AddGas(msg.GasLimit), l1DataFee); err != nil { + failed = err + break + } + if env.finaliseStateAfterApply { + env.state.Finalise(vmenv.ChainConfig().IsEIP158(block.Number())) + } } - if _, err = core.ApplyMessage(vmenv, msg, new(core.GasPool).AddGas(msg.GasLimit), l1DataFee); err != nil { - failed = err - break - } - if env.finaliseStateAfterApply { - env.state.Finalise(vmenv.ChainConfig().IsEIP158(block.Number())) - } - } + }) close(jobs) pend.Wait() @@ -301,6 +318,7 @@ func (env *TraceEnv) getTxResult(state *state.StateDB, index int, block *types.B } } + applyMessageStart := time.Now() structLogger := logger.NewStructLogger(env.logConfig) tracerContext := tracers.Context{ BlockHash: block.Hash(), @@ -331,8 +349,10 @@ func (env *TraceEnv) getTxResult(state *state.StateDB, index int, block *types.B } result, err := core.ApplyMessage(vmenv, msg, new(core.GasPool).AddGas(msg.GasLimit), 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 { @@ -407,6 +427,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 { @@ -476,11 +497,14 @@ 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) } + getTxResultTracerResultTimer.UpdateSince(tracerResultTimer) env.ExecutionResults[index] = &types.ExecutionResult{ From: sender, @@ -501,6 +525,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())