diff --git a/statediff/builder.go b/statediff/builder.go index 04a7ff00e..3aba38139 100644 --- a/statediff/builder.go +++ b/statediff/builder.go @@ -24,6 +24,9 @@ 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" "github.com/ethereum/go-ethereum/core/state" "github.com/ethereum/go-ethereum/core/types" @@ -206,8 +209,8 @@ 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 { - start := time.Now() - defer logger.Debug(fmt.Sprintf("statediff BuildStateDiffWithIntermediateStateNodes total duration=%dms", time.Since(start).Milliseconds())) + logger.Debug("statediff BEGIN BuildStateDiffWithIntermediateStateNodes") + defer timeDuration("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 @@ -259,8 +262,8 @@ func (sdb *StateDiffBuilder) BuildStateDiffWithIntermediateStateNodes(iterPairs } func (sdb *StateDiffBuilder) BuildStateDiffWithoutIntermediateStateNodes(iterPairs []IterPair, params Params, output types2.StateNodeSink, codeOutput types2.CodeSink, logger log.Logger) error { - start := time.Now() - defer logger.Debug(fmt.Sprintf("statediff BuildStateDiffWithoutIntermediateStateNodes total duration=%dms", time.Since(start).Milliseconds())) + logger.Debug("statediff BEGIN BuildStateDiffWithoutIntermediateStateNodes") + defer timeDuration("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( @@ -371,8 +374,8 @@ func (sdb *StateDiffBuilder) createdAndUpdatedState(a, b trie.NodeIterator, watc // 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) createdAndUpdatedStateWithIntermediateNodes(a, b trie.NodeIterator, watchedAddressesLeafPaths [][]byte, output types2.StateNodeSink, logger log.Logger) (types2.AccountMap, map[string]bool, error) { - start := time.Now() - defer logger.Debug(fmt.Sprintf("statediff createdAndUpdatedStateWithIntermediateNodes duration=%dms", time.Since(start).Milliseconds())) + logger.Debug("statediff BEGIN createdAndUpdatedStateWithIntermediateNodes") + defer timeDuration("statediff END createdAndUpdatedStateWithIntermediateNodes", time.Now(), logger, metrics2.IndexerMetrics.CreatedAndUpdatedStateWithIntermediateNodesTimer) diffPathsAtB := make(map[string]bool) diffAccountsAtB := make(types2.AccountMap) watchingAddresses := len(watchedAddressesLeafPaths) > 0 @@ -439,8 +442,8 @@ func (sdb *StateDiffBuilder) createdAndUpdatedStateWithIntermediateNodes(a, b tr // deletedOrUpdatedState returns a slice of all the pathes that are emptied at B // 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) { - start := time.Now() - defer logger.Debug(fmt.Sprintf("statediff deletedOrUpdatedState duration=%dms", time.Since(start).Milliseconds())) + logger.Debug("statediff BEGIN deletedOrUpdatedState") + defer timeDuration("statediff END deletedOrUpdatedState", time.Now(), logger, metrics2.IndexerMetrics.DeletedOrUpdatedStateTimer) diffAccountAtA := make(types2.AccountMap) watchingAddresses := len(watchedAddressesLeafPaths) > 0 @@ -547,8 +550,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 { - start := time.Now() - defer logger.Debug(fmt.Sprintf("statediff buildAccountUpdates duration=%dms", time.Since(start).Milliseconds())) + logger.Debug("statediff BEGIN buildAccountUpdates") + defer timeDuration("statediff END buildAccountUpdates", time.Now(), logger, metrics2.IndexerMetrics.BuildAccountUpdatesTimer) var err error for _, key := range updatedKeys { createdAcc := creations[key] @@ -583,8 +586,8 @@ func (sdb *StateDiffBuilder) buildAccountUpdates(creations, deletions types2.Acc // buildAccountCreations returns the statediff node objects for all the accounts that exist at B but not at A // 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 { - start := time.Now() - defer logger.Debug(fmt.Sprintf("statediff buildAccountCreations duration=%dms", time.Since(start).Milliseconds())) + logger.Debug("statediff BEGIN buildAccountCreations") + defer timeDuration("statediff END buildAccountCreations", time.Now(), logger, metrics2.IndexerMetrics.BuildAccountCreationsTimer) for _, val := range accounts { diff := types2.StateNode{ NodeType: val.NodeType, @@ -914,3 +917,9 @@ 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 95c1a959b..14b5a49e1 100644 --- a/statediff/indexer/database/metrics/metrics.go +++ b/statediff/indexer/database/metrics/metrics.go @@ -70,21 +70,35 @@ type IndexerMetricsHandles struct { TxAndRecProcessingTimer metrics.Timer // State, storage, and code combined processing time StateStoreCodeProcessingTimer metrics.Timer + + // Fine-grained code timers + BuildStateDiffWithIntermediateStateNodesTimer metrics.Timer + BuildStateDiffWithoutIntermediateStateNodesTimer metrics.Timer + CreatedAndUpdatedStateWithIntermediateNodesTimer metrics.Timer + DeletedOrUpdatedStateTimer metrics.Timer + BuildAccountUpdatesTimer metrics.Timer + BuildAccountCreationsTimer metrics.Timer } func RegisterIndexerMetrics(reg metrics.Registry) IndexerMetricsHandles { ctx := IndexerMetricsHandles{ - BlocksCounter: metrics.NewCounter(), - TransactionsCounter: metrics.NewCounter(), - ReceiptsCounter: metrics.NewCounter(), - LogsCounter: metrics.NewCounter(), - AccessListEntriesCounter: metrics.NewCounter(), - FreePostgresTimer: metrics.NewTimer(), - PostgresCommitTimer: metrics.NewTimer(), - HeaderProcessingTimer: metrics.NewTimer(), - UncleProcessingTimer: metrics.NewTimer(), - TxAndRecProcessingTimer: metrics.NewTimer(), - StateStoreCodeProcessingTimer: metrics.NewTimer(), + BlocksCounter: metrics.NewCounter(), + TransactionsCounter: metrics.NewCounter(), + ReceiptsCounter: metrics.NewCounter(), + LogsCounter: metrics.NewCounter(), + AccessListEntriesCounter: metrics.NewCounter(), + FreePostgresTimer: metrics.NewTimer(), + PostgresCommitTimer: metrics.NewTimer(), + HeaderProcessingTimer: metrics.NewTimer(), + UncleProcessingTimer: metrics.NewTimer(), + TxAndRecProcessingTimer: metrics.NewTimer(), + StateStoreCodeProcessingTimer: metrics.NewTimer(), + BuildStateDiffWithIntermediateStateNodesTimer: metrics.NewTimer(), + BuildStateDiffWithoutIntermediateStateNodesTimer: metrics.NewTimer(), + CreatedAndUpdatedStateWithIntermediateNodesTimer: metrics.NewTimer(), + DeletedOrUpdatedStateTimer: metrics.NewTimer(), + BuildAccountUpdatesTimer: metrics.NewTimer(), + BuildAccountCreationsTimer: metrics.NewTimer(), } subsys := "indexer" reg.Register(metricName(subsys, "blocks"), ctx.BlocksCounter) @@ -98,6 +112,12 @@ func RegisterIndexerMetrics(reg metrics.Registry) IndexerMetricsHandles { reg.Register(metricName(subsys, "t_uncle_processing"), ctx.UncleProcessingTimer) 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_build_statediff_with_intermediate_state_nodes"), ctx.BuildStateDiffWithIntermediateStateNodesTimer) + reg.Register(metricName(subsys, "t_build_statediff_without_intermediate_state_nodes"), ctx.BuildStateDiffWithoutIntermediateStateNodesTimer) + 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_build_account_updates"), ctx.BuildAccountUpdatesTimer) + reg.Register(metricName(subsys, "t_build_account_creations"), ctx.BuildAccountCreationsTimer) log.Debug("Registering statediff indexer metrics.") return ctx