Same block imported multiple times per second

[holiman]

On one of the machines which was a bit behind the head, it seemed to "import" the same block many times -- 4-5 times witin the same second. See e..g 15,545,483.
This might be due to some error in geth, or alternatively some quirk in lighthouse with the way they are feeding us block data.

Todo investigate.

INFO [09-16|10:08:22.247] Imported new potential chain segment number=15,545,479 hash=f802f8..866d26 blocks=1 txs=59 mgas=4.564 elapsed=136.462ms mgasps=33.443 age=1m35s dirty=419.40MiB
INFO [09-16|10:08:22.785] Imported new potential chain segment number=15,545,479 hash=f802f8..866d26 blocks=1 txs=59 mgas=4.564 elapsed=538.233ms mgasps=8.479 age=1m35s dirty=419.40MiB
INFO [09-16|10:08:22.845] Imported new potential chain segment number=15,545,479 hash=f802f8..866d26 blocks=1 txs=59 mgas=4.564 elapsed=59.644ms mgasps=76.515 age=1m35s dirty=419.40MiB
INFO [09-16|10:08:22.917] Imported new potential chain segment number=15,545,479 hash=f802f8..866d26 blocks=1 txs=59 mgas=4.564 elapsed=66.052ms mgasps=69.092 age=1m35s dirty=419.40MiB
INFO [09-16|10:08:22.997] Imported new potential chain segment number=15,545,479 hash=f802f8..866d26 blocks=1 txs=59 mgas=4.564 elapsed=78.742ms mgasps=57.957 age=1m35s dirty=419.40MiB
INFO [09-16|10:08:24.260] Imported new potential chain segment number=15,545,480 hash=c69093..2f7abc blocks=1 txs=543 mgas=29.979 elapsed=1.263s mgasps=23.729 age=1m25s dirty=421.94MiB
INFO [09-16|10:08:24.371] Imported new potential chain segment number=15,545,480 hash=c69093..2f7abc blocks=1 txs=543 mgas=29.979 elapsed=110.145ms mgasps=272.179 age=1m25s dirty=421.94MiB
INFO [09-16|10:08:25.060] Imported new potential chain segment number=15,545,480 hash=c69093..2f7abc blocks=1 txs=543 mgas=29.979 elapsed=128.615ms mgasps=233.092 age=1m26s dirty=421.94MiB
INFO [09-16|10:08:26.210] Imported new potential chain segment number=15,545,480 hash=c69093..2f7abc blocks=1 txs=543 mgas=29.979 elapsed=1.150s mgasps=26.056 age=1m27s dirty=421.94MiB
INFO [09-16|10:08:26.976] Imported new potential chain segment number=15,545,480 hash=c69093..2f7abc blocks=1 txs=543 mgas=29.979 elapsed=764.955ms mgasps=39.191 age=1m27s dirty=421.94MiB
INFO [09-16|10:08:27.122] Imported new potential chain segment number=15,545,480 hash=c69093..2f7abc blocks=1 txs=543 mgas=29.979 elapsed=146.066ms mgasps=205.244 age=1m28s dirty=421.94MiB
INFO [09-16|10:08:27.934] Imported new potential chain segment number=15,545,481 hash=1b0f28..1ba040 blocks=1 txs=0 mgas=0.000 elapsed=812.108ms mgasps=0.000 age=1m16s dirty=420.27MiB
INFO [09-16|10:08:27.935] Imported new potential chain segment number=15,545,481 hash=1b0f28..1ba040 blocks=1 txs=0 mgas=0.000 elapsed="161.196µs" mgasps=0.000 age=1m16s dirty=420.27MiB
INFO [09-16|10:08:27.935] Imported new potential chain segment number=15,545,481 hash=1b0f28..1ba040 blocks=1 txs=0 mgas=0.000 elapsed="132.221µs" mgasps=0.000 age=1m16s dirty=420.27MiB
INFO [09-16|10:08:27.935] Imported new potential chain segment number=15,545,481 hash=1b0f28..1ba040 blocks=1 txs=0 mgas=0.000 elapsed="81.615µs" mgasps=0.000 age=1m16s dirty=420.27MiB
INFO [09-16|10:08:27.935] Imported new potential chain segment number=15,545,481 hash=1b0f28..1ba040 blocks=1 txs=0 mgas=0.000 elapsed="74.662µs" mgasps=0.000 age=1m16s dirty=420.27MiB
INFO [09-16|10:08:27.935] Imported new potential chain segment number=15,545,481 hash=1b0f28..1ba040 blocks=1 txs=0 mgas=0.000 elapsed="60.525µs" mgasps=0.000 age=1m16s dirty=420.27MiB
INFO [09-16|10:08:28.964] Imported new potential chain segment number=15,545,482 hash=12a547..0bd9b5 blocks=1 txs=724 mgas=29.981 elapsed=597.298ms mgasps=50.194 age=1m5s dirty=422.68MiB
INFO [09-16|10:08:29.938] Imported new potential chain segment number=15,545,482 hash=12a547..0bd9b5 blocks=1 txs=724 mgas=29.981 elapsed=973.090ms mgasps=30.810 age=1m6s dirty=422.68MiB
INFO [09-16|10:08:30.696] Imported new potential chain segment number=15,545,482 hash=12a547..0bd9b5 blocks=1 txs=724 mgas=29.981 elapsed=757.688ms mgasps=39.569 age=1m7s dirty=422.68MiB
INFO [09-16|10:08:30.821] Imported new potential chain segment number=15,545,482 hash=12a547..0bd9b5 blocks=1 txs=724 mgas=29.981 elapsed=125.563ms mgasps=238.769 age=1m7s dirty=422.68MiB
INFO [09-16|10:08:30.895] Imported new potential chain segment number=15,545,483 hash=071f80..537c2f blocks=1 txs=13 mgas=0.541 elapsed=73.587ms mgasps=7.353 dirty=421.17MiB
INFO [09-16|10:08:30.963] Imported new potential chain segment number=15,545,483 hash=071f80..537c2f blocks=1 txs=13 mgas=0.541 elapsed=8.974ms mgasps=60.293 dirty=421.17MiB
INFO [09-16|10:08:30.971] Imported new potential chain segment number=15,545,483 hash=071f80..537c2f blocks=1 txs=13 mgas=0.541 elapsed=6.964ms mgasps=77.693 dirty=421.17MiB
INFO [09-16|10:08:30.983] Imported new potential chain segment number=15,545,483 hash=071f80..537c2f blocks=1 txs=13 mgas=0.541 elapsed=12.114ms mgasps=44.668 dirty=421.17MiB
INFO [09-16|10:08:33.432] Imported new potential chain segment number=15,545,484 hash=41a700..4e23fa blocks=1 txs=489 mgas=29.991 elapsed=1.288s mgasps=23.270 dirty=423.45MiB
INFO [09-16|10:08:33.813] Imported new potential chain segment number=15,545,484 hash=41a700..4e23fa blocks=1 txs=489 mgas=29.991 elapsed=379.985ms mgasps=78.927 dirty=423.45MiB
INFO [09-16|10:08:34.583] Imported new potential chain segment number=15,545,484 hash=41a700..4e23fa blocks=1 txs=489 mgas=29.991 elapsed=769.967ms mgasps=38.951 dirty=423.45MiB
INFO [09-16|10:08:35.565] Imported new potential chain segment number=15,545,485 hash=ae280b..cb76a5 blocks=1 txs=234 mgas=15.675 elapsed=982.187ms mgasps=15.959 dirty=424.79MiB
INFO [09-16|10:08:35.741] Imported new potential chain segment number=15,545,485 hash=ae280b..cb76a5 blocks=1 txs=234 mgas=15.675 elapsed=173.786ms mgasps=90.196 dirty=424.79MiB
INFO [09-16|10:08:36.777] Imported new potential chain segment number=15,545,485 hash=ae280b..cb76a5 blocks=1 txs=234 mgas=15.675 elapsed=1.036s mgasps=15.128 dirty=424.79MiB
INFO [09-16|10:08:37.045] Imported new potential chain segment number=15,545,486 hash=8cbe27..5e0d63 blocks=1 txs=181 mgas=6.784 elapsed=254.929ms mgasps=26.610 dirty=423.73MiB
INFO [09-16|10:08:37.888] Imported new potential chain segment number=15,545,486 hash=8cbe27..5e0d63 blocks=1 txs=181 mgas=6.784 elapsed=843.472ms mgasps=8.043 dirty=423.73MiB
INFO [09-16|10:08:38.037] Imported new potential chain segment number=15,545,486 hash=8cbe27..5e0d63 blocks=1 txs=181 mgas=6.784 elapsed=142.145ms mgasps=47.724 dirty=423.73MiB
INFO [09-16|10:08:39.453] Imported new potential chain segment number=15,545,487 hash=0c6959..c199a9 blocks=1 txs=365 mgas=29.994 elapsed=1.415s mgasps=21.190 dirty=426.27MiB
INFO [09-16|10:08:40.725] Imported new potential chain segment number=15,545,487 hash=0c6959..c199a9 blocks=1 txs=365 mgas=29.994 elapsed=1.268s mgasps=23.652 dirty=426.27MiB
INFO [09-16|10:08:43.650] Imported new potential chain segment number=15,545,488 hash=bbf391..fc523e blocks=1 txs=151 mgas=12.637 elapsed=450.678ms mgasps=28.040 dirty=426.21MiB
INFO [09-16|10:08:48.183] Imported new potential chain segment number=15,545,489 hash=b81500..6eb6db blocks=1 txs=17 mgas=2.409 elapsed=334.239ms mgasps=7.207 dirty=425.88MiB
INFO [09-16|10:09:00.730] Imported new potential chain segment number=15,545,490 hash=d6bb08..0be2e7 blocks=1 txs=429 mgas=29.984 elapsed=735.222ms mgasps=40.782 dirty=427.91MiB
INFO [09-16|10:09:13.922] Imported new potential chain segment number=15,545,491 hash=556a58..f6d299 blocks=1 txs=219 mgas=22.667 elapsed=197.303ms mgasps=114.884 dirty=428.42MiB
INFO [09-16|10:09:24.811] Imported new potential chain segment number=15,545,492 hash=87dd36..e31600 blocks=1 txs=159 mgas=13.533 elapsed=117.817ms mgasps=114.861 dirty=427.99MiB
INFO [09-16|10:09:38.018] Imported new potential chain segment number=15,545,493 hash=41916b..ca7e62 blocks=1 txs=191 mgas=16.198 elapsed=1.140s mgasps=14.206 dirty=429.18MiB
INFO [09-16|10:09:48.627] Imported new potential chain segment number=15,545,494 hash=dbb8a8..de4e28 blocks=1 txs=137 mgas=16.486 elapsed=500.351ms mgasps=32.949 dirty=429.68MiB
INFO [09-16|10:10:01.172] Imported new potential chain segment number=15,545,495 hash=e10ff1..ae1a47 blocks=1 txs=240 mgas=14.668 elapsed=297.484ms mgasps=49.307 dirty=429.48MiB
INFO [09-16|10:10:13.551] Imported new potential chain segment number=15,545,491 hash=bf8c43..6b79cf blocks=1 txs=281 mgas=29.988 elapsed=501.506ms mgasps=59.795 dirty=430.47MiB
INFO [09-16|10:10:27.377] Imported new potential chain segment number=15,545,496 hash=2f999f..d533ea blocks=1 txs=267 mgas=23.502 elapsed=426.086ms mgasps=55.159 dirty=431.78MiB
INFO [09-16|10:10:36.740] Imported new potential chain segment number=15,545,497 hash=e7d33b..5ac9d8 blocks=1 txs=254 mgas=12.750 elapsed=305.417ms mgasps=41.746 dirty=432.98MiB
INFO [09-16|10:10:48.288] Imported new potential chain segment number=15,545,498 hash=8cbed7..b49f88 blocks=1 txs=36 mgas=2.662 elapsed=476.223ms mgasps=5.590 dirty=432.22MiB
INFO [09-16|10:11:01.226] Imported new potential chain segment number=15,545,499 hash=7da923..a881ac blocks=1 txs=307 mgas=27.064 elapsed=347.970ms mgasps=77.777 dirty=433.23MiB
INFO [09-16|10:11:11.732] Imported new potential chain segment number=15,545,500 hash=f3d349..dd05bc blocks=1 txs=60 mgas=3.918 elapsed=30.223ms mgasps=129.630 dirty=433.28MiB
INFO [09-16|10:11:24.825] Imported new potential chain segment number=15,545,501 hash=d7b13b..b95e97 blocks=1 txs=188 mgas=15.467 elapsed=257.969ms mgasps=59.958 dirty=433.45MiB

