Bootstrapping ETA Mislead by Restart

[aaronbuchwald]

Describe the bug
The bootstrapping ETA calculation uses the time it has taken to fetch/execute blocks in order to calculate an estimate of the ETA for fetching/bootstrapping to complete.

However if the node starts bootstrapping at heigh 1M, fetches the first 25k blocks from height 975k-1m, then after a restart, it will still start at block height 1m and iterate through the blocks that it has already fetched before realizing that it can skip (this could probably be optimized).

When this happens it seems to bias the ETA calculation as a result of it taking significantly longer to start making actual progress. This is most likely because it iterates through 25k blocks before it actually fetches the next 5k and then includes the amount of time spent iterating the first 25k already fetched blocks in the ETA calculation.

To Reproduce
To reproduce this behavior, start a fresh node and bootstrap mainnet, wait for the node to fetch 100k blocks and then restart. You should observe a pause before any ETA logs are printed while the node iterates through the already fetched blocks and then see that the earliest estimates are much higher than they were before the restart.

Expected behavior
Bootstrapping should produce an accurate ETA that is not biased by iterating through already fetched blocks.

Logs
Prior to restart P-Chain logs:

[04-24|01:06:34.848] INFO <P Chain> bootstrap/bootstrapper.go:494 fetching blocks {"numFetchedBlocks": 5000, "numTotalBlocks": 5425884, "eta": "2h39m9s"}
[04-24|01:06:43.319] INFO <P Chain> bootstrap/bootstrapper.go:494 fetching blocks {"numFetchedBlocks": 10000, "numTotalBlocks": 5425884, "eta": "2h35m58s"}
[04-24|01:06:56.551] INFO <P Chain> bootstrap/bootstrapper.go:494 fetching blocks {"numFetchedBlocks": 15000, "numTotalBlocks": 5425884, "eta": "3h3m26s"}
[04-24|01:07:07.653] INFO <P Chain> bootstrap/bootstrapper.go:494 fetching blocks {"numFetchedBlocks": 20000, "numTotalBlocks": 5425884, "eta": "3h7m28s"}
[04-24|01:07:21.882] INFO <P Chain> bootstrap/bootstrapper.go:494 fetching blocks {"numFetchedBlocks": 25000, "numTotalBlocks": 5425884, "eta": "3h21m4s"}

Immediately after restart P-Chain logs:

[04-24|01:08:39.282] INFO <P Chain> common/bootstrapper.go:244 bootstrapping started syncing {"numVerticesInFrontier": 1}
[04-24|01:08:51.836] INFO <P Chain> bootstrap/bootstrapper.go:494 fetching blocks {"numFetchedBlocks": 40000, "numTotalBlocks": 5425887, "eta": "9h41m48s"}
[04-24|01:09:26.798] INFO <P Chain> bootstrap/bootstrapper.go:494 fetching blocks {"numFetchedBlocks": 45000, "numTotalBlocks": 5425887, "eta": "10h14m17s"}
[04-24|01:09:48.256] INFO <P Chain> bootstrap/bootstrapper.go:494 fetching blocks {"numFetchedBlocks": 50000, "numTotalBlocks": 5425887, "eta": "8h37m43s"}
[04-24|01:10:10.351] INFO <P Chain> bootstrap/bootstrapper.go:494 fetching blocks {"numFetchedBlocks": 55000, "numTotalBlocks": 5425887, "eta": "8h1m19s"}
[04-24|01:10:32.284] INFO <P Chain> bootstrap/bootstrapper.go:494 fetching blocks {"numFetchedBlocks": 60000, "numTotalBlocks": 5425887, "eta": "7h40m41s"}
[04-24|01:10:44.736] INFO <P Chain> bootstrap/bootstrapper.go:494 fetching blocks {"numFetchedBlocks": 65000, "numTotalBlocks": 5425887, "eta": "6h56m7s"}

[StephenButtolph]

However if the node starts bootstrapping at heigh 1M, fetches the first 25k blocks from height 975k-1m, then after a restart, it will still start at block height 1m and iterate through the blocks that it has already fetched before realizing that it can skip (this could probably be optimized).

I don't think this is true:

avalanchego/snow/engine/snowman/bootstrap/bootstrapper.go

Lines 470 to 477 in 5354562

	if !pushed {
	// We can stop traversing, as we have reached a block that we
	// previously pushed onto the jobs queue
	if err := b.Blocked.Commit(); err != nil {
	return err
	}
	return b.checkFinish(ctx)
	}

we will stop processing blocks once we have already seen a block.

[github-actions]

This issue has become stale because it has been open 60 days with no activity. Adding the lifecycle/frozen label will cause this issue to ignore lifecycle events.