helium
node loading blocks extremely slow after after running a while
After node has been running a few days without being restarted, block loading slows down to a crawl. This causes the chain to get way ahead which is bad when we're hoping to load extra txn data via {store_json, true}. This started roughly a month or two ago. Seen on Debian 10 and Ubuntu 20.04.
config being used:
%% -*- erlang -*-
[
"config/sys.config",
{lager,
[
{log_root, "log"}
]},
{blockchain,
[
{listen_addresses, ["/ip4/0.0.0.0/tcp/2154"]},
{store_json, true},
{base_dir, "data"}
]}
].
Here are the logs showing slower block loading times. Please note: the error is the node being restarted. Timestamps go back to multiple blocks per minute vs every couple minutes.
2022-03-06 10:09:18.648 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251647 (1318 transactions)
2022-03-06 10:11:26.538 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251648 (2 transactions)
2022-03-06 10:11:32.849 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251649 (764 transactions)
2022-03-06 10:12:40.669 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251650 (785 transactions)
2022-03-06 10:13:59.384 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251651 (1309 transactions)
2022-03-06 10:16:07.424 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251652 (1444 transactions)
2022-03-06 10:18:43.766 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251653 (1343 transactions)
2022-03-06 10:21:05.759 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251654 (1328 transactions)
2022-03-06 10:23:18.395 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251655 (1329 transactions)
2022-03-06 10:25:21.299 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251656 (1466 transactions)
2022-03-06 10:27:30.466 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251657 (1351 transactions)
2022-03-06 10:29:54.761 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251658 (1535 transactions)
2022-03-06 10:32:25.139 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251659 (1404 transactions)
2022-03-06 10:34:48.178 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251660 (1354 transactions)
2022-03-06 10:37:01.403 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251661 (1445 transactions)
2022-03-06 10:39:18.094 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251662 (1493 transactions)
2022-03-06 10:41:38.559 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251663 (1430 transactions)
2022-03-06 10:44:09.973 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251664 (1336 transactions)
2022-03-06 10:46:32.538 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251665 (1372 transactions)
2022-03-06 10:49:01.943 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251666 (1366 transactions)
2022-03-06 10:49:50.038 [error] <0.1127.0> Supervisor bn_sup had child txn_follower started with blockchain_follower:start_link([{follower_module,{bn_txns,[{base_dir,"data"}]}}]) at <0.1194.0> exit with reason shutdown in context shutdown_error
2022-03-06 10:56:17.338 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251666 (1366 transactions)
2022-03-06 10:56:41.456 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251667 (1391 transactions)
2022-03-06 10:57:07.254 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251668 (1458 transactions)
2022-03-06 10:57:36.058 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251669 (1488 transactions)
2022-03-06 10:58:01.926 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251670 (1341 transactions)
2022-03-06 10:58:15.970 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251671 (1416 transactions)
2022-03-06 10:58:31.192 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251672 (1458 transactions)
2022-03-06 10:58:46.509 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251673 (1564 transactions)
2022-03-06 10:59:02.689 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251674 (1333 transactions)
2022-03-06 10:59:15.517 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251675 (1512 transactions)
2022-03-06 10:59:34.478 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251676 (1325 transactions)
2022-03-06 10:59:51.652 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251677 (1311 transactions)
2022-03-06 11:00:10.735 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251678 (1352 transactions)
2022-03-06 11:00:23.112 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251679 (1497 transactions)
2022-03-06 11:00:38.511 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251680 (1441 transactions)
2022-03-06 11:00:58.979 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251681 (2 transactions)
2022-03-06 11:01:02.064 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251682 (1021 transactions)
2022-03-06 11:01:17.036 [info] <0.1194.0>@bn_txns:load_block:79 Loading Block 1251683 (964 transactions)
Observe the same problem on AMD Ryzen9 3900, 128MB RAM. On this system after 4-6 hours, we start to see the time gap between adding sync blocks and loading block starts to grow at a point it cannot catchup anymore.
2022-02-17 14:34:54.807 [info] <0.23673.1>@blockchain_sync_handler:handle_data:132 adding sync blocks [1229734]
2022-02-17 14:35:15.487 [info] <0.1212.0>@bn_txns:load_block:79 Loading Block 1229631 (1387 transactions)
The system was working OK before upgrading to the recent version. It is also verified switching back to 1.1.58 fixes the issue.
mine is source build
I have another copy on AMD Ryzen 9 5950X, 128GB RAM; which behaves the same. Another note: There are ETL instances on similar servers and they do not experience this problem.
Source build for me as well.
@riobah do you have {store_json, true} in your config?