[holiman]

When the node is back closer to head, this does not seem to occur anymore.

[holiman]

So, this seems to be prone to happen particularly in relation to Database compacting:

WARN [09-16|10:32:45.230] Database compacting, degraded performance database=/datadir/geth/geth/chaindata
INFO [09-16|10:33:11.536] Unindexing transactions blocks=12,484,000 txs=1,143,273,246 total=13,195,031 elapsed=1h58m3.322s
INFO [09-16|10:33:11.615] Imported new potential chain segment number=15,545,548 hash=2b719c..414ac5 blocks=1 txs=211 mgas=15.760 elapsed=12m22.721s mgasps=0.021 age=12m24s dirty=452.47MiB
INFO [09-16|10:33:12.276] Imported new potential chain segment number=15,545,548 hash=2b719c..414ac5 blocks=1 txs=211 mgas=15.760 elapsed=661.006ms mgasps=23.842 age=12m25s dirty=452.47MiB
INFO [09-16|10:33:12.478] Imported new potential chain segment number=15,545,548 hash=2b719c..414ac5 blocks=1 txs=211 mgas=15.760 elapsed=201.819ms mgasps=78.089 age=12m25s dirty=452.47MiB
INFO [09-16|10:33:12.550] Imported new potential chain segment number=15,545,548 hash=2b719c..414ac5 blocks=1 txs=211 mgas=15.760 elapsed=72.054ms mgasps=218.723 age=12m25s dirty=452.47MiB
WARN [09-16|10:33:13.169] Ignoring already known beacon payload number=15,545,548 hash=2b719c..414ac5 age=12m26s
INFO [09-16|10:33:13.512] Imported new potential chain segment number=15,545,548 hash=2b719c..414ac5 blocks=1 txs=211 mgas=15.760 elapsed=961.439ms mgasps=16.392 age=12m26s dirty=452.47MiB
INFO [09-16|10:33:13.588] Imported new potential chain segment number=15,545,548 hash=2b719c..414ac5 blocks=1 txs=211 mgas=15.760 elapsed=75.651ms mgasps=208.324 age=12m26s dirty=452.47MiB
INFO [09-16|10:33:13.666] Imported new potential chain segment number=15,545,548 hash=2b719c..414ac5 blocks=1 txs=211 mgas=15.760 elapsed=78.302ms mgasps=201.270 age=12m26s dirty=452.47MiB
INFO [09-16|10:33:14.150] Imported new potential chain segment number=15,545,548 hash=2b719c..414ac5 blocks=1 txs=211 mgas=15.760 elapsed=483.442ms mgasps=32.599 age=12m27s dirty=452.47MiB
INFO [09-16|10:33:14.235] Imported new potential chain segment number=15,545,548 hash=2b719c..414ac5 blocks=1 txs=211 mgas=15.760 elapsed=85.008ms mgasps=185.392 age=12m27s dirty=452.47MiB
INFO [09-16|10:33:14.827] Imported new potential chain segment number=15,545,548 hash=2b719c..414ac5 blocks=1 txs=211 mgas=15.760 elapsed=591.621ms mgasps=26.638 age=12m27s dirty=452.47MiB
INFO [09-16|10:33:15.061] Imported new potential chain segment number=15,545,548 hash=2b719c..414ac5 blocks=1 txs=211 mgas=15.760 elapsed=234.113ms mgasps=67.317 age=12m28s dirty=452.47MiB
INFO [09-16|10:33:15.941] Imported new potential chain segment number=15,545,548 hash=2b719c..414ac5 blocks=1 txs=211 mgas=15.760 elapsed=879.333ms mgasps=17.923 age=12m28s dirty=452.47MiB
INFO [09-16|10:33:16.018] Imported new potential chain segment number=15,545,548 hash=2b719c..414ac5 blocks=1 txs=211 mgas=15.760 elapsed=76.435ms mgasps=206.185 age=12m29s dirty=452.47MiB
INFO [09-16|10:33:16.601] Imported new potential chain segment number=15,545,548 hash=2b719c..414ac5 blocks=1 txs=211 mgas=15.760 elapsed=583.520ms mgasps=27.008 age=12m29s dirty=452.47MiB
INFO [09-16|10:33:16.671] Imported new potential chain segment number=15,545,548 hash=2b719c..414ac5 blocks=1 txs=211 mgas=15.760 elapsed=69.289ms mgasps=227.452 age=12m29s dirty=452.47MiB
INFO [09-16|10:33:16.743] Imported new potential chain segment number=15,545,548 hash=2b719c..414ac5 blocks=1 txs=211 mgas=15.760 elapsed=72.118ms mgasps=218.529 age=12m29s dirty=452.47MiB
INFO [09-16|10:33:17.402] Imported new potential chain segment number=15,545,548 hash=2b719c..414ac5 blocks=1 txs=211 mgas=15.760 elapsed=658.581ms mgasps=23.930 age=12m30s dirty=452.47MiB
INFO [09-16|10:33:17.505] Imported new potential chain segment number=15,545,548 hash=2b719c..414ac5 blocks=1 txs=211 mgas=15.760 elapsed=102.527ms mgasps=153.714 age=12m30s dirty=452.47MiB
INFO [09-16|10:33:17.722] Imported new potential chain segment number=15,545,548 hash=2b719c..414ac5 blocks=1 txs=211 mgas=15.760 elapsed=217.000ms mgasps=72.626 age=12m30s dirty=452.47MiB
INFO [09-16|10:33:17.817] Imported new potential chain segment number=15,545,548 hash=2b719c..414ac5 blocks=1 txs=211 mgas=15.760 elapsed=94.708ms mgasps=166.404 age=12m30s dirty=452.47MiB
INFO [09-16|10:33:18.542] Imported new potential chain segment number=15,545,548 hash=2b719c..414ac5 blocks=1 txs=211 mgas=15.760 elapsed=724.829ms mgasps=21.743 age=12m31s dirty=452.47MiB
INFO [09-16|10:33:18.616] Imported new potential chain segment number=15,545,548 hash=2b719c..414ac5 blocks=1 txs=211 mgas=15.760 elapsed=73.812ms mgasps=213.512 age=12m31s dirty=452.47MiB
INFO [09-16|10:33:19.352] Imported new potential chain segment number=15,545,548 hash=2b719c..414ac5 blocks=1 txs=211 mgas=15.760 elapsed=736.039ms mgasps=21.412 age=12m32s dirty=452.47MiB
INFO [09-16|10:33:19.494] Imported new potential chain segment number=15,545,548 hash=2b719c..414ac5 blocks=1 txs=211 mgas=15.760 elapsed=141.372ms mgasps=111.477 age=12m32s dirty=452.47MiB

The database compaction is somewhat like a 'freeze', and it might be that the CL tries to shove block 15,545,548 at us. Our RPC does not respond, being blocked by compaction, and the CL just times out on the attempt and fires off another request.

Eventually, we handle the requests in order. And it seems that we actually do reprocess each block, looking at the elapsed metric.

This means that if we're already under heavy pressure/load, and do a lot of compaction, then we're also doing extra work by chugging through the upcoming blocks over and over again.