Tracing 202505

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:

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)
 			}
 

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
 	}

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)
 	}

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
 	}

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()

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)
 }
 

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

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()

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() {