From d60c38a675a26b9997d5c9fdbff34572cd30ee62 Mon Sep 17 00:00:00 2001 From: Zsolt Felfoldi Date: Tue, 15 Oct 2024 01:50:05 +0200 Subject: [PATCH] core/filtermaps: improved log messages --- core/filtermaps/filtermaps.go | 10 +++++++++- core/filtermaps/indexer.go | 12 ++++++------ eth/filters/filter.go | 7 +++++-- 3 files changed, 20 insertions(+), 9 deletions(-) diff --git a/core/filtermaps/filtermaps.go b/core/filtermaps/filtermaps.go index 908ee250c8..82a5e374b0 100644 --- a/core/filtermaps/filtermaps.go +++ b/core/filtermaps/filtermaps.go @@ -128,6 +128,14 @@ type filterMapsRange struct { headBlockHash, tailParentHash common.Hash } +// mapCount returns the number of maps fully or partially included in the range. +func (fmr *filterMapsRange) mapCount(logValuesPerMap uint) uint32 { + if !fmr.initialized { + return 0 + } + return uint32(fmr.headLvPointer>>logValuesPerMap) + 1 - uint32(fmr.tailLvPointer>>logValuesPerMap) +} + // NewFilterMaps creates a new FilterMaps and starts the indexer in order to keep // the structure in sync with the given blockchain. func NewFilterMaps(db ethdb.KeyValueStore, chain blockchain, params Params, history, unindexLimit uint64, noHistory bool) *FilterMaps { @@ -222,7 +230,7 @@ func (f *FilterMaps) removeDbWithPrefix(prefix []byte, action string) bool { it := f.db.NewIterator(prefix, nil) batch := f.db.NewBatch() var count int - for ; count < 10000 && it.Next(); count++ { + for ; count < 250000 && it.Next(); count++ { batch.Delete(it.Key()) removed++ } diff --git a/core/filtermaps/indexer.go b/core/filtermaps/indexer.go index 08563f0448..4909e32b0a 100644 --- a/core/filtermaps/indexer.go +++ b/core/filtermaps/indexer.go @@ -325,8 +325,8 @@ func (f *FilterMaps) tryExtendTail(tailTarget uint64, stopFn func() bool) bool { defer func() { if f.tailBlockNumber <= tailTarget { if f.loggedTailExtend { - log.Info("Reverse log indexing finished", "history", f.headBlockNumber+1-f.tailBlockNumber, - "processed", f.ptrTailExtend-f.tailBlockNumber, "elapsed", common.PrettyDuration(time.Since(f.lastLogTailExtend))) + log.Info("Reverse log indexing finished", "maps", f.mapCount(f.logValuesPerMap), "history", f.headBlockNumber+1-f.tailBlockNumber, + "processed", f.ptrTailExtend-f.tailBlockNumber, "elapsed", common.PrettyDuration(time.Since(f.startedTailExtend))) f.loggedTailExtend = false } } @@ -348,7 +348,7 @@ func (f *FilterMaps) tryExtendTail(tailTarget uint64, stopFn func() bool) bool { f.applyUpdateBatch(update) if time.Since(f.lastLogTailExtend) > logFrequency || !f.loggedTailExtend { - log.Info("Reverse log indexing in progress", "history", update.headBlockNumber+1-update.tailBlockNumber, + log.Info("Reverse log indexing in progress", "maps", update.mapCount(f.logValuesPerMap), "history", update.headBlockNumber+1-update.tailBlockNumber, "processed", f.ptrTailExtend-update.tailBlockNumber, "remaining", update.tailBlockNumber-tailTarget, "elapsed", common.PrettyDuration(time.Since(f.startedTailExtend))) f.loggedTailExtend = true @@ -388,13 +388,13 @@ func (f *FilterMaps) tryUnindexTail(tailTarget uint64, stopFn func() bool) bool } for { if f.unindexTailEpoch(tailTarget) { - log.Info("Log unindexing finished", "history", f.headBlockNumber+1-f.tailBlockNumber, - "removed", f.tailBlockNumber-f.ptrTailUnindex, "elapsed", common.PrettyDuration(time.Since(f.lastLogTailUnindex))) + log.Info("Log unindexing finished", "maps", f.mapCount(f.logValuesPerMap), "history", f.headBlockNumber+1-f.tailBlockNumber, + "removed", f.tailBlockNumber-f.ptrTailUnindex, "elapsed", common.PrettyDuration(time.Since(f.startedTailUnindex))) f.loggedTailUnindex = false return true } if time.Since(f.lastLogTailUnindex) > logFrequency || !f.loggedTailUnindex { - log.Info("Log unindexing in progress", "history", f.headBlockNumber+1-f.tailBlockNumber, + log.Info("Log unindexing in progress", "maps", f.mapCount(f.logValuesPerMap), "history", f.headBlockNumber+1-f.tailBlockNumber, "removed", f.tailBlockNumber-f.ptrTailUnindex, "remaining", tailTarget-f.tailBlockNumber, "elapsed", common.PrettyDuration(time.Since(f.startedTailUnindex))) f.loggedTailUnindex = true diff --git a/eth/filters/filter.go b/eth/filters/filter.go index de03c965aa..7cf5e95be0 100644 --- a/eth/filters/filter.go +++ b/eth/filters/filter.go @@ -22,6 +22,7 @@ import ( "math" "math/big" "slices" + "time" "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/core/filtermaps" @@ -315,15 +316,17 @@ func (f *Filter) rangeLogs(ctx context.Context, firstBlock, lastBlock uint64) ([ } func (f *Filter) indexedLogs(ctx context.Context, mb filtermaps.MatcherBackend, begin, end uint64) ([]*types.Log, error) { + start := time.Now() potentialMatches, err := filtermaps.GetPotentialMatches(ctx, mb, begin, end, f.addresses, f.topics) matches := filterLogs(potentialMatches, nil, nil, f.addresses, f.topics) - log.Trace("Performed indexed log search", "begin", begin, "end", end, "true matches", len(matches), "false positives", len(potentialMatches)-len(matches)) + log.Trace("Performed indexed log search", "begin", begin, "end", end, "true matches", len(matches), "false positives", len(potentialMatches)-len(matches), "elapsed", common.PrettyDuration(time.Since(start))) return matches, err } // unindexedLogs returns the logs matching the filter criteria based on raw block // iteration and bloom matching. func (f *Filter) unindexedLogs(ctx context.Context, begin, end uint64) ([]*types.Log, error) { + start := time.Now() log.Warn("Performing unindexed log search", "begin", begin, "end", end) var matches []*types.Log for blockNumber := begin; blockNumber <= end; blockNumber++ { @@ -342,7 +345,7 @@ func (f *Filter) unindexedLogs(ctx context.Context, begin, end uint64) ([]*types } matches = append(matches, found...) } - log.Trace("Performed unindexed log search", "begin", begin, "end", end, "matches", len(matches)) + log.Trace("Performed unindexed log search", "begin", begin, "end", end, "matches", len(matches), "elapsed", common.PrettyDuration(time.Since(start))) return matches, nil }