diff --git a/core/blockchain.go b/core/blockchain.go index 4fe4fcfbc1..b42db6368b 100644 --- a/core/blockchain.go +++ b/core/blockchain.go @@ -83,6 +83,14 @@ var ( blockExecutionTimer = metrics.NewRegisteredTimer("chain/execution", nil) blockWriteTimer = metrics.NewRegisteredTimer("chain/write", nil) + blockWriteExternalTimer = metrics.NewRegisteredTimer("chain/block/write/external", nil) + stateCommitExternalTimer = metrics.NewRegisteredTimer("chain/state/commit/external", nil) + triedbCommitExternalTimer = metrics.NewRegisteredTimer("chain/triedb/commit/external", nil) + innerExecutionTimer = metrics.NewRegisteredTimer("chain/inner/execution", nil) + + blockGasUsedGauge = metrics.NewRegisteredGauge("chain/block/gas/used", nil) + mgaspsGauge = metrics.NewRegisteredGauge("chain/mgas/ps", nil) + blockReorgMeter = metrics.NewRegisteredMeter("chain/reorg/executes", nil) blockReorgAddMeter = metrics.NewRegisteredMeter("chain/reorg/add", nil) blockReorgDropMeter = metrics.NewRegisteredMeter("chain/reorg/drop", nil) @@ -1440,6 +1448,7 @@ func (bc *BlockChain) writeBlockWithState(block *types.Block, receipts []*types. // // Note all the components of block(td, hash->number map, header, body, receipts) // should be written atomically. BlockBatch is used for containing all components. + start := time.Now() blockBatch := bc.db.NewBatch() rawdb.WriteTd(blockBatch, block.Hash(), block.NumberU64(), externTd) rawdb.WriteBlock(blockBatch, block) @@ -1448,17 +1457,29 @@ func (bc *BlockChain) writeBlockWithState(block *types.Block, receipts []*types. if err := blockBatch.Write(); err != nil { log.Crit("Failed to write block into disk", "err", err) } + blockWriteExternalTimer.UpdateSince(start) + log.Debug("blockWriteExternalTimer", "duration", common.PrettyDuration(time.Since(start)), "hash", block.Hash()) + // Commit all cached state changes into underlying memory database. + start = time.Now() root, err := state.Commit(block.NumberU64(), bc.chainConfig.IsEIP158(block.Number())) if err != nil { return err } + stateCommitExternalTimer.UpdateSince(start) + log.Debug("stateCommitExternalTimer", "duration", common.PrettyDuration(time.Since(start)), "hash", block.Hash()) + // If node is running in path mode, skip explicit gc operation // which is unnecessary in this mode. if bc.triedb.Scheme() == rawdb.PathScheme { return nil } // If we're running an archive node, always flush + start = time.Now() + defer func () { + triedbCommitExternalTimer.UpdateSince(start) + log.Debug("triedbCommitExternalTimer", "duration", common.PrettyDuration(time.Since(start)), "hash", block.Hash()) + } () if bc.cacheConfig.TrieDirtyDisabled { return bc.triedb.Commit(root, false) } @@ -1763,7 +1784,11 @@ func (bc *BlockChain) insertChain(chain types.Blocks, setHead bool) (int, error) } }() + defer func () { + DebugInnerExecutionDuration = 0 + }() for ; block != nil && err == nil || errors.Is(err, ErrKnownBlock); block, err = it.next() { + DebugInnerExecutionDuration = 0 // If the chain is terminating, stop processing blocks if bc.insertStopped() { log.Debug("Abort during block processing") @@ -1890,12 +1915,12 @@ func (bc *BlockChain) insertChain(chain types.Blocks, setHead bool) (int, error) storageUpdateTimer.Update(statedb.StorageUpdates) // Storage updates are complete(in validation) accountHashTimer.Update(statedb.AccountHashes) // Account hashes are complete(in validation) storageHashTimer.Update(statedb.StorageHashes) // Storage hashes are complete(in validation) - triehash := statedb.AccountHashes + statedb.StorageHashes // The time spent on tries hashing - trieUpdate := statedb.AccountUpdates + statedb.StorageUpdates // The time spent on tries update - trieRead := statedb.SnapshotAccountReads + statedb.AccountReads // The time spent on account read - trieRead += statedb.SnapshotStorageReads + statedb.StorageReads // The time spent on storage read - blockExecutionTimer.Update(ptime - trieRead) // The time spent on EVM processing - blockValidationTimer.Update(vtime - (triehash + trieUpdate)) // The time spent on block validation + blockExecutionTimer.Update(ptime) // The time spent on block execution + blockValidationTimer.Update(vtime) // The time spent on block validation + + innerExecutionTimer.Update(DebugInnerExecutionDuration) + + log.Debug("New payload execution and validation metrics", "hash", block.Hash(), "execution", common.PrettyDuration(ptime), "validation", common.PrettyDuration(vtime), "accountReads", common.PrettyDuration(statedb.AccountReads), "storageReads", common.PrettyDuration(statedb.StorageReads), "snapshotAccountReads", common.PrettyDuration(statedb.SnapshotAccountReads), "snapshotStorageReads", common.PrettyDuration(statedb.SnapshotStorageReads), "accountUpdates", common.PrettyDuration(statedb.AccountUpdates), "storageUpdates", common.PrettyDuration(statedb.StorageUpdates), "accountHashes", common.PrettyDuration(statedb.AccountHashes), "storageHashes", common.PrettyDuration(statedb.StorageHashes)) // Write the block to the chain and get the status. var ( @@ -1918,9 +1943,11 @@ func (bc *BlockChain) insertChain(chain types.Blocks, setHead bool) (int, error) snapshotCommitTimer.Update(statedb.SnapshotCommits) // Snapshot commits are complete, we can mark them triedbCommitTimer.Update(statedb.TrieDBCommits) // Trie database commits are complete, we can mark them - blockWriteTimer.Update(time.Since(wstart) - statedb.AccountCommits - statedb.StorageCommits - statedb.SnapshotCommits - statedb.TrieDBCommits) + blockWriteTimer.UpdateSince(wstart) blockInsertTimer.UpdateSince(start) + log.Debug("New payload db write metrics", "hash", block.Hash(), "insert", common.PrettyDuration(time.Since(start)), "writeDB", common.PrettyDuration(time.Since(wstart)), "writeBlock", common.PrettyDuration(time.Since(wstart)), "accountCommit", common.PrettyDuration(statedb.AccountCommits), "storageCommit", common.PrettyDuration(statedb.StorageCommits), "snapshotCommits", common.PrettyDuration(statedb.SnapshotCommits), "triedbCommit", common.PrettyDuration(statedb.TrieDBCommits)) + // Report the import stats before returning the various results stats.processed++ stats.usedGas += usedGas @@ -1931,6 +1958,7 @@ func (bc *BlockChain) insertChain(chain types.Blocks, setHead bool) (int, error) } trieDiffNodes, trieBufNodes, trieImmutableBufNodes, _ := bc.triedb.Size() stats.report(chain, it.index, snapDiffItems, snapBufItems, trieDiffNodes, trieBufNodes, trieImmutableBufNodes, setHead) + blockGasUsedGauge.Update(int64(block.GasUsed())/1000000) if !setHead { // After merge we expect few side chains. Simply count diff --git a/core/blockchain_insert.go b/core/blockchain_insert.go index 83a4cea5dc..82a480d0be 100644 --- a/core/blockchain_insert.go +++ b/core/blockchain_insert.go @@ -60,6 +60,7 @@ func (st *insertStats) report(chain []*types.Block, index int, snapDiffItems, sn "blocks", st.processed, "txs", txs, "mgas", float64(st.usedGas) / 1000000, "elapsed", common.PrettyDuration(elapsed), "mgasps", float64(st.usedGas) * 1000 / float64(elapsed), } + mgaspsGauge.Update(int64(st.usedGas)*1000/int64(elapsed)) if timestamp := time.Unix(int64(end.Time()), 0); time.Since(timestamp) > time.Minute { context = append(context, []interface{}{"age", common.PrettyAge(timestamp)}...) } diff --git a/core/rawdb/accessors_snapshot.go b/core/rawdb/accessors_snapshot.go index 3c82b3f731..5e0d6b67c5 100644 --- a/core/rawdb/accessors_snapshot.go +++ b/core/rawdb/accessors_snapshot.go @@ -18,10 +18,12 @@ package rawdb import ( "encoding/binary" + "time" "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/ethdb" "github.com/ethereum/go-ethereum/log" + "github.com/ethereum/go-ethereum/metrics" ) // ReadSnapshotDisabled retrieves if the snapshot maintenance is disabled. @@ -74,6 +76,10 @@ func DeleteSnapshotRoot(db ethdb.KeyValueWriter) { // ReadAccountSnapshot retrieves the snapshot entry of an account trie leaf. func ReadAccountSnapshot(db ethdb.KeyValueReader, hash common.Hash) []byte { + if metrics.EnabledExpensive { + start := time.Now() + defer func() { rawdbGetAccountSnapNodeTimer.UpdateSince(start) }() + } data, _ := db.Get(accountSnapshotKey(hash)) return data } @@ -94,6 +100,10 @@ func DeleteAccountSnapshot(db ethdb.KeyValueWriter, hash common.Hash) { // ReadStorageSnapshot retrieves the snapshot entry of an storage trie leaf. func ReadStorageSnapshot(db ethdb.KeyValueReader, accountHash, storageHash common.Hash) []byte { + if metrics.EnabledExpensive { + start := time.Now() + defer func() { rawdbGetStorageSnapNodeTimer.UpdateSince(start) }() + } data, _ := db.Get(storageSnapshotKey(accountHash, storageHash)) return data } diff --git a/core/rawdb/accessors_trie.go b/core/rawdb/accessors_trie.go index 78f1a70b1c..4284fb6ff7 100644 --- a/core/rawdb/accessors_trie.go +++ b/core/rawdb/accessors_trie.go @@ -19,11 +19,13 @@ package rawdb import ( "fmt" "sync" + "time" "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/crypto" "github.com/ethereum/go-ethereum/ethdb" "github.com/ethereum/go-ethereum/log" + "github.com/ethereum/go-ethereum/metrics" "golang.org/x/crypto/sha3" ) @@ -68,6 +70,10 @@ func (h *hasher) release() { // ReadAccountTrieNode retrieves the account trie node and the associated node // hash with the specified node path. func ReadAccountTrieNode(db ethdb.KeyValueReader, path []byte) ([]byte, common.Hash) { + if metrics.EnabledExpensive { + start := time.Now() + defer func() { rawdbGetAccountTrieNodeTimer.UpdateSince(start) }() + } data, err := db.Get(accountTrieNodeKey(path)) if err != nil { return nil, common.Hash{} @@ -116,6 +122,10 @@ func DeleteAccountTrieNode(db ethdb.KeyValueWriter, path []byte) { // ReadStorageTrieNode retrieves the storage trie node and the associated node // hash with the specified node path. func ReadStorageTrieNode(db ethdb.KeyValueReader, accountHash common.Hash, path []byte) ([]byte, common.Hash) { + if metrics.EnabledExpensive { + start := time.Now() + defer func() { rawdbGetStorageTrieNodeTimer.UpdateSince(start) }() + } data, err := db.Get(storageTrieNodeKey(accountHash, path)) if err != nil { return nil, common.Hash{} diff --git a/core/rawdb/metrics.go b/core/rawdb/metrics.go new file mode 100644 index 0000000000..b4c09f8689 --- /dev/null +++ b/core/rawdb/metrics.go @@ -0,0 +1,10 @@ +package rawdb + +import "github.com/ethereum/go-ethereum/metrics" + +var ( + rawdbGetAccountTrieNodeTimer = metrics.NewRegisteredTimer("rawdb/get/account/trienode/time", nil) + rawdbGetStorageTrieNodeTimer = metrics.NewRegisteredTimer("rawdb/get/storage/trienode/time", nil) + rawdbGetAccountSnapNodeTimer = metrics.NewRegisteredTimer("rawdb/get/account/snapnode/time", nil) + rawdbGetStorageSnapNodeTimer = metrics.NewRegisteredTimer("rawdb/get/storage/snapnode/time", nil) +) diff --git a/core/state_processor.go b/core/state_processor.go index 8b13aa0eb3..f84007cbbe 100644 --- a/core/state_processor.go +++ b/core/state_processor.go @@ -20,6 +20,7 @@ import ( "errors" "fmt" "math/big" + "time" "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/consensus" @@ -28,9 +29,12 @@ import ( "github.com/ethereum/go-ethereum/core/types" "github.com/ethereum/go-ethereum/core/vm" "github.com/ethereum/go-ethereum/crypto" + "github.com/ethereum/go-ethereum/metrics" "github.com/ethereum/go-ethereum/params" ) +var processTxTimer = metrics.NewRegisteredTimer("process/tx/time", nil) + // StateProcessor is a basic Processor, which takes care of transitioning // state from one point to another. // @@ -88,6 +92,7 @@ func (p *StateProcessor) Process(block *types.Block, statedb *state.StateDB, cfg } // Iterate over and process the individual transactions for i, tx := range block.Transactions() { + start := time.Now() msg, err := TransactionToMessage(tx, signer, header.BaseFee) if err != nil { return nil, nil, 0, fmt.Errorf("could not apply tx %d [%v]: %w", i, tx.Hash().Hex(), err) @@ -99,6 +104,9 @@ func (p *StateProcessor) Process(block *types.Block, statedb *state.StateDB, cfg } receipts = append(receipts, receipt) allLogs = append(allLogs, receipt.Logs...) + if metrics.EnabledExpensive { + processTxTimer.UpdateSince(start) + } } // Fail if Shanghai not enabled and len(withdrawals) is non-zero. withdrawals := block.Withdrawals() diff --git a/core/state_transition.go b/core/state_transition.go index f4a8e44e72..8e459d4eeb 100644 --- a/core/state_transition.go +++ b/core/state_transition.go @@ -21,6 +21,7 @@ import ( "fmt" "math" "math/big" + "time" "github.com/ethereum/go-ethereum/common" cmath "github.com/ethereum/go-ethereum/common/math" @@ -29,6 +30,9 @@ import ( "github.com/ethereum/go-ethereum/params" ) +// TODO delete after debug performance metrics +var DebugInnerExecutionDuration time.Duration + // ExecutionResult includes all output after executing given evm // message no matter the execution itself is successful or not. type ExecutionResult struct { @@ -473,6 +477,7 @@ func (st *StateTransition) innerTransitionDb() (*ExecutionResult, error) { ret []byte vmerr error // vm errors do not effect consensus and are therefore not assigned to err ) + start := time.Now() if contractCreation { ret, _, st.gasRemaining, vmerr = st.evm.Create(sender, msg.Data, st.gasRemaining, msg.Value) } else { @@ -480,6 +485,7 @@ func (st *StateTransition) innerTransitionDb() (*ExecutionResult, error) { st.state.SetNonce(msg.From, st.state.GetNonce(sender.Address())+1) ret, st.gasRemaining, vmerr = st.evm.Call(sender, st.to(), msg.Data, st.gasRemaining, msg.Value) } + DebugInnerExecutionDuration += time.Since(start) // if deposit: skip refunds, skip tipping coinbase // Regolith changes this behaviour to report the actual gasUsed instead of always reporting all gas used. diff --git a/eth/catalyst/api.go b/eth/catalyst/api.go index 69599d8c6c..60858b8230 100644 --- a/eth/catalyst/api.go +++ b/eth/catalyst/api.go @@ -32,11 +32,19 @@ import ( "github.com/ethereum/go-ethereum/eth" "github.com/ethereum/go-ethereum/eth/downloader" "github.com/ethereum/go-ethereum/log" + "github.com/ethereum/go-ethereum/metrics" "github.com/ethereum/go-ethereum/miner" "github.com/ethereum/go-ethereum/node" "github.com/ethereum/go-ethereum/rpc" ) +var ( + forkchoiceUpdateAttributesTimer = metrics.NewRegisteredTimer("api/engine/forkchoiceUpdate/attributes", nil) + forkchoiceUpdateHeadsTimer = metrics.NewRegisteredTimer("api/engine/forkchoiceUpdate/heads", nil) + getPayloadTimer = metrics.NewRegisteredTimer("api/engine/get/payload", nil) + newPayloadTimer = metrics.NewRegisteredTimer("api/engine/new/payload", nil) +) + // Register adds the engine API to the full node. func Register(stack *node.Node, backend *eth.Ethereum) error { log.Warn("Engine API enabled", "protocol", "eth") @@ -228,6 +236,8 @@ func checkAttribute(active func(*big.Int, uint64) bool, exists bool, block *big. } func (api *ConsensusAPI) forkchoiceUpdated(update engine.ForkchoiceStateV1, payloadAttributes *engine.PayloadAttributes) (engine.ForkChoiceResponse, error) { + start := time.Now() + api.forkchoiceLock.Lock() defer api.forkchoiceLock.Unlock() @@ -398,8 +408,12 @@ func (api *ConsensusAPI) forkchoiceUpdated(update engine.ForkchoiceStateV1, payl return valid(nil), engine.InvalidPayloadAttributes.With(err) } api.localBlocks.put(id, payload) + forkchoiceUpdateAttributesTimer.UpdateSince(start) + log.Debug("forkchoiceUpdateAttributesTimer", "duration", common.PrettyDuration(time.Since(start)), "id", id) return valid(&id), nil } + forkchoiceUpdateHeadsTimer.UpdateSince(start) + log.Debug("forkchoiceUpdateAttributesTimer", "duration", common.PrettyDuration(time.Since(start)), "hash", update.HeadBlockHash) return valid(nil), nil } @@ -453,6 +467,11 @@ func (api *ConsensusAPI) GetPayloadV3(payloadID engine.PayloadID) (*engine.Execu } func (api *ConsensusAPI) getPayload(payloadID engine.PayloadID, full bool) (*engine.ExecutionPayloadEnvelope, error) { + start := time.Now() + defer func () { + getPayloadTimer.UpdateSince(start) + log.Debug("getPayloadTimer", "duration", common.PrettyDuration(time.Since(start)), "id", payloadID) + } () log.Trace("Engine API request received", "method", "GetPayload", "id", payloadID) data := api.localBlocks.get(payloadID, full) if data == nil { @@ -507,6 +526,12 @@ func (api *ConsensusAPI) NewPayloadV3(params engine.ExecutableData, versionedHas } func (api *ConsensusAPI) newPayload(params engine.ExecutableData, versionedHashes []common.Hash, beaconRoot *common.Hash) (engine.PayloadStatusV1, error) { + start := time.Now() + defer func () { + newPayloadTimer.UpdateSince(start) + log.Debug("newPayloadTimer", "duration", common.PrettyDuration(time.Since(start)), "parentHash", params.ParentHash) + } () + // The locking here is, strictly, not required. Without these locks, this can happen: // // 1. NewPayload( execdata-N ) is invoked from the CL. It goes all the way down to diff --git a/ethdb/metrics.go b/ethdb/metrics.go new file mode 100644 index 0000000000..39133a7243 --- /dev/null +++ b/ethdb/metrics.go @@ -0,0 +1,10 @@ +package ethdb + +import "github.com/ethereum/go-ethereum/metrics" + +var ( + EthdbGetTimer = metrics.NewRegisteredTimer("ethdb/get/time", nil) + EthdbPutTimer = metrics.NewRegisteredTimer("ethdb/put/time", nil) + EthdbDeleteTimer = metrics.NewRegisteredTimer("ethdb/delete/time", nil) + EthdbBatchWriteTimer = metrics.NewRegisteredTimer("ethdb/batch/write/time", nil) +) diff --git a/ethdb/pebble/pebble.go b/ethdb/pebble/pebble.go index ae0039f41e..56e1aa92d8 100644 --- a/ethdb/pebble/pebble.go +++ b/ethdb/pebble/pebble.go @@ -299,6 +299,10 @@ func (d *Database) Has(key []byte) (bool, error) { // Get retrieves the given key if it's present in the key-value store. func (d *Database) Get(key []byte) ([]byte, error) { + if metrics.EnabledExpensive { + start := time.Now() + defer func() { ethdb.EthdbGetTimer.UpdateSince(start) }() + } d.quitLock.RLock() defer d.quitLock.RUnlock() if d.closed { @@ -316,6 +320,10 @@ func (d *Database) Get(key []byte) ([]byte, error) { // Put inserts the given value into the key-value store. func (d *Database) Put(key []byte, value []byte) error { + if metrics.EnabledExpensive { + start := time.Now() + defer func() { ethdb.EthdbPutTimer.UpdateSince(start) }() + } d.quitLock.RLock() defer d.quitLock.RUnlock() if d.closed { @@ -326,6 +334,10 @@ func (d *Database) Put(key []byte, value []byte) error { // Delete removes the key from the key-value store. func (d *Database) Delete(key []byte) error { + if metrics.EnabledExpensive { + start := time.Now() + defer func() { ethdb.EthdbDeleteTimer.UpdateSince(start) }() + } d.quitLock.RLock() defer d.quitLock.RUnlock() if d.closed { @@ -482,6 +494,7 @@ func (d *Database) meter(refresh time.Duration, namespace string) { nonLevel0CompCount = int64(d.nonLevel0Comp.Load()) level0CompCount = int64(d.level0Comp.Load()) ) + d.log.Info("loop print db stats", "comp_time", compTime, "write_delay_count", writeDelayCount, "write_delay_time", writeDelayTime, "non_level0_comp_count", nonLevel0CompCount, "level0_comp_count", level0CompCount) writeDelayTimes[i%2] = writeDelayTime writeDelayCounts[i%2] = writeDelayCount compTimes[i%2] = compTime @@ -580,6 +593,10 @@ func (b *batch) ValueSize() int { // Write flushes any accumulated data to disk. func (b *batch) Write() error { + if metrics.EnabledExpensive { + start := time.Now() + defer func() { ethdb.EthdbBatchWriteTimer.UpdateSince(start) }() + } b.db.quitLock.RLock() defer b.db.quitLock.RUnlock() if b.db.closed { diff --git a/miner/miner.go b/miner/miner.go index 82d353a336..5c0ba3f815 100644 --- a/miner/miner.go +++ b/miner/miner.go @@ -35,9 +35,35 @@ import ( "github.com/ethereum/go-ethereum/eth/tracers" "github.com/ethereum/go-ethereum/event" "github.com/ethereum/go-ethereum/log" + "github.com/ethereum/go-ethereum/metrics" "github.com/ethereum/go-ethereum/params" ) +var ( + commitDepositTxsTimer = metrics.NewRegisteredTimer("miner/commit/deposit/txs", nil) + packFromTxpoolTimer = metrics.NewRegisteredTimer("miner/pack/txpool/txs", nil) + commitTxpoolTxsTimer = metrics.NewRegisteredTimer("miner/commit/txpool/txs", nil) + assembleBlockTimer = metrics.NewRegisteredTimer("miner/assemble/block", nil) + buildBlockTimer = metrics.NewRegisteredTimer("miner/build/block", nil) + + accountReadTimer = metrics.NewRegisteredTimer("miner/account/reads", nil) + accountHashTimer = metrics.NewRegisteredTimer("miner/account/hashes", nil) + accountUpdateTimer = metrics.NewRegisteredTimer("miner/account/updates", nil) + + storageReadTimer = metrics.NewRegisteredTimer("miner/storage/reads", nil) + storageHashTimer = metrics.NewRegisteredTimer("miner/storage/hashes", nil) + storageUpdateTimer = metrics.NewRegisteredTimer("miner/storage/updates", nil) + + innerExecutionTimer = metrics.NewRegisteredTimer("miner/inner/execution", nil) + + snapshotAccountReadTimer = metrics.NewRegisteredTimer("miner/snapshot/account/reads", nil) + snapshotStorageReadTimer = metrics.NewRegisteredTimer("miner/snapshot/storage/reads", nil) + + waitPayloadTimer = metrics.NewRegisteredTimer("miner/wait/payload", nil) + + isBuildBlockInterruptCounter = metrics.NewRegisteredCounter("miner/build/interrupt", nil) +) + // Backend wraps all methods required for mining. Only full node is capable // to offer all the functions here. type Backend interface { diff --git a/miner/payload_building.go b/miner/payload_building.go index ed1916e3c0..f3b8382783 100644 --- a/miner/payload_building.go +++ b/miner/payload_building.go @@ -164,6 +164,7 @@ func (payload *Payload) update(r *newPayloadResult, elapsed time.Duration, postF postFunc() } } + buildBlockTimer.Update(elapsed) } } @@ -211,7 +212,10 @@ func (payload *Payload) resolve(onlyFull bool) *engine.ExecutionPayloadEnvelope // Wait the full payload construction. Note it might block // forever if Resolve is called in the meantime which // terminates the background construction process. + start := time.Now() payload.cond.Wait() + waitPayloadTimer.UpdateSince(start) + log.Debug("waitPayloadTimer", "duration", common.PrettyDuration(time.Since(start)), "id", payload.id) } // Now we can signal the building routine to stop. diff --git a/miner/worker.go b/miner/worker.go index 7b4b2a2676..8b03825cbf 100644 --- a/miner/worker.go +++ b/miner/worker.go @@ -1090,7 +1090,10 @@ func (w *worker) fillTransactions(interrupt *atomic.Int32, env *environment) err } } + start := time.Now() pending := w.eth.TxPool().Pending(true) + packFromTxpoolTimer.UpdateSince(start) + log.Debug("packFromTxpoolTimer", "duration", common.PrettyDuration(time.Since(start)), "hash", env.header.Hash()) // Split the pending transactions into locals and remotes. localTxs, remoteTxs := make(map[common.Address][]*txpool.LazyTransaction), pending @@ -1104,6 +1107,7 @@ func (w *worker) fillTransactions(interrupt *atomic.Int32, env *environment) err // } // Fill the block with all available pending transactions. + start = time.Now() if len(localTxs) > 0 { txs := newTransactionsByPriceAndNonce(env.signer, localTxs, env.header.BaseFee) if err := w.commitTransactions(env, txs, interrupt); err != nil { @@ -1116,11 +1120,19 @@ func (w *worker) fillTransactions(interrupt *atomic.Int32, env *environment) err return err } } + commitTxpoolTxsTimer.UpdateSince(start) + log.Debug("commitTxpoolTxsTimer", "duration", common.PrettyDuration(time.Since(start)), "hash", env.header.Hash()) return nil } // generateWork generates a sealing block based on the given parameters. func (w *worker) generateWork(genParams *generateParams) *newPayloadResult { + // TODO delete after debug performance metrics + core.DebugInnerExecutionDuration = 0 + defer func () { + core.DebugInnerExecutionDuration = 0 + }() + work, err := w.prepareWork(genParams) if err != nil { return &newPayloadResult{err: err} @@ -1137,6 +1149,7 @@ func (w *worker) generateWork(genParams *generateParams) *newPayloadResult { // opBNB no need to hard code this contract via hardfork // misc.EnsureCreate2Deployer(w.chainConfig, work.header.Time, work.state) + start := time.Now() for _, tx := range genParams.txs { from, _ := types.Sender(work.signer, tx) work.state.SetTxContext(tx.Hash(), work.tcount) @@ -1146,6 +1159,8 @@ func (w *worker) generateWork(genParams *generateParams) *newPayloadResult { } work.tcount++ } + commitDepositTxsTimer.UpdateSince(start) + log.Debug("commitDepositTxsTimer", "duration", common.PrettyDuration(time.Since(start)), "parentHash", genParams.parentHash) // forced transactions done, fill rest of block with transactions if !genParams.noTxs { @@ -1161,19 +1176,38 @@ func (w *worker) generateWork(genParams *generateParams) *newPayloadResult { err := w.fillTransactions(interrupt, work) timer.Stop() // don't need timeout interruption any more if errors.Is(err, errBlockInterruptedByTimeout) { - log.Warn("Block building is interrupted", "allowance", common.PrettyDuration(w.newpayloadTimeout)) + log.Warn("Block building is interrupted", "allowance", common.PrettyDuration(w.newpayloadTimeout), "parentHash", genParams.parentHash) + isBuildBlockInterruptCounter.Inc(1) } else if errors.Is(err, errBlockInterruptedByResolve) { - log.Info("Block building got interrupted by payload resolution") + log.Info("Block building got interrupted by payload resolution", "parentHash", genParams.parentHash) + isBuildBlockInterruptCounter.Inc(1) } } if intr := genParams.interrupt; intr != nil && genParams.isUpdate && intr.Load() != commitInterruptNone { return &newPayloadResult{err: errInterruptedUpdate} } + start = time.Now() block, err := w.engine.FinalizeAndAssemble(w.chain, work.header, work.state, work.txs, nil, work.receipts, genParams.withdrawals) if err != nil { return &newPayloadResult{err: err} } + assembleBlockTimer.UpdateSince(start) + log.Debug("assembleBlockTimer", "duration", common.PrettyDuration(time.Since(start)), "parentHash", genParams.parentHash) + + accountReadTimer.Update(work.state.AccountReads) // Account reads are complete(in commit txs) + storageReadTimer.Update(work.state.StorageReads) // Storage reads are complete(in commit txs) + snapshotAccountReadTimer.Update(work.state.SnapshotAccountReads) // Account reads are complete(in commit txs) + snapshotStorageReadTimer.Update(work.state.SnapshotStorageReads) // Storage reads are complete(in commit txs) + accountUpdateTimer.Update(work.state.AccountUpdates) // Account updates are complete(in FinalizeAndAssemble) + storageUpdateTimer.Update(work.state.StorageUpdates) // Storage updates are complete(in FinalizeAndAssemble) + accountHashTimer.Update(work.state.AccountHashes) // Account hashes are complete(in FinalizeAndAssemble) + storageHashTimer.Update(work.state.StorageHashes) // Storage hashes are complete(in FinalizeAndAssemble) + + innerExecutionTimer.Update(core.DebugInnerExecutionDuration) + + log.Debug("build payload statedb metrics", "parentHash", genParams.parentHash, "accountReads", common.PrettyDuration(work.state.AccountReads), "storageReads", common.PrettyDuration(work.state.StorageReads), "snapshotAccountReads", common.PrettyDuration(work.state.SnapshotAccountReads), "snapshotStorageReads", common.PrettyDuration(work.state.SnapshotStorageReads), "accountUpdates", common.PrettyDuration(work.state.AccountUpdates), "storageUpdates", common.PrettyDuration(work.state.StorageUpdates), "accountHashes", common.PrettyDuration(work.state.AccountHashes), "storageHashes", common.PrettyDuration(work.state.StorageHashes)) + return &newPayloadResult{ block: block, fees: totalFees(block, work.receipts), diff --git a/trie/trie.go b/trie/trie.go index 07467ac69c..f4d4d9963c 100644 --- a/trie/trie.go +++ b/trie/trie.go @@ -21,13 +21,21 @@ import ( "bytes" "errors" "fmt" + "time" "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/core/types" "github.com/ethereum/go-ethereum/log" + "github.com/ethereum/go-ethereum/metrics" "github.com/ethereum/go-ethereum/trie/trienode" ) +var ( + trieGetTimer = metrics.NewRegisteredTimer("trie/get/time", nil) + trieReaderGetTimer = metrics.NewRegisteredTimer("trie/reader/get/time", nil) + trieReaderTotalTimer = metrics.NewRegisteredTimer("trie/reader/total/time", nil) +) + // Trie is a Merkle Patricia Trie. Use New to create a trie that sits on // top of a database. Whenever trie performs a commit operation, the generated // nodes will be gathered and returned in a set. Once the trie is committed, @@ -145,6 +153,10 @@ func (t *Trie) Get(key []byte) ([]byte, error) { if t.committed { return nil, ErrCommitted } + if metrics.EnabledExpensive { + start := time.Now() + defer func() { trieGetTimer.UpdateSince(start) }() + } value, newroot, didResolve, err := t.get(t.root, keybytesToHex(key), 0) if err == nil && didResolve { t.root = newroot @@ -177,7 +189,11 @@ func (t *Trie) get(origNode node, key []byte, pos int) (value []byte, newnode no } return value, n, didResolve, err case hashNode: + start := time.Now() child, err := t.resolveAndTrack(n, key[:pos]) + if metrics.EnabledExpensive { + trieReaderGetTimer.UpdateSince(start) + } if err != nil { return nil, n, true, err } @@ -585,6 +601,10 @@ func (t *Trie) resolve(n node, prefix []byte) (node, error) { // node's original value. The rlp-encoded blob is preferred to be loaded from // database because it's easy to decode node while complex to encode node to blob. func (t *Trie) resolveAndTrack(n hashNode, prefix []byte) (node, error) { + if metrics.EnabledExpensive { + start := time.Now() + defer func() { trieReaderTotalTimer.UpdateSince(start) }() + } blob, err := t.reader.node(prefix, common.BytesToHash(n)) if err != nil { return nil, err