diff --git a/core/blockchain.go b/core/blockchain.go index 4ce936ebfa..b4d32f22b9 100644 --- a/core/blockchain.go +++ b/core/blockchain.go @@ -54,6 +54,7 @@ var ( headBlockGauge = metrics.NewRegisteredGauge("chain/head/block", nil) headHeaderGauge = metrics.NewRegisteredGauge("chain/head/header", nil) headFastBlockGauge = metrics.NewRegisteredGauge("chain/head/receipt", nil) + processGasGauge = metrics.NewRegisteredGauge("chain/process/gas", nil) justifiedBlockGauge = metrics.NewRegisteredGauge("chain/head/justified", nil) finalizedBlockGauge = metrics.NewRegisteredGauge("chain/head/finalized", nil) @@ -72,6 +73,14 @@ var ( snapshotStorageReadTimer = metrics.NewRegisteredTimer("chain/snapshot/storage/reads", nil) snapshotCommitTimer = metrics.NewRegisteredTimer("chain/snapshot/commits", nil) + processGasUsedHistogram = metrics.NewRegisteredHistogram("chain/process/gas/used", nil, metrics.NewExpDecaySample(1028, 0.015)) + accountReadsHistogram = metrics.NewRegisteredHistogram("chain/account/reads/hist", nil, metrics.NewExpDecaySample(1028, 0.015)) + storageReadsHistogram = metrics.NewRegisteredHistogram("chain/storage/reads/hist", nil, metrics.NewExpDecaySample(1028, 0.015)) + snapshotAccountReadsHistogram = metrics.NewRegisteredHistogram("chain/snapshot/account/reads/hist", nil, metrics.NewExpDecaySample(1028, 0.015)) + snapshotStorageReadsHistogram = metrics.NewRegisteredHistogram("chain/snapshot/storage/reads/hist", nil, metrics.NewExpDecaySample(1028, 0.015)) + accountUpdatesHistogram = metrics.NewRegisteredHistogram("chain/account/updates/hist", nil, metrics.NewExpDecaySample(1028, 0.015)) + storageUpdatesHistogram = metrics.NewRegisteredHistogram("chain/storage/updates/hist", nil, metrics.NewExpDecaySample(1028, 0.015)) + blockInsertTimer = metrics.NewRegisteredTimer("chain/inserts", nil) blockValidationTimer = metrics.NewRegisteredTimer("chain/validation", nil) blockExecutionTimer = metrics.NewRegisteredTimer("chain/execution", nil) @@ -1975,10 +1984,15 @@ func (bc *BlockChain) insertChain(chain types.Blocks, verifySeals, setHead bool) // Update the metrics touched during block processing accountReadTimer.Update(statedb.AccountReads) // Account reads are complete, we can mark them storageReadTimer.Update(statedb.StorageReads) // Storage reads are complete, we can mark them - accountUpdateTimer.Update(statedb.AccountUpdates) // Account updates are complete, we can mark them - storageUpdateTimer.Update(statedb.StorageUpdates) // Storage updates are complete, we can mark them snapshotAccountReadTimer.Update(statedb.SnapshotAccountReads) // Account reads are complete, we can mark them snapshotStorageReadTimer.Update(statedb.SnapshotStorageReads) // Storage reads are complete, we can mark them + if metrics.EnabledExpensive { + accountReadsHistogram.Update(statedb.AccountReadsCount) + storageReadsHistogram.Update(statedb.StorageReadsCount) + snapshotAccountReadsHistogram.Update(statedb.SnapshotAccountReadsCount) + snapshotStorageReadsHistogram.Update(statedb.SnapshotStorageReadsCount) + } + processGasUsedHistogram.Update(int64(usedGas)) blockExecutionTimer.Update(time.Since(substart)) @@ -1997,8 +2011,14 @@ func (bc *BlockChain) insertChain(chain types.Blocks, verifySeals, setHead bool) proctime := time.Since(start) // Update the metrics touched during block validation - accountHashTimer.Update(statedb.AccountHashes) // Account hashes are complete, we can mark them - storageHashTimer.Update(statedb.StorageHashes) // Storage hashes are complete, we can mark them + accountHashTimer.Update(statedb.AccountHashes) // Account hashes are complete, we can mark them + storageHashTimer.Update(statedb.StorageHashes) // Storage hashes are complete, we can mark them + accountUpdateTimer.Update(statedb.AccountUpdates) // Account updates are complete, we can mark them + storageUpdateTimer.Update(statedb.StorageUpdates) // Storage updates are complete, we can mark them + if metrics.EnabledExpensive { + accountUpdatesHistogram.Update(statedb.AccountUpdatesCount) + storageUpdatesHistogram.Update(statedb.StorageUpdatesCount) + } blockValidationTimer.Update(time.Since(substart)) diff --git a/core/blockchain_insert.go b/core/blockchain_insert.go index 4464870279..f1aa90c560 100644 --- a/core/blockchain_insert.go +++ b/core/blockchain_insert.go @@ -55,11 +55,13 @@ func (st *insertStats) report(chain []*types.Block, index int, dirty common.Stor end := chain[index] // Assemble the log context and send it to the logger + mgasps := float64(st.usedGas) * 1000 / float64(elapsed) context := []interface{}{ "blocks", st.processed, "txs", txs, "mgas", float64(st.usedGas) / 1000000, - "elapsed", common.PrettyDuration(elapsed), "mgasps", float64(st.usedGas) * 1000 / float64(elapsed), + "elapsed", common.PrettyDuration(elapsed), "mgasps", mgasps, "number", end.Number(), "hash", end.Hash(), } + processGasGauge.Update(int64(mgasps)) 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/state/state_object.go b/core/state/state_object.go index 1ede96ec63..1cfdf85e9c 100644 --- a/core/state/state_object.go +++ b/core/state/state_object.go @@ -192,6 +192,8 @@ func (s *StateObject) GetState(db Database, key common.Hash) common.Hash { // If we have a dirty value for this state entry, return it value, dirty := s.dirtyStorage[key] if dirty { + storageMeter.Mark(1) + storageDirtyHitMeter.Mark(1) return value } // Otherwise return the entry's original value @@ -200,6 +202,7 @@ func (s *StateObject) GetState(db Database, key common.Hash) common.Hash { func (s *StateObject) getOriginStorage(key common.Hash) (common.Hash, bool) { if value, cached := s.originStorage[key]; cached { + storageOriginHitMeter.Mark(1) return value, true } // if L1 cache miss, try to get it from shared pool @@ -210,6 +213,7 @@ func (s *StateObject) getOriginStorage(key common.Hash) (common.Hash, bool) { } storage := val.(common.Hash) s.originStorage[key] = storage + storageShareHitMeter.Mark(1) return storage, true } return common.Hash{}, false @@ -224,12 +228,14 @@ func (s *StateObject) setOriginStorage(key common.Hash, value common.Hash) { // GetCommittedState retrieves a value from the committed account storage trie. func (s *StateObject) GetCommittedState(db Database, key common.Hash) common.Hash { + storageMeter.Mark(1) // If the fake storage is set, only lookup the state here(in the debugging mode) if s.fakeStorage != nil { return s.fakeStorage[key] } // If we have a pending write or clean cached, return that if value, pending := s.pendingStorage[key]; pending { + storagePendingHitMeter.Mark(1) return value } @@ -255,6 +261,10 @@ func (s *StateObject) GetCommittedState(db Database, key common.Hash) common.Has enc, err = s.db.snap.Storage(s.addrHash, crypto.Keccak256Hash(key.Bytes())) if metrics.EnabledExpensive { s.db.SnapshotStorageReads += time.Since(start) + s.db.SnapshotStorageReadsCount++ + } + if err == nil { + storageSnapHitMeter.Mark(1) } } @@ -267,11 +277,13 @@ func (s *StateObject) GetCommittedState(db Database, key common.Hash) common.Has enc, err = s.getTrie(db).TryGet(key.Bytes()) if metrics.EnabledExpensive { s.db.StorageReads += time.Since(start) + s.db.StorageReadsCount++ } if err != nil { s.setError(err) return common.Hash{} } + storageTrieHitMeter.Mark(1) } var value common.Hash if len(enc) > 0 { @@ -356,19 +368,21 @@ func (s *StateObject) updateTrie(db Database) Trie { if len(s.pendingStorage) == 0 { return s.trie } + usedStorage := make([][]byte, 0, len(s.pendingStorage)) + dirtyStorage := make(map[common.Hash][]byte) + // Track the amount of time wasted on updating the storage trie if metrics.EnabledExpensive { defer func(start time.Time) { s.db.MetricsMux.Lock() s.db.StorageUpdates += time.Since(start) + s.db.StorageUpdatesCount += int64(len(dirtyStorage)) s.db.MetricsMux.Unlock() }(time.Now()) } // Insert all the pending updates into the trie tr := s.getTrie(db) - usedStorage := make([][]byte, 0, len(s.pendingStorage)) - dirtyStorage := make(map[common.Hash][]byte) for key, value := range s.pendingStorage { // Skip noop changes, persist actual changes if value == s.originStorage[key] { diff --git a/core/state/statedb.go b/core/state/statedb.go index 86d49f1612..754974908a 100644 --- a/core/state/statedb.go +++ b/core/state/statedb.go @@ -51,6 +51,20 @@ var ( emptyRoot = common.HexToHash("56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421") emptyAddr = crypto.Keccak256Hash(common.Address{}.Bytes()) + + // metrics + accountMeter = metrics.NewRegisteredMeter("state/db/account", nil) + accountOriginHitMeter = metrics.NewRegisteredMeter("state/db/account/origin", nil) + accountSnapHitMeter = metrics.NewRegisteredMeter("state/db/account/snap", nil) + accountTrieHitMeter = metrics.NewRegisteredMeter("state/db/account/trie", nil) + + storageMeter = metrics.NewRegisteredMeter("state/db/storage", nil) + storageDirtyHitMeter = metrics.NewRegisteredMeter("state/db/storage/dirty", nil) + storagePendingHitMeter = metrics.NewRegisteredMeter("state/db/storage/pending", nil) + storageOriginHitMeter = metrics.NewRegisteredMeter("state/db/storage/origin", nil) + storageShareHitMeter = metrics.NewRegisteredMeter("state/db/storage/share", nil) + storageSnapHitMeter = metrics.NewRegisteredMeter("state/db/storage/snap", nil) + storageTrieHitMeter = metrics.NewRegisteredMeter("state/db/storage/trie", nil) ) type proofList [][]byte @@ -142,6 +156,13 @@ type StateDB struct { SnapshotStorageReads time.Duration SnapshotCommits time.Duration + AccountReadsCount int64 + StorageReadsCount int64 + SnapshotAccountReadsCount int64 + SnapshotStorageReadsCount int64 + AccountUpdatesCount int64 + StorageUpdatesCount int64 + AccountUpdated int StorageUpdated int AccountDeleted int @@ -639,7 +660,10 @@ func (s *StateDB) updateStateObject(obj *StateObject) { } // Track the amount of time wasted on updating the account from the trie if metrics.EnabledExpensive { - defer func(start time.Time) { s.AccountUpdates += time.Since(start) }(time.Now()) + defer func(start time.Time) { + s.AccountUpdates += time.Since(start) + s.AccountUpdatesCount++ + }(time.Now()) } // Encode the account and update the account trie addr := obj.Address() @@ -655,7 +679,10 @@ func (s *StateDB) deleteStateObject(obj *StateObject) { } // Track the amount of time wasted on deleting the account from the trie if metrics.EnabledExpensive { - defer func(start time.Time) { s.AccountUpdates += time.Since(start) }(time.Now()) + defer func(start time.Time) { + s.AccountUpdates += time.Since(start) + s.AccountUpdatesCount++ + }(time.Now()) } // Delete the account from the trie addr := obj.Address() @@ -679,8 +706,10 @@ func (s *StateDB) getStateObject(addr common.Address) *StateObject { // flag set. This is needed by the state journal to revert to the correct s- // destructed object instead of wiping all knowledge about the state object. func (s *StateDB) getDeletedStateObject(addr common.Address) *StateObject { + accountMeter.Mark(1) // Prefer live objects if any is available if obj := s.stateObjects[addr]; obj != nil { + accountOriginHitMeter.Mark(1) return obj } // If no live objects are available, attempt to use snapshots @@ -690,8 +719,10 @@ func (s *StateDB) getDeletedStateObject(addr common.Address) *StateObject { acc, err := s.snap.Account(crypto.HashData(s.hasher, addr.Bytes())) if metrics.EnabledExpensive { s.SnapshotAccountReads += time.Since(start) + s.SnapshotAccountReadsCount++ } if err == nil { + accountSnapHitMeter.Mark(1) if acc == nil { return nil } @@ -724,11 +755,13 @@ func (s *StateDB) getDeletedStateObject(addr common.Address) *StateObject { enc, err := s.trie.TryGet(addr.Bytes()) if metrics.EnabledExpensive { s.AccountReads += time.Since(start) + s.AccountReadsCount++ } if err != nil { s.setError(fmt.Errorf("getDeleteStateObject (%x) error: %v", addr.Bytes(), err)) return nil } + accountTrieHitMeter.Mark(1) if len(enc) == 0 { return nil } diff --git a/core/state/trie_prefetcher.go b/core/state/trie_prefetcher.go index cd51820e9e..704745ca3a 100644 --- a/core/state/trie_prefetcher.go +++ b/core/state/trie_prefetcher.go @@ -62,6 +62,7 @@ type triePrefetcher struct { fetchersMutex sync.RWMutex prefetchChan chan *prefetchMsg // no need to wait for return + fetchTrieMeter metrics.Meter deliveryMissMeter metrics.Meter accountLoadMeter metrics.Meter accountDupMeter metrics.Meter @@ -92,6 +93,7 @@ func newTriePrefetcher(db Database, root, rootParent common.Hash, namespace stri closeMainDoneChan: make(chan struct{}), prefetchChan: make(chan *prefetchMsg, concurrentChanSize), + fetchTrieMeter: metrics.GetOrRegisterMeter(prefix+"/fetch", nil), deliveryMissMeter: metrics.GetOrRegisterMeter(prefix+"/deliverymiss", nil), accountLoadMeter: metrics.GetOrRegisterMeter(prefix+"/account/load", nil), accountDupMeter: metrics.GetOrRegisterMeter(prefix+"/account/dup", nil), @@ -278,6 +280,9 @@ func (p *triePrefetcher) prefetch(root common.Hash, keys [][]byte, accountHash c // trie returns the trie matching the root hash, or nil if the prefetcher doesn't // have it. func (p *triePrefetcher) trie(root common.Hash) Trie { + if p.fetchTrieMeter != nil { + p.fetchTrieMeter.Mark(1) + } // If the prefetcher is inactive, return from existing deep copies if p.fetches != nil { trie := p.fetches[root] diff --git a/miner/worker.go b/miner/worker.go index 6f196015e7..5535f166f0 100644 --- a/miner/worker.go +++ b/miner/worker.go @@ -73,6 +73,10 @@ const ( var ( writeBlockTimer = metrics.NewRegisteredTimer("worker/writeblock", nil) finalizeBlockTimer = metrics.NewRegisteredTimer("worker/finalizeblock", nil) + packageBlockTimer = metrics.NewRegisteredTimer("worker/packageblock", nil) + processBlockTimer = metrics.NewRegisteredTimer("worker/processblock", nil) + orderTxsTimer = metrics.NewRegisteredTimer("worker/ordertxs", nil) + prepareWorkTimer = metrics.NewRegisteredTimer("worker/preparework", nil) errBlockInterruptedByNewHead = errors.New("new head arrived while building block") errBlockInterruptedByRecommit = errors.New("recommit interrupt while building block") @@ -476,7 +480,9 @@ func (w *worker) mainLoop() { for { select { case req := <-w.newWorkCh: + start := time.Now() w.commitWork(req.interruptCh, req.timestamp) + packageBlockTimer.Update(time.Since(start)) case req := <-w.getWorkCh: block, err := w.generateWork(req.params) @@ -777,6 +783,9 @@ func (w *worker) commitTransaction(env *environment, tx *types.Transaction, rece func (w *worker) commitTransactions(env *environment, txs *types.TransactionsByPriceAndNonce, interruptCh chan int32, stopTimer *time.Timer) error { + defer func(start time.Time) { + processBlockTimer.Update(time.Since(start)) + }(time.Now()) gasLimit := env.header.GasLimit if env.gasPool == nil { env.gasPool = new(core.GasPool).AddGas(gasLimit) @@ -931,6 +940,9 @@ 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) (*environment, error) { + defer func(start time.Time) { + prepareWorkTimer.Update(time.Since(start)) + }(time.Now()) w.mu.RLock() defer w.mu.RUnlock() @@ -1026,7 +1038,9 @@ func (w *worker) fillTransactions(interruptCh chan int32, env *environment, stop err = nil if len(localTxs) > 0 { + start := time.Now() txs := types.NewTransactionsByPriceAndNonce(env.signer, localTxs, env.header.BaseFee) + orderTxsTimer.Update(time.Since(start)) err = w.commitTransactions(env, txs, interruptCh, stopTimer) // we will abort here when: // 1.new block was imported @@ -1039,7 +1053,9 @@ func (w *worker) fillTransactions(interruptCh chan int32, env *environment, stop } } if len(remoteTxs) > 0 { + start := time.Now() txs := types.NewTransactionsByPriceAndNonce(env.signer, remoteTxs, env.header.BaseFee) + orderTxsTimer.Update(time.Since(start)) err = w.commitTransactions(env, txs, interruptCh, stopTimer) }