Skip to content

Commit

Permalink
chore: add more metrics for perf
Browse files Browse the repository at this point in the history
  • Loading branch information
will@2012 committed Mar 6, 2024
1 parent 495e737 commit 386cc32
Show file tree
Hide file tree
Showing 9 changed files with 109 additions and 5 deletions.
8 changes: 3 additions & 5 deletions core/blockchain.go
Original file line number Diff line number Diff line change
Expand Up @@ -1890,12 +1890,10 @@ func (bc *BlockChain) insertChain(chain types.Blocks, setHead bool) (int, error)
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
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 (
Expand All @@ -1918,7 +1916,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
Expand Down
10 changes: 10 additions & 0 deletions core/rawdb/accessors_snapshot.go
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down Expand Up @@ -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 {
start := time.Now()
if metrics.EnabledExpensive {
defer func() { rawdbGetAccountSnapNodeTimer.UpdateSince(start) }()
}
data, _ := db.Get(accountSnapshotKey(hash))
return data
}
Expand All @@ -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 {
start := time.Now()
if metrics.EnabledExpensive {
defer func() { rawdbGetStorageSnapNodeTimer.UpdateSince(start) }()
}
data, _ := db.Get(storageSnapshotKey(accountHash, storageHash))
return data
}
Expand Down
10 changes: 10 additions & 0 deletions core/rawdb/accessors_trie.go
Original file line number Diff line number Diff line change
Expand Up @@ -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"
)

