cerc-io/plugeth-statediff
16
0
Fork 0
Code Issues 3 Pull Requests 1 Actions Packages Projects Releases Wiki Activity

simplify func names, clean up metrics

Browse Source 
cleanup
This commit is contained in:
Roy Crihfield 2023-06-20 20:35:31 +08:00
parent 5c59e09423
commit ddf9aff945
5 changed files with 122 additions and 130 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

50
builder.go
View File

@ -112,11 +112,11 @@ func (sdb *StateDiffBuilder) WriteStateDiffObject(args Args, params Params, outp
// Load tries for old and new states // Load tries for old and new states
oldTrie, err := sdb.StateCache.OpenTrie(args.OldStateRoot) oldTrie, err := sdb.StateCache.OpenTrie(args.OldStateRoot)
if err != nil { if err != nil {
return fmt.Errorf("error creating trie for oldStateRoot: %v", err) return fmt.Errorf("error creating trie for oldStateRoot: %w", err)
} }
newTrie, err := sdb.StateCache.OpenTrie(args.NewStateRoot) newTrie, err := sdb.StateCache.OpenTrie(args.NewStateRoot)
if err != nil { if err != nil {
return fmt.Errorf("error creating trie for newStateRoot: %v", err) return fmt.Errorf("error creating trie for newStateRoot: %w", err)
} }
// we do two state trie iterations: // we do two state trie iterations:
@ -135,20 +135,20 @@ func (sdb *StateDiffBuilder) WriteStateDiffObject(args Args, params Params, outp
} }
logger := log.New("hash", args.BlockHash.String(), "number", args.BlockNumber) logger := log.New("hash", args.BlockHash.String(), "number", args.BlockNumber)
return sdb.BuildStateDiffWithIntermediateStateNodes(iterPairs, params, output, ipldOutput, logger, nil) return sdb.BuildStateDiff(iterPairs, params, output, ipldOutput, logger, nil)
} }
func (sdb *StateDiffBuilder) BuildStateDiffWithIntermediateStateNodes(iterPairs []IterPair, params Params, func (sdb *StateDiffBuilder) BuildStateDiff(iterPairs []IterPair, params Params,
output sdtypes.StateNodeSink, ipldOutput sdtypes.IPLDSink, logger log.Logger, prefixPath []byte) error { output sdtypes.StateNodeSink, ipldOutput sdtypes.IPLDSink, logger log.Logger, prefixPath []byte) error {
logger.Debug("statediff BEGIN BuildStateDiffWithIntermediateStateNodes") logger.Debug("statediff BEGIN BuildStateDiff")
defer metrics.ReportAndUpdateDuration("statediff END BuildStateDiffWithIntermediateStateNodes", time.Now(), logger, metrics.IndexerMetrics.BuildStateDiffWithIntermediateStateNodesTimer) defer metrics.ReportAndUpdateDuration("statediff END BuildStateDiff", time.Now(), logger, metrics.IndexerMetrics.BuildStateDiffTimer)
// collect a slice of all the nodes that were touched and exist at B (B-A) // collect a slice of all the nodes that were touched and exist at B (B-A)
// a map of their leafkey to all the accounts that were touched and exist at B // a map of their leafkey to all the accounts that were touched and exist at B
// and a slice of all the paths for the nodes in both of the above sets // and a slice of all the paths for the nodes in both of the above sets
diffAccountsAtB, err := sdb.createdAndUpdatedState( diffAccountsAtB, err := sdb.createdAndUpdatedState(
iterPairs[0].Older, iterPairs[0].Newer, params.watchedAddressesLeafPaths, ipldOutput, logger, prefixPath) iterPairs[0].Older, iterPairs[0].Newer, params.watchedAddressesLeafPaths, ipldOutput, logger, prefixPath)
if err != nil { if err != nil {
return fmt.Errorf("error collecting createdAndUpdatedNodes: %v", err) return fmt.Errorf("error collecting createdAndUpdatedNodes: %w", err)
} }
// collect a slice of all the nodes that existed at a path in A that doesn't exist in B // collect a slice of all the nodes that existed at a path in A that doesn't exist in B
@ -157,14 +157,14 @@ func (sdb *StateDiffBuilder) BuildStateDiffWithIntermediateStateNodes(iterPairs
iterPairs[1].Older, iterPairs[1].Newer, diffAccountsAtB, iterPairs[1].Older, iterPairs[1].Newer, diffAccountsAtB,
params.watchedAddressesLeafPaths, output, logger, prefixPath) params.watchedAddressesLeafPaths, output, logger, prefixPath)
if err != nil { if err != nil {
return fmt.Errorf("error collecting deletedOrUpdatedNodes: %v", err) return fmt.Errorf("error collecting deletedOrUpdatedNodes: %w", err)
} }
// collect and sort the leafkey keys for both account mappings into a slice // collect and sort the leafkey keys for both account mappings into a slice
t := time.Now() t := time.Now()
createKeys := trie_helpers.SortKeys(diffAccountsAtB) createKeys := trie_helpers.SortKeys(diffAccountsAtB)
deleteKeys := trie_helpers.SortKeys(diffAccountsAtA) deleteKeys := trie_helpers.SortKeys(diffAccountsAtA)
logger.Debug(fmt.Sprintf("statediff BuildStateDiffWithIntermediateStateNodes sort duration=%dms", time.Since(t).Milliseconds())) logger.Debug("statediff BuildStateDiff sort", "duration", time.Since(t))
// and then find the intersection of these keys // and then find the intersection of these keys
// these are the leafkeys for the accounts which exist at both A and B but are different // these are the leafkeys for the accounts which exist at both A and B but are different
@ -172,19 +172,19 @@ func (sdb *StateDiffBuilder) BuildStateDiffWithIntermediateStateNodes(iterPairs
// and leaving the truly created or deleted keys in place // and leaving the truly created or deleted keys in place
t = time.Now() t = time.Now()
updatedKeys := trie_helpers.FindIntersection(createKeys, deleteKeys) updatedKeys := trie_helpers.FindIntersection(createKeys, deleteKeys)
logger.Debug(fmt.Sprintf("statediff BuildStateDiffWithIntermediateStateNodes intersection count=%d duration=%dms", logger.Debug("statediff BuildStateDiff intersection",
len(updatedKeys), "count", len(updatedKeys),
time.Since(t).Milliseconds())) "duration", time.Since(t))
// build the diff nodes for the updated accounts using the mappings at both A and B as directed by the keys found as the intersection of the two // build the diff nodes for the updated accounts using the mappings at both A and B as directed by the keys found as the intersection of the two
err = sdb.buildAccountUpdates(diffAccountsAtB, diffAccountsAtA, updatedKeys, output, ipldOutput, logger) err = sdb.buildAccountUpdates(diffAccountsAtB, diffAccountsAtA, updatedKeys, output, ipldOutput, logger)
if err != nil { if err != nil {
return fmt.Errorf("error building diff for updated accounts: %v", err) return fmt.Errorf("error building diff for updated accounts: %w", err)
} }
// build the diff nodes for created accounts // build the diff nodes for created accounts
err = sdb.buildAccountCreations(diffAccountsAtB, output, ipldOutput, logger) err = sdb.buildAccountCreations(diffAccountsAtB, output, ipldOutput, logger)
if err != nil { if err != nil {
return fmt.Errorf("error building diff for created accounts: %v", err) return fmt.Errorf("error building diff for created accounts: %w", err)
} }
return nil return nil
} }
@ -255,7 +255,7 @@ func (sdb *StateDiffBuilder) createdAndUpdatedState(a, b trie.NodeIterator,
prevBlob = nodeVal prevBlob = nodeVal
} }
} }
logger.Debug("statediff COUNTS createdAndUpdatedStateWithIntermediateNodes", "it", itCount, "diffAccountsAtB", len(diffAccountsAtB)) logger.Debug("statediff COUNTS createdAndUpdatedState", "it", itCount, "diffAccountsAtB", len(diffAccountsAtB))
metrics.IndexerMetrics.DifferenceIteratorCounter.Inc(int64(*itCount)) metrics.IndexerMetrics.DifferenceIteratorCounter.Inc(int64(*itCount))
return diffAccountsAtB, it.Error() return diffAccountsAtB, it.Error()
} }
@ -318,7 +318,7 @@ func (sdb *StateDiffBuilder) deletedOrUpdatedState(a, b trie.NodeIterator, diffA
storageDiff := make([]sdtypes.StorageLeafNode, 0) storageDiff := make([]sdtypes.StorageLeafNode, 0)
err := sdb.buildRemovedAccountStorageNodes(accountW.Account.Root, StorageNodeAppender(&storageDiff)) err := sdb.buildRemovedAccountStorageNodes(accountW.Account.Root, StorageNodeAppender(&storageDiff))
if err != nil { if err != nil {
return nil, fmt.Errorf("failed building storage diffs for removed state account with key %x\r\nerror: %v", leafKey, err) return nil, fmt.Errorf("failed building storage diffs for removed state account with key %x\r\nerror: %w", leafKey, err)
} }
diff.StorageDiff = storageDiff diff.StorageDiff = storageDiff
if err := output(diff); err != nil { if err := output(diff); err != nil {
@ -339,8 +339,10 @@ func (sdb *StateDiffBuilder) deletedOrUpdatedState(a, b trie.NodeIterator, diffA
// those account maps to remove the accounts which were updated // those account maps to remove the accounts which were updated
func (sdb *StateDiffBuilder) buildAccountUpdates(creations, deletions sdtypes.AccountMap, updatedKeys []string, func (sdb *StateDiffBuilder) buildAccountUpdates(creations, deletions sdtypes.AccountMap, updatedKeys []string,
output sdtypes.StateNodeSink, ipldOutput sdtypes.IPLDSink, logger log.Logger) error { output sdtypes.StateNodeSink, ipldOutput sdtypes.IPLDSink, logger log.Logger) error {
logger.Debug("statediff BEGIN buildAccountUpdates", "creations", len(creations), "deletions", len(deletions), "updatedKeys", len(updatedKeys)) logger.Debug("statediff BEGIN buildAccountUpdates",
defer metrics.ReportAndUpdateDuration("statediff END buildAccountUpdates ", time.Now(), logger, metrics.IndexerMetrics.BuildAccountUpdatesTimer) "creations", len(creations), "deletions", len(deletions), "updatedKeys", len(updatedKeys))
defer metrics.ReportAndUpdateDuration("statediff END buildAccountUpdates ",
time.Now(), logger, metrics.IndexerMetrics.BuildAccountUpdatesTimer)
var err error var err error
for _, key := range updatedKeys { for _, key := range updatedKeys {
createdAcc := creations[key] createdAcc := creations[key]
@ -352,7 +354,7 @@ func (sdb *StateDiffBuilder) buildAccountUpdates(creations, deletions sdtypes.Ac
StorageNodeAppender(&storageDiff), ipldOutput, StorageNodeAppender(&storageDiff), ipldOutput,
) )
if err != nil { if err != nil {
return fmt.Errorf("failed building incremental storage diffs for account with leafkey %s\r\nerror: %v", key, err) return fmt.Errorf("failed building incremental storage diffs for account with leafkey %x\r\nerror: %w", key, err)
} }
} }
if err = output(sdtypes.StateLeafNode{ if err = output(sdtypes.StateLeafNode{
@ -374,7 +376,8 @@ func (sdb *StateDiffBuilder) buildAccountUpdates(creations, deletions sdtypes.Ac
func (sdb *StateDiffBuilder) buildAccountCreations(accounts sdtypes.AccountMap, output sdtypes.StateNodeSink, func (sdb *StateDiffBuilder) buildAccountCreations(accounts sdtypes.AccountMap, output sdtypes.StateNodeSink,
ipldOutput sdtypes.IPLDSink, logger log.Logger) error { ipldOutput sdtypes.IPLDSink, logger log.Logger) error {
logger.Debug("statediff BEGIN buildAccountCreations") logger.Debug("statediff BEGIN buildAccountCreations")
defer metrics.ReportAndUpdateDuration("statediff END buildAccountCreations", time.Now(), logger, metrics.IndexerMetrics.BuildAccountCreationsTimer) defer metrics.ReportAndUpdateDuration("statediff END buildAccountCreations",
time.Now(), logger, metrics.IndexerMetrics.BuildAccountCreationsTimer)
for _, val := range accounts { for _, val := range accounts {
diff := sdtypes.StateLeafNode{ diff := sdtypes.StateLeafNode{
AccountWrapper: val, AccountWrapper: val,
@ -385,14 +388,14 @@ func (sdb *StateDiffBuilder) buildAccountCreations(accounts sdtypes.AccountMap,
storageDiff := make([]sdtypes.StorageLeafNode, 0) storageDiff := make([]sdtypes.StorageLeafNode, 0)
err := sdb.buildStorageNodesEventual(val.Account.Root, StorageNodeAppender(&storageDiff), ipldOutput) err := sdb.buildStorageNodesEventual(val.Account.Root, StorageNodeAppender(&storageDiff), ipldOutput)
if err != nil { if err != nil {
return fmt.Errorf("failed building eventual storage diffs for node with leaf key %x\r\nerror: %v", val.LeafKey, err) return fmt.Errorf("failed building eventual storage diffs for node with leaf key %x\r\nerror: %w", val.LeafKey, err)
} }
diff.StorageDiff = storageDiff diff.StorageDiff = storageDiff
// emit codehash => code mappings for contract // emit codehash => code mappings for contract
codeHash := common.BytesToHash(val.Account.CodeHash) codeHash := common.BytesToHash(val.Account.CodeHash)
code, err := sdb.StateCache.ContractCode(codeHash) code, err := sdb.StateCache.ContractCode(codeHash)
if err != nil { if err != nil {
return fmt.Errorf("failed to retrieve code for codehash %s\r\n error: %v", codeHash.String(), err) return fmt.Errorf("failed to retrieve code for codehash %x\r\n error: %w", codeHash, err)
} }
if err := ipldOutput(sdtypes.IPLD{ if err := ipldOutput(sdtypes.IPLD{
CID: ipld.Keccak256ToCid(ipld.RawBinary, codeHash.Bytes()).String(), CID: ipld.Keccak256ToCid(ipld.RawBinary, codeHash.Bytes()).String(),
@ -431,8 +434,7 @@ func (sdb *StateDiffBuilder) buildStorageNodesEventual(sr common.Hash, output sd
return nil return nil
} }
// buildStorageNodesFromTrie returns all the storage diff node objects in the provided node interator // buildStorageNodesFromTrie returns all the storage diff node objects in the provided node iterator
// including intermediate nodes can be turned on or off
func (sdb *StateDiffBuilder) buildStorageNodesFromTrie(it trie.NodeIterator, output sdtypes.StorageNodeSink, func (sdb *StateDiffBuilder) buildStorageNodesFromTrie(it trie.NodeIterator, output sdtypes.StorageNodeSink,
ipldOutput sdtypes.IPLDSink) error { ipldOutput sdtypes.IPLDSink) error {
defer metrics.UpdateDuration(time.Now(), metrics.IndexerMetrics.BuildStorageNodesFromTrieTimer) defer metrics.UpdateDuration(time.Now(), metrics.IndexerMetrics.BuildStorageNodesFromTrieTimer)

2
indexer/database/file/indexer.go
View File

@ -175,7 +175,7 @@ func (sdi *StateDiffIndexer) PushBlock(block *types.Block, receipts types.Receip
metrics.IndexerMetrics.PostgresCommitTimer.Update(tDiff) metrics.IndexerMetrics.PostgresCommitTimer.Update(tDiff)
traceMsg += fmt.Sprintf("postgres transaction commit duration: %s\r\n", tDiff.String()) traceMsg += fmt.Sprintf("postgres transaction commit duration: %s\r\n", tDiff.String())
traceMsg += fmt.Sprintf(" TOTAL PROCESSING DURATION: %s\r\n", time.Since(start).String()) traceMsg += fmt.Sprintf(" TOTAL PROCESSING DURATION: %s\r\n", time.Since(start).String())
log.Debug(traceMsg) log.Trace(traceMsg)
return err return err
}, },
} }

25
indexer/database/metrics/metrics.go
View File

@ -72,9 +72,8 @@ type IndexerMetricsHandles struct {
StateStoreCodeProcessingTimer metrics.Timer StateStoreCodeProcessingTimer metrics.Timer
// Fine-grained code timers // Fine-grained code timers
BuildStateDiffWithIntermediateStateNodesTimer metrics.Timer BuildStateDiffTimer metrics.Timer
BuildStateDiffWithoutIntermediateStateNodesTimer metrics.Timer CreatedAndUpdatedStateTimer metrics.Timer
CreatedAndUpdatedStateWithIntermediateNodesTimer metrics.Timer
DeletedOrUpdatedStateTimer metrics.Timer DeletedOrUpdatedStateTimer metrics.Timer
BuildAccountUpdatesTimer metrics.Timer BuildAccountUpdatesTimer metrics.Timer
BuildAccountCreationsTimer metrics.Timer BuildAccountCreationsTimer metrics.Timer
@ -88,11 +87,8 @@ type IndexerMetricsHandles struct {
DeletedOrUpdatedStorageTimer metrics.Timer DeletedOrUpdatedStorageTimer metrics.Timer
CreatedAndUpdatedStorageTimer metrics.Timer CreatedAndUpdatedStorageTimer metrics.Timer
BuildStorageNodesIncrementalTimer metrics.Timer BuildStorageNodesIncrementalTimer metrics.Timer
BuildStateTrieObjectTimer metrics.Timer
BuildStateTrieTimer metrics.Timer
BuildStateDiffObjectTimer metrics.Timer BuildStateDiffObjectTimer metrics.Timer
WriteStateDiffObjectTimer metrics.Timer WriteStateDiffObjectTimer metrics.Timer
CreatedAndUpdatedStateTimer metrics.Timer
BuildStorageNodesEventualTimer metrics.Timer BuildStorageNodesEventualTimer metrics.Timer
BuildStorageNodesFromTrieTimer metrics.Timer BuildStorageNodesFromTrieTimer metrics.Timer
BuildRemovedAccountStorageNodesTimer metrics.Timer BuildRemovedAccountStorageNodesTimer metrics.Timer
@ -113,9 +109,8 @@ func RegisterIndexerMetrics(reg metrics.Registry) IndexerMetricsHandles {
UncleProcessingTimer: metrics.NewTimer(), UncleProcessingTimer: metrics.NewTimer(),
TxAndRecProcessingTimer: metrics.NewTimer(), TxAndRecProcessingTimer: metrics.NewTimer(),
StateStoreCodeProcessingTimer: metrics.NewTimer(), StateStoreCodeProcessingTimer: metrics.NewTimer(),
BuildStateDiffWithIntermediateStateNodesTimer: metrics.NewTimer(), BuildStateDiffTimer: metrics.NewTimer(),
BuildStateDiffWithoutIntermediateStateNodesTimer: metrics.NewTimer(), CreatedAndUpdatedStateTimer: metrics.NewTimer(),
CreatedAndUpdatedStateWithIntermediateNodesTimer: metrics.NewTimer(),
DeletedOrUpdatedStateTimer: metrics.NewTimer(), DeletedOrUpdatedStateTimer: metrics.NewTimer(),
BuildAccountUpdatesTimer: metrics.NewTimer(), BuildAccountUpdatesTimer: metrics.NewTimer(),
BuildAccountCreationsTimer: metrics.NewTimer(), BuildAccountCreationsTimer: metrics.NewTimer(),
@ -129,11 +124,8 @@ func RegisterIndexerMetrics(reg metrics.Registry) IndexerMetricsHandles {
DeletedOrUpdatedStorageTimer: metrics.NewTimer(), DeletedOrUpdatedStorageTimer: metrics.NewTimer(),
CreatedAndUpdatedStorageTimer: metrics.NewTimer(), CreatedAndUpdatedStorageTimer: metrics.NewTimer(),
BuildStorageNodesIncrementalTimer: metrics.NewTimer(), BuildStorageNodesIncrementalTimer: metrics.NewTimer(),
BuildStateTrieObjectTimer: metrics.NewTimer(),
BuildStateTrieTimer: metrics.NewTimer(),
BuildStateDiffObjectTimer: metrics.NewTimer(), BuildStateDiffObjectTimer: metrics.NewTimer(),
WriteStateDiffObjectTimer: metrics.NewTimer(), WriteStateDiffObjectTimer: metrics.NewTimer(),
CreatedAndUpdatedStateTimer: metrics.NewTimer(),
BuildStorageNodesEventualTimer: metrics.NewTimer(), BuildStorageNodesEventualTimer: metrics.NewTimer(),
BuildStorageNodesFromTrieTimer: metrics.NewTimer(), BuildStorageNodesFromTrieTimer: metrics.NewTimer(),
BuildRemovedAccountStorageNodesTimer: metrics.NewTimer(), BuildRemovedAccountStorageNodesTimer: metrics.NewTimer(),
@ -152,9 +144,8 @@ func RegisterIndexerMetrics(reg metrics.Registry) IndexerMetricsHandles {
reg.Register(metricName(subsys, "t_uncle_processing"), ctx.UncleProcessingTimer) reg.Register(metricName(subsys, "t_uncle_processing"), ctx.UncleProcessingTimer)
reg.Register(metricName(subsys, "t_tx_receipt_processing"), ctx.TxAndRecProcessingTimer) reg.Register(metricName(subsys, "t_tx_receipt_processing"), ctx.TxAndRecProcessingTimer)
reg.Register(metricName(subsys, "t_state_store_code_processing"), ctx.StateStoreCodeProcessingTimer) reg.Register(metricName(subsys, "t_state_store_code_processing"), ctx.StateStoreCodeProcessingTimer)
reg.Register(metricName(subsys, "t_build_statediff_with_intermediate_state_nodes"), ctx.BuildStateDiffWithIntermediateStateNodesTimer) reg.Register(metricName(subsys, "t_build_statediff"), ctx.BuildStateDiffTimer)
reg.Register(metricName(subsys, "t_build_statediff_without_intermediate_state_nodes"), ctx.BuildStateDiffWithoutIntermediateStateNodesTimer) reg.Register(metricName(subsys, "t_created_and_update_state"), ctx.CreatedAndUpdatedStateTimer)
reg.Register(metricName(subsys, "t_created_and_update_state_with_intermediate_nodes"), ctx.CreatedAndUpdatedStateWithIntermediateNodesTimer)
reg.Register(metricName(subsys, "t_deleted_or_updated_state"), ctx.DeletedOrUpdatedStateTimer) reg.Register(metricName(subsys, "t_deleted_or_updated_state"), ctx.DeletedOrUpdatedStateTimer)
reg.Register(metricName(subsys, "t_build_account_updates"), ctx.BuildAccountUpdatesTimer) reg.Register(metricName(subsys, "t_build_account_updates"), ctx.BuildAccountUpdatesTimer)
reg.Register(metricName(subsys, "t_build_account_creations"), ctx.BuildAccountCreationsTimer) reg.Register(metricName(subsys, "t_build_account_creations"), ctx.BuildAccountCreationsTimer)
@ -168,8 +159,6 @@ func RegisterIndexerMetrics(reg metrics.Registry) IndexerMetricsHandles {
reg.Register(metricName(subsys, "t_created_and_updated_storage"), ctx.CreatedAndUpdatedStorageTimer) reg.Register(metricName(subsys, "t_created_and_updated_storage"), ctx.CreatedAndUpdatedStorageTimer)
reg.Register(metricName(subsys, "t_deleted_or_updated_storage"), ctx.DeletedOrUpdatedStorageTimer) reg.Register(metricName(subsys, "t_deleted_or_updated_storage"), ctx.DeletedOrUpdatedStorageTimer)
reg.Register(metricName(subsys, "t_build_storage_nodes_incremental"), ctx.BuildStorageNodesIncrementalTimer) reg.Register(metricName(subsys, "t_build_storage_nodes_incremental"), ctx.BuildStorageNodesIncrementalTimer)
reg.Register(metricName(subsys, "t_build_state_trie_object"), ctx.BuildStateTrieObjectTimer)
reg.Register(metricName(subsys, "t_build_state_trie"), ctx.BuildStateTrieTimer)
reg.Register(metricName(subsys, "t_build_statediff_object"), ctx.BuildStateDiffObjectTimer) reg.Register(metricName(subsys, "t_build_statediff_object"), ctx.BuildStateDiffObjectTimer)
reg.Register(metricName(subsys, "t_write_statediff_object"), ctx.WriteStateDiffObjectTimer) reg.Register(metricName(subsys, "t_write_statediff_object"), ctx.WriteStateDiffObjectTimer)
reg.Register(metricName(subsys, "t_created_and_updated_state"), ctx.CreatedAndUpdatedStateTimer) reg.Register(metricName(subsys, "t_created_and_updated_state"), ctx.CreatedAndUpdatedStateTimer)
@ -252,7 +241,7 @@ func (met *dbMetricsHandles) Update(stats DbStats) {
func ReportAndUpdateDuration(msg string, start time.Time, logger log.Logger, timer metrics.Timer) { func ReportAndUpdateDuration(msg string, start time.Time, logger log.Logger, timer metrics.Timer) {
since := UpdateDuration(start, timer) since := UpdateDuration(start, timer)
logger.Trace(msg, "duration", since.Milliseconds()) logger.Debug(msg, "duration", since)
} }
func UpdateDuration(start time.Time, timer metrics.Timer) time.Duration { func UpdateDuration(start time.Time, timer metrics.Timer) time.Duration {

47
metrics_helpers.go
View File

@ -17,7 +17,6 @@
package statediff package statediff
import ( import (
"fmt"
"time" "time"
"github.com/cerc-io/plugeth-statediff/utils/log" "github.com/cerc-io/plugeth-statediff/utils/log"
@ -29,12 +28,12 @@ func countStateDiffBegin(block *types.Block) (time.Time, log.Logger) {
logger := log.New("hash", block.Hash().String(), "number", block.NumberU64()) logger := log.New("hash", block.Hash().String(), "number", block.NumberU64())
defaultStatediffMetrics.underway.Inc(1) defaultStatediffMetrics.underway.Inc(1)
logger.Debug(fmt.Sprintf("writeStateDiff BEGIN [underway=%d, succeeded=%d, failed=%d, total_time=%dms]", logger.Debug("writeStateDiff BEGIN",
defaultStatediffMetrics.underway.Count(), "underway", defaultStatediffMetrics.underway.Count(),
defaultStatediffMetrics.succeeded.Count(), "succeeded", defaultStatediffMetrics.succeeded.Count(),
defaultStatediffMetrics.failed.Count(), "failed", defaultStatediffMetrics.failed.Count(),
defaultStatediffMetrics.totalProcessingTime.Value(), "total_time", defaultStatediffMetrics.totalProcessingTime.Value(),
)) )
return start, logger return start, logger
} }
@ -49,13 +48,14 @@ func countStateDiffEnd(start time.Time, logger log.Logger, err error) time.Durat
} }
defaultStatediffMetrics.totalProcessingTime.Inc(duration.Milliseconds()) defaultStatediffMetrics.totalProcessingTime.Inc(duration.Milliseconds())
logger.Debug(fmt.Sprintf("writeStateDiff END (duration=%dms, err=%t) [underway=%d, succeeded=%d, failed=%d, total_time=%dms]", logger.Debug("writeStateDiff END",
duration.Milliseconds(), nil != err, "duration", duration,
defaultStatediffMetrics.underway.Count(), "error", err != nil,
defaultStatediffMetrics.succeeded.Count(), "underway", defaultStatediffMetrics.underway.Count(),
defaultStatediffMetrics.failed.Count(), "succeeded", defaultStatediffMetrics.succeeded.Count(),
defaultStatediffMetrics.totalProcessingTime.Value(), "failed", defaultStatediffMetrics.failed.Count(),
)) "total_time", defaultStatediffMetrics.totalProcessingTime.Value(),
)
return duration return duration
} }
@ -67,10 +67,10 @@ func countApiRequestBegin(methodName string, blockHashOrNumber interface{}) (tim
defaultStatediffMetrics.apiRequests.Inc(1) defaultStatediffMetrics.apiRequests.Inc(1)
defaultStatediffMetrics.apiRequestsUnderway.Inc(1) defaultStatediffMetrics.apiRequestsUnderway.Inc(1)
logger.Debug(fmt.Sprintf("statediff API BEGIN [underway=%d, requests=%d])", logger.Debug("statediff API BEGIN",
defaultStatediffMetrics.apiRequestsUnderway.Count(), "underway", defaultStatediffMetrics.apiRequestsUnderway.Count(),
defaultStatediffMetrics.apiRequests.Count(), "requests", defaultStatediffMetrics.apiRequests.Count(),
)) )
return start, logger return start, logger
} }
@ -79,11 +79,12 @@ func countApiRequestEnd(start time.Time, logger log.Logger, err error) time.Dura
duration := time.Since(start) duration := time.Since(start)
defaultStatediffMetrics.apiRequestsUnderway.Dec(1) defaultStatediffMetrics.apiRequestsUnderway.Dec(1)
logger.Debug(fmt.Sprintf("statediff API END (duration=%dms, err=%t) [underway=%d, requests=%d]", logger.Debug("statediff API END",
duration.Milliseconds(), nil != err, "duration", duration,
defaultStatediffMetrics.apiRequestsUnderway.Count(), "error", err != nil,
defaultStatediffMetrics.apiRequests.Count(), "underway", defaultStatediffMetrics.apiRequestsUnderway.Count(),
)) "requests", defaultStatediffMetrics.apiRequests.Count(),
)
return duration return duration
} }

26
service.go
View File

@ -222,10 +222,10 @@ func (sds *Service) WriteLoop(chainEventCh chan core.ChainEvent) {
for { for {
select { select {
case event := <-chainEventCh: case event := <-chainEventCh:
log.Debug("Chain event received", "event", event)
// First process metrics for chain events, then forward to workers // First process metrics for chain events, then forward to workers
lastHeight := defaultStatediffMetrics.lastEventHeight.Value() lastHeight := defaultStatediffMetrics.lastEventHeight.Value()
block := event.Block block := event.Block
log.Debug("Chain event received", "number", block.Number(), "hash", event.Hash)
nextHeight := int64(block.Number().Uint64()) nextHeight := int64(block.Number().Uint64())
if nextHeight-lastHeight != 1 { if nextHeight-lastHeight != 1 {
log.Warn("Received block out-of-order", "next", nextHeight, "last", lastHeight) log.Warn("Received block out-of-order", "next", nextHeight, "last", lastHeight)
@ -252,27 +252,28 @@ func (sds *Service) WriteLoop(chainEventCh chan core.ChainEvent) {
wg.Wait() wg.Wait()
} }
func (sds *Service) writeGenesisStateDiff(currBlock *types.Block, workerId uint) { func (sds *Service) writeGenesisStateDiff(currBlock *types.Block, logger log.Logger) {
// For genesis block we need to return the entire state trie hence we diff it with an empty trie. // For genesis block we need to return the entire state trie hence we diff it with an empty trie.
log.Info("Writing genesis state diff", "number", genesisBlockNumber, "worker", workerId) log.Info("Writing genesis state diff", "number", genesisBlockNumber)
sds.writeLoopParams.RLock() sds.writeLoopParams.RLock()
defer sds.writeLoopParams.RUnlock() defer sds.writeLoopParams.RUnlock()
err := sds.writeStateDiffWithRetry(currBlock, common.Hash{}, sds.writeLoopParams.Params) err := sds.writeStateDiffWithRetry(currBlock, common.Hash{}, sds.writeLoopParams.Params)
if err != nil { if err != nil {
log.Error("failed to write state diff", "number", log.Error("failed to write state diff", "number",
genesisBlockNumber, "error", err.Error(), "worker", workerId) genesisBlockNumber, "error", err.Error())
return return
} }
defaultStatediffMetrics.lastStatediffHeight.Update(genesisBlockNumber) defaultStatediffMetrics.lastStatediffHeight.Update(genesisBlockNumber)
} }
func (sds *Service) writeLoopWorker(params workerParams) { func (sds *Service) writeLoopWorker(params workerParams) {
log := log.New("context", "statediff writing", "worker", params.id)
defer params.wg.Done() defer params.wg.Done()
for { for {
select { select {
case chainEvent := <-params.chainEventCh: case chainEvent := <-params.chainEventCh:
log.Debug("WriteLoop(): chain event received", "event", chainEvent) log.Debug("Chain event received", "event", chainEvent)
block := chainEvent.Block block := chainEvent.Block
parent := sds.BlockCache.getParentBlock(block, sds.BlockChain) parent := sds.BlockCache.getParentBlock(block, sds.BlockChain)
@ -283,10 +284,10 @@ func (sds *Service) writeLoopWorker(params workerParams) {
// chainEvent streams block from block 1, but we also need to include data from the genesis block. // chainEvent streams block from block 1, but we also need to include data from the genesis block.
if parent.Number().Uint64() == genesisBlockNumber { if parent.Number().Uint64() == genesisBlockNumber {
sds.writeGenesisStateDiff(parent, params.id) sds.writeGenesisStateDiff(parent, log)
} }
log.Info("Writing state diff", "number", block.Number().Uint64(), "worker", params.id) log.Info("Writing state diff", "number", block.Number().Uint64())
sds.writeLoopParams.RLock() sds.writeLoopParams.RLock()
err := sds.writeStateDiffWithRetry(block, parent.Root(), sds.writeLoopParams.Params) err := sds.writeStateDiffWithRetry(block, parent.Root(), sds.writeLoopParams.Params)
sds.writeLoopParams.RUnlock() sds.writeLoopParams.RUnlock()
@ -294,15 +295,14 @@ func (sds *Service) writeLoopWorker(params workerParams) {
log.Error("failed to write state diff", log.Error("failed to write state diff",
"number", block.Number().Uint64(), "number", block.Number().Uint64(),
"hash", block.Hash().String(), "hash", block.Hash().String(),
"error", err.Error(), "error", err.Error())
"worker", params.id)
continue continue
} }
// FIXME: reported height will be non-monotonic with concurrent workers // FIXME: reported height will be non-monotonic with concurrent workers
defaultStatediffMetrics.lastStatediffHeight.Update(int64(block.Number().Uint64())) defaultStatediffMetrics.lastStatediffHeight.Update(int64(block.Number().Uint64()))
case <-sds.QuitChan: case <-sds.QuitChan:
log.Info("Quitting the statediff writing process", "worker", params.id) log.Info("Quitting")
return return
} }
} }
@ -325,14 +325,14 @@ func (sds *Service) PublishLoop(chainEventCh chan core.ChainEvent) {
//Notify chain event channel of events //Notify chain event channel of events
case event := <-chainEventCh: case event := <-chainEventCh:
defaultStatediffMetrics.serviceLoopChannelLen.Update(int64(len(chainEventCh))) defaultStatediffMetrics.serviceLoopChannelLen.Update(int64(len(chainEventCh)))
log.Debug("Chain event received", "event", event) block := event.Block
log.Debug("Chain event received", "number", block.Number(), "hash", event.Hash)
// if we don't have any subscribers, do not process a statediff // if we don't have any subscribers, do not process a statediff
if atomic.LoadInt32(&sds.subscribers) == 0 { if atomic.LoadInt32(&sds.subscribers) == 0 {
log.Debug("Currently no subscribers; processing is halted") log.Debug("Currently no subscribers; processing is halted")
continue continue
} }
block := event.Block
parent := sds.BlockCache.getParentBlock(block, sds.BlockChain) parent := sds.BlockCache.getParentBlock(block, sds.BlockChain)
if parent == nil { if parent == nil {
log.Error("Parent block is nil, skipping this block", "number", block.Number()) log.Error("Parent block is nil, skipping this block", "number", block.Number())
@ -703,7 +703,7 @@ func (sds *Service) writeStateDiff(block *types.Block, parentRoot common.Hash, p
defer func() { defer func() {
// This is very noisy so we log at Trace. // This is very noisy so we log at Trace.
since := metrics.UpdateDuration(time.Now(), metrics.IndexerMetrics.OutputTimer) since := metrics.UpdateDuration(time.Now(), metrics.IndexerMetrics.OutputTimer)
logger.Trace("statediff output", "duration", since.Milliseconds()) logger.Trace("statediff output", "duration", since)
}() }()
return sds.indexer.PushStateNode(tx, node, block.Hash().String()) return sds.indexer.PushStateNode(tx, node, block.Hash().String())
} }