write_lock_acquisition_time = 1000225μs exceeds warning threshold of 50ms
99% of the time I attempt to download a block from my private HIVE node using RPC I get the following error:
2557953ms chain_plugin.cpp:299 operator() ] write_lock_acquisition_time = 1000216μs exceeds warning threshold of 50ms
2558979ms database.cpp:558 fetch_block_by_numbe ] 13 N5boost16exception_detail10clone_implINS0_19error_info_injectorIN9chainbase14lock_exceptionEEEEE: Unable to acquire database lock
rethrow Unable to acquire database lock:
{"what":"Unable to acquire database lock"}
database.cpp:558 fetch_block_by_number_unlocked
I have tried reinstalling the node multiple times, on different hardware, and I always get the same error message.
Repro steps:
- Install hive-in-a-box from the master branch of https://github.com/Someguy123/hive-docker. The latest commit as of this time is https://github.com/Someguy123/hive-docker/commit/10cdf46028975e8351f50c7465c301081802abcc
- Create .env containing
PORTS=2001,8091
-
nano config.ini
and increaseshared-file-size
from 25G to 30G (I tried both values and neither worked) ./run.sh shm_size 30G
- Follow the steps in the README.md until and including
./run.sh replay
- Eventually the node reached the following point:
$ sudo ./run.sh health
Hostname: ip-10-0-10-70
Host http://127.0.0.1:8091
Running Version 1.25.0
Head Block 63456222
Block Time 2022-04-12T19:37:24 (5 months + 1 day + 8 hours + 11 minutes ago) (12211905 seconds)
Installed Image Version:
Signing Private Key: <hidden>
Signing Public Key:
Latest block received (from logs):
But every time my client requests a block I get back the aforementioned error.
Here is what a sample request looks like:
HTTP POST http://server-ip:8091/
{"jsonrpc":"2.0","method":"condenser_api.get_block","id":"0","params":[22000001]}
The disk latency is ~2ms, which is much lower than the required 50ms:
$ sudo dd if=/dev/zero of=/tmp/test.img bs=512 count=1000 oflag=dsync
1000+0 records in
1000+0 records out
512000 bytes (512 kB, 500 KiB) copied, 2.21376 s, 231 kB/s
$ sudo dd if=/dev/zero of=/dev/shm/test.img bs=512 count=1000 oflag=dsync
1000+0 records in
1000+0 records out
512000 bytes (512 kB, 500 KiB) copied, 0.00133917 s, 382 MB/s
Here is the output I see on startup (immediately after invoking ./run.sh replay
):
[2022-09-01 04:01:15 UTC] DOCKER LOGS: (press ctrl-c to exit)
72155ms p2p_plugin.cpp:644 operator() ] P2P adding seed node 178.32.202.159:2001
72155ms p2p_plugin.cpp:644 operator() ] P2P adding seed node 104.21.88.47:2001
72156ms p2p_plugin.cpp:644 operator() ] P2P adding seed node 172.67.172.140:2001
72156ms p2p_plugin.cpp:644 operator() ] P2P adding seed node 104.21.5.177:2001
72156ms p2p_plugin.cpp:644 operator() ] P2P adding seed node 172.67.133.175:2001
72156ms p2p_plugin.cpp:644 operator() ] P2P adding seed node 95.217.192.18:2001
72156ms p2p_plugin.cpp:644 operator() ] P2P adding seed node 91.183.35.138:2001
72156ms p2p_plugin.cpp:644 operator() ] P2P adding seed node 51.79.99.14:2001
72156ms p2p_plugin.cpp:644 operator() ] P2P adding seed node 65.21.199.174:2001
72156ms p2p_plugin.cpp:644 operator() ] P2P adding seed node 195.201.172.94:2001
72156ms p2p_plugin.cpp:644 operator() ] P2P adding seed node 65.21.235.184:2001
72156ms p2p_plugin.cpp:644 operator() ] P2P adding seed node 116.202.168.187:2001
72156ms p2p_plugin.cpp:644 operator() ] P2P adding seed node 88.99.165.91:2001
72157ms p2p_plugin.cpp:644 operator() ] P2P adding seed node 172.67.220.60:2001
72157ms p2p_plugin.cpp:644 operator() ] P2P adding seed node 104.21.62.47:2001
72157ms p2p_plugin.cpp:644 operator() ] P2P adding seed node 95.217.203.90:2016
72157ms p2p_plugin.cpp:644 operator() ] P2P adding seed node 185.130.44.110:2001
72157ms p2p_plugin.cpp:644 operator() ] P2P adding seed node 54.37.87.31:2001
72158ms p2p_plugin.cpp:672 operator() ] P2P node listening at 0.0.0.0:2001
72158ms p2p_plugin.cpp:674 plugin_startup ] P2P Plugin started
72158ms witness_plugin.cpp:534 plugin_startup ] witness plugin: plugin_startup() begin
72158ms witness_plugin.cpp:539 plugin_startup ] Launching block production for 1 witnesses.
72158ms witness_plugin.cpp:550 plugin_startup ] witness plugin: plugin_startup() end
72159ms state_snapshot_plugin.cpp:1434 plugin_startup ] Starting up state_snapshot_plugin...
72167ms webserver_plugin.cpp:186 operator() ] start processing ws thread
72167ms webserver_plugin.cpp:220 operator() ] start processing http thread
72167ms webserver_plugin.cpp:202 operator() ] start listening for ws requests
Entering application main loop...
72167ms webserver_plugin.cpp:230 operator() ] start listening for http requests
75258ms database.cpp:4037 check_free_memory ] Free memory is now 10G. Current block number: 63477447
Here is the output from glances:
$ sudo glances
ip-10-0-10-70 (Ubuntu 22.04 64bit / Linux 5.15.0-1017-aws) Uptime: 5 days, 8:05:29
Cloud r5a.2xlarge instance i-01bf62ddb93820076 (us-east-2a)
AMD EPYC 7571 CPU \ 15.0% idle: 85.1% ctx_sw 5K MEM - 35.5% active 26.9G SWAP - 0.0% LOAD 8-core
CPU [|||| 15.0%] user 13.5% irq 0.0% inter 4K total 62.2G inactive 30.1G total 0 1 min: 1.01
MEM [|||||||||| 35.5%] system 0.9% nice 0.0% sw_int 3K used 22.1G buffers 101M used 0 5 min: 1.11
SWAP [ 0.0%] iowait 0.0% steal 0.0% free 40.1G cached 57.8G free 0 15 min: 1.06
NETWORK Rx/s Tx/s CONTAINERS 1 (served by Docker 20.10.17)
docker0 3Kb 495Kb
ens5 505Kb 5Kb Name Status CPU% MEM /MAX IOR/s IOW/s Rx/s Tx/s Command
lo 0b 0b seed running 100.3 324M 62.2G 0B 0B 51.5Mb 346Kb hived --data-dir=/hive/witness_node_data_dir --replay
veth15b2048 4Kb 495Kb
TASKS 170 (556 thr), 1 run, 86 slp, 83 oth sorted automatically by CPU consumption
DefaultGateway 7ms
CPU% MEM% VIRT RES PID USER TIME+ THR NI S R/s W/s Command ('k' to kill)
DISK I/O R/s W/s >118 24.5 33.4G 15.2G 57347 root 1:10 271 0 S 0 979K hived --data-dir=/hive/witness_node_data_dir --replay
nvme0n1 0 26K 2.2 0.1 340M 43.6M 57925 root 0:01 2 0 R 0 0 python3 /usr/bin/glances
nvme0n1p1 0 26K 0.5 0.0 1.65G 29.0M 544 root 17:10 14 0 S 0 0 containerd
nvme0n1p14 0 0 0.5 0.0 696M 8.54M 57327 root 0:00 11 0 S 0 0 containerd-shim-runc-v2 -namespace moby -id 302
nvme0n1p15 0 0 0.2 0.1 1.74G 60.6M 789 root 10:19 15 0 S 0 0 dockerd -H fd:// --containerd=/run/containerd/c
0.2 0.0 16.8M 7.79M 18140 ubuntu 0:02 1 0 S 0 0 0
FILE SYS Used Total 0.2 0.0 0 0 45 root 1:26 1 0 S 0 0 [ksoftirqd/5]
/ (nvme0n1p1) 568G 969G 0.2 0.0 0 0 51 root 0:38 1 0 S 0 0 [ksoftirqd/6]
0.0 0.1 336M 39.6M 34822 root 0:29 1 0 S 0 0 python3 /usr/bin/glances -s -B 127.0.0.1
SENSORS 0.0 0.0 283M 26.5M 260 root 0:38 7 0 S 0 0 multipathd -d -s
Composite -273C 0.0 0.0 1.75G 23.5M 2943 root 0:22 16 0 S 0 0 snapd
0.0 0.0 108M 20.3M 639 root 0:00 2 0 S 0 0 python3 /usr/share/unattended-upgrades/unattend
0.0 0.0 32.3M 18.3M 523 root 0:00 1 0 S 0 0 python3 /usr/bin/networkd-dispatcher --run-star
0.0 0.0 54.7M 17.7M 211 root 0:01 1 -1 S 0 0 systemd-journald
0.0 0.0 289M 16.2M 1378 root 0:01 3 0 S 0 0 packagekitd
0.0 0.0 1.68G 12.8M 1021 root 0:20 15 0 S 0 0 ssm-agent-worker
0.0 0.0 24.8M 11.7M 473 systemd-r 0:01 1 0 S 0 0 systemd-resolved
0.0 0.0 164M 11.1M 1 root 0:09 1 0 S 0 0 init
0.0 0.0 16.5M 10.6M 18061 root 0:00 1 0 S 0 0 sshd: ubuntu [priv]
0.0 0.0 383M 10.5M 541 root 0:00 5 0 S 0 0 udisksd
0.0 0.0 237M 8.98M 609 root 0:00 3 0 S 0 0 ModemManager
0.0 0.0 16.6M 8.69M 11449 ubuntu 0:00 1 0 S 0 0 systemd --user
0.0 0.0 1.67G 8.60M 526 root 0:34 15 0 S 0 0 amazon-ssm-agent
0.0 0.0 231M 7.62M 524 root 0:00 3 0 S 0 0 polkitd --no-debug
0.0 0.0 15.1M 7.57M 790 root 0:00 1 0 S 0 0 sshd: /usr/sbin/sshd -D -o AuthorizedKeysComman
0.0 0.0 15.2M 6.55M 536 root 0:00 1 0 S 0 0 systemd-logind
0.0 0.0 15.9M 6.03M 471 systemd-n 0:02 1 0 S 0 0 systemd-networkd
2022-09-01 04:02:13 UTC
Edited by Gili Tzabari