From a952a1f39f3a0cc581ed013e1e681f3eaba21d12 Mon Sep 17 00:00:00 2001 From: Thomas E Lackey Date: Wed, 15 Feb 2023 17:28:17 -0600 Subject: [PATCH] Add timers and update StandardTimer to include total time. (#316) * Add timers and update StandardTimer to include total time. * Even more timers. --- metrics/prometheus/collector.go | 3 + metrics/prometheus/collector_test.go | 3 + metrics/timer.go | 25 +++++-- statediff/builder.go | 35 +++++---- statediff/indexer/database/metrics/metrics.go | 72 +++++++++++++++++++ statediff/service.go | 6 +- statediff/trie_helpers/helpers.go | 5 ++ trie/iterator.go | 4 ++ 8 files changed, 132 insertions(+), 21 deletions(-) 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 5cc432c8d..9b79b1dee 100644 --- a/statediff/builder.go +++ b/statediff/builder.go @@ -29,7 +29,6 @@ import ( "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" metrics2 "github.com/ethereum/go-ethereum/statediff/indexer/database/metrics" ipld2 "github.com/ethereum/go-ethereum/statediff/indexer/ipld" @@ -87,6 +86,7 @@ func NewBuilder(stateCache state.Database) Builder { // 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.StateLeafNode var iplds []types2.IPLD err := sdb.WriteStateDiffObject(args, params, StateNodeAppender(&stateNodes), IPLDMappingAppender(&iplds)) @@ -104,6 +104,7 @@ func (sdb *StateDiffBuilder) BuildStateDiffObject(args Args, params Params) (typ // WriteStateDiffObject writes a statediff object to output sinks func (sdb *StateDiffBuilder) WriteStateDiffObject(args Args, params Params, output types2.StateNodeSink, ipldOutput types2.IPLDSink) 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 { @@ -136,7 +137,7 @@ func (sdb *StateDiffBuilder) WriteStateDiffObject(args Args, params Params, outp func (sdb *StateDiffBuilder) BuildStateDiffWithIntermediateStateNodes(iterPairs []IterPair, params Params, output types2.StateNodeSink, ipldOutput types2.IPLDSink, 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 @@ -190,12 +191,12 @@ func (sdb *StateDiffBuilder) BuildStateDiffWithIntermediateStateNodes(iterPairs // and a slice of the paths for all of the nodes included in both func (sdb *StateDiffBuilder) createdAndUpdatedState(a, b trie.NodeIterator, watchedAddressesLeafPaths [][]byte, output types2.IPLDSink, logger log.Logger) (types2.AccountMap, error) { - logger.Debug("statediff BEGIN createdAndUpdatedStateWithIntermediateNodes") - defer timeDuration("statediff END createdAndUpdatedStateWithIntermediateNodes", time.Now(), logger, metrics2.IndexerMetrics.CreatedAndUpdatedStateWithIntermediateNodesTimer) + logger.Debug("statediff BEGIN createdAndUpdatedState") + defer metrics2.ReportAndUpdateDuration("statediff END createdAndUpdatedState", time.Now(), logger, metrics2.IndexerMetrics.CreatedAndUpdatedStateTimer) 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()) { @@ -248,6 +249,8 @@ func (sdb *StateDiffBuilder) createdAndUpdatedState(a, b trie.NodeIterator, } } } + logger.Debug("statediff COUNTS createdAndUpdatedStateWithIntermediateNodes", "it", itCount, "diffAccountsAtB", len(diffAccountsAtB)) + metrics2.IndexerMetrics.DifferenceIteratorCounter.Inc(int64(*itCount)) return diffAccountsAtB, it.Error() } @@ -289,7 +292,7 @@ func (sdb *StateDiffBuilder) processStateValueNode(it trie.NodeIterator, watched func (sdb *StateDiffBuilder) deletedOrUpdatedState(a, b trie.NodeIterator, diffAccountsAtB types2.AccountMap, watchedAddressesLeafPaths [][]byte, 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 @@ -345,8 +348,8 @@ func (sdb *StateDiffBuilder) deletedOrUpdatedState(a, b trie.NodeIterator, diffA // those account maps to remove the accounts which were updated func (sdb *StateDiffBuilder) buildAccountUpdates(creations, deletions types2.AccountMap, updatedKeys []string, output types2.StateNodeSink, ipldOutput types2.IPLDSink, 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] @@ -380,7 +383,7 @@ func (sdb *StateDiffBuilder) buildAccountUpdates(creations, deletions types2.Acc func (sdb *StateDiffBuilder) buildAccountCreations(accounts types2.AccountMap, output types2.StateNodeSink, ipldOutput types2.IPLDSink, 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.StateLeafNode{ AccountWrapper: val, @@ -419,6 +422,7 @@ func (sdb *StateDiffBuilder) buildAccountCreations(accounts types2.AccountMap, o // i.e. it returns all the storage nodes at this state, since there is no previous state func (sdb *StateDiffBuilder) buildStorageNodesEventual(sr common.Hash, output types2.StorageNodeSink, ipldOutput types2.IPLDSink) error { + defer metrics2.UpdateDuration(time.Now(), metrics2.IndexerMetrics.BuildStorageNodesEventualTimer) if bytes.Equal(sr.Bytes(), emptyContractRoot.Bytes()) { return nil } @@ -440,6 +444,7 @@ func (sdb *StateDiffBuilder) buildStorageNodesEventual(sr common.Hash, output ty // including intermediate nodes can be turned on or off func (sdb *StateDiffBuilder) buildStorageNodesFromTrie(it trie.NodeIterator, output types2.StorageNodeSink, ipldOutput types2.IPLDSink) error { + defer metrics2.UpdateDuration(time.Now(), metrics2.IndexerMetrics.BuildStorageNodesFromTrieTimer) for it.Next(true) { if it.Leaf() { storageLeafNode, err := sdb.processStorageValueNode(it) @@ -489,6 +494,7 @@ func (sdb *StateDiffBuilder) processStorageValueNode(it trie.NodeIterator) (type // buildRemovedAccountStorageNodes builds the "removed" diffs for all the storage nodes for a destroyed account func (sdb *StateDiffBuilder) buildRemovedAccountStorageNodes(sr common.Hash, output types2.StorageNodeSink) error { + defer metrics2.UpdateDuration(time.Now(), metrics2.IndexerMetrics.BuildRemovedAccountStorageNodesTimer) if bytes.Equal(sr.Bytes(), emptyContractRoot.Bytes()) { return nil } @@ -508,6 +514,7 @@ func (sdb *StateDiffBuilder) buildRemovedAccountStorageNodes(sr common.Hash, out // buildRemovedStorageNodesFromTrie returns diffs for all the storage nodes in the provided node interator func (sdb *StateDiffBuilder) buildRemovedStorageNodesFromTrie(it trie.NodeIterator, output types2.StorageNodeSink) error { + defer metrics2.UpdateDuration(time.Now(), metrics2.IndexerMetrics.BuildRemovedStorageNodesFromTrieTimer) for it.Next(true) { if it.Leaf() { // only leaf values are indexed, don't need to demarcate removed intermediate nodes leafKey := make([]byte, len(it.LeafKey())) @@ -528,6 +535,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, output types2.StorageNodeSink, ipldOutput types2.IPLDSink) error { + defer metrics2.UpdateDuration(time.Now(), metrics2.IndexerMetrics.BuildStorageNodesIncrementalTimer) if bytes.Equal(newSR.Bytes(), oldSR.Bytes()) { return nil } @@ -556,6 +564,7 @@ func (sdb *StateDiffBuilder) buildStorageNodesIncremental(oldSR common.Hash, new func (sdb *StateDiffBuilder) createdAndUpdatedStorage(a, b trie.NodeIterator, output types2.StorageNodeSink, ipldOutput types2.IPLDSink) (map[string]bool, error) { + defer metrics2.UpdateDuration(time.Now(), metrics2.IndexerMetrics.CreatedAndUpdatedStorageTimer) diffSlotsAtB := make(map[string]bool) it, _ := trie.NewDifferenceIterator(a, b) for it.Next(true) { @@ -585,6 +594,7 @@ func (sdb *StateDiffBuilder) createdAndUpdatedStorage(a, b trie.NodeIterator, ou } func (sdb *StateDiffBuilder) deletedOrUpdatedStorage(a, b trie.NodeIterator, diffSlotsAtB map[string]bool, output types2.StorageNodeSink) error { + defer metrics2.UpdateDuration(time.Now(), metrics2.IndexerMetrics.DeletedOrUpdatedStorageTimer) it, _ := trie.NewDifferenceIterator(b, a) for it.Next(true) { if it.Leaf() { @@ -621,6 +631,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) for _, watchedAddressPath := range watchedAddressesLeafPaths { if bytes.Equal(watchedAddressPath, valueNodePath) { return true @@ -651,9 +662,3 @@ func isLeaf(elements []interface{}) (bool, error) { return false, fmt.Errorf("unknown hex prefix") } } - -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 e8b4a278e..880d56aa1 100644 --- a/statediff/service.go +++ b/statediff/service.go @@ -26,8 +26,6 @@ import ( "sync/atomic" "time" - "github.com/ethereum/go-ethereum/trie" - "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/core" "github.com/ethereum/go-ethereum/core/state" @@ -43,9 +41,11 @@ import ( "github.com/ethereum/go-ethereum/rlp" "github.com/ethereum/go-ethereum/rpc" ind "github.com/ethereum/go-ethereum/statediff/indexer" + "github.com/ethereum/go-ethereum/statediff/indexer/database/metrics" "github.com/ethereum/go-ethereum/statediff/indexer/interfaces" nodeinfo "github.com/ethereum/go-ethereum/statediff/indexer/node" types2 "github.com/ethereum/go-ethereum/statediff/types" + "github.com/ethereum/go-ethereum/trie" "github.com/thoas/go-funk" ) @@ -794,9 +794,11 @@ func (sds *Service) writeStateDiff(block *types.Block, parentRoot common.Hash, p } output := func(node types2.StateLeafNode) error { + defer metrics.ReportAndUpdateDuration("statediff output", time.Now(), logger, metrics.IndexerMetrics.OutputTimer) return sds.indexer.PushStateNode(tx, node, block.Hash().String()) } ipldOutput := func(c types2.IPLD) error { + defer metrics.ReportAndUpdateDuration("statediff ipldOutput", time.Now(), logger, metrics.IndexerMetrics.CodeOutputTimer) return sds.indexer.PushIPLD(tx, c) } diff --git a/statediff/trie_helpers/helpers.go b/statediff/trie_helpers/helpers.go index 0f5152774..d6c024ee4 100644 --- a/statediff/trie_helpers/helpers.go +++ b/statediff/trie_helpers/helpers.go @@ -22,12 +22,16 @@ package trie_helpers import ( "sort" "strings" + "time" + + metrics2 "github.com/ethereum/go-ethereum/statediff/indexer/database/metrics" "github.com/ethereum/go-ethereum/statediff/types" ) // 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) @@ -41,6 +45,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.