Slow backwards sync

[ForceConstant]

Description

Had Besu shutoff for a week due to some issues, now restarted with 2.7.4, and it is slowly doing Backwards Sync Algorithm, it has been 15 hours, and seems like it will be another 24 hours at this rate. CPU is low at 10%, and load is 1.4, io is low. I am running as part of rocketpool tool. 16GB Ram, '--Xplugin-rocksdb-high-spec-enabled'

I do have grafana dashboard running, so can include any plots for that if wanted.

  | 2022-09-27 12:33:10.058+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15588292 -> 15588292 (target: 15624713)
eth1_1           | 2022-09-27 12:33:10.060+00:00 | ForkJoinPool.commonPool-worker-2 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:11.592+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15588293 -> 15588293 (target: 15624713)
eth1_1           | 2022-09-27 12:33:11.594+00:00 | ForkJoinPool.commonPool-worker-2 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:14.665+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15588294 -> 15588294 (target: 15624714)
eth1_1           | 2022-09-27 12:33:14.670+00:00 | ForkJoinPool.commonPool-worker-2 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:17.299+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15588295 -> 15588295 (target: 15624714)
eth1_1           | 2022-09-27 12:33:17.301+00:00 | ForkJoinPool.commonPool-worker-2 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:19.472+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15588296 -> 15588296 (target: 15624714)
eth1_1           | 2022-09-27 12:33:19.474+00:00 | ForkJoinPool.commonPool-worker-2 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:19.575+00:00 | nioEventLoopGroup-3-8 | INFO  | ForwardSyncStep | No blocks to save...
eth1_1           | 2022-09-27 12:33:19.576+00:00 | nioEventLoopGroup-3-8 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:19.832+00:00 | nioEventLoopGroup-3-5 | INFO  | ForwardSyncStep | No blocks to save...
eth1_1           | 2022-09-27 12:33:19.833+00:00 | nioEventLoopGroup-3-5 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:22.872+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15588297 -> 15588297 (target: 15624714)
eth1_1           | 2022-09-27 12:33:22.874+00:00 | ForkJoinPool.commonPool-worker-2 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:22.933+00:00 | nioEventLoopGroup-3-8 | INFO  | ForwardSyncStep | No blocks to save...
eth1_1           | 2022-09-27 12:33:22.933+00:00 | nioEventLoopGroup-3-8 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:23.211+00:00 | nioEventLoopGroup-3-5 | INFO  | ForwardSyncStep | No blocks to save...
eth1_1           | 2022-09-27 12:33:23.212+00:00 | nioEventLoopGroup-3-5 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:24.792+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15588298 -> 15588298 (target: 15624715)
eth1_1           | 2022-09-27 12:33:24.794+00:00 | ForkJoinPool.commonPool-worker-1 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:24.996+00:00 | nioEventLoopGroup-3-8 | INFO  | ForwardSyncStep | No blocks to save...
eth1_1           | 2022-09-27 12:33:24.996+00:00 | nioEventLoopGroup-3-8 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:25.322+00:00 | nioEventLoopGroup-3-5 | INFO  | ForwardSyncStep | No blocks to save...
eth1_1           | 2022-09-27 12:33:25.323+00:00 | nioEventLoopGroup-3-5 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:27.356+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15588299 -> 15588299 (target: 15624715)
eth1_1           | 2022-09-27 12:33:27.359+00:00 | ForkJoinPool.commonPool-worker-1 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:29.361+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15588300 -> 15588300 (target: 15624715)
eth1_1           | 2022-09-27 12:33:29.363+00:00 | ForkJoinPool.commonPool-worker-1 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:29.429+00:00 | nioEventLoopGroup-3-8 | INFO  | ForwardSyncStep | No blocks to save...
eth1_1           | 2022-09-27 12:33:29.430+00:00 | nioEventLoopGroup-3-8 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:29.690+00:00 | nioEventLoopGroup-3-5 | INFO  | ForwardSyncStep | No blocks to save...
eth1_1           | 2022-09-27 12:33:29.690+00:00 | nioEventLoopGroup-3-5 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:31.632+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15588301 -> 15588301 (target: 15624715)
eth1_1           | 2022-09-27 12:33:31.634+00:00 | ForkJoinPool.commonPool-worker-2 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:34.730+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15588302 -> 15588302 (target: 15624715)
eth1_1           | 2022-09-27 12:33:34.733+00:00 | ForkJoinPool.commonPool-worker-2 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:36.260+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15588303 -> 15588303 (target: 15624715)
eth1_1           | 2022-09-27 12:33:36.262+00:00 | ForkJoinPool.commonPool-worker-2 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:39.146+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15588304 -> 15588304 (target: 15624716)
eth1_1           | 2022-09-27 12:33:39.151+00:00 | ForkJoinPool.commonPool-worker-2 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:40.681+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15588305 -> 15588305 (target: 15624716)
eth1_1           | 2022-09-27 12:33:40.684+00:00 | ForkJoinPool.commonPool-worker-2 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:42.970+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15588306 -> 15588306 (target: 15624716)
eth1_1           | 2022-09-27 12:33:42.972+00:00 | ForkJoinPool.commonPool-worker-2 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:44.901+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15588307 -> 15588307 (target: 15624716)
eth1_1           | 2022-09-27 12:33:44.904+00:00 | ForkJoinPool.commonPool-worker-2 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:33:48.589+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15588308 -> 15588308 (target: 15624717)
eth1_1           | 2022-09-27 12:33:48.591+00:00 | ForkJoinPool.commonPool-worker-2 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:34:00.913+00:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | SYNCING for fork-choice-update: head: 0x2fde5cf0a49ff9f6db5781a7bb92a41671498eb060aa1ec933d55925a0cfb8a1, finalized: 0x0fdbf36038871f716899616046b7d5fef94561ec04af5c0d51691bee10a6083f, safeBlockHash: 0xc491055ef1bfcdb2158b268ce0739adc845d95ae127854b0c605b0eb9242fb70
eth1_1           | 2022-09-27 12:34:25.407+00:00 | nioEventLoopGroup-3-3 | INFO  | ForwardSyncStep | Saved blocks 15588309 -> 15588337 (target: 15624720)
eth1_1           | 2022-09-27 12:34:25.411+00:00 | ForkJoinPool.commonPool-worker-2 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 12:34:25.487+00:00 | nioEventLoopGroup-3-6 | INFO  | ForwardSyncStep | No blocks to save...
eth1_1           | 2022-09-27 12:34:25.488+00:00 | nioEventLoopGroup-3-6 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync

