[BUG] - Restarting node just got a LOT slower

[TerminadaPool]

External

Area

• Other: Node performance

Summary Nodes very slow to restart with significant delay during "Pushing ledger state" from 22% to 44%.

Steps to reproduce systemctl restart cardano-node

Expected behavior Restart on a low power ARM machine used to take 8.5 minutes, now takes 36 minutes.

Restart on a more powerful AMD machine used to take 2 minutes, now takes 6 minutes.

All the extra time occurs when "Pushing ledger state" from 22% to 45%.

System info (please complete the following information):

• OS Name: Debian

• OS Version: 12 (Bookworm)

• Node version (low power ARM machine)

cardano-node 8.9.3 - linux-aarch64 - ghc-9.8 git rev e7f5f3ac9e031b8ea12a16aee0bb37d94b5e1d11

• Node version (AMD machine)

cardano-node 8.9.3 - linux-x86_64 - ghc-9.8 git rev e7f5f3ac9e031b8ea12a16aee0bb37d94b5e1d11

• Both AMD and ARM versions compiled with:
  • ghc_version=9.8.2
  • cabal_version=3.10.2.1

Logs

• Logs from low power ARM machine (equivalent processor to raspberry pi but with more RAM) running cardano-node version 8.9.3:

Jun 25 07:51:26 bp1 systemd[1]: Started cardano-node.service - Cardano Node.
... snip ...
Jun 25 07:51:29 bp1 cardano-node[783721]: [bp1:cardano.node.ChainDB:Info:11] [2024-06-24 21:51:29.36 UTC] Started opening Chain DB
Jun 25 07:51:29 bp1 cardano-node[783721]: [bp1:cardano.node.ChainDB:Info:11] [2024-06-24 21:51:29.36 UTC] Started opening Immutable DB
... snip ...
Jun 25 07:57:32 bp1 cardano-node[783721]: [bp1:cardano.node.ChainDB:Info:11] [2024-06-24 21:57:32.20 UTC] Opened lgr db
Jun 25 07:57:32 bp1 cardano-node[783721]: [bp1:cardano.node.ChainDB:Info:11] [2024-06-24 21:57:32.20 UTC] Started initial chain selection
Jun 25 07:57:33 bp1 cardano-node[783721]: [bp1:cardano.node.ChainDB:Info:11] [2024-06-24 21:57:33.70 UTC] Pushing ledger state for block b5b51f187630ebed4a3072f486a60b5a126241f1d99d563d2e42e02fcb97e31d at slot 127654809. Progress: 0.00%
Jun 25 07:58:36 bp1 cardano-node[783721]: [bp1:cardano.node.ChainDB:Info:11] [2024-06-24 21:58:36.66 UTC] before next, messages elided = 127654824
Jun 25 07:58:36 bp1 cardano-node[783721]: [bp1:cardano.node.ChainDB:Info:11] [2024-06-24 21:58:36.66 UTC] Pushing ledger state for block 009c88b1b75321ae217bcb8bd38ffcb0b51e458f9cdd4ce6abde0d399a41efbd at slot 127664808. Progress: 22.36%
... snip ...
Jun 25 08:24:11 bp1 cardano-node[783721]: [bp1:cardano.node.ChainDB:Info:11] [2024-06-24 22:24:11.57 UTC] before next, messages elided = 127664916
Jun 25 08:24:11 bp1 cardano-node[783721]: [bp1:cardano.node.ChainDB:Info:11] [2024-06-24 22:24:11.57 UTC] Pushing ledger state for block 731dde558c6ecb3bbd3e313147a3a4a19461ac445afba0d57d590b8a8ca81151 at slot 127674899. Progress: 44.92%
... snip ...
Jun 25 08:25:27 bp1 cardano-node[783721]: [bp1:cardano.node.ChainDB:Info:11] [2024-06-24 22:25:27.79 UTC] before next, messages elided = 127674927
Jun 25 08:25:27 bp1 cardano-node[783721]: [bp1:cardano.node.ChainDB:Info:11] [2024-06-24 22:25:27.79 UTC] Pushing ledger state for block d471b680b20f95be52bb10667bfecf84bf0beaee616ce3ea4a2db461909d304c at slot 127684905. Progress: 67.29%
... snip ...
Jun 25 08:26:51 bp1 cardano-node[783721]: [bp1:cardano.node.ChainDB:Info:11] [2024-06-24 22:26:51.68 UTC] before next, messages elided = 127684986
Jun 25 08:26:51 bp1 cardano-node[783721]: [bp1:cardano.node.ChainDB:Info:11] [2024-06-24 22:26:51.68 UTC] Pushing ledger state for block 2b2f68b7d1772fa157bca6ef1b53753464864dc13e06cc17b4a8045202e8328d at slot 127694979. Progress: 89.81%
... snip ...
Jun 25 08:27:25 bp1 cardano-node[783721]: [bp1:cardano.node.ChainDB:Info:11] [2024-06-24 22:27:25.94 UTC] before next, messages elided = 127695028
Jun 25 08:27:25 bp1 cardano-node[783721]: [bp1:cardano.node.ChainDB:Info:11] [2024-06-24 22:27:25.94 UTC] Pushing ledger state for block 159d6126d2a2cbfe76cafe5d8f244d96e5f8a1ae3e426b4fd946f5be93448219 at slot 127699537. Progress: 100.00%
Jun 25 08:27:25 bp1 cardano-node[783721]: [bp1:cardano.node.ChainDB:Info:11] [2024-06-24 22:27:25.94 UTC] Valid candidate at tip b5b51f187630ebed4a3072f486a60b5a126241f1d99d563d2e42e02fcb97e31d at slot 127654809
Jun 25 08:27:25 bp1 cardano-node[783721]: [bp1:cardano.node.ChainDB:Info:11] [2024-06-24 22:27:25.94 UTC] Initial chain selected
Jun 25 08:27:25 bp1 cardano-node[783721]: [bp1:cardano.node.ChainDB:Info:11] [2024-06-24 22:27:25.94 UTC] Opened db with immutable tip at e11fd98ac6b0a6fc4a504b30024bc9c75ea1111225bd9eb0cfb925c0b2aff27e at slot 127654750 and tip 159d6126d