Expand Down Expand Up @@ -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) {
start := time.Now()
if metrics.EnabledExpensive {
defer func() { rawdbGetAccountTrieNodeTimer.UpdateSince(start) }()
}
data, err := db.Get(accountTrieNodeKey(path))
if err != nil {
return nil, common.Hash{}
Expand Down Expand Up @@ -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) {
start := time.Now()
if metrics.EnabledExpensive {
defer func() { rawdbGetStorageTrieNodeTimer.UpdateSince(start) }()
}
data, err := db.Get(storageTrieNodeKey(accountHash, path))
if err != nil {
return nil, common.Hash{}
Expand Down
10 changes: 10 additions & 0 deletions core/rawdb/metrics.go
Original file line number Diff line number Diff line change
@@ -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)
)
10 changes: 10 additions & 0 deletions core/state_processor.go
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,7 @@ import (
"errors"
"fmt"
"math/big"
"time"

"github.com/ethereum/go-ethereum/common"
"github.com/ethereum/go-ethereum/consensus"
Expand All @@ -28,9 +29,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.
//
Expand Down Expand Up @@ -88,6 +94,7 @@ func (p *StateProcessor) Process(block *types.Block, statedb *state.StateDB, cfg
}
// Iterate over and process the individual transactions
for i, tx := range block.Transactions() {
start := time.Now()
msg, err := TransactionToMessage(tx, signer, header.BaseFee)
if err != nil {
return nil, nil, 0, fmt.Errorf("could not apply tx %d [%v]: %w", i, tx.Hash().Hex(), err)
Expand All @@ -99,6 +106,9 @@ func (p *StateProcessor) Process(block *types.Block, statedb *state.StateDB, cfg
}
receipts = append(receipts, receipt)
allLogs = append(allLogs, receipt.Logs...)
if metrics.EnabledExpensive {
processTxTimer.UpdateSince(start)
}
}
// Fail if Shanghai not enabled and len(withdrawals) is non-zero.
withdrawals := block.Withdrawals()
Expand Down
16 changes: 16 additions & 0 deletions ethdb/leveldb/leveldb.go
Original file line number Diff line number Diff line change
Expand Up @@ -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) {
start := time.Now()
if metrics.EnabledExpensive {
defer func() { ethdb.EthdbGetTimer.UpdateSince(start) }()
}
dat, err := db.db.Get(key, nil)
if err != nil {
return nil, err
Expand All @@ -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 {
start := time.Now()
if metrics.EnabledExpensive {
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 {
start := time.Now()
if metrics.EnabledExpensive {
defer func() { ethdb.EthdbDeleteTimer.UpdateSince(start) }()
}
return db.db.Delete(key, nil)
}

Expand Down Expand Up @@ -414,6 +426,10 @@ func (b *batch) ValueSize() int {

// Write flushes any accumulated data to disk.
func (b *batch) Write() error {
start := time.Now()
if metrics.EnabledExpensive {
defer func() { ethdb.EthdbBatchWriteTimer.UpdateSince(start) }()
}
return b.db.Write(b.b, nil)
}

Expand Down
10 changes: 10 additions & 0 deletions ethdb/metrics.go
Original file line number Diff line number Diff line change
@@ -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)
)
20 changes: 20 additions & 0 deletions ethdb/pebble/pebble.go
Original file line number Diff line number Diff line change
Expand Up @@ -299,6 +299,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) {
start := time.Now()
if metrics.EnabledExpensive {
defer func() { ethdb.EthdbGetTimer.UpdateSince(start) }()
}
d.quitLock.RLock()
defer d.quitLock.RUnlock()
if d.closed {
Expand All @@ -316,6 +320,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 {
start := time.Now()
if metrics.EnabledExpensive {
defer func() { ethdb.EthdbPutTimer.UpdateSince(start) }()
}
d.quitLock.RLock()
defer d.quitLock.RUnlock()
if d.closed {
Expand All @@ -326,6 +334,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 {
start := time.Now()
if metrics.EnabledExpensive {
defer func() { ethdb.EthdbDeleteTimer.UpdateSince(start) }()
}
d.quitLock.RLock()
defer d.quitLock.RUnlock()
if d.closed {
Expand Down Expand Up @@ -482,6 +494,10 @@ func (d *Database) meter(refresh time.Duration, namespace string) {
nonLevel0CompCount = int64(d.nonLevel0Comp.Load())
level0CompCount = int64(d.level0Comp.Load())
)
fmt.Printf("loop print db stats db_metrics=\n%v\n", stats)
d.log.Info("loop print db stats", "comp_time", compTime, "write_delay_count", writeDelayCount, "write_delay_time",
writeDelayTime, "non_level0_comp_count", nonLevel0CompCount, "level0_comp_count", level0CompCount)

writeDelayTimes[i%2] = writeDelayTime
writeDelayCounts[i%2] = writeDelayCount
compTimes[i%2] = compTime
Expand Down Expand Up @@ -580,6 +596,10 @@ func (b *batch) ValueSize() int {

// Write flushes any accumulated data to disk.
func (b *batch) Write() error {
start := time.Now()
if metrics.EnabledExpensive {
defer func() { ethdb.EthdbBatchWriteTimer.UpdateSince(start) }()
}
b.db.quitLock.RLock()
defer b.db.quitLock.RUnlock()
if b.db.closed {
Expand Down
20 changes: 20 additions & 0 deletions trie/trie.go
Original file line number Diff line number Diff line change
Expand Up @@ -21,13 +21,21 @@ 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"
)

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,
Expand Down Expand Up @@ -145,6 +153,10 @@ func (t *Trie) Get(key []byte) ([]byte, error) {
if t.committed {
return nil, ErrCommitted
}
start := time.Now()
if metrics.EnabledExpensive {
defer func() { trieGetTimer.UpdateSince(start) }()
}
value, newroot, didResolve, err := t.get(t.root, keybytesToHex(key), 0)
if err == nil && didResolve {
t.root = newroot
Expand Down Expand Up @@ -177,7 +189,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
}
Expand Down Expand Up @@ -585,6 +601,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) {
start := time.Now()
if metrics.EnabledExpensive {
defer func() { trieReaderTotalTimer.UpdateSince(start) }()
}
blob, err := t.reader.node(prefix, common.BytesToHash(n))
if err != nil {
return nil, err
Expand Down

0 comments on commit 386cc32

Please sign in to comment.