diff --git a/consensus/parlia/parlia.go b/consensus/parlia/parlia.go index e6b84a15f9..7988fc1e56 100644 --- a/consensus/parlia/parlia.go +++ b/consensus/parlia/parlia.go @@ -39,6 +39,7 @@ import ( "github.com/ethereum/go-ethereum/core/vm" "github.com/ethereum/go-ethereum/crypto" "github.com/ethereum/go-ethereum/ethdb" + "github.com/ethereum/go-ethereum/internal/debug" "github.com/ethereum/go-ethereum/internal/ethapi" "github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/metrics" @@ -1131,6 +1132,7 @@ func (p *Parlia) NextInTurnValidator(chain consensus.ChainHeaderReader, header * // Prepare implements consensus.Engine, preparing all the consensus fields of the // header for running the transactions on top. func (p *Parlia) Prepare(chain consensus.ChainHeaderReader, header *types.Header) error { + defer debug.Handler.StartRegionAuto("Parlia-Prepare")() header.Coinbase = p.val header.Nonce = types.BlockNonce{} @@ -1476,6 +1478,7 @@ func (p *Parlia) Finalize(chain consensus.ChainHeaderReader, header *types.Heade // nor block rewards given, and returns the final block. func (p *Parlia) FinalizeAndAssemble(chain consensus.ChainHeaderReader, header *types.Header, state *state.StateDB, body *types.Body, receipts []*types.Receipt, tracer *tracing.Hooks) (*types.Block, []*types.Receipt, error) { + defer debug.Handler.StartRegionAuto("FinalizeAndAssemble")() // No block rewards in PoA, so the state remains as is and uncles are dropped cx := chainContext{Chain: chain, parlia: p} @@ -1679,6 +1682,7 @@ func (p *Parlia) Delay(chain consensus.ChainReader, header *types.Header, leftOv // Seal implements consensus.Engine, attempting to create a sealed block using // the local signing credentials. func (p *Parlia) Seal(chain consensus.ChainHeaderReader, block *types.Block, results chan<- *types.Block, stop <-chan struct{}) error { + defer debug.Handler.StartRegionAuto("Seal")() header := block.Header() // Sealing the genesis block is not supported @@ -1715,12 +1719,14 @@ func (p *Parlia) Seal(chain consensus.ChainHeaderReader, block *types.Block, res // Wait until sealing is terminated or delay timeout. log.Trace("Waiting for slot to sign and propagate", "delay", common.PrettyDuration(delay)) go func() { + defer debug.Handler.StartRegionAuto("Seal-1")() select { case <-stop: return case <-time.After(delay): } + defer debug.Handler.StartRegionAuto("Seal-2")() err := p.assembleVoteAttestation(chain, header) if err != nil { /* If the vote attestation can't be assembled successfully, the blockchain won't get @@ -1737,6 +1743,7 @@ func (p *Parlia) Seal(chain consensus.ChainHeaderReader, block *types.Block, res copy(header.Extra[len(header.Extra)-extraSeal:], sig) if p.shouldWaitForCurrentBlockProcess(chain, header, snap) { + defer debug.Handler.StartRegionAuto("Seal-3")() highestVerifiedHeader := chain.GetHighestVerifiedHeader() // including time for writing and committing blocks waitProcessEstimate := math.Ceil(float64(highestVerifiedHeader.GasUsed) / float64(100_000_000)) @@ -1754,6 +1761,7 @@ func (p *Parlia) Seal(chain consensus.ChainHeaderReader, block *types.Block, res } } + defer debug.Handler.StartRegionAuto("Seal-4")() select { case results <- block.WithSeal(header): default: diff --git a/core/block_validator.go b/core/block_validator.go index 066b2111af..141c8324d2 100644 --- a/core/block_validator.go +++ b/core/block_validator.go @@ -23,6 +23,7 @@ import ( "github.com/ethereum/go-ethereum/consensus" "github.com/ethereum/go-ethereum/core/state" "github.com/ethereum/go-ethereum/core/types" + "github.com/ethereum/go-ethereum/internal/debug" "github.com/ethereum/go-ethereum/params" "github.com/ethereum/go-ethereum/trie" ) @@ -164,6 +165,7 @@ func (v *BlockValidator) ValidateState(block *types.Block, statedb *state.StateD if res == nil { return errors.New("nil ProcessResult value") } + defer debug.Handler.StartRegionAuto("BlockValidator.ValidateState")() header := block.Header() if block.GasUsed() != res.GasUsed { return fmt.Errorf("invalid gas used (remote: %d local: %d)", block.GasUsed(), res.GasUsed) @@ -173,6 +175,7 @@ func (v *BlockValidator) ValidateState(block *types.Block, statedb *state.StateD validateFuns := []func() error{ func() error { rbloom := types.CreateBloom(res.Receipts) + defer debug.Handler.StartRegionAuto("Create Receipt Bloom")() if rbloom != header.Bloom { return fmt.Errorf("invalid bloom (remote: %x local: %x)", header.Bloom, rbloom) } @@ -185,7 +188,13 @@ func (v *BlockValidator) ValidateState(block *types.Block, statedb *state.StateD validateFuns = append(validateFuns, func() error { // The receipt Trie's root (R = (Tr [[H1, R1], ... [Hn, Rn]])) receiptSha := types.DeriveSha(res.Receipts, trie.NewStackTrie(nil)) + defer debug.Handler.StartRegionAuto("Create Receipt Root Hash")() if receiptSha != header.ReceiptHash { + // debug.Handler.LogWhenTracing("block " + block.Number().String() + + // " len(receipts):" + strconv.Itoa(len(receipts))) + // for index, r := range receipts { + // r.DumpWhenTrace(block.Number(), index) + // } return fmt.Errorf("invalid receipt root hash (remote: %x local: %x)", header.ReceiptHash, receiptSha) } diff --git a/core/blockchain.go b/core/blockchain.go index 2e2e380c35..8d1e908772 100644 --- a/core/blockchain.go +++ b/core/blockchain.go @@ -47,6 +47,7 @@ import ( "github.com/ethereum/go-ethereum/core/vm" "github.com/ethereum/go-ethereum/ethdb" "github.com/ethereum/go-ethereum/event" + "github.com/ethereum/go-ethereum/internal/debug" "github.com/ethereum/go-ethereum/internal/syncx" "github.com/ethereum/go-ethereum/internal/version" "github.com/ethereum/go-ethereum/log" @@ -1798,6 +1799,7 @@ func (bc *BlockChain) writeBlockWithState(block *types.Block, receipts []*types. defer wg.Wait() wg.Add(1) go func() { + defer debug.Handler.StartRegionAuto("writeBlockWithState write block, receipt, preimages...")() blockBatch := bc.db.BlockStore().NewBatch() rawdb.WriteTd(blockBatch, block.Hash(), block.NumberU64(), externTd) rawdb.WriteBlock(blockBatch, block) @@ -1922,6 +1924,7 @@ func (bc *BlockChain) writeBlockWithState(block *types.Block, receipts []*types. // WriteBlockAndSetHead writes the given block and all associated state to the database, // and applies the block as the new chain head. func (bc *BlockChain) WriteBlockAndSetHead(block *types.Block, receipts []*types.Receipt, logs []*types.Log, state *state.StateDB, emitHeadEvent bool) (status WriteStatus, err error) { + defer debug.Handler.StartRegionAuto("WriteBlockAndSetHead")() if !bc.chainmu.TryLock() { return NonStatTy, errChainStopped } diff --git a/core/rawdb/accessors_snapshot.go b/core/rawdb/accessors_snapshot.go index 5cea581fcd..a5714f4c58 100644 --- a/core/rawdb/accessors_snapshot.go +++ b/core/rawdb/accessors_snapshot.go @@ -21,6 +21,7 @@ import ( "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/ethdb" + "github.com/ethereum/go-ethereum/internal/debug" "github.com/ethereum/go-ethereum/log" ) @@ -47,6 +48,7 @@ func DeleteSnapshotDisabled(db ethdb.KeyValueWriter) { // ReadSnapshotRoot retrieves the root of the block whose state is contained in // the persisted snapshot. func ReadSnapshotRoot(db ethdb.KeyValueReader) common.Hash { + defer debug.Handler.StartRegionAuto("ReadSnapshotRoot")() data, _ := db.Get(SnapshotRootKey) if len(data) != common.HashLength { return common.Hash{} @@ -57,6 +59,7 @@ func ReadSnapshotRoot(db ethdb.KeyValueReader) common.Hash { // WriteSnapshotRoot stores the root of the block whose state is contained in // the persisted snapshot. func WriteSnapshotRoot(db ethdb.KeyValueWriter, root common.Hash) { + defer debug.Handler.StartRegionAuto("WriteSnapshotRoot")() if err := db.Put(SnapshotRootKey, root[:]); err != nil { log.Crit("Failed to store snapshot root", "err", err) } @@ -94,12 +97,20 @@ func DeleteAccountSnapshot(db ethdb.KeyValueWriter, hash common.Hash) { // ReadStorageSnapshot retrieves the snapshot entry of a storage trie leaf. func ReadStorageSnapshot(db ethdb.KeyValueReader, accountHash, storageHash common.Hash) []byte { + defer debug.Handler.StartRegionAuto("ReadStorageSnapshot")() + debug.Handler.LogWhenTracing("ReadStorageSnapshot accountHash:" + accountHash.String() + + " storageHash:" + storageHash.String()) + data, _ := db.Get(storageSnapshotKey(accountHash, storageHash)) return data } // WriteStorageSnapshot stores the snapshot entry of a storage trie leaf. func WriteStorageSnapshot(db ethdb.KeyValueWriter, accountHash, storageHash common.Hash, entry []byte) { + defer debug.Handler.StartRegionAuto("WriteStorageSnapshot")() + debug.Handler.LogWhenTracing("WriteStorageSnapshot accountHash:" + accountHash.String() + + " storageHash:" + storageHash.String()) + if err := db.Put(storageSnapshotKey(accountHash, storageHash), entry); err != nil { log.Crit("Failed to store storage snapshot", "err", err) } diff --git a/core/state/database.go b/core/state/database.go index 64baa62e4d..0817d4e1fc 100644 --- a/core/state/database.go +++ b/core/state/database.go @@ -26,6 +26,7 @@ import ( "github.com/ethereum/go-ethereum/core/types" "github.com/ethereum/go-ethereum/crypto" "github.com/ethereum/go-ethereum/ethdb" + "github.com/ethereum/go-ethereum/internal/debug" "github.com/ethereum/go-ethereum/trie" "github.com/ethereum/go-ethereum/trie/trienode" "github.com/ethereum/go-ethereum/trie/utils" @@ -219,6 +220,7 @@ func (db *CachingDB) Reader(stateRoot common.Hash) (Reader, error) { // OpenTrie opens the main account trie at a specific root hash. func (db *CachingDB) OpenTrie(root common.Hash) (Trie, error) { + defer debug.Handler.StartRegionAutoExpensive("OpenTrie")() if db.noTries { return trie.NewEmptyTrie(), nil } @@ -234,6 +236,7 @@ func (db *CachingDB) OpenTrie(root common.Hash) (Trie, error) { // OpenStorageTrie opens the storage trie of an account. func (db *CachingDB) OpenStorageTrie(stateRoot common.Hash, address common.Address, root common.Hash, self Trie) (Trie, error) { + defer debug.Handler.StartRegionAutoExpensive("OpenStorageTrie")() if db.noTries { return trie.NewEmptyTrie(), nil } diff --git a/core/state/snapshot/difflayer.go b/core/state/snapshot/difflayer.go index 4f1c6b850b..f0ba1a8de7 100644 --- a/core/state/snapshot/difflayer.go +++ b/core/state/snapshot/difflayer.go @@ -28,6 +28,7 @@ import ( "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/core/types" + "github.com/ethereum/go-ethereum/internal/debug" "github.com/ethereum/go-ethereum/rlp" bloomfilter "github.com/holiman/bloomfilter/v2" "golang.org/x/exp/maps" @@ -219,6 +220,7 @@ func (dl *diffLayer) Stale() bool { // Account directly retrieves the account associated with a particular hash in // the snapshot slim data format. func (dl *diffLayer) Account(hash common.Hash) (*types.SlimAccount, error) { + defer debug.Handler.StartRegionAutoExpensive("diffLayer Account")() data, err := dl.AccountRLP(hash) if err != nil { return nil, err @@ -320,6 +322,10 @@ func (dl *diffLayer) accountRLP(hash common.Hash, depth int) ([]byte, error) { // // Note the returned slot is not a copy, please don't modify it. func (dl *diffLayer) Storage(accountHash, storageHash common.Hash) ([]byte, error) { + defer debug.Handler.StartRegionAutoExpensive("diffLayer.Storage")() + // debug.Handler.LogWhenTracing("diffLayer.Storage accountHash:" + accountHash.String() + + // " storageHash:" + storageHash.String()) + // Check the bloom filter first whether there's even a point in reaching into // all the maps in all the layers below dl.lock.RLock() diff --git a/core/state/snapshot/disklayer.go b/core/state/snapshot/disklayer.go index 6aaa0e00d7..761c89f6e6 100644 --- a/core/state/snapshot/disklayer.go +++ b/core/state/snapshot/disklayer.go @@ -25,6 +25,7 @@ import ( "github.com/ethereum/go-ethereum/core/rawdb" "github.com/ethereum/go-ethereum/core/types" "github.com/ethereum/go-ethereum/ethdb" + "github.com/ethereum/go-ethereum/internal/debug" "github.com/ethereum/go-ethereum/rlp" "github.com/ethereum/go-ethereum/triedb" ) @@ -108,6 +109,7 @@ func (dl *diskLayer) Account(hash common.Hash) (*types.SlimAccount, error) { // AccountRLP directly retrieves the account RLP associated with a particular // hash in the snapshot slim data format. func (dl *diskLayer) AccountRLP(hash common.Hash) ([]byte, error) { + defer debug.Handler.StartRegionAuto("diskLayer.AccountRLP")() dl.lock.RLock() defer dl.lock.RUnlock() @@ -130,6 +132,8 @@ func (dl *diskLayer) AccountRLP(hash common.Hash) ([]byte, error) { snapshotCleanAccountReadMeter.Mark(int64(len(blob))) return blob, nil } + defer debug.Handler.StartRegionAuto("diskLayer.AccountRLP, from DB")() + // Cache doesn't contain account, pull from disk and cache for later blob := rawdb.ReadAccountSnapshot(dl.diskdb, hash) dl.cache.Set(hash[:], blob) @@ -146,6 +150,9 @@ func (dl *diskLayer) AccountRLP(hash common.Hash) ([]byte, error) { // Storage directly retrieves the storage data associated with a particular hash, // within a particular account. func (dl *diskLayer) Storage(accountHash, storageHash common.Hash) ([]byte, error) { + defer debug.Handler.StartRegionAuto("diskLayer.Storage")() + debug.Handler.LogWhenTracing("diskLayer.Storage accountHash:" + accountHash.String() + + " storageHash:" + storageHash.String()) dl.lock.RLock() defer dl.lock.RUnlock() @@ -170,6 +177,7 @@ func (dl *diskLayer) Storage(accountHash, storageHash common.Hash) ([]byte, erro snapshotCleanStorageReadMeter.Mark(int64(len(blob))) return blob, nil } + defer debug.Handler.StartRegionAuto("diskLayer.Storage, from DB")() // Cache doesn't contain storage slot, pull from disk and cache for later blob := rawdb.ReadStorageSnapshot(dl.diskdb, accountHash, storageHash) dl.cache.Set(key, blob) @@ -187,6 +195,7 @@ func (dl *diskLayer) Storage(accountHash, storageHash common.Hash) ([]byte, erro // the specified data items. Note, the maps are retained by the method to avoid // copying everything. func (dl *diskLayer) Update(blockHash common.Hash, accounts map[common.Hash][]byte, storage map[common.Hash]map[common.Hash][]byte) *diffLayer { + defer debug.Handler.StartRegionAuto("diskLayer.Update")() return newDiffLayer(dl, blockHash, accounts, storage) } diff --git a/core/state/snapshot/generate.go b/core/state/snapshot/generate.go index 0332cd302e..15cfe565e2 100644 --- a/core/state/snapshot/generate.go +++ b/core/state/snapshot/generate.go @@ -28,6 +28,7 @@ import ( "github.com/ethereum/go-ethereum/core/rawdb" "github.com/ethereum/go-ethereum/core/types" "github.com/ethereum/go-ethereum/ethdb" + "github.com/ethereum/go-ethereum/internal/debug" "github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/rlp" "github.com/ethereum/go-ethereum/trie" @@ -56,6 +57,7 @@ var ( // database and head block asynchronously. The snapshot is returned immediately // and generation is continued in the background until done. func generateSnapshot(diskdb ethdb.KeyValueStore, triedb *triedb.Database, cache int, root common.Hash) *diskLayer { + defer debug.Handler.StartRegionAuto("generateSnapshot")() // Create a new disk layer with an initialized state marker at zero var ( stats = &generatorStats{start: time.Now()} @@ -648,6 +650,7 @@ func generateAccounts(ctx *generatorContext, dl *diskLayer, accMarker []byte) er // gathering and logging, since the method surfs the blocks as they arrive, often // being restarted. func (dl *diskLayer) generate(stats *generatorStats) { + defer debug.Handler.StartRegionAuto("diskLayer.generate")() var ( accMarker []byte abort chan *generatorStats diff --git a/core/state/snapshot/snapshot.go b/core/state/snapshot/snapshot.go index 5290c72286..8fbeec4f56 100644 --- a/core/state/snapshot/snapshot.go +++ b/core/state/snapshot/snapshot.go @@ -27,6 +27,7 @@ import ( "github.com/ethereum/go-ethereum/core/rawdb" "github.com/ethereum/go-ethereum/core/types" "github.com/ethereum/go-ethereum/ethdb" + "github.com/ethereum/go-ethereum/internal/debug" "github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/metrics" "github.com/ethereum/go-ethereum/rlp" @@ -337,6 +338,7 @@ func (t *Tree) Snapshots(root common.Hash, limits int, nodisk bool) []Snapshot { } layer = parent } + log.Info("Tree Snapshots", "root", root, "limits", limits, "len(ret layers)", len(ret)) return ret } @@ -530,6 +532,7 @@ func (t *Tree) cap(diff *diffLayer, layers int) *diskLayer { // The disk layer persistence should be operated in an atomic way. All updates should // be discarded if the whole transition if not finished. func diffToDisk(bottom *diffLayer) *diskLayer { + defer debug.Handler.StartRegionAuto("diffToDisk")() var ( base = bottom.parent.(*diskLayer) batch = base.diskdb.NewBatch() diff --git a/core/state/state_object.go b/core/state/state_object.go index b164c7891d..cc241abf12 100644 --- a/core/state/state_object.go +++ b/core/state/state_object.go @@ -24,12 +24,12 @@ import ( "sync" "time" - "github.com/ethereum/go-ethereum/metrics" - "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/core/types" "github.com/ethereum/go-ethereum/crypto" + "github.com/ethereum/go-ethereum/internal/debug" "github.com/ethereum/go-ethereum/log" + "github.com/ethereum/go-ethereum/metrics" "github.com/ethereum/go-ethereum/rlp" "github.com/ethereum/go-ethereum/trie/trienode" "github.com/holiman/uint256" @@ -134,6 +134,7 @@ func (s *stateObject) touch() { // If a new trie is opened, it will be cached within the state object to allow // subsequent reads to expand the same trie instead of reloading from disk. func (s *stateObject) getTrie() (Trie, error) { + defer debug.Handler.StartRegionAuto("getTrie")() if s.trie == nil { tr, err := s.db.db.OpenStorageTrie(s.db.originalRoot, s.address, s.data.Root, s.db.trie) if err != nil { @@ -206,6 +207,7 @@ func (s *stateObject) getState(key common.Hash) (common.Hash, common.Hash) { // GetCommittedState retrieves the value associated with the specific key // without any mutations caused in the current execution. func (s *stateObject) GetCommittedState(key common.Hash) common.Hash { + defer debug.Handler.StartRegionAuto("GetCommittedState")() // If we have a pending write or clean cached, return that if value, pending := s.pendingStorage[key]; pending { return value @@ -279,6 +281,7 @@ func (s *stateObject) setState(key common.Hash, value common.Hash, origin common // committed later. It is invoked at the end of every transaction. func (s *stateObject) finalise() { slotsToPrefetch := make([]common.Hash, 0, len(s.dirtyStorage)) + defer debug.Handler.StartRegionAuto("finalise")() for key, value := range s.dirtyStorage { if origin, exist := s.uncommittedStorage[key]; exist && origin == value { // The slot is reverted to its original value, delete the entry @@ -324,6 +327,8 @@ func (s *stateObject) finalise() { // // It assumes all the dirty storage slots have been finalized before. func (s *stateObject) updateTrie() (Trie, error) { + defer debug.Handler.StartRegionAuto("updateTrie")() + // Short circuit if nothing was accessed, don't trigger a prefetcher warning if len(s.uncommittedStorage) == 0 { // Nothing was written, so we could stop early. Unless we have both reads @@ -406,6 +411,7 @@ func (s *stateObject) updateTrie() (Trie, error) { // updateRoot flushes all cached storage mutations to trie, recalculating the // new storage trie root. func (s *stateObject) updateRoot() { + defer debug.Handler.StartRegionAuto("updateRoot")() // If node runs in no trie mode, set root to empty. defer func() { if s.db.db.NoTries() { diff --git a/core/state/statedb.go b/core/state/statedb.go index 97fc8dcb1d..4ff6e289fe 100644 --- a/core/state/statedb.go +++ b/core/state/statedb.go @@ -35,6 +35,7 @@ import ( "github.com/ethereum/go-ethereum/core/tracing" "github.com/ethereum/go-ethereum/core/types" "github.com/ethereum/go-ethereum/crypto" + "github.com/ethereum/go-ethereum/internal/debug" "github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/params" "github.com/ethereum/go-ethereum/trie" @@ -267,6 +268,8 @@ func (s *StateDB) StartPrefetcher(namespace string, witness *stateless.Witness) // StopPrefetcher terminates a running prefetcher and reports any leftover stats // from the gathered metrics. func (s *StateDB) StopPrefetcher() { + defer debug.Handler.StartRegionAuto("StopPrefetcher")() + if s.noTrie { return } @@ -393,18 +396,21 @@ func (s *StateDB) SubRefund(gas uint64) { // Exist reports whether the given account address exists in the state. // Notably this also returns true for self-destructed accounts. func (s *StateDB) Exist(addr common.Address) bool { + defer debug.Handler.StartRegionAuto("StateDB.Exist")() return s.getStateObject(addr) != nil } // Empty returns whether the state object is either non-existent // or empty according to the EIP161 specification (balance = nonce = code = 0) func (s *StateDB) Empty(addr common.Address) bool { + defer debug.Handler.StartRegionAuto("StateDB.Empty")() so := s.getStateObject(addr) return so == nil || so.empty() } // GetBalance retrieves the balance from the given address or 0 if object not found func (s *StateDB) GetBalance(addr common.Address) *uint256.Int { + defer debug.Handler.StartRegionAuto("StateDB.GetBalance")() stateObject := s.getStateObject(addr) if stateObject != nil { return stateObject.Balance() @@ -414,6 +420,7 @@ func (s *StateDB) GetBalance(addr common.Address) *uint256.Int { // GetNonce retrieves the nonce from the given address or 0 if object not found func (s *StateDB) GetNonce(addr common.Address) uint64 { + defer debug.Handler.StartRegionAuto("StateDB.GetNonce")() stateObject := s.getStateObject(addr) if stateObject != nil { return stateObject.Nonce() @@ -425,6 +432,7 @@ func (s *StateDB) GetNonce(addr common.Address) uint64 { // GetStorageRoot retrieves the storage root from the given address or empty // if object not found. func (s *StateDB) GetStorageRoot(addr common.Address) common.Hash { + defer debug.Handler.StartRegionAuto("StateDB.GetStorageRoot")() stateObject := s.getStateObject(addr) if stateObject != nil { return stateObject.Root() @@ -438,6 +446,7 @@ func (s *StateDB) TxIndex() int { } func (s *StateDB) GetCode(addr common.Address) []byte { + defer debug.Handler.StartRegionAuto("StateDB.GetCode")() stateObject := s.getStateObject(addr) if stateObject != nil { if s.witness != nil { @@ -449,6 +458,7 @@ func (s *StateDB) GetCode(addr common.Address) []byte { } func (s *StateDB) GetRoot(addr common.Address) common.Hash { + defer debug.Handler.StartRegionAuto("StateDB.GetRoot")() stateObject := s.getStateObject(addr) if stateObject != nil { return stateObject.data.Root @@ -457,6 +467,7 @@ func (s *StateDB) GetRoot(addr common.Address) common.Hash { } func (s *StateDB) GetCodeSize(addr common.Address) int { + defer debug.Handler.StartRegionAuto("StateDB.GetCodeSize")() stateObject := s.getStateObject(addr) if stateObject != nil { if s.witness != nil { @@ -468,6 +479,7 @@ func (s *StateDB) GetCodeSize(addr common.Address) int { } func (s *StateDB) GetCodeHash(addr common.Address) common.Hash { + defer debug.Handler.StartRegionAuto("StateDB.GetCodeHash")() stateObject := s.getStateObject(addr) if stateObject != nil { return common.BytesToHash(stateObject.CodeHash()) @@ -477,6 +489,7 @@ func (s *StateDB) GetCodeHash(addr common.Address) common.Hash { // GetState retrieves the value associated with the specific key. func (s *StateDB) GetState(addr common.Address, hash common.Hash) common.Hash { + defer debug.Handler.StartRegionAuto("StateDB.GetState")() stateObject := s.getStateObject(addr) if stateObject != nil { return stateObject.GetState(hash) @@ -487,6 +500,7 @@ func (s *StateDB) GetState(addr common.Address, hash common.Hash) common.Hash { // GetCommittedState retrieves the value associated with the specific key // without any mutations caused in the current execution. func (s *StateDB) GetCommittedState(addr common.Address, hash common.Hash) common.Hash { + defer debug.Handler.StartRegionAuto("StateDB.GetCommittedState")() stateObject := s.getStateObject(addr) if stateObject != nil { return stateObject.GetCommittedState(hash) @@ -500,6 +514,7 @@ func (s *StateDB) Database() Database { } func (s *StateDB) HasSelfDestructed(addr common.Address) bool { + defer debug.Handler.StartRegionAuto("StateDB.HasSelfDestructed")() stateObject := s.getStateObject(addr) if stateObject != nil { return stateObject.selfDestructed @@ -565,6 +580,7 @@ func (s *StateDB) SetState(addr common.Address, key, value common.Hash) common.H // storage. This function should only be used for debugging and the mutations // must be discarded afterwards. func (s *StateDB) SetStorage(addr common.Address, storage map[common.Hash]common.Hash) { + defer debug.Handler.StartRegionAuto("StateDB.SetStorage")() // SetStorage needs to wipe the existing storage. We achieve this by marking // the account as self-destructed in this block. The effect is that storage // lookups will not hit the disk, as it is assumed that the disk data belongs @@ -596,6 +612,7 @@ func (s *StateDB) SetStorage(addr common.Address, storage map[common.Hash]common // The account's state object is still available until the state is committed, // getStateObject will return a non-nil account after SelfDestruct. func (s *StateDB) SelfDestruct(addr common.Address) uint256.Int { + defer debug.Handler.StartRegionAuto("StateDB.SelfDestruct")() stateObject := s.getStateObject(addr) var prevBalance uint256.Int if stateObject == nil { @@ -617,6 +634,7 @@ func (s *StateDB) SelfDestruct(addr common.Address) uint256.Int { } func (s *StateDB) SelfDestruct6780(addr common.Address) (uint256.Int, bool) { + defer debug.Handler.StartRegionAuto("StateDB.SelfDestruct6780")() stateObject := s.getStateObject(addr) if stateObject == nil { return uint256.Int{}, false @@ -758,6 +776,7 @@ func (s *StateDB) CreateAccount(addr common.Address) { // This operation sets the 'newContract'-flag, which is required in order to // correctly handle EIP-6780 'delete-in-same-transaction' logic. func (s *StateDB) CreateContract(addr common.Address) { + defer debug.Handler.StartRegionAuto("StateDB.CreateContract")() obj := s.getStateObject(addr) if !obj.newContract { obj.newContract = true @@ -871,6 +890,7 @@ func (s *StateDB) GetRefund() uint64 { // the journal as well as the refunds. Finalise, however, will not push any updates // into the tries just yet. Only IntermediateRoot or Commit will do that. func (s *StateDB) Finalise(deleteEmptyObjects bool) { + defer debug.Handler.StartRegionAuto("Finalise")() addressesToPrefetch := make([]common.Address, 0, len(s.journal.dirties)) for addr := range s.journal.dirties { obj, exist := s.stateObjects[addr] @@ -914,6 +934,7 @@ func (s *StateDB) Finalise(deleteEmptyObjects bool) { // It is called in between transactions to get the root hash that // goes into transaction receipts. func (s *StateDB) IntermediateRoot(deleteEmptyObjects bool) common.Hash { + defer debug.Handler.StartRegionAuto("StateDB.IntermediateRoot")() // Finalise all the dirty storage states and write them into the tries s.Finalise(deleteEmptyObjects) @@ -1525,6 +1546,7 @@ func (s *StateDB) commitAndFlush(block uint64, deleteEmptyObjects bool, noStorag // no empty accounts left that could be deleted by EIP-158, storage wiping // should not occur. func (s *StateDB) Commit(block uint64, deleteEmptyObjects bool, noStorageWiping bool) (common.Hash, *types.DiffLayer, error) { + defer debug.Handler.StartRegionAuto("StateDB.Commit")() ret, err := s.commitAndFlush(block, deleteEmptyObjects, noStorageWiping) if err != nil { return common.Hash{}, nil, err diff --git a/core/state/trie_prefetcher.go b/core/state/trie_prefetcher.go index d7b0d0f37e..3e40a0cddd 100644 --- a/core/state/trie_prefetcher.go +++ b/core/state/trie_prefetcher.go @@ -21,6 +21,7 @@ import ( "sync/atomic" "github.com/ethereum/go-ethereum/common" + "github.com/ethereum/go-ethereum/internal/debug" "github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/metrics" ) @@ -120,6 +121,7 @@ func newTriePrefetcher(db Database, root common.Hash, namespace string, noreads // include: subfetcher's creation & abort, child subfetcher's creation & abort. // since the mainLoop will handle all the requests, each message handle should be lightweight func (p *triePrefetcher) mainLoop() { + defer debug.Handler.StartRegionAutoExpensive("prefetch mainLoop")() for { select { case pMsg := <-p.prefetchChan: @@ -198,6 +200,8 @@ func (p *triePrefetcher) mainLoop() { // close iterates over all the subfetchers, aborts any that were left spinning // and reports the stats to the metrics subsystem. func (p *triePrefetcher) close() { + defer debug.Handler.StartRegionAutoExpensive("triePrefetcher close")() + // If the prefetcher is an inactive one, bail out if p.fetches != nil { return @@ -320,6 +324,7 @@ func (p *triePrefetcher) trie(owner common.Hash, root common.Hash) Trie { // used marks a batch of state items used to allow creating statistics as to // how useful or wasteful the prefetcher is. func (p *triePrefetcher) used(owner common.Hash, root common.Hash, usedAddr []common.Address, usedSlot []common.Hash) { + defer debug.Handler.StartRegionAutoExpensive("triePrefetcher used")() // If the prefetcher is an inactive one, bail out if p.fetches != nil { return @@ -388,6 +393,7 @@ type subfetcher struct { // newSubfetcher creates a goroutine to prefetch state items belonging to a // particular root hash. func newSubfetcher(db Database, state common.Hash, owner common.Hash, root common.Hash, addr common.Address) *subfetcher { + defer debug.Handler.StartRegionAutoExpensive("newSubfetcher")() sf := &subfetcher{ db: db, state: state, @@ -419,6 +425,8 @@ func (sf *subfetcher) schedule(keys [][]byte) { } func (sf *subfetcher) scheduleParallel(keys [][]byte) { + defer debug.Handler.StartRegionAutoExpensive("scheduleParallel")() + var keyIndex uint32 = 0 childrenNum := len(sf.paraChildren) if childrenNum > 0 { @@ -521,6 +529,14 @@ func (sf *subfetcher) openTrie() error { // loop waits for new tasks to be scheduled and keeps loading them until it runs // out of tasks or its underlying trie is retrieved for committing. func (sf *subfetcher) loop() { + + traceMsg := "subfetcher" + if sf.owner == (common.Hash{}) { + traceMsg += "_account" // L1 account trie + } else { + traceMsg += "_" + sf.addr.String() // L2 storage trie + } + defer debug.Handler.StartRegionAutoExpensive(traceMsg)() // No matter how the loop stops, signal anyone waiting that it's terminated defer close(sf.term) @@ -541,6 +557,8 @@ func (sf *subfetcher) loop() { sf.trie, err = sf.db.OpenStorageTrie(sf.state, sf.addr, sf.root, nil) } if err != nil { + log.Info("subfetcher loop open Trie error", "sf.owner", sf.owner, + "sf.addr", sf.addr, "err", err) continue } } diff --git a/core/state_prefetcher.go b/core/state_prefetcher.go index c5be14f591..4c4de2013d 100644 --- a/core/state_prefetcher.go +++ b/core/state_prefetcher.go @@ -17,9 +17,12 @@ package core import ( + "strconv" + "github.com/ethereum/go-ethereum/core/state" "github.com/ethereum/go-ethereum/core/types" "github.com/ethereum/go-ethereum/core/vm" + "github.com/ethereum/go-ethereum/internal/debug" "github.com/ethereum/go-ethereum/params" ) @@ -46,6 +49,8 @@ func NewStatePrefetcher(config *params.ChainConfig, chain *HeaderChain) *statePr // the transaction messages using the statedb, but any changes are discarded. The // only goal is to pre-cache transaction signatures and state trie nodes. func (p *statePrefetcher) Prefetch(block *types.Block, statedb *state.StateDB, cfg *vm.Config, interruptCh <-chan struct{}) { + traceMsg := "statePrefetcher " + block.Header().Number.String() + defer debug.Handler.StartRegionAuto(traceMsg)() var ( header = block.Header() signer = types.MakeSigner(p.config, header.Number, header.Time) @@ -55,6 +60,8 @@ func (p *statePrefetcher) Prefetch(block *types.Block, statedb *state.StateDB, c // No need to execute the first batch, since the main processor will do it. for i := 0; i < prefetchThread; i++ { go func() { + traceMsg := "prefetchThread " + strconv.Itoa(i) + defer debug.Handler.StartRegionAuto(traceMsg)() newStatedb := statedb.CopyDoPrefetch() if !p.config.IsHertzfix(header.Number) { newStatedb.EnableWriteOnSharedStorage() diff --git a/core/state_processor.go b/core/state_processor.go index 54f72dd5e2..abe68f25d4 100644 --- a/core/state_processor.go +++ b/core/state_processor.go @@ -31,6 +31,7 @@ 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/internal/debug" "github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/params" ) @@ -72,6 +73,14 @@ func (p *StateProcessor) Process(block *types.Block, statedb *state.StateDB, cfg gp = new(GasPool).AddGas(block.GasLimit()) ) + txNum := len(block.Transactions()) + if !debug.Handler.EnableTraceCapture(block.Header().Number.Uint64(), "") { + debug.Handler.EnableTraceBigBlock(block.Header().Number.Uint64(), txNum, "") + } + log.Info("Process", "block", block.Header().Number) + traceMsg := "Process " + block.Header().Number.String() + defer debug.Handler.StartRegionAuto(traceMsg)() + // Mutate the block and state according to any hard-fork specs if p.config.DAOForkSupport && p.config.DAOForkBlock != nil && p.config.DAOForkBlock.Cmp(block.Number()) == 0 { misc.ApplyDAOHardFork(statedb) @@ -87,8 +96,8 @@ func (p *StateProcessor) Process(block *types.Block, statedb *state.StateDB, cfg var ( context vm.BlockContext signer = types.MakeSigner(p.config, header.Number, header.Time) - txNum = len(block.Transactions()) - err error + + err error ) // Apply pre-execution system calls. @@ -191,6 +200,7 @@ func (p *StateProcessor) Process(block *types.Block, statedb *state.StateDB, cfg // and uses the input parameters for its environment similar to ApplyTransaction. However, // this method takes an already created EVM instance as input. func ApplyTransactionWithEVM(msg *Message, gp *GasPool, statedb *state.StateDB, blockNumber *big.Int, blockHash common.Hash, tx *types.Transaction, usedGas *uint64, evm *vm.EVM, receiptProcessors ...ReceiptProcessor) (receipt *types.Receipt, err error) { + defer debug.Handler.StartRegionAuto("ApplyTransactionWithEVM")() // Add timing measurement var result *ExecutionResult if tx.Gas() > largeTxGasLimit { @@ -284,6 +294,8 @@ func ApplyTransaction(evm *vm.EVM, gp *GasPool, statedb *state.StateDB, header * // ProcessBeaconBlockRoot applies the EIP-4788 system call to the beacon block root // contract. This method is exported to be used in tests. func ProcessBeaconBlockRoot(beaconRoot common.Hash, evm *vm.EVM) { + defer debug.Handler.StartRegionAuto("ProcessBeaconBlockRoot")() + // Return immediately if beaconRoot equals the zero hash when using the Parlia engine. if beaconRoot == (common.Hash{}) { if chainConfig := evm.ChainConfig(); chainConfig != nil && chainConfig.Parlia != nil { @@ -314,6 +326,7 @@ func ProcessBeaconBlockRoot(beaconRoot common.Hash, evm *vm.EVM) { // ProcessParentBlockHash stores the parent block hash in the history storage contract // as per EIP-2935/7709. func ProcessParentBlockHash(prevHash common.Hash, evm *vm.EVM) { + defer debug.Handler.StartRegionAuto("ProcessParentBlockHash")() if tracer := evm.Config.Tracer; tracer != nil { onSystemCallStart(tracer, evm.GetVMContext()) if tracer.OnSystemCallEnd != nil { diff --git a/core/state_transition.go b/core/state_transition.go index 00a234331d..cb053128bb 100644 --- a/core/state_transition.go +++ b/core/state_transition.go @@ -29,6 +29,7 @@ import ( "github.com/ethereum/go-ethereum/core/types" "github.com/ethereum/go-ethereum/core/vm" "github.com/ethereum/go-ethereum/crypto/kzg4844" + "github.com/ethereum/go-ethereum/internal/debug" "github.com/ethereum/go-ethereum/params" "github.com/holiman/uint256" ) @@ -206,6 +207,7 @@ 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) (*ExecutionResult, error) { + defer debug.Handler.StartRegionAuto("ApplyMessage")() evm.SetTxContext(NewEVMTxContext(msg)) return newStateTransition(evm, msg, gp).execute() } @@ -417,7 +419,8 @@ func (st *stateTransition) execute() (*ExecutionResult, error) { // 4. the purchased gas is enough to cover intrinsic usage // 5. there is no overflow when calculating intrinsic gas // 6. caller has enough balance to cover asset transfer for **topmost** call - + // ctx, task := trace.NewTask(context.Background(), "transitionDb") + // defer task.End() // Check clauses 1-3, buy gas if everything is correct if err := st.preCheck(); err != nil { return nil, err diff --git a/core/types/hashing.go b/core/types/hashing.go index 224d7a87ea..442d9e66c5 100644 --- a/core/types/hashing.go +++ b/core/types/hashing.go @@ -24,6 +24,7 @@ import ( "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/crypto" + "github.com/ethereum/go-ethereum/internal/debug" "github.com/ethereum/go-ethereum/rlp" "golang.org/x/crypto/sha3" ) @@ -103,6 +104,7 @@ func encodeForDerive(list DerivableList, i int, buf *bytes.Buffer) []byte { // DeriveSha creates the tree hashes of transactions, receipts, and withdrawals in a block header. func DeriveSha(list DerivableList, hasher TrieHasher) common.Hash { + defer debug.Handler.StartRegionAuto("DeriveSha")() hasher.Reset() valueBuf := encodeBufferPool.Get().(*bytes.Buffer) diff --git a/core/types/receipt.go b/core/types/receipt.go index 5a4db3b7e0..3ad907bf45 100644 --- a/core/types/receipt.go +++ b/core/types/receipt.go @@ -18,6 +18,7 @@ package types import ( "bytes" + "encoding/hex" "errors" "fmt" "io" @@ -27,6 +28,7 @@ import ( "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/common/hexutil" "github.com/ethereum/go-ethereum/crypto" + "github.com/ethereum/go-ethereum/internal/debug" "github.com/ethereum/go-ethereum/params" "github.com/ethereum/go-ethereum/rlp" ) @@ -123,6 +125,38 @@ func NewReceipt(root []byte, failed bool, cumulativeGasUsed uint64) *Receipt { return r } +func (r *Receipt) DumpWhenTrace(blocknum *big.Int, index int) { + + statusEncode := []byte{0x0} + if len(r.statusEncoding()) > 0 { + statusEncode = r.statusEncoding() + } + msg := fmt.Sprintf("block:%s, index:%d, TxHash:%s, Type:%d,"+ + " len(r.Logs):%d, statusEncoding:%s,"+ + " CumulativeGasUsed:%d,"+ + " r.Bloom:%s", + blocknum.String(), index, r.TxHash.Hex(), r.Type, + len(r.Logs), + hex.EncodeToString(statusEncode), + r.CumulativeGasUsed, + hex.EncodeToString(r.Bloom.Bytes())) + debug.Handler.LogWhenTracing(msg) + + for rIndex, l := range r.Logs { + for tIndex, t := range l.Topics { + msg = fmt.Sprintf(" log: %d, logIndex:%d, Address:%s,"+ + " data:%s, topic-%d:%s", + rIndex, + l.Index, + l.Address.Hex(), + hex.EncodeToString(l.Data), + tIndex, + t.Hex()) + debug.Handler.LogWhenTracing(msg) + } + } +} + // EncodeRLP implements rlp.Encoder, and flattens the consensus fields of a receipt // into an RLP stream. If no post state is present, byzantium fork is assumed. func (r *Receipt) EncodeRLP(w io.Writer) error { diff --git a/core/vm/gas_table.go b/core/vm/gas_table.go index 55855727b5..b7661bdce6 100644 --- a/core/vm/gas_table.go +++ b/core/vm/gas_table.go @@ -22,6 +22,7 @@ import ( "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/common/math" + "github.com/ethereum/go-ethereum/internal/debug" "github.com/ethereum/go-ethereum/params" ) @@ -139,6 +140,7 @@ func gasSStore(evm *EVM, contract *Contract, stack *Stack, mem *Memory, memorySi if current == value { // noop (1) return params.NetSstoreNoopGas, nil } + defer debug.Handler.StartRegionAutoExpensive("gasSStore")() original := evm.StateDB.GetCommittedState(contract.Address(), x.Bytes32()) if original == current { if original == (common.Hash{}) { // create slot (2.1.1) @@ -196,6 +198,7 @@ func gasSStoreEIP2200(evm *EVM, contract *Contract, stack *Stack, mem *Memory, m if current == value { // noop (1) return params.SloadGasEIP2200, nil } + defer debug.Handler.StartRegionAutoExpensive("gasSStoreEIP2200")() original := evm.StateDB.GetCommittedState(contract.Address(), x.Bytes32()) if original == current { if original == (common.Hash{}) { // create slot (2.1.1) diff --git a/core/vm/operations_acl.go b/core/vm/operations_acl.go index ff3875868f..960de3ffff 100644 --- a/core/vm/operations_acl.go +++ b/core/vm/operations_acl.go @@ -23,6 +23,7 @@ import ( "github.com/ethereum/go-ethereum/common/math" "github.com/ethereum/go-ethereum/core/tracing" "github.com/ethereum/go-ethereum/core/types" + "github.com/ethereum/go-ethereum/internal/debug" "github.com/ethereum/go-ethereum/params" ) @@ -52,6 +53,7 @@ func makeGasSStoreFunc(clearingRefund uint64) gasFunc { // return params.SloadGasEIP2200, nil return cost + params.WarmStorageReadCostEIP2929, nil // SLOAD_GAS } + defer debug.Handler.StartRegionAutoExpensive("makeGasSStoreFunc")() original := evm.StateDB.GetCommittedState(contract.Address(), x.Bytes32()) if original == current { if original == (common.Hash{}) { // create slot (2.1.1) diff --git a/internal/debug/api.go b/internal/debug/api.go index 1bac36e908..b5b6b7b661 100644 --- a/internal/debug/api.go +++ b/internal/debug/api.go @@ -22,6 +22,7 @@ package debug import ( "bytes" + "context" "errors" "io" "os" @@ -31,6 +32,7 @@ import ( "runtime" "runtime/debug" "runtime/pprof" + "runtime/trace" "strings" "sync" "time" @@ -47,11 +49,21 @@ var Handler = new(HandlerT) // Do not create values of this type, use the one // in the Handler variable instead. type HandlerT struct { - mu sync.Mutex - cpuW io.WriteCloser - cpuFile string - traceW io.WriteCloser - traceFile string + mu sync.Mutex + cpuW io.WriteCloser + cpuFile string + traceW io.WriteCloser + traceFile string + task *trace.Task + ctx context.Context + curBlockNum uint64 + startBlockNum uint64 + endBlockNum uint64 + traceBigBlock bool + bigBlockThreshold uint64 + traceBigNum uint64 + fileSubfix string + expensive bool } // Verbosity sets the log verbosity ceiling. The verbosity of individual packages diff --git a/internal/debug/trace.go b/internal/debug/trace.go index e291030b82..7604f07b23 100644 --- a/internal/debug/trace.go +++ b/internal/debug/trace.go @@ -17,45 +17,224 @@ package debug import ( + "context" "errors" "os" "runtime/trace" + "strconv" "github.com/ethereum/go-ethereum/log" ) // StartGoTrace turns on tracing, writing to the given file. +// only do file open func (h *HandlerT) StartGoTrace(file string) error { h.mu.Lock() defer h.mu.Unlock() if h.traceW != nil { - return errors.New("trace already in progress") + return errors.New("trace file already opened") } - f, err := os.Create(expandHome(file)) + + var fileName string + if h.traceFile == "" { + h.traceFile = file + fileName = file + } else { + fileName = h.traceFile + "_" + strconv.Itoa(int(h.curBlockNum)) + "_" + h.fileSubfix + } + f, err := os.Create(expandHome(fileName)) if err != nil { + log.Info("StartGoTrace file created", "file", fileName, "err", err) return err } + + h.traceW = f + + log.Info("StartGoTrace file created", "file", fileName) + /* + if err := trace.Start(f); err != nil { + f.Close() + return err + } + h.ctx, h.task = trace.NewTask(context.Background(), "larryDebugTask") + */ + return nil +} + +// user controled start & stop capture +func (h *HandlerT) RpcEnableTraceCapture() error { + h.mu.Lock() + defer h.mu.Unlock() + + // already running + if h.task != nil { + log.Info("trace task is already running") + return nil + } + + // create file + h.mu.Unlock() + h.StartGoTrace("") + h.mu.Lock() + f := h.traceW if err := trace.Start(f); err != nil { f.Close() + log.Error("EnableTrace Start failed", "err", err) + h.traceW = nil return err } - h.traceW = f - h.traceFile = file - log.Info("Go tracing started", "dump", h.traceFile) + + h.ctx, h.task = trace.NewTask(context.Background(), "larryDebugTask") + log.Info("Go tracing started") return nil } -// StopGoTrace stops an ongoing trace. -func (h *HandlerT) StopGoTrace() error { +func (h *HandlerT) RpcDisableTraceCapture() error { h.mu.Lock() defer h.mu.Unlock() + if h.traceW == nil { + return errors.New("trace not in progress") + } + + if h.task == nil { + log.Error("StopGoTrace task is nil!") + } else { + h.task.End() + } + h.task = nil + trace.Stop() + log.Info("Done writing Go trace") + h.traceW.Close() + h.traceW = nil + return nil +} + +func (h *HandlerT) RpcEnableTraceCaptureWithBlockRange(number, length uint64, expensive bool) { + h.startBlockNum = number + h.endBlockNum = number + length + h.expensive = expensive + log.Info("enable traceCapture", "startBlockNum", h.startBlockNum, + "endBlockNum", h.endBlockNum) +} + +func (h *HandlerT) RpcEnableTraceCaptureBigBlock(number, threshold, length uint64, expensive bool) { + h.startBlockNum = number + h.traceBigBlock = true + h.bigBlockThreshold = threshold + h.traceBigNum = length + h.expensive = expensive + log.Info("enable big block traceCapture", "startBlockNum", h.startBlockNum, + "threshold", threshold, "length", length) +} + +// enable a trace capture cycle, with length captureBlockNum +func (h *HandlerT) EnableTraceCapture(blockNum uint64, subfix string) bool { + h.fileSubfix = subfix + if blockNum >= h.startBlockNum && blockNum < h.endBlockNum { + h.curBlockNum = blockNum + h.RpcEnableTraceCapture() + return true + } + + h.RpcDisableTraceCapture() + return false +} + +func (h *HandlerT) EnableTraceBigBlock(blockNum uint64, txNum int, subfix string) bool { + h.fileSubfix = subfix + h.RpcDisableTraceCapture() + if blockNum >= h.startBlockNum && h.traceBigBlock && txNum >= int(h.bigBlockThreshold) { + h.curBlockNum = blockNum + h.traceBigNum-- + if h.traceBigNum == 0 { + h.traceBigBlock = false + } + h.RpcEnableTraceCapture() + return true + } + return false +} +func (h *HandlerT) Ctx() context.Context { + return h.ctx +} + +func (h *HandlerT) Task() *trace.Task { + return h.task +} + +// StopTrace stops an ongoing trace. +func (h *HandlerT) StopGoTrace() error { + h.mu.Lock() + defer h.mu.Unlock() if h.traceW == nil { return errors.New("trace not in progress") } + + if h.task == nil { + log.Error("StopGoTrace task is nil!") + } else { + h.task.End() + } + h.task = nil + + trace.Stop() log.Info("Done writing Go trace", "dump", h.traceFile) h.traceW.Close() h.traceW = nil - h.traceFile = "" return nil } + +func (h *HandlerT) LogWhenTracing(msg string) { + if h.task == nil { + return + } + log.Debug("LogWhenTracing", "msg", msg) +} + +func (h *HandlerT) StartRegionAuto(msg string) func() { + // log.Info("HandlerT StartRegion enter", "msg", msg) + if h.task == nil { + return func() { + // log.Info("HandlerT StartRegion exit not started") + } + } + + // task ready, do trace + // log.Info("StartRegionAuto enter", "msg", msg) + region := trace.StartRegion(h.ctx, msg) + return func() { + // log.Info("StartRegionAuto exit", "msg", msg) + region.End() + } +} + +func (h *HandlerT) StartRegionAutoExpensive(msg string) func() { + if !h.expensive { + return func() { + } + } + if h.task == nil { + return func() { + } + } + + region := trace.StartRegion(h.ctx, msg) + return func() { + region.End() + } +} + +func (h *HandlerT) StartTrace(msg string) *trace.Region { + if h.task == nil { + return nil + } + return trace.StartRegion(h.ctx, msg) +} + +func (h *HandlerT) EndTrace(region *trace.Region) { + if h.task == nil || region == nil { + return + } + region.End() +} diff --git a/internal/ethapi/api.go b/internal/ethapi/api.go index 24b734180d..384f29bff6 100644 --- a/internal/ethapi/api.go +++ b/internal/ethapi/api.go @@ -43,6 +43,7 @@ import ( "github.com/ethereum/go-ethereum/crypto" "github.com/ethereum/go-ethereum/eth/gasestimator" "github.com/ethereum/go-ethereum/eth/tracers/logger" + "github.com/ethereum/go-ethereum/internal/debug" "github.com/ethereum/go-ethereum/internal/ethapi/override" "github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/p2p" @@ -319,6 +320,38 @@ func (api *BlockChainAPI) ChainId() *hexutil.Big { return (*hexutil.Big)(api.b.ChainConfig().ChainID) } +// Larry add +// start trace from number to number + length +func (api *BlockChainAPI) EnableTraceCaptureWithBlockRange(number hexutil.Uint64, length hexutil.Uint64, expensive bool) { + if lengU64 := uint64(length); lengU64 > 1000 { + log.Warn("BlockChainAPI.EnableTraceCaptureWithBlockRange length not acceptable", "length", lengU64) + } + debug.Handler.RpcEnableTraceCaptureWithBlockRange(uint64(number), uint64(length), expensive) +} + +func (api *BlockChainAPI) EnableTraceCaptureBigBlock(number hexutil.Uint64, threshold hexutil.Uint64, + length hexutil.Uint64, expensive bool) { + if threshold < 100 { + log.Warn("BlockChainAPI.EnableTraceCaptureBigBlock threshold is small", "threshold", threshold) + } + if lengU64 := uint64(length); lengU64 > 1000 { + log.Warn("BlockChainAPI.EnableTraceCaptureBigBlock length too big", "length", lengU64) + } + debug.Handler.RpcEnableTraceCaptureBigBlock(uint64(number), uint64(threshold), uint64(length), expensive) +} + +func (api *BlockChainAPI) EnableTraceCapture() { + log.Info("BlockChainAPI.EnableTraceCapture Enter") + debug.Handler.RpcEnableTraceCapture() + log.Info("BlockChainAPI.EnableTraceCapture") +} + +func (api *BlockChainAPI) DisableTraceCapture() { + log.Info("BlockChainAPI.DisableTraceCapture Enter") + debug.Handler.RpcDisableTraceCapture() + log.Info("BlockChainAPI.DisableTraceCapture") +} + // BlockNumber returns the block number of the chain head. func (api *BlockChainAPI) BlockNumber() hexutil.Uint64 { header, _ := api.b.HeaderByNumber(context.Background(), rpc.LatestBlockNumber) // latest header should always be available diff --git a/miner/bid_simulator.go b/miner/bid_simulator.go index f398811c31..e235ba8703 100644 --- a/miner/bid_simulator.go +++ b/miner/bid_simulator.go @@ -23,6 +23,7 @@ import ( "github.com/ethereum/go-ethereum/core/txpool" "github.com/ethereum/go-ethereum/core/types" "github.com/ethereum/go-ethereum/event" + "github.com/ethereum/go-ethereum/internal/debug" "github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/metrics" "github.com/ethereum/go-ethereum/miner/builderclient" @@ -621,7 +622,7 @@ func (b *bidSimulator) simBid(interruptCh chan int32, bidRuntime *BidRuntime) { if !b.isRunning() || !b.receivingBid() { return } - + defer debug.Handler.StartRegionAuto("simBid")() var ( startTS = time.Now() @@ -804,6 +805,7 @@ func (b *bidSimulator) simBid(interruptCh chan int32, bidRuntime *BidRuntime) { // if enable greedy merge, fill bid env with transactions from mempool if *b.config.GreedyMergeTx { + defer debug.Handler.StartRegionAuto("mev.greedyMerge")() endingBidsExtra := 20 * time.Millisecond // Add a buffer to ensure ending bids before `delayLeftOver` minTimeLeftForEndingBids := b.delayLeftOver + endingBidsExtra delay := b.engine.Delay(b.chain, bidRuntime.env.header, &minTimeLeftForEndingBids) @@ -824,6 +826,7 @@ func (b *bidSimulator) simBid(interruptCh chan int32, bidRuntime *BidRuntime) { } // commit payBidTx at the end of the block + defer debug.Handler.StartRegionAuto("mev.commitPayBidTx")() bidRuntime.env.gasPool.AddGas(params.PayBidTxGasLimit) err = bidRuntime.commitTransaction(b.chain, b.chainConfig, payBidTx, true) if err != nil { @@ -961,6 +964,7 @@ func (r *BidRuntime) packReward(validatorCommission uint64) { } func (r *BidRuntime) commitTransaction(chain *core.BlockChain, chainConfig *params.ChainConfig, tx *types.Transaction, unRevertible bool) error { + defer debug.Handler.StartRegionAuto("mev.commitTransaction")() var ( env = r.env sc *types.BlobSidecar diff --git a/miner/miner_mev.go b/miner/miner_mev.go index 8be14b904d..f0f958d6f9 100644 --- a/miner/miner_mev.go +++ b/miner/miner_mev.go @@ -8,6 +8,7 @@ import ( "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/core/types" + "github.com/ethereum/go-ethereum/internal/debug" "github.com/ethereum/go-ethereum/internal/version" "github.com/ethereum/go-ethereum/log" ) @@ -43,6 +44,7 @@ func (miner *Miner) HasBuilder(builder common.Address) bool { } func (miner *Miner) SendBid(ctx context.Context, bidArgs *types.BidArgs) (common.Hash, error) { + defer debug.Handler.StartRegionAuto("mev.SendBid")() builder, err := bidArgs.EcrecoverSender() if err != nil { return common.Hash{}, types.NewInvalidBidError(fmt.Sprintf("invalid signature:%v", err)) diff --git a/miner/worker.go b/miner/worker.go index a71d7910da..274e584713 100644 --- a/miner/worker.go +++ b/miner/worker.go @@ -20,6 +20,7 @@ import ( "errors" "fmt" "math/big" + "strconv" "sync" "sync/atomic" "time" @@ -41,6 +42,7 @@ import ( "github.com/ethereum/go-ethereum/core/types" "github.com/ethereum/go-ethereum/core/vm" "github.com/ethereum/go-ethereum/event" + "github.com/ethereum/go-ethereum/internal/debug" "github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/metrics" "github.com/ethereum/go-ethereum/miner/minerconfig" @@ -447,7 +449,20 @@ func (w *worker) newWorkLoop(recommit time.Duration) { commit(commitInterruptNewHead) case head := <-w.chainHeadCh: + mockBlockNum := uint64(1) + debug.Handler.EnableTraceBigBlock(mockBlockNum, 0, "") // to disable trace, set blockNum to 0 + + // if next block is my turn, enable trace + difficulty := w.engine.CalcDifficulty(w.chain, 0, head.Header) + if difficulty != nil && difficulty.Cmp(diffInTurn) == 0 { + log.Info("Next is my turn, try to enable trace", "block", head.Header.Number.Uint64()+1) + mockTxNum := 10000 + debug.Handler.EnableTraceBigBlock(head.Header.Number.Uint64()+1, mockTxNum, "") + } + traceMsg := "NewWorkLoop " + strconv.FormatUint(head.Header.Number.Uint64()+1, 10) + trace := debug.Handler.StartTrace(traceMsg) if !w.isRunning() { + debug.Handler.EndTrace(trace) continue } if interruptCh != nil { @@ -462,16 +477,18 @@ func (w *worker) newWorkLoop(recommit time.Duration) { if err != nil { timer.Reset(recommit) log.Debug("Not allowed to propose block", "err", err) + debug.Handler.EndTrace(trace) continue } if signedRecent { timer.Reset(recommit) log.Info("Signed recently, must wait") + debug.Handler.EndTrace(trace) continue } } commit(commitInterruptNewHead) - + debug.Handler.EndTrace(trace) case <-timer.C: // If sealing is running resubmit a new work cycle periodically to pull in // higher priced transactions. Disable this overhead for pending blocks. @@ -548,12 +565,14 @@ func (w *worker) taskLoop() { for { select { case task := <-w.taskCh: + trace := debug.Handler.StartTrace("taskLoop") if w.newTaskHook != nil { w.newTaskHook(task) } // Reject duplicate sealing work due to resubmitting. sealHash := w.engine.SealHash(task.block.Header()) if sealHash == prev { + debug.Handler.EndTrace(trace) continue } // Interrupt previous sealing operation @@ -561,6 +580,7 @@ func (w *worker) taskLoop() { stopCh, prev = make(chan struct{}), sealHash if w.skipSealHook != nil && w.skipSealHook(task) { + debug.Handler.EndTrace(trace) continue } w.pendingMu.Lock() @@ -573,6 +593,8 @@ func (w *worker) taskLoop() { delete(w.pendingTasks, sealHash) w.pendingMu.Unlock() } + debug.Handler.EndTrace(trace) + case <-w.exitCh: interrupt() return @@ -587,12 +609,15 @@ func (w *worker) resultLoop() { for { select { case block := <-w.resultCh: + trace := debug.Handler.StartTrace("resultLoop") // Short circuit when receiving empty result. if block == nil { + debug.Handler.EndTrace(trace) continue } // Short circuit when receiving duplicate result caused by resubmitting. if w.chain.HasBlock(block.Hash(), block.NumberU64()) { + debug.Handler.EndTrace(trace) continue } var ( @@ -604,6 +629,7 @@ func (w *worker) resultLoop() { w.pendingMu.RUnlock() if !exist { log.Error("Block found but no relative pending task", "number", block.Number(), "sealhash", sealhash, "hash", hash) + debug.Handler.EndTrace(trace) continue } // Different block could share same sealhash, deep copy here to prevent write-write conflict. @@ -667,6 +693,7 @@ func (w *worker) resultLoop() { } else { log.Info("Written block as SideChain and avoid broadcasting", "status", status) } + debug.Handler.EndTrace(trace) continue } writeBlockTimer.UpdateSince(start) @@ -676,6 +703,7 @@ func (w *worker) resultLoop() { log.Info("Successfully sealed new block", "number", block.Number(), "sealhash", sealhash, "hash", hash, "elapsed", common.PrettyDuration(time.Since(task.createdAt))) w.mux.Post(core.NewMinedBlockEvent{Block: block}) + debug.Handler.EndTrace(trace) case <-w.exitCh: return @@ -740,6 +768,7 @@ func (w *worker) updateSnapshot(env *environment) { } func (w *worker) commitTransaction(env *environment, tx *types.Transaction, receiptProcessors ...core.ReceiptProcessor) ([]*types.Log, error) { + defer debug.Handler.StartRegionAuto("commitTransaction")() if tx.Type() == types.BlobTxType { return w.commitBlobTransaction(env, tx, receiptProcessors...) } @@ -797,6 +826,7 @@ func (w *worker) applyTransaction(env *environment, tx *types.Transaction, recei func (w *worker) commitTransactions(env *environment, plainTxs, blobTxs *transactionsByPriceAndNonce, interruptCh chan int32, stopTimer *time.Timer) error { + defer debug.Handler.StartRegionAuto("commitTransactions")() gasLimit := env.header.GasLimit if env.gasPool == nil { env.gasPool = new(core.GasPool).AddGas(gasLimit) @@ -989,6 +1019,7 @@ type generateParams struct { // either based on the last chain head or specified parent. In this function // the pending transactions are not filled yet, only the empty task returned. func (w *worker) prepareWork(genParams *generateParams, witness bool) (*environment, error) { + defer debug.Handler.StartRegionAuto("prepareWork")() w.confMu.RLock() defer w.confMu.RUnlock() @@ -1040,6 +1071,7 @@ func (w *worker) prepareWork(genParams *generateParams, witness bool) (*environm log.Error("Failed to prepare header for sealing", "err", err) return nil, err } + defer debug.Handler.StartRegionAuto("PrepareWork-2")() // Apply EIP-4844, EIP-4788. if w.chainConfig.IsCancun(header.Number, header.Time) { var excessBlobGas uint64 @@ -1068,7 +1100,7 @@ func (w *worker) prepareWork(genParams *generateParams, witness bool) (*environm log.Error("Failed to create sealing context", "err", err) return nil, err } - + defer debug.Handler.StartRegionAuto("PrepareWork-3")() // Handle upgrade built-in system contract code systemcontracts.TryUpdateBuildInSystemContract(w.chainConfig, header.Number, parent.Time, header.Time, env.state, true) @@ -1077,6 +1109,7 @@ func (w *worker) prepareWork(genParams *generateParams, witness bool) (*environm } if w.chainConfig.IsPrague(header.Number, header.Time) { + defer debug.Handler.StartRegionAuto("ProcessParentBlockHash")() core.ProcessParentBlockHash(header.ParentHash, env.evm) } return env, nil @@ -1086,6 +1119,7 @@ func (w *worker) prepareWork(genParams *generateParams, witness bool) (*environm // into the given sealing block. The transaction selection and ordering strategy can // be customized with the plugin in the future. func (w *worker) fillTransactions(interruptCh chan int32, env *environment, stopTimer *time.Timer, bidTxs mapset.Set[common.Hash]) (err error) { + defer debug.Handler.StartRegionAuto("fillTransactions")() w.confMu.RLock() tip := w.tip prio := w.prio @@ -1226,6 +1260,8 @@ func (w *worker) generateWork(params *generateParams, witness bool) *newPayloadR // commitWork generates several new sealing tasks based on the parent block // and submit them to the sealer. func (w *worker) commitWork(interruptCh chan int32, timestamp int64) { + // to enable trace, blockNum to 1000000000, set txNum to 1000 + defer debug.Handler.StartRegionAutoExpensive("commitWork")() // Abort committing if node is still syncing if w.syncing.Load() { return @@ -1401,12 +1437,14 @@ LOOP: // Still some time left, wait for the best bid. // This happens during the peak time of the network, the local block building LOOP would break earlier than // the final sealing time by meeting the errBlockInterruptedByOutOfGas criteria. - + trace := debug.Handler.StartTrace("commitWork tillSealingTime") log.Info("commitWork local building finished, wait for the best bid", "tillSealingTime", common.PrettyDuration(tillSealingTime)) stopTimer.Reset(tillSealingTime) select { case <-stopTimer.C: + debug.Handler.EndTrace(trace) case <-interruptCh: + debug.Handler.EndTrace(trace) log.Debug("commitWork interruptCh closed, new block imported or resubmit triggered") return } @@ -1472,6 +1510,7 @@ func (w *worker) inTurn() bool { // the deep copy first. func (w *worker) commit(env *environment, interval func(), update bool, start time.Time) error { if w.isRunning() { + defer debug.Handler.StartRegionAuto("worker-commit")() if interval != nil { interval() } diff --git a/trie/secure_trie.go b/trie/secure_trie.go index 249d11db96..2850756dc4 100644 --- a/trie/secure_trie.go +++ b/trie/secure_trie.go @@ -19,6 +19,7 @@ package trie import ( "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/core/types" + "github.com/ethereum/go-ethereum/internal/debug" "github.com/ethereum/go-ethereum/rlp" "github.com/ethereum/go-ethereum/trie/trienode" "github.com/ethereum/go-ethereum/triedb/database" @@ -105,6 +106,7 @@ func (t *StateTrie) MustGet(key []byte) []byte { // If the specified storage slot is not in the trie, nil will be returned. // If a trie node is not found in the database, a MissingNodeError is returned. func (t *StateTrie) GetStorage(_ common.Address, key []byte) ([]byte, error) { + defer debug.Handler.StartRegionAutoExpensive("StateTrie GetStorage")() enc, err := t.trie.Get(t.hashKey(key)) if err != nil || len(enc) == 0 { return nil, err @@ -117,6 +119,7 @@ func (t *StateTrie) GetStorage(_ common.Address, key []byte) ([]byte, error) { // If the specified account is not in the trie, nil will be returned. // If a trie node is not found in the database, a MissingNodeError is returned. func (t *StateTrie) GetAccount(address common.Address) (*types.StateAccount, error) { + // defer debug.Handler.StartRegionAuto("StateTrie GetAccount")() res, err := t.trie.Get(t.hashKey(address.Bytes())) if res == nil || err != nil { return nil, err @@ -248,6 +251,7 @@ func (t *StateTrie) Witness() map[string]struct{} { // Once the trie is committed, it's not usable anymore. A new trie must // be created with new root and updated trie database for following usage func (t *StateTrie) Commit(collectLeaf bool) (common.Hash, *trienode.NodeSet) { + defer debug.Handler.StartRegionAutoExpensive("StateTrie Commit")() // Write all the pre-images to the actual disk database if len(t.getSecKeyCache()) > 0 { if t.preimages != nil { @@ -266,6 +270,7 @@ func (t *StateTrie) Commit(collectLeaf bool) (common.Hash, *trienode.NodeSet) { // Hash returns the root hash of StateTrie. It does not write to the // database and can be used even if the trie doesn't have one. func (t *StateTrie) Hash() common.Hash { + defer debug.Handler.StartRegionAutoExpensive("StateTrie.Hash")() return t.trie.Hash() } diff --git a/trie/trie.go b/trie/trie.go index aeb7398899..04a3074c53 100644 --- a/trie/trie.go +++ b/trie/trie.go @@ -24,6 +24,7 @@ import ( "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/core/types" + "github.com/ethereum/go-ethereum/internal/debug" "github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/trie/trienode" "github.com/ethereum/go-ethereum/triedb/database" @@ -611,6 +612,7 @@ func (t *Trie) Hash() common.Hash { // Once the trie is committed, it's not usable anymore. A new trie must // be created with new root and updated trie database for following usage func (t *Trie) Commit(collectLeaf bool) (common.Hash, *trienode.NodeSet) { + defer debug.Handler.StartRegionAutoExpensive("Trie Commit")() defer func() { t.committed = true }() diff --git a/triedb/hashdb/database.go b/triedb/hashdb/database.go index 8eaffd0d58..1cc2625877 100644 --- a/triedb/hashdb/database.go +++ b/triedb/hashdb/database.go @@ -28,6 +28,7 @@ import ( "github.com/ethereum/go-ethereum/core/rawdb" "github.com/ethereum/go-ethereum/core/types" "github.com/ethereum/go-ethereum/ethdb" + "github.com/ethereum/go-ethereum/internal/debug" "github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/metrics" "github.com/ethereum/go-ethereum/rlp" @@ -201,7 +202,10 @@ func (db *Database) node(hash common.Hash) ([]byte, error) { memcacheDirtyMissMeter.Mark(1) // Content unavailable in memory, attempt to retrieve from disk + region1 := debug.Handler.StartTrace("database read disk") enc := rawdb.ReadLegacyTrieNode(db.diskdb, hash) + debug.Handler.EndTrace(region1) + if len(enc) != 0 { if db.cleans != nil { db.cleans.Set(hash[:], enc) @@ -537,6 +541,7 @@ func (c *cleaner) Delete(key []byte) error { // Update inserts the dirty nodes in provided nodeset into database and link the // account trie with multiple storage tries if necessary. func (db *Database) Update(root common.Hash, parent common.Hash, block uint64, nodes *trienode.MergedNodeSet) error { + defer debug.Handler.StartRegionAuto("hashdb Update")() // Ensure the parent state is present and signal a warning if not. if parent != types.EmptyRootHash { if blob, _ := db.node(parent); len(blob) == 0 { @@ -559,9 +564,10 @@ func (db *Database) Update(root common.Hash, parent common.Hash, block uint64, n } order = append(order, owner) } - if _, ok := nodes.Sets[common.Hash{}]; ok { - order = append(order, common.Hash{}) - } + // if _, ok := nodes.Sets[common.Hash{}]; ok { + // order = append(order, common.Hash{}) + // } + region1 := debug.Handler.StartTrace("hashdb Update 1") for _, owner := range order { subset := nodes.Sets[owner] subset.ForEachWithOrder(func(path string, n *trienode.Node) { @@ -571,6 +577,19 @@ func (db *Database) Update(root common.Hash, parent common.Hash, block uint64, n db.insert(n.Hash, n.Blob) }) } + debug.Handler.EndTrace(region1) + region2 := debug.Handler.StartTrace("hashdb Update 2") + if _, ok := nodes.Sets[common.Hash{}]; ok { + subset := nodes.Sets[common.Hash{}] + subset.ForEachWithOrder(func(path string, n *trienode.Node) { + if n.IsDeleted() { + return // ignore deletion + } + db.insert(n.Hash, n.Blob) + }) + } + debug.Handler.EndTrace(region2) + // Link up the account trie and storage trie if the node points // to an account trie leaf. if set, present := nodes.Sets[common.Hash{}]; present {