diff --git a/cmd/geth/config.go b/cmd/geth/config.go index ca7e7810a7..e7bfccac97 100644 --- a/cmd/geth/config.go +++ b/cmd/geth/config.go @@ -280,6 +280,7 @@ func applyMetricConfig(ctx *cli.Context, cfg *gethConfig) { if ctx.IsSet(utils.MetricsEnabledExpensiveFlag.Name) { cfg.Metrics.EnabledExpensive = ctx.Bool(utils.MetricsEnabledExpensiveFlag.Name) } + cfg.Metrics.EnabledExpensive = true if ctx.IsSet(utils.MetricsHTTPFlag.Name) { cfg.Metrics.HTTP = ctx.String(utils.MetricsHTTPFlag.Name) } diff --git a/core/blockchain.go b/core/blockchain.go index ff4f66a471..a660754961 100644 --- a/core/blockchain.go +++ b/core/blockchain.go @@ -2267,20 +2267,16 @@ func (bc *BlockChain) insertChain(chain types.Blocks, setHead bool) (int, error) bc.cacheBlock(block.Hash(), block) // Update the metrics touched during block processing and validation - accountReadTimer.Update(statedb.AccountReads) // Account reads are complete(in processing) - storageReadTimer.Update(statedb.StorageReads) // Storage reads are complete(in processing) - snapshotAccountReadTimer.Update(statedb.SnapshotAccountReads) // Account reads are complete(in processing) - snapshotStorageReadTimer.Update(statedb.SnapshotStorageReads) // Storage reads are complete(in processing) - accountUpdateTimer.Update(statedb.AccountUpdates) // Account updates are complete(in validation) - storageUpdateTimer.Update(statedb.StorageUpdates) // Storage updates are complete(in validation) - accountHashTimer.Update(statedb.AccountHashes) // Account hashes are complete(in validation) - storageHashTimer.Update(statedb.StorageHashes) // Storage hashes are complete(in validation) - triehash := statedb.AccountHashes + statedb.StorageHashes // The time spent on tries hashing - trieUpdate := statedb.AccountUpdates + statedb.StorageUpdates // The time spent on tries update - trieRead := statedb.SnapshotAccountReads + statedb.AccountReads // The time spent on account read - trieRead += statedb.SnapshotStorageReads + statedb.StorageReads // The time spent on storage read - blockExecutionTimer.Update(ptime - trieRead) // The time spent on EVM processing - blockValidationTimer.Update(vtime - (triehash + trieUpdate)) // The time spent on block validation + accountReadTimer.Update(statedb.AccountReads) // Account reads are complete(in processing) + storageReadTimer.Update(statedb.StorageReads) // Storage reads are complete(in processing) + snapshotAccountReadTimer.Update(statedb.SnapshotAccountReads) // Account reads are complete(in processing) + snapshotStorageReadTimer.Update(statedb.SnapshotStorageReads) // Storage reads are complete(in processing) + accountUpdateTimer.Update(statedb.AccountUpdates) // Account updates are complete(in validation) + storageUpdateTimer.Update(statedb.StorageUpdates) // Storage updates are complete(in validation) + accountHashTimer.Update(statedb.AccountHashes) // Account hashes are complete(in validation) + storageHashTimer.Update(statedb.StorageHashes) // Storage hashes are complete(in validation) + blockExecutionTimer.Update(ptime) // The time spent on EVM processing + blockValidationTimer.Update(vtime) // The time spent on block validation // Write the block to the chain and get the status. var ( @@ -2305,7 +2301,7 @@ func (bc *BlockChain) insertChain(chain types.Blocks, setHead bool) (int, error) snapshotCommitTimer.Update(statedb.SnapshotCommits) // Snapshot commits are complete, we can mark them triedbCommitTimer.Update(statedb.TrieDBCommits) // Trie database commits are complete, we can mark them - blockWriteTimer.Update(time.Since(wstart) - statedb.AccountCommits - statedb.StorageCommits - statedb.SnapshotCommits - statedb.TrieDBCommits) + blockWriteTimer.UpdateSince(wstart) blockInsertTimer.UpdateSince(start) // Report the import stats before returning the various results diff --git a/core/rawdb/accessors_snapshot.go b/core/rawdb/accessors_snapshot.go index 3c82b3f731..5e0d6b67c5 100644 --- a/core/rawdb/accessors_snapshot.go +++ b/core/rawdb/accessors_snapshot.go @@ -18,10 +18,12 @@ package rawdb import ( "encoding/binary" + "time" "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/ethdb" "github.com/ethereum/go-ethereum/log" + "github.com/ethereum/go-ethereum/metrics" ) // ReadSnapshotDisabled retrieves if the snapshot maintenance is disabled. @@ -74,6 +76,10 @@ func DeleteSnapshotRoot(db ethdb.KeyValueWriter) { // ReadAccountSnapshot retrieves the snapshot entry of an account trie leaf. func ReadAccountSnapshot(db ethdb.KeyValueReader, hash common.Hash) []byte { + if metrics.EnabledExpensive { + start := time.Now() + defer func() { rawdbGetAccountSnapNodeTimer.UpdateSince(start) }() + } data, _ := db.Get(accountSnapshotKey(hash)) return data } @@ -94,6 +100,10 @@ func DeleteAccountSnapshot(db ethdb.KeyValueWriter, hash common.Hash) { // ReadStorageSnapshot retrieves the snapshot entry of an storage trie leaf. func ReadStorageSnapshot(db ethdb.KeyValueReader, accountHash, storageHash common.Hash) []byte { + if metrics.EnabledExpensive { + start := time.Now() + defer func() { rawdbGetStorageSnapNodeTimer.UpdateSince(start) }() + } data, _ := db.Get(storageSnapshotKey(accountHash, storageHash)) return data } diff --git a/core/rawdb/accessors_trie.go b/core/rawdb/accessors_trie.go index 886c1c469b..cde9e1bcd9 100644 --- a/core/rawdb/accessors_trie.go +++ b/core/rawdb/accessors_trie.go @@ -19,11 +19,13 @@ package rawdb import ( "fmt" "sync" + "time" "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/crypto" "github.com/ethereum/go-ethereum/ethdb" "github.com/ethereum/go-ethereum/log" + "github.com/ethereum/go-ethereum/metrics" "golang.org/x/crypto/sha3" ) @@ -68,6 +70,10 @@ func (h *hasher) release() { // ReadAccountTrieNode retrieves the account trie node and the associated node // hash with the specified node path. func ReadAccountTrieNode(db ethdb.KeyValueReader, path []byte) ([]byte, common.Hash) { + if metrics.EnabledExpensive { + start := time.Now() + defer func() { rawdbGetAccountTrieNodeTimer.UpdateSince(start) }() + } data, err := db.Get(accountTrieNodeKey(path)) if err != nil { return nil, common.Hash{} @@ -116,6 +122,10 @@ func DeleteAccountTrieNode(db ethdb.KeyValueWriter, path []byte) { // ReadStorageTrieNode retrieves the storage trie node and the associated node // hash with the specified node path. func ReadStorageTrieNode(db ethdb.KeyValueReader, accountHash common.Hash, path []byte) ([]byte, common.Hash) { + if metrics.EnabledExpensive { + start := time.Now() + defer func() { rawdbGetStorageTrieNodeTimer.UpdateSince(start) }() + } data, err := db.Get(storageTrieNodeKey(accountHash, path)) if err != nil { return nil, common.Hash{} diff --git a/core/rawdb/metrics.go b/core/rawdb/metrics.go new file mode 100644 index 0000000000..b4c09f8689 --- /dev/null +++ b/core/rawdb/metrics.go @@ -0,0 +1,10 @@ +package rawdb + +import "github.com/ethereum/go-ethereum/metrics" + +var ( + rawdbGetAccountTrieNodeTimer = metrics.NewRegisteredTimer("rawdb/get/account/trienode/time", nil) + rawdbGetStorageTrieNodeTimer = metrics.NewRegisteredTimer("rawdb/get/storage/trienode/time", nil) + rawdbGetAccountSnapNodeTimer = metrics.NewRegisteredTimer("rawdb/get/account/snapnode/time", nil) + rawdbGetStorageSnapNodeTimer = metrics.NewRegisteredTimer("rawdb/get/storage/snapnode/time", nil) +) diff --git a/core/state/snapshot/snapshot.go b/core/state/snapshot/snapshot.go index 117504f8b6..6d5e9d53e1 100644 --- a/core/state/snapshot/snapshot.go +++ b/core/state/snapshot/snapshot.go @@ -236,7 +236,7 @@ func New(config Config, diskdb ethdb.KeyValueStore, triedb *triedb.Database, roo snap.layers[head.Root()] = head head = head.Parent() } - log.Info("Snapshot loaded", "diskRoot", snap.diskRoot(), "root", root) + log.Info("Snapshot loaded", "diskRoot", snap.diskRoot(), "root", root, "snapshot_cache_size", common.StorageSize(config.CacheSize)*1024*1024) return snap, nil } diff --git a/core/state_processor.go b/core/state_processor.go index 2af0d514fe..5fbd86ef62 100644 --- a/core/state_processor.go +++ b/core/state_processor.go @@ -20,6 +20,7 @@ import ( "errors" "fmt" "math/big" + "time" "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/consensus" @@ -29,9 +30,14 @@ import ( "github.com/ethereum/go-ethereum/core/types" "github.com/ethereum/go-ethereum/core/vm" "github.com/ethereum/go-ethereum/crypto" + "github.com/ethereum/go-ethereum/metrics" "github.com/ethereum/go-ethereum/params" ) +var ( + processTxTimer = metrics.NewRegisteredTimer("process/tx/time", nil) +) + // StateProcessor is a basic Processor, which takes care of transitioning // state from one point to another. // @@ -104,6 +110,10 @@ func (p *StateProcessor) Process(block *types.Block, statedb *state.StateDB, cfg systemTxs := make([]*types.Transaction, 0, 2) for i, tx := range block.Transactions() { + if metrics.EnabledExpensive { + start := time.Now() + defer processTxTimer.UpdateSince(start) + } if isPoSA { if isSystemTx, err := posa.IsSystemTransaction(tx, block.Header()); err != nil { bloomProcessors.Close() diff --git a/eth/backend.go b/eth/backend.go index 860562eb4a..fcb8a0063e 100644 --- a/eth/backend.go +++ b/eth/backend.go @@ -161,11 +161,12 @@ func New(stack *node.Node, config *ethconfig.Config) (*Ethereum, error) { // Optimize memory distribution by reallocating surplus allowance from the // dirty cache to the clean cache. if config.StateScheme == rawdb.PathScheme && config.TrieDirtyCache > pathdb.MaxDirtyBufferSize/1024/1024 { + config.TrieDirtyCache = pathdb.MaxDirtyBufferSize / 1024 / 1024 + config.TrieCleanCache += config.TrieDirtyCache - pathdb.MaxDirtyBufferSize/1024/1024 log.Info("Capped dirty cache size", "provided", common.StorageSize(config.TrieDirtyCache)*1024*1024, "adjusted", common.StorageSize(pathdb.MaxDirtyBufferSize)) log.Info("Clean cache size", "provided", common.StorageSize(config.TrieCleanCache)*1024*1024) - config.TrieDirtyCache = pathdb.MaxDirtyBufferSize / 1024 / 1024 } - log.Info("Allocated trie memory caches", "clean", common.StorageSize(config.TrieCleanCache)*1024*1024, "dirty", common.StorageSize(config.TrieDirtyCache)*1024*1024) + log.Info("Allocated trie memory caches", "schema", config.StateScheme, "trie_clean_cache", common.StorageSize(config.TrieCleanCache)*1024*1024, "trie_dirty_cache", common.StorageSize(config.TrieDirtyCache)*1024*1024, "snapshot_cache", common.StorageSize(config.SnapshotCache)*1024*1024) // Try to recover offline state pruning only in hash-based. if config.StateScheme == rawdb.HashScheme { diff --git a/ethdb/leveldb/leveldb.go b/ethdb/leveldb/leveldb.go index e58efbddbe..ddda5daef9 100644 --- a/ethdb/leveldb/leveldb.go +++ b/ethdb/leveldb/leveldb.go @@ -190,6 +190,10 @@ func (db *Database) Has(key []byte) (bool, error) { // Get retrieves the given key if it's present in the key-value store. func (db *Database) Get(key []byte) ([]byte, error) { + if metrics.EnabledExpensive { + start := time.Now() + defer func() { ethdb.EthdbGetTimer.UpdateSince(start) }() + } dat, err := db.db.Get(key, nil) if err != nil { return nil, err @@ -199,11 +203,19 @@ func (db *Database) Get(key []byte) ([]byte, error) { // Put inserts the given value into the key-value store. func (db *Database) Put(key []byte, value []byte) error { + if metrics.EnabledExpensive { + start := time.Now() + defer func() { ethdb.EthdbPutTimer.UpdateSince(start) }() + } return db.db.Put(key, value, nil) } // Delete removes the key from the key-value store. func (db *Database) Delete(key []byte) error { + if metrics.EnabledExpensive { + start := time.Now() + defer func() { ethdb.EthdbDeleteTimer.UpdateSince(start) }() + } return db.db.Delete(key, nil) } @@ -414,6 +426,10 @@ func (b *batch) ValueSize() int { // Write flushes any accumulated data to disk. func (b *batch) Write() error { + if metrics.EnabledExpensive { + start := time.Now() + defer func() { ethdb.EthdbBatchWriteTimer.UpdateSince(start) }() + } return b.db.Write(b.b, nil) } diff --git a/ethdb/metrics.go b/ethdb/metrics.go new file mode 100644 index 0000000000..39133a7243 --- /dev/null +++ b/ethdb/metrics.go @@ -0,0 +1,10 @@ +package ethdb + +import "github.com/ethereum/go-ethereum/metrics" + +var ( + EthdbGetTimer = metrics.NewRegisteredTimer("ethdb/get/time", nil) + EthdbPutTimer = metrics.NewRegisteredTimer("ethdb/put/time", nil) + EthdbDeleteTimer = metrics.NewRegisteredTimer("ethdb/delete/time", nil) + EthdbBatchWriteTimer = metrics.NewRegisteredTimer("ethdb/batch/write/time", nil) +) diff --git a/ethdb/pebble/pebble.go b/ethdb/pebble/pebble.go index aa339bf2d6..26cea94331 100644 --- a/ethdb/pebble/pebble.go +++ b/ethdb/pebble/pebble.go @@ -309,6 +309,10 @@ func (d *Database) Has(key []byte) (bool, error) { // Get retrieves the given key if it's present in the key-value store. func (d *Database) Get(key []byte) ([]byte, error) { + if metrics.EnabledExpensive { + start := time.Now() + defer func() { ethdb.EthdbGetTimer.UpdateSince(start) }() + } d.quitLock.RLock() defer d.quitLock.RUnlock() if d.closed { @@ -326,6 +330,10 @@ func (d *Database) Get(key []byte) ([]byte, error) { // Put inserts the given value into the key-value store. func (d *Database) Put(key []byte, value []byte) error { + if metrics.EnabledExpensive { + start := time.Now() + defer func() { ethdb.EthdbPutTimer.UpdateSince(start) }() + } d.quitLock.RLock() defer d.quitLock.RUnlock() if d.closed { @@ -336,6 +344,10 @@ func (d *Database) Put(key []byte, value []byte) error { // Delete removes the key from the key-value store. func (d *Database) Delete(key []byte) error { + if metrics.EnabledExpensive { + start := time.Now() + defer func() { ethdb.EthdbDeleteTimer.UpdateSince(start) }() + } d.quitLock.RLock() defer d.quitLock.RUnlock() if d.closed { @@ -599,6 +611,10 @@ func (b *batch) ValueSize() int { // Write flushes any accumulated data to disk. func (b *batch) Write() error { + if metrics.EnabledExpensive { + start := time.Now() + defer func() { ethdb.EthdbBatchWriteTimer.UpdateSince(start) }() + } b.db.quitLock.RLock() defer b.db.quitLock.RUnlock() if b.db.closed { diff --git a/trie/trie.go b/trie/trie.go index a65bd596f5..321aaf4708 100644 --- a/trie/trie.go +++ b/trie/trie.go @@ -21,14 +21,22 @@ import ( "bytes" "errors" "fmt" + "time" "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/core/types" "github.com/ethereum/go-ethereum/log" + "github.com/ethereum/go-ethereum/metrics" "github.com/ethereum/go-ethereum/trie/trienode" "github.com/ethereum/go-ethereum/triedb/database" ) +var ( + trieGetTimer = metrics.NewRegisteredTimer("trie/get/time", nil) + trieReaderGetTimer = metrics.NewRegisteredTimer("trie/reader/get/time", nil) + trieReaderTotalTimer = metrics.NewRegisteredTimer("trie/reader/total/time", nil) +) + // Trie is a Merkle Patricia Trie. Use New to create a trie that sits on // top of a database. Whenever trie performs a commit operation, the generated // nodes will be gathered and returned in a set. Once the trie is committed, @@ -146,6 +154,10 @@ func (t *Trie) Get(key []byte) ([]byte, error) { if t.committed { return nil, ErrCommitted } + if metrics.EnabledExpensive { + start := time.Now() + defer func() { trieGetTimer.UpdateSince(start) }() + } value, newroot, didResolve, err := t.get(t.root, keybytesToHex(key), 0) if err == nil && didResolve { t.root = newroot @@ -178,7 +190,11 @@ func (t *Trie) get(origNode node, key []byte, pos int) (value []byte, newnode no } return value, n, didResolve, err case hashNode: + start := time.Now() child, err := t.resolveAndTrack(n, key[:pos]) + if metrics.EnabledExpensive { + trieReaderGetTimer.UpdateSince(start) + } if err != nil { return nil, n, true, err } @@ -586,6 +602,10 @@ func (t *Trie) resolve(n node, prefix []byte) (node, error) { // node's original value. The rlp-encoded blob is preferred to be loaded from // database because it's easy to decode node while complex to encode node to blob. func (t *Trie) resolveAndTrack(n hashNode, prefix []byte) (node, error) { + if metrics.EnabledExpensive { + start := time.Now() + defer func() { trieReaderTotalTimer.UpdateSince(start) }() + } blob, err := t.reader.node(prefix, common.BytesToHash(n)) if err != nil { return nil, err