From 32524efad6a92f0dd6a9b5bfde1db8c73bdbd13b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?P=C3=A9ter=20Szil=C3=A1gyi?= Date: Fri, 22 Mar 2019 13:14:49 +0200 Subject: [PATCH] core: split out detailed trie access metrics from insertion time --- core/blockchain.go | 29 +++++++++++++++++-- core/state/state_object.go | 13 +++++++++ core/state/statedb.go | 58 ++++++++++++++++++++++++++++---------- 3 files changed, 83 insertions(+), 17 deletions(-) diff --git a/core/blockchain.go b/core/blockchain.go index c4481588f9..539f40d196 100644 --- a/core/blockchain.go +++ b/core/blockchain.go @@ -47,6 +47,16 @@ import ( ) var ( + accountReadTimer = metrics.NewRegisteredTimer("chain/account/reads", nil) + accountHashTimer = metrics.NewRegisteredTimer("chain/account/hashes", nil) + accountUpdateTimer = metrics.NewRegisteredTimer("chain/account/updates", nil) + accountCommitTimer = metrics.NewRegisteredTimer("chain/account/commits", nil) + + storageReadTimer = metrics.NewRegisteredTimer("chain/storage/reads", nil) + storageHashTimer = metrics.NewRegisteredTimer("chain/storage/hashes", nil) + storageUpdateTimer = metrics.NewRegisteredTimer("chain/storage/updates", nil) + storageCommitTimer = metrics.NewRegisteredTimer("chain/storage/commits", nil) + blockInsertTimer = metrics.NewRegisteredTimer("chain/inserts", nil) blockValidationTimer = metrics.NewRegisteredTimer("chain/validation", nil) blockExecutionTimer = metrics.NewRegisteredTimer("chain/execution", nil) @@ -1249,10 +1259,26 @@ func (bc *BlockChain) insertChain(chain types.Blocks, verifySeals bool) (int, [] if err != nil { return it.index, events, coalescedLogs, err } + + // Update the metrics subsystem with all the measurements + accountReadTimer.Update(state.AccountReads) + accountHashTimer.Update(state.AccountHashes) + accountUpdateTimer.Update(state.AccountUpdates) + accountCommitTimer.Update(state.AccountCommits) + + storageReadTimer.Update(state.StorageReads) + storageHashTimer.Update(state.StorageHashes) + storageUpdateTimer.Update(state.StorageUpdates) + storageCommitTimer.Update(state.StorageCommits) + + trieAccess := state.AccountReads + state.AccountHashes + state.AccountUpdates + state.AccountCommits + trieAccess += state.StorageReads + state.StorageHashes + state.StorageUpdates + state.StorageCommits + blockInsertTimer.UpdateSince(start) - blockExecutionTimer.Update(t1.Sub(t0)) + blockExecutionTimer.Update(t1.Sub(t0) - trieAccess) blockValidationTimer.Update(t2.Sub(t1)) blockWriteTimer.Update(t3.Sub(t2)) + switch status { case CanonStatTy: log.Debug("Inserted new block", "number", block.Number(), "hash", block.Hash(), @@ -1274,7 +1300,6 @@ func (bc *BlockChain) insertChain(chain types.Blocks, verifySeals bool) (int, [] "root", block.Root()) events = append(events, ChainSideEvent{block}) } - blockInsertTimer.UpdateSince(start) stats.processed++ stats.usedGas += usedGas diff --git a/core/state/state_object.go b/core/state/state_object.go index f41ab04092..15e76bd01a 100644 --- a/core/state/state_object.go +++ b/core/state/state_object.go @@ -21,6 +21,7 @@ import ( "fmt" "io" "math/big" + "time" "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/crypto" @@ -177,6 +178,9 @@ func (self *stateObject) GetCommittedState(db Database, key common.Hash) common. if cached { return value } + // Track the amount of time wasted on reading the storge trie + defer func(start time.Time) { self.db.StorageReads += time.Since(start) }(time.Now()) + // Otherwise load the value from the database enc, err := self.getTrie(db).TryGet(key[:]) if err != nil { @@ -216,6 +220,9 @@ func (self *stateObject) setState(key, value common.Hash) { // updateTrie writes cached storage modifications into the object's storage trie. func (self *stateObject) updateTrie(db Database) Trie { + // Track the amount of time wasted on updating the storge trie + defer func(start time.Time) { self.db.StorageUpdates += time.Since(start) }(time.Now()) + tr := self.getTrie(db) for key, value := range self.dirtyStorage { delete(self.dirtyStorage, key) @@ -240,6 +247,9 @@ func (self *stateObject) updateTrie(db Database) Trie { // UpdateRoot sets the trie root to the current root hash of func (self *stateObject) updateRoot(db Database) { self.updateTrie(db) + + // Track the amount of time wasted on hashing the storge trie + defer func(start time.Time) { self.db.StorageHashes += time.Since(start) }(time.Now()) self.data.Root = self.trie.Hash() } @@ -250,6 +260,9 @@ func (self *stateObject) CommitTrie(db Database) error { if self.dbErr != nil { return self.dbErr } + // Track the amount of time wasted on committing the storge trie + defer func(start time.Time) { self.db.StorageCommits += time.Since(start) }(time.Now()) + root, err := self.trie.Commit(nil) if err == nil { self.data.Root = root diff --git a/core/state/statedb.go b/core/state/statedb.go index 4c00092f4e..20a1f0128e 100644 --- a/core/state/statedb.go +++ b/core/state/statedb.go @@ -22,6 +22,7 @@ import ( "fmt" "math/big" "sort" + "time" "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/core/types" @@ -86,6 +87,16 @@ type StateDB struct { journal *journal validRevisions []revision nextRevisionId int + + // Measurements gathered during execution for debugging purposes + AccountReads time.Duration + AccountHashes time.Duration + AccountUpdates time.Duration + AccountCommits time.Duration + StorageReads time.Duration + StorageHashes time.Duration + StorageUpdates time.Duration + StorageCommits time.Duration } // Create a new state from a given trie. @@ -386,36 +397,48 @@ func (self *StateDB) Suicide(addr common.Address) bool { // // updateStateObject writes the given object to the trie. -func (self *StateDB) updateStateObject(stateObject *stateObject) { +func (s *StateDB) updateStateObject(stateObject *stateObject) { + // Track the amount of time wasted on updating the account from the trie + defer func(start time.Time) { s.AccountUpdates += time.Since(start) }(time.Now()) + + // Encode the account and update the account trie addr := stateObject.Address() + data, err := rlp.EncodeToBytes(stateObject) if err != nil { panic(fmt.Errorf("can't encode object at %x: %v", addr[:], err)) } - self.setError(self.trie.TryUpdate(addr[:], data)) + s.setError(s.trie.TryUpdate(addr[:], data)) } // deleteStateObject removes the given object from the state trie. -func (self *StateDB) deleteStateObject(stateObject *stateObject) { +func (s *StateDB) deleteStateObject(stateObject *stateObject) { + // Track the amount of time wasted on deleting the account from the trie + defer func(start time.Time) { s.AccountUpdates += time.Since(start) }(time.Now()) + + // Delete the account from the trie stateObject.deleted = true + addr := stateObject.Address() - self.setError(self.trie.TryDelete(addr[:])) + s.setError(s.trie.TryDelete(addr[:])) } // Retrieve a state object given by the address. Returns nil if not found. -func (self *StateDB) getStateObject(addr common.Address) (stateObject *stateObject) { - // Prefer 'live' objects. - if obj := self.stateObjects[addr]; obj != nil { +func (s *StateDB) getStateObject(addr common.Address) (stateObject *stateObject) { + // Prefer live objects + if obj := s.stateObjects[addr]; obj != nil { if obj.deleted { return nil } return obj } + // Track the amount of time wasted on loading the object from the database + defer func(start time.Time) { s.AccountReads += time.Since(start) }(time.Now()) - // Load the object from the database. - enc, err := self.trie.TryGet(addr[:]) + // Load the object from the database + enc, err := s.trie.TryGet(addr[:]) if len(enc) == 0 { - self.setError(err) + s.setError(err) return nil } var data Account @@ -423,9 +446,9 @@ func (self *StateDB) getStateObject(addr common.Address) (stateObject *stateObje log.Error("Failed to decode state object", "addr", addr, "err", err) return nil } - // Insert into the live set. - obj := newObject(self, addr, data) - self.setStateObject(obj) + // Insert into the live set + obj := newObject(s, addr, data) + s.setStateObject(obj) return obj } @@ -600,6 +623,9 @@ func (s *StateDB) Finalise(deleteEmptyObjects bool) { // goes into transaction receipts. func (s *StateDB) IntermediateRoot(deleteEmptyObjects bool) common.Hash { s.Finalise(deleteEmptyObjects) + + // Track the amount of time wasted on hashing the account trie + defer func(start time.Time) { s.AccountHashes += time.Since(start) }(time.Now()) return s.trie.Hash() } @@ -624,7 +650,7 @@ func (s *StateDB) Commit(deleteEmptyObjects bool) (root common.Hash, err error) for addr := range s.journal.dirties { s.stateObjectsDirty[addr] = struct{}{} } - // Commit objects to the trie. + // Commit objects to the trie, measuring the elapsed time for addr, stateObject := range s.stateObjects { _, isDirty := s.stateObjectsDirty[addr] switch { @@ -647,7 +673,9 @@ func (s *StateDB) Commit(deleteEmptyObjects bool) (root common.Hash, err error) } delete(s.stateObjectsDirty, addr) } - // Write trie changes. + // Write the account trie changes, measuing the amount of wasted time + defer func(start time.Time) { s.AccountCommits += time.Since(start) }(time.Now()) + root, err = s.trie.Commit(func(leaf []byte, parent common.Hash) error { var account Account if err := rlp.DecodeBytes(leaf, &account); err != nil {