diff --git a/core/filtermaps/filtermaps.go b/core/filtermaps/filtermaps.go index 3da7f4b721..b927f812d2 100644 --- a/core/filtermaps/filtermaps.go +++ b/core/filtermaps/filtermaps.go @@ -114,6 +114,7 @@ type FilterMaps struct { renderSnapshots *lru.Cache[uint64, *renderedMap] startedHeadIndex, startedTailIndex, startedTailUnindex bool startedHeadIndexAt, startedTailIndexAt, startedTailUnindexAt time.Time + pausedHeadIndex, pausedTailIndex, pausedRangeDelete time.Duration loggedHeadIndex, loggedTailIndex bool lastLogHeadIndex, lastLogTailIndex time.Time ptrHeadIndex, ptrTailIndex, ptrTailUnindexBlock uint64 @@ -427,21 +428,28 @@ func (f *FilterMaps) safeDeleteWithLogs(deleteFn func(db ethdb.KeyValueStore, ha start = time.Now() logPrinted bool lastLogPrinted = start + paused time.Duration ) + defer func() { + f.pausedRangeDelete += paused + }() switch err := deleteFn(f.db, f.hashScheme, func(deleted bool) bool { - if deleted && !logPrinted || time.Since(lastLogPrinted) > time.Second*10 { - log.Info(action+" in progress...", "elapsed", common.PrettyDuration(time.Since(start))) + if deleted && !logPrinted || time.Since(lastLogPrinted)-paused > time.Second*10 { + log.Info(action+" in progress...", "elapsed", common.PrettyDuration(time.Since(start)-paused)) logPrinted, lastLogPrinted = true, time.Now() } - return stopCb() + cbStart := time.Now() + stop := stopCb() + paused += time.Since(cbStart) + return stop }); { case err == nil: if logPrinted { - log.Info(action+" finished", "elapsed", common.PrettyDuration(time.Since(start))) + log.Info(action+" finished", "elapsed", common.PrettyDuration(time.Since(start)-paused)) } return nil case errors.Is(err, rawdb.ErrDeleteRangeInterrupted): - log.Warn(action+" interrupted", "elapsed", common.PrettyDuration(time.Since(start))) + log.Warn(action+" interrupted", "elapsed", common.PrettyDuration(time.Since(start)-paused)) return err default: log.Error(action+" failed", "error", err) diff --git a/core/filtermaps/indexer.go b/core/filtermaps/indexer.go index 3ec49ca116..56de76ab55 100644 --- a/core/filtermaps/indexer.go +++ b/core/filtermaps/indexer.go @@ -244,20 +244,23 @@ func (f *FilterMaps) tryIndexHead() error { f.startedHeadIndexAt = f.lastLogHeadIndex f.startedHeadIndex = true f.ptrHeadIndex = f.indexedRange.blocks.AfterLast() + f.pausedHeadIndex = 0 } if _, err := headRenderer.run(func() bool { + cbStart := time.Now() f.processEvents() + f.pausedHeadIndex += time.Since(cbStart) return f.stop }, func() { f.tryUnindexTail() if f.indexedRange.hasIndexedBlocks() && f.indexedRange.blocks.AfterLast() >= f.ptrHeadIndex && - ((!f.loggedHeadIndex && time.Since(f.startedHeadIndexAt) > headLogDelay) || + ((!f.loggedHeadIndex && time.Since(f.startedHeadIndexAt)-f.pausedHeadIndex > headLogDelay) || time.Since(f.lastLogHeadIndex) > logFrequency) { log.Info("Log index head rendering in progress", "first block", f.indexedRange.blocks.First(), "last block", f.indexedRange.blocks.Last(), "processed", f.indexedRange.blocks.AfterLast()-f.ptrHeadIndex, "remaining", f.indexedView.HeadNumber()-f.indexedRange.blocks.Last(), - "elapsed", common.PrettyDuration(time.Since(f.startedHeadIndexAt))) + "elapsed", common.PrettyDuration(time.Since(f.startedHeadIndexAt)-f.pausedHeadIndex)) f.loggedHeadIndex = true f.lastLogHeadIndex = time.Now() } @@ -268,7 +271,7 @@ func (f *FilterMaps) tryIndexHead() error { log.Info("Log index head rendering finished", "first block", f.indexedRange.blocks.First(), "last block", f.indexedRange.blocks.Last(), "processed", f.indexedRange.blocks.AfterLast()-f.ptrHeadIndex, - "elapsed", common.PrettyDuration(time.Since(f.startedHeadIndexAt))) + "elapsed", common.PrettyDuration(time.Since(f.startedHeadIndexAt)-f.pausedHeadIndex)) } f.loggedHeadIndex, f.startedHeadIndex = false, false return nil @@ -310,9 +313,12 @@ func (f *FilterMaps) tryIndexTail() (bool, error) { f.startedTailIndexAt = f.lastLogTailIndex f.startedTailIndex = true f.ptrTailIndex = f.indexedRange.blocks.First() - f.tailPartialBlocks() + f.pausedTailIndex = 0 } done, err := tailRenderer.run(func() bool { + cbStart := time.Now() f.processEvents() + f.pausedTailIndex += time.Since(cbStart) return f.stop || !f.targetHeadIndexed() }, func() { tpb, ttb := f.tailPartialBlocks(), f.tailTargetBlock() @@ -327,7 +333,7 @@ func (f *FilterMaps) tryIndexTail() (bool, error) { "processed", f.ptrTailIndex-f.indexedRange.blocks.First()+tpb, "remaining", remaining, "next tail epoch percentage", f.indexedRange.tailPartialEpoch*100/f.mapsPerEpoch, - "elapsed", common.PrettyDuration(time.Since(f.startedTailIndexAt))) + "elapsed", common.PrettyDuration(time.Since(f.startedTailIndexAt)-f.pausedTailIndex)) f.loggedTailIndex = true f.lastLogTailIndex = time.Now() } @@ -348,7 +354,7 @@ func (f *FilterMaps) tryIndexTail() (bool, error) { log.Info("Log index tail rendering finished", "first block", f.indexedRange.blocks.First(), "last block", f.indexedRange.blocks.Last(), "processed", f.ptrTailIndex-f.indexedRange.blocks.First(), - "elapsed", common.PrettyDuration(time.Since(f.startedTailIndexAt))) + "elapsed", common.PrettyDuration(time.Since(f.startedTailIndexAt)-f.pausedTailIndex)) f.loggedTailIndex = false } return true, nil @@ -364,11 +370,12 @@ func (f *FilterMaps) tryUnindexTail() (bool, error) { firstEpoch-- } for epoch := min(firstEpoch, f.cleanedEpochsBefore); !f.needTailEpoch(epoch); epoch++ { - if !f.startedTailUnindex { + if !f.startedTailUnindex && epoch >= firstEpoch { // do not log initial cleanup f.startedTailUnindexAt = time.Now() f.startedTailUnindex = true f.ptrTailUnindexMap = f.indexedRange.maps.First() - f.indexedRange.tailPartialEpoch f.ptrTailUnindexBlock = f.indexedRange.blocks.First() - f.tailPartialBlocks() + f.pausedRangeDelete = 0 } if done, err := f.deleteTailEpoch(epoch); !done { return false, err @@ -383,7 +390,7 @@ func (f *FilterMaps) tryUnindexTail() (bool, error) { "first block", f.indexedRange.blocks.First(), "last block", f.indexedRange.blocks.Last(), "removed maps", f.indexedRange.maps.First()-f.ptrTailUnindexMap, "removed blocks", f.indexedRange.blocks.First()-f.tailPartialBlocks()-f.ptrTailUnindexBlock, - "elapsed", common.PrettyDuration(time.Since(f.startedTailUnindexAt))) + "elapsed", common.PrettyDuration(time.Since(f.startedTailUnindexAt)-f.pausedRangeDelete)) f.startedTailUnindex = false } return true, nil