[ForceConstant]

I also get the error NO_PEERS_FOUND sometimes

eth1_1           | 2022-09-27 21:55:30.877+00:00 | ForkJoinPool.commonPool-worker-3 | WARN  | BackwardSyncContext | Backward sync failed (org.hyperledger.besu.ethereum.eth.manager.exceptions.NoAvailablePeersException: Task failed: NO_AVAILABLE_PEERS). Current Peers: 1. Retrying in 5000 milliseconds...
eth1_1           | 2022-09-27 21:55:35.878+00:00 | EthScheduler-Timer-0 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 21:55:37.629+00:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | SYNCING for fork-choice-update: head: 0x2324285c691da3bda2b39922be5579c2d07a4c0d63ad76ec8287a7e78edda730, finalized: 0x3900f75eb3e46d1bd414028341ebd9d43adf78d9d305fc59a6721ce92100a08b, safeBlockHash: 0x52429b0cf7bcbd5efea3f0cda3b250fc9f0aea5cd6c588bfc6d178a53336dd1d
eth1_1           | 2022-09-27 21:55:39.786+00:00 | nioEventLoopGroup-3-1 | INFO  | ForwardSyncStep | Saved blocks 15599173 -> 15599174 (target: 15627498)
eth1_1           | 2022-09-27 21:55:39.876+00:00 | ForkJoinPool.commonPool-worker-3 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 21:55:39.889+00:00 | ForkJoinPool.commonPool-worker-3 | WARN  | BackwardSyncContext | Backward sync failed (org.hyperledger.besu.ethereum.eth.manager.exceptions.NoAvailablePeersException: Task failed: NO_AVAILABLE_PEERS). Current Peers: 0. Retrying in 5000 milliseconds...
eth1_1           | 2022-09-27 21:55:44.890+00:00 | EthScheduler-Timer-0 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 21:55:44.904+00:00 | ForkJoinPool.commonPool-worker-3 | WARN  | BackwardSyncContext | Backward sync failed (org.hyperledger.besu.ethereum.eth.manager.exceptions.NoAvailablePeersException: Task failed: NO_AVAILABLE_PEERS). Current Peers: 0. Retrying in 5000 milliseconds...
eth1_1           | 2022-09-27 21:55:49.904+00:00 | EthScheduler-Timer-0 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 21:55:49.912+00:00 | ForkJoinPool.commonPool-worker-3 | WARN  | BackwardSyncContext | Backward sync failed (org.hyperledger.besu.ethereum.eth.manager.exceptions.NoAvailablePeersException: Task failed: NO_AVAILABLE_PEERS). Current Peers: 0. Retrying in 5000 milliseconds...
eth1_1           | 2022-09-27 21:55:54.913+00:00 | EthScheduler-Timer-0 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 21:55:54.926+00:00 | ForkJoinPool.commonPool-worker-3 | WARN  | BackwardSyncContext | Backward sync failed (org.hyperledger.besu.ethereum.eth.manager.exceptions.NoAvailablePeersException: Task failed: NO_AVAILABLE_PEERS). Current Peers: 0. Retrying in 5000 milliseconds...
eth1_1           | 2022-09-27 21:55:59.927+00:00 | EthScheduler-Timer-0 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 21:55:59.940+00:00 | ForkJoinPool.commonPool-worker-3 | WARN  | BackwardSyncContext | Backward sync failed (org.hyperledger.besu.ethereum.eth.manager.exceptions.NoAvailablePeersException: Task failed: NO_AVAILABLE_PEERS). Current Peers: 1. Retrying in 5000 milliseconds...
eth1_1           | 2022-09-27 21:56:04.941+00:00 | EthScheduler-Timer-0 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 21:56:06.525+00:00 | nioEventLoopGroup-3-9 | INFO  | ForwardSyncStep | No blocks to save...
eth1_1           | 2022-09-27 21:56:06.526+00:00 | nioEventLoopGroup-3-9 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 21:56:06.694+00:00 | nioEventLoopGroup-3-9 | INFO  | ForwardSyncStep | No blocks to save...
eth1_1           | 2022-09-27 21:56:06.695+00:00 | nioEventLoopGroup-3-9 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 21:56:06.858+00:00 | nioEventLoopGroup-3-9 | INFO  | ForwardSyncStep | No blocks to save...
eth1_1           | 2022-09-27 21:56:06.859+00:00 | nioEventLoopGroup-3-9 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 21:56:06.861+00:00 | ForkJoinPool.commonPool-worker-3 | WARN  | BackwardSyncContext | Backward sync failed (org.hyperledger.besu.ethereum.eth.manager.exceptions.NoAvailablePeersException: Task failed: NO_AVAILABLE_PEERS). Current Peers: 1. Retrying in 5000 milliseconds...
eth1_1           | 2022-09-27 21:56:11.862+00:00 | EthScheduler-Timer-0 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
eth1_1           | 2022-09-27 21:56:48.537+00:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | SYNCING for fork-choice-update: head: 0x3dc71a74911f99d9e7fdd89f8fb2486485a94a86141c4a59895556fe5fd423a8, finalized: 0xe7fd

[zymox]

Same issue(s). Also running Rocketpool, Besu 22.7.5 (just upgraded from 22.7.4) in combination with Nimbus.

[non-fungible-nelson]

@fab-10 @gezero - Maybe we consider some new logging around this to better inform users?

[fab-10]

I agree we can improve the logging, showing only the progress and critical errors, and pushing transient errors to debug.

Instead for the timing, it is normal that it takes more time that the initial sync, since backward sync needs to fully import blocks, in a serial way, so the improvements around block import that are ongoing will benefit backward sync as well, but as rule of thumb, if Besu is down for some day is usually faster to delete the database and perform a snapsync from scratch, that wait for the backward sync to complete, since the latter is only meant for the sync of few blocks.

[non-fungible-nelson]

Understood - maybe we paste that in the logs if the BWS queue is large enough? Or a docs change - I will open a PR on this page.