From 5ba628f0493f5eda2268c99a1e1dee500202b2c5 Mon Sep 17 00:00:00 2001 From: Thomas E Lackey Date: Wed, 15 Feb 2023 01:41:10 -0600 Subject: [PATCH 1/8] Add timers and update StandardTimer to include total time. --- metrics/prometheus/collector.go | 2 + metrics/timer.go | 20 +++++++-- statediff/builder.go | 29 +++++++------ statediff/indexer/database/metrics/metrics.go | 42 +++++++++++++++++++ statediff/service.go | 3 ++ statediff/trie_helpers/helpers.go | 5 +++ trie/iterator.go | 3 ++ 7 files changed, 85 insertions(+), 19 deletions(-) diff --git a/metrics/prometheus/collector.go b/metrics/prometheus/collector.go index e8d5e4f5d..f9da6baa9 100644 --- a/metrics/prometheus/collector.go +++ b/metrics/prometheus/collector.go @@ -78,6 +78,8 @@ func (c *collector) addTimer(name string, m metrics.Timer) { ps := m.Percentiles(pv) c.writeSummaryCounter(name, m.Count()) c.buff.WriteString(fmt.Sprintf(typeSummaryTpl, mutateKey(name))) + c.buff.WriteString(fmt.Sprintf(typeGaugeTpl, mutateKey(name+"_total"))) + c.buff.WriteString(fmt.Sprintf(keyValueTpl, mutateKey(name+"_total"), m.Total())) for i := range pv { c.writeSummaryPercentile(name, strconv.FormatFloat(pv[i], 'f', -1, 64), ps[i]) } diff --git a/metrics/timer.go b/metrics/timer.go index a63c9dfb6..9d0957781 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,14 @@ func (NilTimer) UpdateSince(time.Time) {} // Variance is a no-op. func (NilTimer) Variance() float64 { return 0.0 } +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 +206,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 +238,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 +251,15 @@ func (t *StandardTimer) Variance() float64 { return t.histogram.Variance() } +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 +334,5 @@ 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() } + +func (t *TimerSnapshot) Total() int64 { return t.total.Count() } diff --git a/statediff/builder.go b/statediff/builder.go index 3aba38139..776943541 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" @@ -210,7 +209,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 +262,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( @@ -375,12 +374,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 +435,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 +444,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 +551,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] @@ -580,6 +581,7 @@ func (sdb *StateDiffBuilder) buildAccountUpdates(creations, deletions types2.Acc delete(deletions, key) } + logger.Debug("Counts") return nil } @@ -587,7 +589,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, @@ -751,6 +753,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 +782,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 +829,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 @@ -917,9 +922,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..7b2224513 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,16 @@ 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 } func RegisterIndexerMetrics(reg metrics.Registry) IndexerMetricsHandles { @@ -99,6 +110,16 @@ 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(), } subsys := "indexer" reg.Register(metricName(subsys, "blocks"), ctx.BlocksCounter) @@ -118,6 +139,16 @@ 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) log.Debug("Registering statediff indexer metrics.") return ctx @@ -189,3 +220,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..fadbde333 100644 --- a/statediff/service.go +++ b/statediff/service.go @@ -19,6 +19,7 @@ package statediff import ( "bytes" "fmt" + "github.com/ethereum/go-ethereum/statediff/indexer/database/metrics" "math/big" "strconv" "strings" @@ -861,9 +862,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..36514655d 100644 --- a/statediff/trie_helpers/helpers.go +++ b/statediff/trie_helpers/helpers.go @@ -21,8 +21,10 @@ package trie_helpers import ( "fmt" + metrics2 "github.com/ethereum/go-ethereum/statediff/indexer/database/metrics" "sort" "strings" + "time" "github.com/ethereum/go-ethereum/rlp" "github.com/ethereum/go-ethereum/statediff/types" @@ -53,6 +55,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 +79,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 +93,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..2ba82a0c0 100644 --- a/trie/iterator.go +++ b/trie/iterator.go @@ -20,6 +20,8 @@ import ( "bytes" "container/heap" "errors" + "github.com/ethereum/go-ethereum/statediff/indexer/database/metrics" + "time" "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/ethdb" @@ -584,6 +586,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. -- 2.45.2 From 5f7d033ed9f5db1b49f9583ad6ed01f4d92b1795 Mon Sep 17 00:00:00 2001 From: Thomas E Lackey Date: Wed, 15 Feb 2023 01:43:38 -0600 Subject: [PATCH 2/8] Remove line --- statediff/builder.go | 1 - 1 file changed, 1 deletion(-) diff --git a/statediff/builder.go b/statediff/builder.go index 776943541..2a4be8eb1 100644 --- a/statediff/builder.go +++ b/statediff/builder.go @@ -581,7 +581,6 @@ func (sdb *StateDiffBuilder) buildAccountUpdates(creations, deletions types2.Acc delete(deletions, key) } - logger.Debug("Counts") return nil } -- 2.45.2 From 7a5d6116e38ed69741420f32961623244536c245 Mon Sep 17 00:00:00 2001 From: Thomas E Lackey Date: Wed, 15 Feb 2023 12:05:02 -0600 Subject: [PATCH 3/8] lint --- statediff/service.go | 3 ++- statediff/trie_helpers/helpers.go | 3 ++- 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/statediff/service.go b/statediff/service.go index fadbde333..a0b8424e3 100644 --- a/statediff/service.go +++ b/statediff/service.go @@ -19,7 +19,6 @@ package statediff import ( "bytes" "fmt" - "github.com/ethereum/go-ethereum/statediff/indexer/database/metrics" "math/big" "strconv" "strings" @@ -27,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" diff --git a/statediff/trie_helpers/helpers.go b/statediff/trie_helpers/helpers.go index 36514655d..869b0cc88 100644 --- a/statediff/trie_helpers/helpers.go +++ b/statediff/trie_helpers/helpers.go @@ -21,11 +21,12 @@ package trie_helpers import ( "fmt" - metrics2 "github.com/ethereum/go-ethereum/statediff/indexer/database/metrics" "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" "github.com/ethereum/go-ethereum/trie" -- 2.45.2 From bac62698458a606807ac2555c1195d1f4b0ec974 Mon Sep 17 00:00:00 2001 From: Thomas E Lackey Date: Wed, 15 Feb 2023 12:09:58 -0600 Subject: [PATCH 4/8] lint --- trie/iterator.go | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/trie/iterator.go b/trie/iterator.go index 2ba82a0c0..3c2bc4ada 100644 --- a/trie/iterator.go +++ b/trie/iterator.go @@ -20,9 +20,10 @@ import ( "bytes" "container/heap" "errors" - "github.com/ethereum/go-ethereum/statediff/indexer/database/metrics" "time" + "github.com/ethereum/go-ethereum/statediff/indexer/database/metrics" + "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/ethdb" ) -- 2.45.2 From b3f363274126c18aec50fe84b5558e7cb0788b4f Mon Sep 17 00:00:00 2001 From: Thomas E Lackey Date: Wed, 15 Feb 2023 12:16:59 -0600 Subject: [PATCH 5/8] Comment --- metrics/timer.go | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/metrics/timer.go b/metrics/timer.go index 9d0957781..3d68c3135 100644 --- a/metrics/timer.go +++ b/metrics/timer.go @@ -137,6 +137,7 @@ 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 @@ -251,6 +252,9 @@ 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() } @@ -335,4 +339,5 @@ func (*TimerSnapshot) UpdateSince(time.Time) { // 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() } -- 2.45.2 From 52c06d74a09b6409a2a7ab126c3bbc65f8b6d345 Mon Sep 17 00:00:00 2001 From: Thomas E Lackey Date: Wed, 15 Feb 2023 13:40:35 -0600 Subject: [PATCH 6/8] Fix metrics output. --- metrics/prometheus/collector.go | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/metrics/prometheus/collector.go b/metrics/prometheus/collector.go index f9da6baa9..8fdca36be 100644 --- a/metrics/prometheus/collector.go +++ b/metrics/prometheus/collector.go @@ -78,12 +78,14 @@ func (c *collector) addTimer(name string, m metrics.Timer) { ps := m.Percentiles(pv) c.writeSummaryCounter(name, m.Count()) c.buff.WriteString(fmt.Sprintf(typeSummaryTpl, mutateKey(name))) - c.buff.WriteString(fmt.Sprintf(typeGaugeTpl, mutateKey(name+"_total"))) - c.buff.WriteString(fmt.Sprintf(keyValueTpl, mutateKey(name+"_total"), m.Total())) for i := range pv { 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())) + c.buff.WriteRune('\n') } func (c *collector) addResettingTimer(name string, m metrics.ResettingTimer) { -- 2.45.2 From f3bc8a65502b8b098908da6e2084f9bf1c50f500 Mon Sep 17 00:00:00 2001 From: Thomas E Lackey Date: Wed, 15 Feb 2023 14:46:41 -0600 Subject: [PATCH 7/8] Update expected test output. --- metrics/prometheus/collector.go | 1 - metrics/prometheus/collector_test.go | 3 +++ 2 files changed, 3 insertions(+), 1 deletion(-) diff --git a/metrics/prometheus/collector.go b/metrics/prometheus/collector.go index 8fdca36be..76bece915 100644 --- a/metrics/prometheus/collector.go +++ b/metrics/prometheus/collector.go @@ -85,7 +85,6 @@ func (c *collector) addTimer(name string, m metrics.Timer) { c.buff.WriteString(fmt.Sprintf(typeGaugeTpl, mutateKey(name+"_total"))) c.buff.WriteString(fmt.Sprintf(keyValueTpl, mutateKey(name+"_total"), m.Total())) - c.buff.WriteRune('\n') } 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 -- 2.45.2 From 217c5f0776741a67524698b5d1cae0a741971701 Mon Sep 17 00:00:00 2001 From: Thomas E Lackey Date: Wed, 15 Feb 2023 15:11:20 -0600 Subject: [PATCH 8/8] Even more timers. --- statediff/builder.go | 11 +++++++ statediff/indexer/database/metrics/metrics.go | 30 +++++++++++++++++++ 2 files changed, 41 insertions(+) diff --git a/statediff/builder.go b/statediff/builder.go index 2a4be8eb1..3c413fad7 100644 --- a/statediff/builder.go +++ b/statediff/builder.go @@ -88,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) @@ -106,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) { @@ -158,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)) @@ -174,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 { @@ -317,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 @@ -628,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 } @@ -648,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()) { @@ -690,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 } @@ -710,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()) { @@ -908,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 diff --git a/statediff/indexer/database/metrics/metrics.go b/statediff/indexer/database/metrics/metrics.go index 7b2224513..550dd238e 100644 --- a/statediff/indexer/database/metrics/metrics.go +++ b/statediff/indexer/database/metrics/metrics.go @@ -89,6 +89,16 @@ type IndexerMetricsHandles struct { 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 { @@ -120,6 +130,16 @@ func RegisterIndexerMetrics(reg metrics.Registry) IndexerMetricsHandles { 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) @@ -149,6 +169,16 @@ func RegisterIndexerMetrics(reg metrics.Registry) IndexerMetricsHandles { 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 -- 2.45.2