Note that it took 7 minutes to get to "Pushing ledger state" progress 22% which is typical for this machine from past experience. However it then took over 25 minutes to progress "Pushing ledger state" from 22% to 44%. Normally this stage takes only around 1 to 1.5 minutes. It then took 1.5 minutes to Push the ledger state from 45% to 67% and another 1.5 minutes from 67% to 90% both of which is typical for this slow ARM machine compared to the past.

Logs from more powerful AMD machine running cardano-node version 8.9.3:

Jun 25 08:27:21 relay1 systemd[1]: Started cardano-node.service - Cardano Node.
... snip ...
Jun 25 08:28:39 relay1 cardano-node[183103]: [relay1:cardano.node.ChainDB:Info:9] [2024-06-24 22:28:39.58 UTC] Opened lgr db
Jun 25 08:28:39 relay1 cardano-node[183103]: [relay1:cardano.node.ChainDB:Info:9] [2024-06-24 22:28:39.58 UTC] Started initial chain selection
Jun 25 08:28:39 relay1 cardano-node[183103]: [relay1:cardano.node.ChainDB:Info:9] [2024-06-24 22:28:39.92 UTC] Pushing ledger state for block bc48fc99af50edfd1f0443d1c735743797d11c511d2ca36d1fb375c0b164b33e at slot 127657338. Progress: 0.00%
Jun 25 08:28:54 relay1 cardano-node[183103]: [relay1:cardano.node.ChainDB:Info:9] [2024-06-24 22:28:54.80 UTC] before next, messages elided = 127657363
Jun 25 08:28:54 relay1 cardano-node[183103]: [relay1:cardano.node.ChainDB:Info:9] [2024-06-24 22:28:54.80 UTC] Pushing ledger state for block be03bf8d2c52b0f81ea0f3496af44c9462262d0b003d632f742c69cb6b7ee2db at slot 127667331. Progress: 22.52%
... snip ...
Jun 25 08:32:58 relay1 cardano-node[183103]: [relay1:cardano.node.ChainDB:Info:9] [2024-06-24 22:32:58.36 UTC] before next, messages elided = 127667424
Jun 25 08:32:58 relay1 cardano-node[183103]: [relay1:cardano.node.ChainDB:Info:9] [2024-06-24 22:32:58.36 UTC] Pushing ledger state for block 489b5d6a0914bed294f47750e38f5b7ce6d118e804bd505ffcb8be3136a010ff at slot 127677401. Progress: 45.22%
... snip ...
Jun 25 08:33:16 relay1 cardano-node[183103]: [relay1:cardano.node.ChainDB:Info:9] [2024-06-24 22:33:16.05 UTC] before next, messages elided = 127677490
Jun 25 08:33:16 relay1 cardano-node[183103]: [relay1:cardano.node.ChainDB:Info:9] [2024-06-24 22:33:16.06 UTC] Pushing ledger state for block 2852062d7f2186f1dd8556b78639993b2a46868ca2ea1067f9d8751e06fd9d25 at slot 127687464. Progress: 67.90%
... snip ...
Jun 25 08:33:33 relay1 cardano-node[183103]: [relay1:cardano.node.ChainDB:Info:9] [2024-06-24 22:33:33.02 UTC] before next, messages elided = 127687563
Jun 25 08:33:33 relay1 cardano-node[183103]: [relay1:cardano.node.ChainDB:Info:9] [2024-06-24 22:33:33.02 UTC] Pushing ledger state for block 0b7b08976bcb3a8ece7da3bb95a3816d7394d456917b5983cf2077d54e8409ae at slot 127697558. Progress: 90.65%
... snip ...
Jun 25 08:33:40 relay1 cardano-node[183103]: [relay1:cardano.node.ChainDB:Info:9] [2024-06-24 22:33:40.25 UTC] before next, messages elided = 127697621
Jun 25 08:33:40 relay1 cardano-node[183103]: [relay1:cardano.node.ChainDB:Info:9] [2024-06-24 22:33:40.25 UTC] Pushing ledger state for block 9d2e8da71a8732120e7aa2ec1b4facf731789643484c23e7ac9cda0864598aad at slot 127701707. Progress: 100.00%
Jun 25 08:33:40 relay1 cardano-node[183103]: [relay1:cardano.node.ChainDB:Info:9] [2024-06-24 22:33:40.25 UTC] Valid candidate at tip bc48fc99af50edfd1f0443d1c735743797d11c511d2ca36d1fb375c0b164b33e at slot 127657338
Jun 25 08:33:40 relay1 cardano-node[183103]: [relay1:cardano.node.ChainDB:Info:9] [2024-06-24 22:33:40.25 UTC] Initial chain selected
Jun 25 08:33:40 relay1 cardano-node[183103]: [relay1:cardano.node.ChainDB:Info:9] [2024-06-24 22:33:40.25 UTC] Opened db with immutable tip at d25ceb3b1a757d5f874c62d0f93526722c5609ede55b31c9c5ad82e50f089bf7 at slot 127657337 and tip 9d2e8da71

The AMD machine is more powerful but it has similarly seen a significant increase in restart time with all the time increase occurring when pushing the ledger state from 22% to 45%.

From restart this machine took 1.5 minutes to get to "Pushing ledger state" progress 22%. But then to progress from 22% to 45% took 4 minutes. While the progress from 45% to 67% and 67% to 90% took only 18 seconds. In the past it only took around 15-20 seconds to progress the ledger state from 22% to 45% on this machine.

Something in the ledger is now making the nodes take a lot longer to push their ledger state. I also checked a relay running version 8.9.2 (similarly compiled with ghc 9.8.2) and it also now takes much longer to restart with all the extra time occurring when pushing the ledger state from 22% to 45%.

Additional context Something has changed in the ledger which is causing the node software to do a lot more processing. Maybe there is some particular transaction causing a problem??? Maybe there is a bug???