diff --git a/metrics/prometheus/collector.go b/metrics/prometheus/collector.go index e8d5e4f5d..76bece915 100644 --- a/metrics/prometheus/collector.go +++ b/metrics/prometheus/collector.go @@ -82,6 +82,9 @@ func (c *collector) addTimer(name string, m metrics.Timer) { c.writeSummaryPercentile(name, strconv.FormatFloat(pv[i], 'f', -1, 64), ps[i]) } c.buff.WriteRune('\n') + + c.buff.WriteString(fmt.Sprintf(typeGaugeTpl, mutateKey(name+"_total"))) + c.buff.WriteString(fmt.Sprintf(keyValueTpl, mutateKey(name+"_total"), m.Total())) } func (c *collector) addResettingTimer(name string, m metrics.ResettingTimer) { diff --git a/metrics/prometheus/collector_test.go b/metrics/prometheus/collector_test.go index 43f2f804d..194ff5541 100644 --- a/metrics/prometheus/collector_test.go +++ b/metrics/prometheus/collector_test.go @@ -92,6 +92,9 @@ test_timer {quantile="0.99"} 1.2e+08 test_timer {quantile="0.999"} 1.2e+08 test_timer {quantile="0.9999"} 1.2e+08 +# TYPE test_timer_total gauge +test_timer_total 230000000 + # TYPE test_resetting_timer_count counter test_resetting_timer_count 6 diff --git a/metrics/timer.go b/metrics/timer.go index a63c9dfb6..3d68c3135 100644 --- a/metrics/timer.go +++ b/metrics/timer.go @@ -25,6 +25,7 @@ type Timer interface { Update(time.Duration) UpdateSince(time.Time) Variance() float64 + Total() int64 } // GetOrRegisterTimer returns an existing Timer or constructs and registers a @@ -47,6 +48,7 @@ func NewCustomTimer(h Histogram, m Meter) Timer { return &StandardTimer{ histogram: h, meter: m, + total: NewCounter(), } } @@ -72,6 +74,7 @@ func NewTimer() Timer { return &StandardTimer{ histogram: NewHistogram(NewExpDecaySample(1028, 0.015)), meter: NewMeter(), + total: NewCounter(), } } @@ -134,11 +137,15 @@ func (NilTimer) UpdateSince(time.Time) {} // Variance is a no-op. func (NilTimer) Variance() float64 { return 0.0 } +// Total is a no-op. +func (NilTimer) Total() int64 { return int64(0) } + // StandardTimer is the standard implementation of a Timer and uses a Histogram // and Meter. type StandardTimer struct { histogram Histogram meter Meter + total Counter mutex sync.Mutex } @@ -200,6 +207,7 @@ func (t *StandardTimer) Snapshot() Timer { return &TimerSnapshot{ histogram: t.histogram.Snapshot().(*HistogramSnapshot), meter: t.meter.Snapshot().(*MeterSnapshot), + total: t.total.Snapshot().(CounterSnapshot), } } @@ -231,14 +239,12 @@ func (t *StandardTimer) Update(d time.Duration) { defer t.mutex.Unlock() t.histogram.Update(int64(d)) t.meter.Mark(1) + t.total.Inc(int64(d)) } // Record the duration of an event that started at a time and ends now. func (t *StandardTimer) UpdateSince(ts time.Time) { - t.mutex.Lock() - defer t.mutex.Unlock() - t.histogram.Update(int64(time.Since(ts))) - t.meter.Mark(1) + t.Update(time.Since(ts)) } // Variance returns the variance of the values in the sample. @@ -246,10 +252,18 @@ func (t *StandardTimer) Variance() float64 { return t.histogram.Variance() } +// Total returns the total time the timer has run in nanoseconds. +// This differs from Sum in that it is a simple counter, not based +// on a histogram Sample. +func (t *StandardTimer) Total() int64 { + return t.total.Count() +} + // TimerSnapshot is a read-only copy of another Timer. type TimerSnapshot struct { histogram *HistogramSnapshot meter *MeterSnapshot + total CounterSnapshot } // Count returns the number of events recorded at the time the snapshot was @@ -324,3 +338,6 @@ func (*TimerSnapshot) UpdateSince(time.Time) { // Variance returns the variance of the values at the time the snapshot was // taken. func (t *TimerSnapshot) Variance() float64 { return t.histogram.Variance() } + +// Total returns the total time the timer has run in nanoseconds. +func (t *TimerSnapshot) Total() int64 { return t.total.Count() } diff --git a/statediff/builder.go b/statediff/builder.go index 3aba38139..3c413fad7 100644 --- a/statediff/builder.go +++ b/statediff/builder.go @@ -24,7 +24,6 @@ import ( "fmt" "time" - "github.com/ethereum/go-ethereum/metrics" metrics2 "github.com/ethereum/go-ethereum/statediff/indexer/database/metrics" "github.com/ethereum/go-ethereum/common" @@ -89,6 +88,7 @@ func NewBuilder(stateCache state.Database) Builder { // BuildStateTrieObject builds a state trie object from the provided block func (sdb *StateDiffBuilder) BuildStateTrieObject(current *types.Block) (types2.StateObject, error) { + defer metrics2.UpdateDuration(time.Now(), metrics2.IndexerMetrics.BuildStateTrieObjectTimer) currentTrie, err := sdb.StateCache.OpenTrie(current.Root()) if err != nil { return types2.StateObject{}, fmt.Errorf("error creating trie for block %d: %v", current.Number(), err) @@ -107,6 +107,7 @@ func (sdb *StateDiffBuilder) BuildStateTrieObject(current *types.Block) (types2. } func (sdb *StateDiffBuilder) buildStateTrie(it trie.NodeIterator) ([]types2.StateNode, []types2.CodeAndCodeHash, error) { + defer metrics2.UpdateDuration(time.Now(), metrics2.IndexerMetrics.BuildStateTrieTimer) stateNodes := make([]types2.StateNode, 0) codeAndCodeHashes := make([]types2.CodeAndCodeHash, 0) for it.Next(true) { @@ -159,6 +160,7 @@ func (sdb *StateDiffBuilder) buildStateTrie(it trie.NodeIterator) ([]types2.Stat // BuildStateDiffObject builds a statediff object from two blocks and the provided parameters func (sdb *StateDiffBuilder) BuildStateDiffObject(args Args, params Params) (types2.StateObject, error) { + defer metrics2.UpdateDuration(time.Now(), metrics2.IndexerMetrics.BuildStateDiffObjectTimer) var stateNodes []types2.StateNode var codeAndCodeHashes []types2.CodeAndCodeHash err := sdb.WriteStateDiffObject(args, params, StateNodeAppender(&stateNodes), CodeMappingAppender(&codeAndCodeHashes)) @@ -175,6 +177,7 @@ func (sdb *StateDiffBuilder) BuildStateDiffObject(args Args, params Params) (typ // WriteStateDiffObject writes a statediff object to output callback func (sdb *StateDiffBuilder) WriteStateDiffObject(args Args, params Params, output types2.StateNodeSink, codeOutput types2.CodeSink) error { + defer metrics2.UpdateDuration(time.Now(), metrics2.IndexerMetrics.WriteStateDiffObjectTimer) // Load tries for old and new states oldTrie, err := sdb.StateCache.OpenTrie(args.OldStateRoot) if err != nil { @@ -210,7 +213,7 @@ func (sdb *StateDiffBuilder) WriteStateDiffObject(args Args, params Params, outp func (sdb *StateDiffBuilder) BuildStateDiffWithIntermediateStateNodes(iterPairs []IterPair, params Params, output types2.StateNodeSink, codeOutput types2.CodeSink, logger log.Logger) error { logger.Debug("statediff BEGIN BuildStateDiffWithIntermediateStateNodes") - defer timeDuration("statediff END BuildStateDiffWithIntermediateStateNodes", time.Now(), logger, metrics2.IndexerMetrics.BuildStateDiffWithIntermediateStateNodesTimer) + defer metrics2.ReportAndUpdateDuration("statediff END BuildStateDiffWithIntermediateStateNodes", time.Now(), logger, metrics2.IndexerMetrics.BuildStateDiffWithIntermediateStateNodesTimer) // 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 // and a slice of all the paths for the nodes in both of the above sets @@ -263,7 +266,7 @@ func (sdb *StateDiffBuilder) BuildStateDiffWithIntermediateStateNodes(iterPairs func (sdb *StateDiffBuilder) BuildStateDiffWithoutIntermediateStateNodes(iterPairs []IterPair, params Params, output types2.StateNodeSink, codeOutput types2.CodeSink, logger log.Logger) error { logger.Debug("statediff BEGIN BuildStateDiffWithoutIntermediateStateNodes") - defer timeDuration("statediff END BuildStateDiffWithoutIntermediateStateNodes", time.Now(), logger, metrics2.IndexerMetrics.BuildStateDiffWithoutIntermediateStateNodesTimer) + defer metrics2.ReportAndUpdateDuration("statediff END BuildStateDiffWithoutIntermediateStateNodes", time.Now(), logger, metrics2.IndexerMetrics.BuildStateDiffWithoutIntermediateStateNodesTimer) // collect 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 diffAccountsAtB, diffPathsAtB, err := sdb.createdAndUpdatedState( @@ -318,6 +321,8 @@ func (sdb *StateDiffBuilder) BuildStateDiffWithoutIntermediateStateNodes(iterPai // a mapping of their leafkeys to all the accounts that exist in a different state at B than A // and a slice of the paths for all of the nodes included in both func (sdb *StateDiffBuilder) createdAndUpdatedState(a, b trie.NodeIterator, watchedAddressesLeafPaths [][]byte, logger log.Logger) (types2.AccountMap, map[string]bool, error) { + logger.Debug("statediff BEGIN createdAndUpdatedState") + defer metrics2.ReportAndUpdateDuration("statediff END createdAndUpdatedState", time.Now(), logger, metrics2.IndexerMetrics.CreatedAndUpdatedStateTimer) diffPathsAtB := make(map[string]bool) diffAccountsAtB := make(types2.AccountMap) watchingAddresses := len(watchedAddressesLeafPaths) > 0 @@ -375,12 +380,12 @@ func (sdb *StateDiffBuilder) createdAndUpdatedState(a, b trie.NodeIterator, watc // and a slice of the paths for all of the nodes included in both func (sdb *StateDiffBuilder) createdAndUpdatedStateWithIntermediateNodes(a, b trie.NodeIterator, watchedAddressesLeafPaths [][]byte, output types2.StateNodeSink, logger log.Logger) (types2.AccountMap, map[string]bool, error) { logger.Debug("statediff BEGIN createdAndUpdatedStateWithIntermediateNodes") - defer timeDuration("statediff END createdAndUpdatedStateWithIntermediateNodes", time.Now(), logger, metrics2.IndexerMetrics.CreatedAndUpdatedStateWithIntermediateNodesTimer) + defer metrics2.ReportAndUpdateDuration("statediff END createdAndUpdatedStateWithIntermediateNodes", time.Now(), logger, metrics2.IndexerMetrics.CreatedAndUpdatedStateWithIntermediateNodesTimer) diffPathsAtB := make(map[string]bool) diffAccountsAtB := make(types2.AccountMap) watchingAddresses := len(watchedAddressesLeafPaths) > 0 - it, _ := trie.NewDifferenceIterator(a, b) + it, itCount := trie.NewDifferenceIterator(a, b) for it.Next(true) { // ignore node if it is not along paths of interest if watchingAddresses && !isValidPrefixPath(watchedAddressesLeafPaths, it.Path()) { @@ -436,6 +441,8 @@ func (sdb *StateDiffBuilder) createdAndUpdatedStateWithIntermediateNodes(a, b tr // add both intermediate and leaf node paths to the list of diffPathsAtB diffPathsAtB[common.Bytes2Hex(node.Path)] = true } + logger.Debug("statediff COUNTS createdAndUpdatedStateWithIntermediateNodes", "it", itCount, "diffAccountsAtB", len(diffAccountsAtB), "diffPathsAtB", len(diffPathsAtB)) + metrics2.IndexerMetrics.DifferenceIteratorCounter.Inc(int64(*itCount)) return diffAccountsAtB, diffPathsAtB, it.Error() } @@ -443,7 +450,7 @@ func (sdb *StateDiffBuilder) createdAndUpdatedStateWithIntermediateNodes(a, b tr // and a mapping of their leafkeys to all the accounts that exist in a different state at A than B func (sdb *StateDiffBuilder) deletedOrUpdatedState(a, b trie.NodeIterator, diffAccountsAtB types2.AccountMap, diffPathsAtB map[string]bool, watchedAddressesLeafPaths [][]byte, intermediateStateNodes, intermediateStorageNodes bool, output types2.StateNodeSink, logger log.Logger) (types2.AccountMap, error) { logger.Debug("statediff BEGIN deletedOrUpdatedState") - defer timeDuration("statediff END deletedOrUpdatedState", time.Now(), logger, metrics2.IndexerMetrics.DeletedOrUpdatedStateTimer) + defer metrics2.ReportAndUpdateDuration("statediff END deletedOrUpdatedState", time.Now(), logger, metrics2.IndexerMetrics.DeletedOrUpdatedStateTimer) diffAccountAtA := make(types2.AccountMap) watchingAddresses := len(watchedAddressesLeafPaths) > 0 @@ -550,8 +557,8 @@ func (sdb *StateDiffBuilder) deletedOrUpdatedState(a, b trie.NodeIterator, diffA // needs to be called before building account creations and deletions as this mutates // those account maps to remove the accounts which were updated func (sdb *StateDiffBuilder) buildAccountUpdates(creations, deletions types2.AccountMap, updatedKeys []string, intermediateStorageNodes bool, output types2.StateNodeSink, logger log.Logger) error { - logger.Debug("statediff BEGIN buildAccountUpdates") - defer timeDuration("statediff END buildAccountUpdates", time.Now(), logger, metrics2.IndexerMetrics.BuildAccountUpdatesTimer) + logger.Debug("statediff BEGIN buildAccountUpdates", "creations", len(creations), "deletions", len(deletions), "updatedKeys", len(updatedKeys)) + defer metrics2.ReportAndUpdateDuration("statediff END buildAccountUpdates ", time.Now(), logger, metrics2.IndexerMetrics.BuildAccountUpdatesTimer) var err error for _, key := range updatedKeys { createdAcc := creations[key] @@ -587,7 +594,7 @@ func (sdb *StateDiffBuilder) buildAccountUpdates(creations, deletions types2.Acc // it also returns the code and codehash for created contract accounts func (sdb *StateDiffBuilder) buildAccountCreations(accounts types2.AccountMap, intermediateStorageNodes bool, output types2.StateNodeSink, codeOutput types2.CodeSink, logger log.Logger) error { logger.Debug("statediff BEGIN buildAccountCreations") - defer timeDuration("statediff END buildAccountCreations", time.Now(), logger, metrics2.IndexerMetrics.BuildAccountCreationsTimer) + defer metrics2.ReportAndUpdateDuration("statediff END buildAccountCreations", time.Now(), logger, metrics2.IndexerMetrics.BuildAccountCreationsTimer) for _, val := range accounts { diff := types2.StateNode{ NodeType: val.NodeType, @@ -627,6 +634,7 @@ func (sdb *StateDiffBuilder) buildAccountCreations(accounts types2.AccountMap, i // buildStorageNodesEventual builds the storage diff node objects for a created account // i.e. it returns all the storage nodes at this state, since there is no previous state func (sdb *StateDiffBuilder) buildStorageNodesEventual(sr common.Hash, intermediateNodes bool, output types2.StorageNodeSink) error { + defer metrics2.UpdateDuration(time.Now(), metrics2.IndexerMetrics.BuildStorageNodesEventualTimer) if bytes.Equal(sr.Bytes(), emptyContractRoot.Bytes()) { return nil } @@ -647,6 +655,7 @@ func (sdb *StateDiffBuilder) buildStorageNodesEventual(sr common.Hash, intermedi // buildStorageNodesFromTrie returns all the storage diff node objects in the provided node interator // including intermediate nodes can be turned on or off func (sdb *StateDiffBuilder) buildStorageNodesFromTrie(it trie.NodeIterator, intermediateNodes bool, output types2.StorageNodeSink) error { + defer metrics2.UpdateDuration(time.Now(), metrics2.IndexerMetrics.BuildStorageNodesFromTrieTimer) for it.Next(true) { // skip value nodes if it.Leaf() || bytes.Equal(nullHashBytes, it.Hash().Bytes()) { @@ -689,6 +698,7 @@ func (sdb *StateDiffBuilder) buildStorageNodesFromTrie(it trie.NodeIterator, int // buildRemovedAccountStorageNodes builds the "removed" diffs for all the storage nodes for a destroyed account func (sdb *StateDiffBuilder) buildRemovedAccountStorageNodes(sr common.Hash, intermediateNodes bool, output types2.StorageNodeSink) error { + defer metrics2.UpdateDuration(time.Now(), metrics2.IndexerMetrics.BuildRemovedAccountStorageNodesTimer) if bytes.Equal(sr.Bytes(), emptyContractRoot.Bytes()) { return nil } @@ -709,6 +719,7 @@ func (sdb *StateDiffBuilder) buildRemovedAccountStorageNodes(sr common.Hash, int // buildRemovedStorageNodesFromTrie returns diffs for all the storage nodes in the provided node interator // including intermediate nodes can be turned on or off func (sdb *StateDiffBuilder) buildRemovedStorageNodesFromTrie(it trie.NodeIterator, intermediateNodes bool, output types2.StorageNodeSink) error { + defer metrics2.UpdateDuration(time.Now(), metrics2.IndexerMetrics.BuildRemovedStorageNodesFromTrieTimer) for it.Next(true) { // skip value nodes if it.Leaf() || bytes.Equal(nullHashBytes, it.Hash().Bytes()) { @@ -751,6 +762,7 @@ func (sdb *StateDiffBuilder) buildRemovedStorageNodesFromTrie(it trie.NodeIterat // buildStorageNodesIncremental builds the storage diff node objects for all nodes that exist in a different state at B than A func (sdb *StateDiffBuilder) buildStorageNodesIncremental(oldSR common.Hash, newSR common.Hash, intermediateNodes bool, output types2.StorageNodeSink) error { + defer metrics2.UpdateDuration(time.Now(), metrics2.IndexerMetrics.BuildStorageNodesIncrementalTimer) if bytes.Equal(newSR.Bytes(), oldSR.Bytes()) { return nil } @@ -779,6 +791,7 @@ func (sdb *StateDiffBuilder) buildStorageNodesIncremental(oldSR common.Hash, new } func (sdb *StateDiffBuilder) createdAndUpdatedStorage(a, b trie.NodeIterator, intermediateNodes bool, output types2.StorageNodeSink) (map[string]bool, map[string]bool, error) { + defer metrics2.UpdateDuration(time.Now(), metrics2.IndexerMetrics.CreatedAndUpdatedStorageTimer) diffPathsAtB := make(map[string]bool) diffSlotsAtB := make(map[string]bool) it, _ := trie.NewDifferenceIterator(a, b) @@ -825,6 +838,7 @@ func (sdb *StateDiffBuilder) createdAndUpdatedStorage(a, b trie.NodeIterator, in } func (sdb *StateDiffBuilder) deletedOrUpdatedStorage(a, b trie.NodeIterator, diffSlotsAtB, diffPathsAtB map[string]bool, intermediateNodes bool, output types2.StorageNodeSink) error { + defer metrics2.UpdateDuration(time.Now(), metrics2.IndexerMetrics.DeletedOrUpdatedStorageTimer) it, _ := trie.NewDifferenceIterator(b, a) for it.Next(true) { // skip value nodes @@ -904,6 +918,7 @@ func isValidPrefixPath(watchedAddressesLeafPaths [][]byte, currentPath []byte) b // isWatchedAddress is used to check if a state account corresponds to one of the addresses the builder is configured to watch func isWatchedAddress(watchedAddressesLeafPaths [][]byte, valueNodePath []byte) bool { + defer metrics2.UpdateDuration(time.Now(), metrics2.IndexerMetrics.IsWatchedAddressTimer) // If we aren't watching any specific addresses, we are watching everything if len(watchedAddressesLeafPaths) == 0 { return true @@ -917,9 +932,3 @@ func isWatchedAddress(watchedAddressesLeafPaths [][]byte, valueNodePath []byte) return false } - -func timeDuration(msg string, start time.Time, logger log.Logger, timer metrics.Timer) { - since := time.Since(start) - timer.Update(since) - logger.Debug(fmt.Sprintf("%s duration=%dms", msg, since.Milliseconds())) -} diff --git a/statediff/indexer/database/metrics/metrics.go b/statediff/indexer/database/metrics/metrics.go index 14b5a49e1..550dd238e 100644 --- a/statediff/indexer/database/metrics/metrics.go +++ b/statediff/indexer/database/metrics/metrics.go @@ -17,6 +17,7 @@ package metrics import ( + "fmt" "strings" "time" @@ -78,6 +79,26 @@ type IndexerMetricsHandles struct { DeletedOrUpdatedStateTimer metrics.Timer BuildAccountUpdatesTimer metrics.Timer BuildAccountCreationsTimer metrics.Timer + ResolveNodeTimer metrics.Timer + SortKeysTimer metrics.Timer + FindIntersectionTimer metrics.Timer + OutputTimer metrics.Timer + CodeOutputTimer metrics.Timer + DifferenceIteratorNextTimer metrics.Timer + DifferenceIteratorCounter metrics.Counter + DeletedOrUpdatedStorageTimer metrics.Timer + CreatedAndUpdatedStorageTimer metrics.Timer + BuildStorageNodesIncrementalTimer metrics.Timer + BuildStateTrieObjectTimer metrics.Timer + BuildStateTrieTimer metrics.Timer + BuildStateDiffObjectTimer metrics.Timer + WriteStateDiffObjectTimer metrics.Timer + CreatedAndUpdatedStateTimer metrics.Timer + BuildStorageNodesEventualTimer metrics.Timer + BuildStorageNodesFromTrieTimer metrics.Timer + BuildRemovedAccountStorageNodesTimer metrics.Timer + BuildRemovedStorageNodesFromTrieTimer metrics.Timer + IsWatchedAddressTimer metrics.Timer } func RegisterIndexerMetrics(reg metrics.Registry) IndexerMetricsHandles { @@ -99,6 +120,26 @@ func RegisterIndexerMetrics(reg metrics.Registry) IndexerMetricsHandles { DeletedOrUpdatedStateTimer: metrics.NewTimer(), BuildAccountUpdatesTimer: metrics.NewTimer(), BuildAccountCreationsTimer: metrics.NewTimer(), + ResolveNodeTimer: metrics.NewTimer(), + SortKeysTimer: metrics.NewTimer(), + FindIntersectionTimer: metrics.NewTimer(), + OutputTimer: metrics.NewTimer(), + CodeOutputTimer: metrics.NewTimer(), + DifferenceIteratorNextTimer: metrics.NewTimer(), + DifferenceIteratorCounter: metrics.NewCounter(), + DeletedOrUpdatedStorageTimer: metrics.NewTimer(), + CreatedAndUpdatedStorageTimer: metrics.NewTimer(), + BuildStorageNodesIncrementalTimer: metrics.NewTimer(), + BuildStateTrieObjectTimer: metrics.NewTimer(), + BuildStateTrieTimer: metrics.NewTimer(), + BuildStateDiffObjectTimer: metrics.NewTimer(), + WriteStateDiffObjectTimer: metrics.NewTimer(), + CreatedAndUpdatedStateTimer: metrics.NewTimer(), + BuildStorageNodesEventualTimer: metrics.NewTimer(), + BuildStorageNodesFromTrieTimer: metrics.NewTimer(), + BuildRemovedAccountStorageNodesTimer: metrics.NewTimer(), + BuildRemovedStorageNodesFromTrieTimer: metrics.NewTimer(), + IsWatchedAddressTimer: metrics.NewTimer(), } subsys := "indexer" reg.Register(metricName(subsys, "blocks"), ctx.BlocksCounter) @@ -118,6 +159,26 @@ func RegisterIndexerMetrics(reg metrics.Registry) IndexerMetricsHandles { 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_creations"), ctx.BuildAccountCreationsTimer) + reg.Register(metricName(subsys, "t_resolve_node"), ctx.ResolveNodeTimer) + reg.Register(metricName(subsys, "t_sort_keys"), ctx.SortKeysTimer) + reg.Register(metricName(subsys, "t_find_intersection"), ctx.FindIntersectionTimer) + reg.Register(metricName(subsys, "t_output_fn"), ctx.OutputTimer) + reg.Register(metricName(subsys, "t_code_output_fn"), ctx.CodeOutputTimer) + reg.Register(metricName(subsys, "t_difference_iterator_next"), ctx.DifferenceIteratorNextTimer) + reg.Register(metricName(subsys, "difference_iterator_counter"), ctx.DifferenceIteratorCounter) + 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_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_write_statediff_object"), ctx.WriteStateDiffObjectTimer) + reg.Register(metricName(subsys, "t_created_and_updated_state"), ctx.CreatedAndUpdatedStateTimer) + reg.Register(metricName(subsys, "t_build_storage_nodes_eventual"), ctx.BuildStorageNodesEventualTimer) + reg.Register(metricName(subsys, "t_build_storage_nodes_from_trie"), ctx.BuildStorageNodesFromTrieTimer) + reg.Register(metricName(subsys, "t_build_removed_accounts_storage_nodes"), ctx.BuildRemovedAccountStorageNodesTimer) + reg.Register(metricName(subsys, "t_build_removed_storage_nodes_from_trie"), ctx.BuildRemovedStorageNodesFromTrieTimer) + reg.Register(metricName(subsys, "t_is_watched_address"), ctx.IsWatchedAddressTimer) log.Debug("Registering statediff indexer metrics.") return ctx @@ -189,3 +250,14 @@ func (met *dbMetricsHandles) Update(stats DbStats) { met.closedMaxIdle.Inc(stats.MaxIdleClosed()) met.closedMaxLifetime.Inc(stats.MaxLifetimeClosed()) } + +func ReportAndUpdateDuration(msg string, start time.Time, logger log.Logger, timer metrics.Timer) { + since := UpdateDuration(start, timer) + logger.Debug(fmt.Sprintf("%s duration=%dms", msg, since.Milliseconds())) +} + +func UpdateDuration(start time.Time, timer metrics.Timer) time.Duration { + since := time.Since(start) + timer.Update(since) + return since +} diff --git a/statediff/service.go b/statediff/service.go index 2847850bf..a0b8424e3 100644 --- a/statediff/service.go +++ b/statediff/service.go @@ -26,6 +26,8 @@ import ( "sync/atomic" "time" + "github.com/ethereum/go-ethereum/statediff/indexer/database/metrics" + "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/core" "github.com/ethereum/go-ethereum/core/state" @@ -861,9 +863,11 @@ func (sds *Service) writeStateDiff(block *types.Block, parentRoot common.Hash, p } output := func(node types2.StateNode) error { + defer metrics.ReportAndUpdateDuration("statediff output", time.Now(), logger, metrics.IndexerMetrics.OutputTimer) return sds.indexer.PushStateNode(tx, node, block.Hash().String()) } codeOutput := func(c types2.CodeAndCodeHash) error { + defer metrics.ReportAndUpdateDuration("statediff codeOutput", time.Now(), logger, metrics.IndexerMetrics.CodeOutputTimer) return sds.indexer.PushCodeAndCodeHash(tx, c) } diff --git a/statediff/trie_helpers/helpers.go b/statediff/trie_helpers/helpers.go index 087cfe419..869b0cc88 100644 --- a/statediff/trie_helpers/helpers.go +++ b/statediff/trie_helpers/helpers.go @@ -23,6 +23,9 @@ import ( "fmt" "sort" "strings" + "time" + + metrics2 "github.com/ethereum/go-ethereum/statediff/indexer/database/metrics" "github.com/ethereum/go-ethereum/rlp" "github.com/ethereum/go-ethereum/statediff/types" @@ -53,6 +56,7 @@ func CheckKeyType(elements []interface{}) (types.NodeType, error) { // ResolveNode return the state diff node pointed by the iterator. func ResolveNode(it trie.NodeIterator, trieDB *trie.Database) (types.StateNode, []interface{}, error) { + defer metrics2.UpdateDuration(time.Now(), metrics2.IndexerMetrics.ResolveNodeTimer) nodePath := make([]byte, len(it.Path())) copy(nodePath, it.Path()) node, err := trieDB.Node(it.Hash()) @@ -76,6 +80,7 @@ func ResolveNode(it trie.NodeIterator, trieDB *trie.Database) (types.StateNode, // SortKeys sorts the keys in the account map func SortKeys(data types.AccountMap) []string { + defer metrics2.UpdateDuration(time.Now(), metrics2.IndexerMetrics.SortKeysTimer) keys := make([]string, 0, len(data)) for key := range data { keys = append(keys, key) @@ -89,6 +94,7 @@ func SortKeys(data types.AccountMap) []string { // a and b must first be sorted // this is used to find which keys have been both "deleted" and "created" i.e. they were updated func FindIntersection(a, b []string) []string { + defer metrics2.UpdateDuration(time.Now(), metrics2.IndexerMetrics.FindIntersectionTimer) lenA := len(a) lenB := len(b) iOfA, iOfB := 0, 0 diff --git a/trie/iterator.go b/trie/iterator.go index d2c8b6a78..3c2bc4ada 100644 --- a/trie/iterator.go +++ b/trie/iterator.go @@ -20,6 +20,9 @@ import ( "bytes" "container/heap" "errors" + "time" + + "github.com/ethereum/go-ethereum/statediff/indexer/database/metrics" "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/ethdb" @@ -584,6 +587,7 @@ func (it *differenceIterator) AddResolver(resolver ethdb.KeyValueReader) { } func (it *differenceIterator) Next(bool) bool { + defer metrics.UpdateDuration(time.Now(), metrics.IndexerMetrics.DifferenceIteratorNextTimer) // Invariants: // - We always advance at least one element in b. // - At the start of this function, a's path is lexically greater than b's.