diff --git a/core/blockchain.go b/core/blockchain.go index 78adf978be..79dbe7c818 100644 --- a/core/blockchain.go +++ b/core/blockchain.go @@ -79,6 +79,8 @@ var ( blockWriteTimer = metrics.NewRegisteredCounter("chain/block/writes", nil) acceptorQueueGauge = metrics.NewRegisteredGauge("chain/acceptor/queue/size", nil) + acceptorWorkTimer = metrics.NewRegisteredCounter("chain/acceptor/work", nil) + acceptorWorkCount = metrics.NewRegisteredCounter("chain/acceptor/work/count", nil) processedBlockGasUsedCounter = metrics.NewRegisteredCounter("chain/block/gas/used/processed", nil) acceptedBlockGasUsedCounter = metrics.NewRegisteredCounter("chain/block/gas/used/accepted", nil) badBlockCounter = metrics.NewRegisteredCounter("chain/block/bad/count", nil) @@ -267,6 +269,10 @@ type BlockChain struct { // processed blocks. This may be equal to [lastAccepted]. acceptorTip *types.Block acceptorTipLock sync.Mutex + + // [flattenLock] prevents the [acceptor] from flattening snapshots while + // a block is being verified. + flattenLock sync.Mutex } // NewBlockChain returns a fully initialised block chain using information @@ -414,6 +420,12 @@ func (bc *BlockChain) flattenSnapshot(postAbortWork func() error, hash common.Ha return err } + // Ensure we avoid flattening the snapshot while we are processing a block, or + // block execution will fallback to reading from the trie (which is much + // slower). + bc.flattenLock.Lock() + defer bc.flattenLock.Unlock() + // Flatten the entire snap Trie to disk // // Note: This resumes snapshot generation. @@ -426,6 +438,7 @@ func (bc *BlockChain) startAcceptor() { log.Info("Starting Acceptor", "queue length", bc.cacheConfig.AcceptorQueueLimit) for next := range bc.acceptorQueue { + start := time.Now() acceptorQueueGauge.Dec(1) if err := bc.flattenSnapshot(func() error { @@ -455,6 +468,9 @@ func (bc *BlockChain) startAcceptor() { bc.acceptorTip = next bc.acceptorTipLock.Unlock() bc.acceptorWg.Done() + + acceptorWorkTimer.Inc(time.Since(start).Milliseconds()) + acceptorWorkCount.Inc(1) } } @@ -1142,9 +1158,16 @@ func (bc *BlockChain) insertBlock(block *types.Block, writes bool) error { } }() - // Retrieve the parent block and its state to execute on top + // Retrieve the parent block to determine which root to build state on substart = time.Now() parent := bc.GetHeader(block.ParentHash(), block.NumberU64()-1) + + // Instantiate the statedb to use for processing transactions + // + // NOTE: Flattening a snapshot during block execution requires fetching state + // entries directly from the trie (much slower). + bc.flattenLock.Lock() + defer bc.flattenLock.Unlock() statedb, err := state.New(parent.Root, bc.stateCache, bc.snaps) if err != nil { return err diff --git a/core/state/state_object.go b/core/state/state_object.go index 2421034b75..62bf38131a 100644 --- a/core/state/state_object.go +++ b/core/state/state_object.go @@ -39,12 +39,10 @@ import ( "github.com/ava-labs/subnet-evm/trie" "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/crypto" - "github.com/ethereum/go-ethereum/log" "github.com/ethereum/go-ethereum/rlp" ) var emptyCodeHash = crypto.Keccak256(nil) -var logged = 0 type Code []byte @@ -238,13 +236,8 @@ func (s *stateObject) GetCommittedState(db Database, key common.Hash) common.Has // If the snapshot is unavailable or reading from it fails, load from the database. if s.db.snap == nil || err != nil { start := time.Now() - snapErr := err enc, err = s.getTrie(db).TryGet(key.Bytes()) if metrics.EnabledExpensive { - if logged < 1000 { - log.Warn("reading storage from trie", "snap missing", s.db.snap == nil, "err", snapErr) - logged++ - } s.db.StorageReads += time.Since(start) } if err != nil { diff --git a/utils/metered_cache.go b/utils/metered_cache.go index 16cadb81ec..17c86bdaa2 100644 --- a/utils/metered_cache.go +++ b/utils/metered_cache.go @@ -5,11 +5,15 @@ package utils import ( "fmt" + "os" + "path/filepath" "sync/atomic" "time" "github.com/VictoriaMetrics/fastcache" "github.com/ava-labs/subnet-evm/metrics" + "github.com/ethereum/go-ethereum/common" + "github.com/ethereum/go-ethereum/log" ) // MeteredCache wraps *fastcache.Cache and periodically pulls stats from it. @@ -31,6 +35,20 @@ type MeteredCache struct { updateFrequency uint64 } +func dirSize(path string) (int64, error) { + var size int64 + err := filepath.Walk(path, func(_ string, info os.FileInfo, err error) error { + if err != nil { + return err + } + if !info.IsDir() { + size += info.Size() + } + return nil + }) + return size, err +} + // NewMeteredCache returns a new MeteredCache that will update stats to the // provided namespace once per each [updateFrequency] operations. // Note: if [updateFrequency] is passed as 0, it will be treated as 1. @@ -39,6 +57,8 @@ func NewMeteredCache(size int, journal string, namespace string, updateFrequency if journal == "" { cache = fastcache.New(size) } else { + dirSize, err := dirSize(journal) + log.Info("attempting to load cache from disk", "path", journal, "dirSize", common.StorageSize(dirSize), "err", err) cache = fastcache.LoadFromFileOrNew(journal, size) } if updateFrequency == 0 {