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
This commit is contained in:
Péter Szilágyi 2019-03-25 10:01:18 +02:00 committed by GitHub
parent e852505ace
commit 86989e3fcd
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
7 changed files with 132 additions and 38 deletions

View File

@ -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,

View File

@ -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)",

View File

@ -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",

View File

@ -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

View File

@ -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

View File

@ -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 {

View File

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