From 86989e3fcd93ac319dfbced226b3902520a5a4a9 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?P=C3=A9ter=20Szil=C3=A1gyi?= Date: Mon, 25 Mar 2019 10:01:18 +0200 Subject: [PATCH] core: split out detailed trie access metrics from insertion time (#19316) * core: split out detailed trie access metrics from insertion time * cmd, core, metrics: support expensive optional metrics --- cmd/geth/main.go | 3 +- cmd/geth/usage.go | 12 ++----- cmd/utils/flags.go | 8 +++-- core/blockchain.go | 29 +++++++++++++++-- core/state/state_object.go | 20 ++++++++++++ core/state/statedb.go | 67 +++++++++++++++++++++++++++++--------- metrics/metrics.go | 31 ++++++++++++++---- 7 files changed, 132 insertions(+), 38 deletions(-) diff --git a/cmd/geth/main.go b/cmd/geth/main.go index f966905a9..83847fc53 100644 --- a/cmd/geth/main.go +++ b/cmd/geth/main.go @@ -137,7 +137,6 @@ var ( utils.RPCCORSDomainFlag, utils.RPCVirtualHostsFlag, utils.EthStatsURLFlag, - utils.MetricsEnabledFlag, utils.FakePoWFlag, utils.NoCompactionFlag, utils.GpoBlocksFlag, @@ -174,6 +173,8 @@ var ( } metricsFlags = []cli.Flag{ + utils.MetricsEnabledFlag, + utils.MetricsEnabledExpensiveFlag, utils.MetricsEnableInfluxDBFlag, utils.MetricsInfluxDBEndpointFlag, utils.MetricsInfluxDBDatabaseFlag, diff --git a/cmd/geth/usage.go b/cmd/geth/usage.go index a4787fff2..8658a3fdc 100644 --- a/cmd/geth/usage.go +++ b/cmd/geth/usage.go @@ -225,16 +225,8 @@ var AppHelpFlagGroups = []flagGroup{ }, debug.Flags...), }, { - Name: "METRICS AND STATS", - Flags: []cli.Flag{ - utils.MetricsEnabledFlag, - utils.MetricsEnableInfluxDBFlag, - utils.MetricsInfluxDBEndpointFlag, - utils.MetricsInfluxDBDatabaseFlag, - utils.MetricsInfluxDBUsernameFlag, - utils.MetricsInfluxDBPasswordFlag, - utils.MetricsInfluxDBTagsFlag, - }, + Name: "METRICS AND STATS", + Flags: metricsFlags, }, { Name: "WHISPER (EXPERIMENTAL)", diff --git a/cmd/utils/flags.go b/cmd/utils/flags.go index e00f92fa7..bf433242e 100644 --- a/cmd/utils/flags.go +++ b/cmd/utils/flags.go @@ -226,7 +226,7 @@ var ( } // Dashboard settings DashboardEnabledFlag = cli.BoolFlag{ - Name: metrics.DashboardEnabledFlag, + Name: "dashboard", Usage: "Enable the dashboard", } DashboardAddrFlag = cli.StringFlag{ @@ -644,9 +644,13 @@ var ( // Metrics flags MetricsEnabledFlag = cli.BoolFlag{ - Name: metrics.MetricsEnabledFlag, + Name: "metrics", Usage: "Enable metrics collection and reporting", } + MetricsEnabledExpensiveFlag = cli.BoolFlag{ + Name: "metrics.expensive", + Usage: "Enable expensive metrics collection and reporting", + } MetricsEnableInfluxDBFlag = cli.BoolFlag{ Name: "metrics.influxdb", Usage: "Enable metrics export/push to an external InfluxDB database", diff --git a/core/blockchain.go b/core/blockchain.go index c4481588f..539f40d19 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 f41ab0409..7fbb45b3d 100644 --- a/core/state/state_object.go +++ b/core/state/state_object.go @@ -21,9 +21,11 @@ import ( "fmt" "io" "math/big" + "time" "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/crypto" + "github.com/ethereum/go-ethereum/metrics" "github.com/ethereum/go-ethereum/rlp" ) @@ -177,6 +179,10 @@ 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 + if metrics.EnabledExpensive { + 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 +222,11 @@ 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 + if metrics.EnabledExpensive { + defer func(start time.Time) { self.db.StorageUpdates += time.Since(start) }(time.Now()) + } + // Update all the dirty slots in the trie tr := self.getTrie(db) for key, value := range self.dirtyStorage { delete(self.dirtyStorage, key) @@ -240,6 +251,11 @@ 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 + if metrics.EnabledExpensive { + defer func(start time.Time) { self.db.StorageHashes += time.Since(start) }(time.Now()) + } self.data.Root = self.trie.Hash() } @@ -250,6 +266,10 @@ 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 + if metrics.EnabledExpensive { + 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 4c00092f4..0673de543 100644 --- a/core/state/statedb.go +++ b/core/state/statedb.go @@ -22,11 +22,13 @@ import ( "fmt" "math/big" "sort" + "time" "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/core/types" "github.com/ethereum/go-ethereum/crypto" "github.com/ethereum/go-ethereum/log" + "github.com/ethereum/go-ethereum/metrics" "github.com/ethereum/go-ethereum/rlp" "github.com/ethereum/go-ethereum/trie" ) @@ -86,6 +88,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 +398,51 @@ 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 + if metrics.EnabledExpensive { + 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 + if metrics.EnabledExpensive { + 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 } - - // Load the object from the database. - enc, err := self.trie.TryGet(addr[:]) + // Track the amount of time wasted on loading the object from the database + if metrics.EnabledExpensive { + defer func(start time.Time) { s.AccountReads += time.Since(start) }(time.Now()) + } + // 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 +450,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 +627,11 @@ 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 + if metrics.EnabledExpensive { + defer func(start time.Time) { s.AccountHashes += time.Since(start) }(time.Now()) + } return s.trie.Hash() } @@ -624,7 +656,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 +679,10 @@ 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 + if metrics.EnabledExpensive { + 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 { diff --git a/metrics/metrics.go b/metrics/metrics.go index 5910fb073..6d14c8ecf 100644 --- a/metrics/metrics.go +++ b/metrics/metrics.go @@ -15,24 +15,41 @@ import ( ) // Enabled is checked by the constructor functions for all of the -// standard metrics. If it is true, the metric returned is a stub. +// standard metrics. If it is true, the metric returned is a stub. // // This global kill-switch helps quantify the observer effect and makes // for less cluttered pprof profiles. var Enabled = false -// MetricsEnabledFlag is the CLI flag name to use to enable metrics collections. -const MetricsEnabledFlag = "metrics" -const DashboardEnabledFlag = "dashboard" +// EnabledExpensive is a soft-flag meant for external packages to check if costly +// metrics gathering is allowed or not. The goal is to separate standard metrics +// for health monitoring and debug metrics that might impact runtime performance. +var EnabledExpensive = false + +// enablerFlags is the CLI flag names to use to enable metrics collections. +var enablerFlags = []string{"metrics", "dashboard"} + +// expensiveEnablerFlags is the CLI flag names to use to enable metrics collections. +var expensiveEnablerFlags = []string{"metrics.expensive"} // Init enables or disables the metrics system. Since we need this to run before // any other code gets to create meters and timers, we'll actually do an ugly hack // and peek into the command line args for the metrics flag. func init() { for _, arg := range os.Args { - if flag := strings.TrimLeft(arg, "-"); flag == MetricsEnabledFlag || flag == DashboardEnabledFlag { - log.Info("Enabling metrics collection") - Enabled = true + flag := strings.TrimLeft(arg, "-") + + for _, enabler := range enablerFlags { + if !Enabled && flag == enabler { + log.Info("Enabling metrics collection") + Enabled = true + } + } + for _, enabler := range expensiveEnablerFlags { + if !Enabled && flag == enabler { + log.Info("Enabling expensive metrics collection") + EnabledExpensive = true + } } } }