forks/go-ethereum
1
0
Fork 1
mirror of https://github.com/ethereum/go-ethereum.git synced 2026-07-26 06:36:43 +00:00
Code Issues Projects Releases Packages Wiki Activity Actions

core/filtermaps: do not include paused time in indexing log messages

Browse source
This commit is contained in:
Zsolt Felfoldi 2025-05-01 06:09:46 +02:00
parent 7612872761
commit 6528bd8bc6
2 changed files with 27 additions and 12 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

18
core/filtermaps/filtermaps.go
View file

@ -114,6 +114,7 @@ type FilterMaps struct {
renderSnapshots *lru.Cache[uint64, *renderedMap] renderSnapshots *lru.Cache[uint64, *renderedMap]
startedHeadIndex, startedTailIndex, startedTailUnindex bool startedHeadIndex, startedTailIndex, startedTailUnindex bool
startedHeadIndexAt, startedTailIndexAt, startedTailUnindexAt time.Time startedHeadIndexAt, startedTailIndexAt, startedTailUnindexAt time.Time
pausedHeadIndex, pausedTailIndex, pausedRangeDelete time.Duration
loggedHeadIndex, loggedTailIndex bool loggedHeadIndex, loggedTailIndex bool
lastLogHeadIndex, lastLogTailIndex time.Time lastLogHeadIndex, lastLogTailIndex time.Time
ptrHeadIndex, ptrTailIndex, ptrTailUnindexBlock uint64 ptrHeadIndex, ptrTailIndex, ptrTailUnindexBlock uint64
@ -427,21 +428,28 @@ func (f *FilterMaps) safeDeleteWithLogs(deleteFn func(db ethdb.KeyValueStore, ha
start = time.Now() start = time.Now()
logPrinted bool logPrinted bool
lastLogPrinted = start lastLogPrinted = start
paused time.Duration
) )
defer func() {
f.pausedRangeDelete += paused
}()
switch err := deleteFn(f.db, f.hashScheme, func(deleted bool) bool { switch err := deleteFn(f.db, f.hashScheme, func(deleted bool) bool {
if deleted && !logPrinted || time.Since(lastLogPrinted) > time.Second*10 { if deleted && !logPrinted || time.Since(lastLogPrinted)-paused > time.Second*10 {
log.Info(action+" in progress...", "elapsed", common.PrettyDuration(time.Since(start))) log.Info(action+" in progress...", "elapsed", common.PrettyDuration(time.Since(start)-paused))
logPrinted, lastLogPrinted = true, time.Now() logPrinted, lastLogPrinted = true, time.Now()
} }
return stopCb() cbStart := time.Now()
stop := stopCb()
paused += time.Since(cbStart)
return stop
}); { }); {
case err == nil: case err == nil:
if logPrinted { 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 return nil
case errors.Is(err, rawdb.ErrDeleteRangeInterrupted): 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 return err
default: default:
log.Error(action+" failed", "error", err) log.Error(action+" failed", "error", err)

21
core/filtermaps/indexer.go
View file

@ -244,20 +244,23 @@ func (f *FilterMaps) tryIndexHead() error {
f.startedHeadIndexAt = f.lastLogHeadIndex f.startedHeadIndexAt = f.lastLogHeadIndex
f.startedHeadIndex = true f.startedHeadIndex = true
f.ptrHeadIndex = f.indexedRange.blocks.AfterLast() f.ptrHeadIndex = f.indexedRange.blocks.AfterLast()
f.pausedHeadIndex = 0
} }
if _, err := headRenderer.run(func() bool { if _, err := headRenderer.run(func() bool {
cbStart := time.Now()
f.processEvents() f.processEvents()
f.pausedHeadIndex += time.Since(cbStart)
return f.stop return f.stop
}, func() { }, func() {
f.tryUnindexTail() f.tryUnindexTail()
if f.indexedRange.hasIndexedBlocks() && f.indexedRange.blocks.AfterLast() >= f.ptrHeadIndex && 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) { time.Since(f.lastLogHeadIndex) > logFrequency) {
log.Info("Log index head rendering in progress", log.Info("Log index head rendering in progress",
"first block", f.indexedRange.blocks.First(), "last block", f.indexedRange.blocks.Last(), "first block", f.indexedRange.blocks.First(), "last block", f.indexedRange.blocks.Last(),
"processed", f.indexedRange.blocks.AfterLast()-f.ptrHeadIndex, "processed", f.indexedRange.blocks.AfterLast()-f.ptrHeadIndex,
"remaining", f.indexedView.HeadNumber()-f.indexedRange.blocks.Last(), "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.loggedHeadIndex = true
f.lastLogHeadIndex = time.Now() f.lastLogHeadIndex = time.Now()
} }
@ -268,7 +271,7 @@ func (f *FilterMaps) tryIndexHead() error {
log.Info("Log index head rendering finished", log.Info("Log index head rendering finished",
"first block", f.indexedRange.blocks.First(), "last block", f.indexedRange.blocks.Last(), "first block", f.indexedRange.blocks.First(), "last block", f.indexedRange.blocks.Last(),
"processed", f.indexedRange.blocks.AfterLast()-f.ptrHeadIndex, "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 f.loggedHeadIndex, f.startedHeadIndex = false, false
return nil return nil
@ -310,9 +313,12 @@ func (f *FilterMaps) tryIndexTail() (bool, error) {
f.startedTailIndexAt = f.lastLogTailIndex f.startedTailIndexAt = f.lastLogTailIndex
f.startedTailIndex = true f.startedTailIndex = true
f.ptrTailIndex = f.indexedRange.blocks.First() - f.tailPartialBlocks() f.ptrTailIndex = f.indexedRange.blocks.First() - f.tailPartialBlocks()
f.pausedTailIndex = 0
} }
done, err := tailRenderer.run(func() bool { done, err := tailRenderer.run(func() bool {
cbStart := time.Now()
f.processEvents() f.processEvents()
f.pausedTailIndex += time.Since(cbStart)
return f.stop || !f.targetHeadIndexed() return f.stop || !f.targetHeadIndexed()
}, func() { }, func() {
tpb, ttb := f.tailPartialBlocks(), f.tailTargetBlock() tpb, ttb := f.tailPartialBlocks(), f.tailTargetBlock()
@ -327,7 +333,7 @@ func (f *FilterMaps) tryIndexTail() (bool, error) {
"processed", f.ptrTailIndex-f.indexedRange.blocks.First()+tpb, "processed", f.ptrTailIndex-f.indexedRange.blocks.First()+tpb,
"remaining", remaining, "remaining", remaining,
"next tail epoch percentage", f.indexedRange.tailPartialEpoch*100/f.mapsPerEpoch, "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.loggedTailIndex = true
f.lastLogTailIndex = time.Now() f.lastLogTailIndex = time.Now()
} }
@ -348,7 +354,7 @@ func (f *FilterMaps) tryIndexTail() (bool, error) {
log.Info("Log index tail rendering finished", log.Info("Log index tail rendering finished",
"first block", f.indexedRange.blocks.First(), "last block", f.indexedRange.blocks.Last(), "first block", f.indexedRange.blocks.First(), "last block", f.indexedRange.blocks.Last(),
"processed", f.ptrTailIndex-f.indexedRange.blocks.First(), "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 f.loggedTailIndex = false
} }
return true, nil return true, nil
@ -364,11 +370,12 @@ func (f *FilterMaps) tryUnindexTail() (bool, error) {
firstEpoch-- firstEpoch--
} }
for epoch := min(firstEpoch, f.cleanedEpochsBefore); !f.needTailEpoch(epoch); epoch++ { 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.startedTailUnindexAt = time.Now()
f.startedTailUnindex = true f.startedTailUnindex = true
f.ptrTailUnindexMap = f.indexedRange.maps.First() - f.indexedRange.tailPartialEpoch f.ptrTailUnindexMap = f.indexedRange.maps.First() - f.indexedRange.tailPartialEpoch
f.ptrTailUnindexBlock = f.indexedRange.blocks.First() - f.tailPartialBlocks() f.ptrTailUnindexBlock = f.indexedRange.blocks.First() - f.tailPartialBlocks()
f.pausedRangeDelete = 0
} }
if done, err := f.deleteTailEpoch(epoch); !done { if done, err := f.deleteTailEpoch(epoch); !done {
return false, err 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(), "first block", f.indexedRange.blocks.First(), "last block", f.indexedRange.blocks.Last(),
"removed maps", f.indexedRange.maps.First()-f.ptrTailUnindexMap, "removed maps", f.indexedRange.maps.First()-f.ptrTailUnindexMap,
"removed blocks", f.indexedRange.blocks.First()-f.tailPartialBlocks()-f.ptrTailUnindexBlock, "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 f.startedTailUnindex = false
} }
return true, nil return true, nil