erigontech
Block height consistently behind
Hi - I'm running erigon via docker-compose on an SSD (more hardware details below) and its unable to keep up.
System information
Erigon version:
erigon version 2022.04.3-alpha-f9d7cb5c
OS & Version: ubuntu 20.04 host but running erigon using the default docker-compose
Commit hash :
Currently running it against tag v2022.04.04, but I initially sync'd on a random devel commit which had a bug related to "empty block body". Switching to this tag fixed the bug at least.
Expected behaviour
Node stays fully synced
Actual behaviour
Node is consistently behind by around 2-5 blocks when checking via rpcdaemon (using geth attach).
Steps to reproduce the behaviour
XDG_DATA_HOME=/mnt/data docker-compose up -d --build
geth attach http://localhost:8545
> eth.getBlock()['number']
Backtrace
click to expand erigon logs
erigon_1 | [INFO] [05-03|03:44:39.559] Commit cycle in=34.590843424s
erigon_1 | [INFO] [05-03|03:44:39.559] RPC Daemon notified of new headers from=14702330 to=14702333 header sending=12.751µs log sending=391ns
erigon_1 | [INFO] [05-03|03:44:39.559] [1/16 Headers] Waiting for headers... from=14702333
erigon_1 | [INFO] [05-03|03:44:39.572] [1/16 Headers] Processed highest inserted=14702336 age=20s
erigon_1 | [INFO] [05-03|03:44:40.077] [6/16 Execution] Completed on block=14702336
erigon_1 | [INFO] [05-03|03:44:41.273] Timings (slower than 50ms) Bodies=188ms Senders=68ms Execution=246ms HashState=182ms IntermediateHashes=398ms CallTraces=223ms AccountHistoryIndex=219ms StorageHistoryIndex=52ms TxLookup=79ms
erigon_1 | [INFO] [05-03|03:44:41.273] Tables freelist=147.9Mb PlainState=64.9Gb AccountChangeSet=148.8Gb StorageChangeSet=216.2Gb BlockTransaction=21.2Gb TransactionLog=386.9Gb
erigon_1 | [INFO] [05-03|03:44:52.538] Commit cycle in=11.265452593s
erigon_1 | [INFO] [05-03|03:44:52.538] RPC Daemon notified of new headers from=14702333 to=14702336 header sending=12.506µs log sending=351ns
erigon_1 | [INFO] [05-03|03:44:52.538] [1/16 Headers] Waiting for headers... from=14702336
erigon_1 | [INFO] [05-03|03:44:52.543] [1/16 Headers] Processed highest inserted=14702337 age=27s
erigon_1 | [INFO] [05-03|03:44:52.664] [6/16 Execution] Completed on block=14702337
erigon_1 | [INFO] [05-03|03:44:52.935] Timings (slower than 50ms) Execution=98ms IntermediateHashes=93ms
erigon_1 | [INFO] [05-03|03:44:52.935] Tables freelist=147.9Mb PlainState=64.9Gb AccountChangeSet=148.8Gb StorageChangeSet=216.2Gb BlockTransaction=21.2Gb TransactionLog=386.9Gb
erigon_1 | [INFO] [05-03|03:45:20.100] [txpool] stat block=14702336 pending=629 baseFee=30000 queued=30000 alloc=7.5Gb sys=10.2Gb
erigon_1 | [INFO] [05-03|03:45:27.686] Commit cycle in=34.750342202s
erigon_1 | [INFO] [05-03|03:45:27.686] RPC Daemon notified of new headers from=14702336 to=14702337 header sending=10.596µs log sending=311ns
erigon_1 | [INFO] [05-03|03:45:27.686] [1/16 Headers] Waiting for headers... from=14702337
erigon_1 | [INFO] [05-03|03:45:27.698] [1/16 Headers] Processed highest inserted=14702340 age=11s
erigon_1 | [INFO] [05-03|03:45:27.890] [6/16 Execution] Completed on block=14702340
erigon_1 | [INFO] [05-03|03:45:28.360] Timings (slower than 50ms) Execution=166ms HashState=79ms IntermediateHashes=164ms CallTraces=60ms StorageHistoryIndex=57ms
erigon_1 | [INFO] [05-03|03:45:28.360] Tables freelist=147.9Mb PlainState=64.9Gb AccountChangeSet=148.8Gb StorageChangeSet=216.2Gb BlockTransaction=21.2Gb TransactionLog=386.9Gb
erigon_1 | [INFO] [05-03|03:46:02.587] Commit cycle in=34.226093168s
erigon_1 | [INFO] [05-03|03:46:02.587] RPC Daemon notified of new headers from=14702337 to=14702340 header sending=15.224µs log sending=476ns
erigon_1 | [INFO] [05-03|03:46:02.587] [1/16 Headers] Waiting for headers... from=14702340
erigon_1 | [INFO] [05-03|03:46:02.595] [1/16 Headers] Processed highest inserted=14702342 age=32s
erigon_1 | [INFO] [05-03|03:46:02.878] [6/16 Execution] Completed on block=14702342
erigon_1 | [INFO] [05-03|03:46:03.441] Timings (slower than 50ms) Execution=223ms HashState=93ms IntermediateHashes=189ms CallTraces=74ms StorageHistoryIndex=73ms LogIndex=57ms
erigon_1 | [INFO] [05-03|03:46:03.441] Tables freelist=147.9Mb PlainState=64.9Gb AccountChangeSet=148.8Gb StorageChangeSet=216.2Gb BlockTransaction=21.2Gb TransactionLog=386.9Gb
erigon_1 | [INFO] [05-03|03:46:19.645] [p2p] GoodPeers eth66=38
erigon_1 | [INFO] [05-03|03:46:19.903] Commit cycle in=16.461822553s
erigon_1 | [INFO] [05-03|03:46:19.903] RPC Daemon notified of new headers from=14702340 to=14702342 header sending=8.507µs log sending=274ns
erigon_1 | [INFO] [05-03|03:46:19.903] [1/16 Headers] Waiting for headers... from=14702342
erigon_1 | [INFO] [05-03|03:46:19.910] [1/16 Headers] Processed highest inserted=14702344 age=14s
erigon_1 | [INFO] [05-03|03:46:19.976] [6/16 Execution] Completed on block=14702344
erigon_1 | [INFO] [05-03|03:46:20.113] [txpool] stat block=14702342 pending=303 baseFee=30000 queued=29998 alloc=7.3Gb sys=10.2Gb
erigon_1 | [INFO] [05-03|03:46:20.129] Timings (slower than 50ms) Execution=51ms IntermediateHashes=58ms
erigon_1 | [INFO] [05-03|03:46:20.129] Tables freelist=147.9Mb PlainState=64.9Gb AccountChangeSet=148.8Gb StorageChangeSet=216.2Gb BlockTransaction=21.2Gb TransactionLog=386.9Gb
erigon_1 | [INFO] [05-03|03:46:20.266] Commit cycle in=136.644966ms
erigon_1 | [INFO] [05-03|03:46:20.266] RPC Daemon notified of new headers from=14702342 to=14702344 header sending=11.483µs log sending=350ns
erigon_1 | [INFO] [05-03|03:46:20.266] [1/16 Headers] Waiting for headers... from=14702344
erigon_1 | [INFO] [05-03|03:46:38.164] [1/16 Headers] Processed highest inserted=14702345 age=31s
erigon_1 | [INFO] [05-03|03:46:38.389] [6/16 Execution] Completed on block=14702345
erigon_1 | [INFO] [05-03|03:46:38.867] Timings (slower than 50ms) Headers=17.897s Execution=189ms HashState=79ms IntermediateHashes=162ms CallTraces=61ms StorageHistoryIndex=62ms
erigon_1 | [INFO] [05-03|03:46:38.867] Tables freelist=147.9Mb PlainState=64.9Gb AccountChangeSet=148.8Gb StorageChangeSet=216.2Gb BlockTransaction=21.2Gb TransactionLog=386.9Gb
erigon_1 | [INFO] [05-03|03:47:15.348] Commit cycle in=36.480363595s
erigon_1 | [INFO] [05-03|03:47:15.348] RPC Daemon notified of new headers from=14702344 to=14702345 header sending=9.577µs log sending=330ns
erigon_1 | [INFO] [05-03|03:47:15.348] [1/16 Headers] Waiting for headers... from=14702345
erigon_1 | [INFO] [05-03|03:47:15.367] [1/16 Headers] Processed highest inserted=14702350 age=4s
erigon_1 | [INFO] [05-03|03:47:15.751] [6/16 Execution] Completed on block=14702350
erigon_1 | [INFO] [05-03|03:47:16.721] Timings (slower than 50ms) Execution=344ms HashState=148ms IntermediateHashes=320ms CallTraces=140ms AccountHistoryIndex=85ms StorageHistoryIndex=133ms LogIndex=83ms TxLookup=58ms
erigon_1 | [INFO] [05-03|03:47:16.721] Tables freelist=147.9Mb PlainState=64.9Gb AccountChangeSet=148.8Gb StorageChangeSet=216.2Gb BlockTransaction=21.2Gb TransactionLog=386.9Gb
erigon_1 | [INFO] [05-03|03:47:20.100] [txpool] stat block=14702345 pending=712 baseFee=30000 queued=30000 alloc=7.6Gb sys=10.2Gb
erigon_1 | [INFO] [05-03|03:47:21.022] Commit cycle in=4.300701835s
erigon_1 | [INFO] [05-03|03:47:21.022] RPC Daemon notified of new headers from=14702345 to=14702350 header sending=14.387µs log sending=322ns
erigon_1 | [INFO] [05-03|03:47:21.022] [1/16 Headers] Waiting for headers... from=14702350
erigon_1 | [INFO] [05-03|03:47:34.532] [1/16 Headers] Processed highest inserted=14702351 age=21s
erigon_1 | [INFO] [05-03|03:47:34.784] [6/16 Execution] Completed on block=14702351
erigon_1 | [INFO] [05-03|03:47:35.146] Timings (slower than 50ms) Headers=13.509s Bodies=60ms Execution=162ms HashState=60ms IntermediateHashes=125ms
erigon_1 | [INFO] [05-03|03:47:35.146] Tables freelist=147.9Mb PlainState=64.9Gb AccountChangeSet=148.8Gb StorageChangeSet=216.2Gb BlockTransaction=21.2Gb TransactionLog=386.9Gb
erigon_1 | [INFO] [05-03|03:48:03.406] Commit cycle in=28.260031496s
erigon_1 | [INFO] [05-03|03:48:03.406] RPC Daemon notified of new headers from=14702350 to=14702351 header sending=8.105µs log sending=460ns
erigon_1 | [INFO] [05-03|03:48:03.407] [1/16 Headers] Waiting for headers... from=14702351
erigon_1 | [INFO] [05-03|03:48:03.410] [1/16 Headers] Processed highest inserted=14702352 age=29s
erigon_1 | [INFO] [05-03|03:48:03.511] [6/16 Execution] Completed on block=14702352
erigon_1 | [INFO] [05-03|03:48:03.691] Timings (slower than 50ms) Execution=79ms IntermediateHashes=63ms
erigon_1 | [INFO] [05-03|03:48:03.691] Tables freelist=147.9Mb PlainState=64.9Gb AccountChangeSet=148.8Gb StorageChangeSet=216.2Gb BlockTransaction=21.2Gb TransactionLog=386.9Gb
erigon_1 | [INFO] [05-03|03:48:19.645] [p2p] GoodPeers eth66=38
erigon_1 | [INFO] [05-03|03:48:32.853] [txpool] stat block=14702351 pending=600 baseFee=30000 queued=30000 alloc=7.3Gb sys=10.2Gb
click to see hardware details
erigon@Ubuntu-2004-focal-64-minimal-hwe:~$ free -mh
total used free shared buff/cache available
Mem: 125Gi 17Gi 77Gi 2.0Mi 30Gi 106Gi
Swap: 4.0Gi 0B 4.0Gi
erigon@Ubuntu-2004-focal-64-minimal-hwe:~$ lspci | grep Eth
04:00.0 Ethernet controller: Intel Corporation I210 Gigabit Network Connection (rev 03)
erigon@Ubuntu-2004-focal-64-minimal-hwe:~$ lscpu | grep "Model name:"
Model name: Intel(R) Xeon(R) CPU E5-1650 v3 @ 3.50GHz
XDG_DATA_HOME=/mnt/data
erigon@Ubuntu-2004-focal-64-minimal-hwe:~$ df -h
Filesystem Size Used Avail Use% Mounted on
udev 63G 0 63G 0% /dev
tmpfs 13G 2.1M 13G 1% /run
/dev/sdb3 215G 30G 174G 15% /
tmpfs 63G 0 63G 0% /dev/shm
tmpfs 5.0M 0 5.0M 0% /run/lock
tmpfs 63G 0 63G 0% /sys/fs/cgroup
/dev/sdb2 975M 90M 835M 10% /boot
/dev/sda 220G 61M 208G 1% /mnt/cache
/dev/sdc 3.5T 1.5T 1.9T 45% /mnt/data
tmpfs 13G 0 13G 0% /run/user/1000
sudo lshw -class volume
*-disk
description: EXT4 volume
product: SAMSUNG MZ7LH3T8
vendor: Linux
physical id: 0.0.0
bus info: scsi@2:0.0.0
logical name: /dev/sdc
logical name: /mnt/data
version: 1.0
serial: dad67300-2e7f-443b-99ad-9d9c4e5f4efb
size: 3576GiB
capabilities: journaled extended_attributes large_files huge_files dir_nlink recover 64bit extents ext4 ext2 initialized
click for prometheus output
erigon@Ubuntu-2004-focal-64-minimal-hwe:~/erigon$ curl http://localhost:6060/debug/metrics/prometheus cache_total{target="acc_read"} 0 cache_total{target="st_read"} 0 cache_total{target="write"} 0 chain_execution_seconds_sum 182.7791414250004 chain_execution_seconds_count 1866 chain_execution_seconds{quantile="0.5"} 0.079410341 chain_execution_seconds{quantile="0.9"} 0.100188507 chain_execution_seconds{quantile="0.97"} 0.146238035 chain_execution_seconds{quantile="0.99"} 0.146238035 chain_execution_seconds{quantile="1"} 0.146238035 db_commit_seconds{phase="audit",quantile="0.5"} 0 db_commit_seconds{phase="audit",quantile="0.9"} 0 db_commit_seconds{phase="audit",quantile="0.97"} 0 db_commit_seconds{phase="audit",quantile="0.99"} 0 db_commit_seconds{phase="audit",quantile="1"} 0 db_commit_seconds_sum{phase="audit"} 0 db_commit_seconds_count{phase="audit"} 742 db_commit_seconds{phase="ending",quantile="0.5"} 0.009902442 db_commit_seconds{phase="ending",quantile="0.9"} 0.010894212 db_commit_seconds{phase="ending",quantile="0.97"} 0.011321436 db_commit_seconds{phase="ending",quantile="0.99"} 0.011321436 db_commit_seconds{phase="ending",quantile="1"} 0.011321436 db_commit_seconds_sum{phase="ending"} 6.239240328000002 db_commit_seconds_count{phase="ending"} 742 db_commit_seconds{phase="gc",quantile="0.5"} 33.458779944 db_commit_seconds{phase="gc",quantile="0.9"} 34.261442292 db_commit_seconds{phase="gc",quantile="0.97"} 34.801956942 db_commit_seconds{phase="gc",quantile="0.99"} 34.801956942 db_commit_seconds{phase="gc",quantile="1"} 34.801956942 db_commit_seconds_sum{phase="gc"} 20691.53674018199 db_commit_seconds_count{phase="gc"} 742 db_commit_seconds{phase="preparation",quantile="0.5"} 1.5258e-05 db_commit_seconds{phase="preparation",quantile="0.9"} 1.5258e-05 db_commit_seconds{phase="preparation",quantile="0.97"} 1.5258e-05 db_commit_seconds{phase="preparation",quantile="0.99"} 1.5258e-05 db_commit_seconds{phase="preparation",quantile="1"} 1.5258e-05 db_commit_seconds_sum{phase="preparation"} 0.011412984000000114 db_commit_seconds_count{phase="preparation"} 742 db_commit_seconds{phase="sync",quantile="0.5"} 0.611067642 db_commit_seconds{phase="sync",quantile="0.9"} 0.78487152 db_commit_seconds{phase="sync",quantile="0.97"} 0.857438568 db_commit_seconds{phase="sync",quantile="0.99"} 0.857438568 db_commit_seconds{phase="sync",quantile="1"} 0.857438568 db_commit_seconds_sum{phase="sync"} 453.98084076600003 db_commit_seconds_count{phase="sync"} 742 db_commit_seconds{phase="total",quantile="0.5"} 34.518692172 db_commit_seconds{phase="total",quantile="0.9"} 35.05197453 db_commit_seconds{phase="total",quantile="0.97"} 35.552391156 db_commit_seconds{phase="total",quantile="0.99"} 35.552391156 db_commit_seconds{phase="total",quantile="1"} 35.552391156 db_commit_seconds_sum{phase="total"} 21315.520447020004 db_commit_seconds_count{phase="total"} 742 db_commit_seconds{phase="write",quantile="0.5"} 0.205403196 db_commit_seconds{phase="write",quantile="0.9"} 0.291061608 db_commit_seconds{phase="write",quantile="0.97"} 0.298888962 db_commit_seconds{phase="write",quantile="0.99"} 0.298888962 db_commit_seconds{phase="write",quantile="1"} 0.298888962 db_commit_seconds_sum{phase="write"} 163.73463554399996 db_commit_seconds_count{phase="write"} 742 db_gc_leaf 2 db_gc_overflow 37852 db_gc_pages 19381248 db_pgops_clone 0 db_pgops_cow 16466621 db_pgops_merge 72488 db_pgops_newly 46348471 db_pgops_spill 0 db_pgops_split 342702 db_pgops_unspill 0 db_pgops_wops 16985919 db_size 1363652116480 p2p_dials 9062 p2p_egress 1596599855 p2p_ingress 2157143936 p2p_ingress_eth_66_0x00 91 p2p_ingress_eth_66_0x00_packets 1 p2p_ingress_eth_66_0x01 41 p2p_ingress_eth_66_0x01_packets 1 p2p_ingress_eth_66_0x02 1890 p2p_ingress_eth_66_0x02_packets 1 p2p_ingress_eth_66_0x03 20 p2p_ingress_eth_66_0x03_packets 1 p2p_ingress_eth_66_0x04 562 p2p_ingress_eth_66_0x04_packets 1 p2p_ingress_eth_66_0x05 82 p2p_ingress_eth_66_0x05_packets 1 p2p_ingress_eth_66_0x06 60698 p2p_ingress_eth_66_0x06_packets 1 p2p_ingress_eth_66_0x07 41915 p2p_ingress_eth_66_0x07_packets 1 p2p_ingress_eth_66_0x08 36 p2p_ingress_eth_66_0x08_packets 1 p2p_ingress_eth_66_0x09 38 p2p_ingress_eth_66_0x09_packets 1 p2p_ingress_eth_66_0x0a 128 p2p_ingress_eth_66_0x0a_packets 1 p2p_ingress_eth_66_0x0d 12692 p2p_ingress_eth_66_0x0d_packets 1 p2p_ingress_eth_66_0x0f 149 p2p_ingress_eth_66_0x0f_packets 1 p2p_peers 40 p2p_serves 7593 pool_add_remote_txs_sum 96.61554769596434 pool_add_remote_txs_count 1185672 pool_add_remote_txs{quantile="0.5"} 1.071e-06 pool_add_remote_txs{quantile="0.9"} 1.343e-06 pool_add_remote_txs{quantile="0.97"} 1.547e-06 pool_add_remote_txs{quantile="0.99"} 1.804e-06 pool_add_remote_txs{quantile="1"} 0.002924232 pool_new_block_sum 608.0018507519999 pool_new_block_count 713 pool_new_block{quantile="0.5"} 0.007320334 pool_new_block{quantile="0.9"} 0.009352533 pool_new_block{quantile="0.97"} 3.048271083 pool_new_block{quantile="0.99"} 3.048271083 pool_new_block{quantile="1"} 3.048271083 pool_process_remote_txs_sum 355.527541667003 pool_process_remote_txs_count 221440 pool_process_remote_txs{quantile="0.5"} 0.000376663 pool_process_remote_txs{quantile="0.9"} 0.000654932 pool_process_remote_txs{quantile="0.97"} 0.000879913 pool_process_remote_txs{quantile="0.99"} 0.001342035 pool_process_remote_txs{quantile="1"} 0.0444353 pool_propagate_new_txs_sum 489.3841055019967 pool_propagate_new_txs_count 188605 pool_propagate_new_txs{quantile="0.5"} 0.000134049 pool_propagate_new_txs{quantile="0.9"} 0.000252645 pool_propagate_new_txs{quantile="0.97"} 0.000293487 pool_propagate_new_txs{quantile="0.99"} 0.000318199 pool_propagate_new_txs{quantile="1"} 0.000675923 pool_propagate_to_new_peer_sum 2.5061327979999994 pool_propagate_to_new_peer_count 198 pool_propagate_to_new_peer{quantile="0.5"} 0.014194984 pool_propagate_to_new_peer{quantile="0.9"} 0.014194984 pool_propagate_to_new_peer{quantile="0.97"} 0.014194984 pool_propagate_to_new_peer{quantile="0.99"} 0.014194984 pool_propagate_to_new_peer{quantile="1"} 0.014194984 pool_write_to_db_sum 1154.668464437 pool_write_to_db_count 78 pool_write_to_db_bytes 9830400 pool_write_to_db{quantile="0.5"} 19.149088595 pool_write_to_db{quantile="0.9"} 19.149088595 pool_write_to_db{quantile="0.97"} 19.149088595 pool_write_to_db{quantile="0.99"} 19.149088595 pool_write_to_db{quantile="1"} 19.149088595 rpc_failure 0 rpc_total 0 sync{stage="execution"} 14702431 sync{stage="finish"} 14702431 sync{stage="headers"} 14702431 table_log_branch 409721 table_log_entries 826797177 table_log_leaf 74977600 table_log_overflow 26048518 table_log_size 415481196544 table_scs_branch 2733194 table_scs_entries 3098009766 table_scs_leaf 53937393 table_scs_size 232122724352 table_state_branch 395400 table_state_entries 864540242 table_state_leaf 16625720 table_state_size 69718507520 table_tx_branch 10482 table_tx_entries 35516714 table_tx_leaf 2346882 table_tx_overflow 3205405 table_tx_size 22785101824 tx_dirty 90038272 tx_limit 12796076032 tx_spill 0 tx_unspill 0 go_memstats_alloc_bytes 7905975784 go_memstats_alloc_bytes_total 120739957512 go_memstats_buck_hash_sys_bytes 15851622 go_memstats_frees_total 1073566424 go_memstats_gc_cpu_fraction 0.0010513280195699824 go_memstats_gc_sys_bytes 369680872 go_memstats_heap_alloc_bytes 7905975784 go_memstats_heap_idle_bytes 2430435328 go_memstats_heap_inuse_bytes 8033435648 go_memstats_heap_objects 8688101 go_memstats_heap_released_bytes 1528070144 go_memstats_heap_sys_bytes 10463870976 go_memstats_last_gc_time_seconds 1.6515507844978364e+09 go_memstats_lookups_total 0 go_memstats_mallocs_total 1082254525 go_memstats_mcache_inuse_bytes 14400 go_memstats_mcache_sys_bytes 15600 go_memstats_mspan_inuse_bytes 68976072 go_memstats_mspan_sys_bytes 77813760 go_memstats_next_gc_bytes 15578464896 go_memstats_other_sys_bytes 9962986 go_memstats_stack_inuse_bytes 17694720 go_memstats_stack_sys_bytes 17694720 go_memstats_sys_bytes 10954890536 go_cgo_calls_count 101381937 go_cpu_count 12 go_gc_duration_seconds{quantile="0"} 0 go_gc_duration_seconds{quantile="0.25"} 0.000102082 go_gc_duration_seconds{quantile="0.5"} 0.000116252 go_gc_duration_seconds{quantile="0.75"} 0.000134889 go_gc_duration_seconds{quantile="1"} 0.000345909 go_gc_duration_seconds_sum 0.029277436 go_gc_duration_seconds_count 221 go_gc_forced_count 0 go_gomaxprocs 12 go_goroutines 5441 go_threads 23 go_info{version="go1.18.1"} 1 go_info_ext{compiler="gc", GOARCH="amd64", GOOS="linux", GOROOT="go"} 1 process_cpu_seconds_system_total 1969.09 process_cpu_seconds_total 28437.27 process_cpu_seconds_user_total 26468.18 process_major_pagefaults_total 5069386 process_minor_pagefaults_total 83297656 process_num_threads 22 process_resident_memory_bytes 39554822144 process_start_time_seconds 1651526899 process_virtual_memory_bytes 10150776324096 process_virtual_memory_peak_bytes 10151063805952 process_resident_memory_peak_bytes 39734996992 process_resident_memory_anon_bytes 9708412928 process_resident_memory_file_bytes 29846409216 process_resident_memory_shared_bytes 0 process_io_read_bytes_total 2178511137 process_io_written_bytes_total 179455110615 process_io_read_syscalls_total 18246729 process_io_write_syscalls_total 24092449 process_io_storage_read_bytes_total 20764708864 process_io_storage_written_bytes_total 177539088384
After reading through historical issues, I tried running mdbx_stat. it's either hanging or takes a really long time? (it's been going for hours)
erigon@Ubuntu-2004-focal-64-minimal-hwe:~/erigon$ sudo ./build/bin/mdbx_stat -ef /mnt/data/erigon/chaindata
[sudo] password for erigon:
mdbx_stat v0.11.6-4-ga6b506be (2022-03-25T13:54:34+03:00, T-48c2c9f4cfff32e32d043427a7c46b342ddf988f)
Running for /mnt/data/erigon/chaindata...
Any help would be greatly appreciated, thanks!
[INFO] [05-03|06:59:14.389] RPC Daemon notified of new headers from=14703182 to=14703187 header sending=17.796µs log sending=394ns
[INFO] [05-03|06:59:14.389] [1/16 Headers] Waiting for headers... from=14703187
[INFO] [05-03|06:59:20.097] [1/16 Headers] Processed highest inserted=14703188 age=17s
[INFO] [05-03|06:59:20.320] [6/16 Execution] Completed on block=14703188
[INFO] [05-03|06:59:20.722] Timings (slower than 50ms) Headers=5.708s Execution=143ms HashState=71ms IntermediateHashes=142ms StorageHistoryIndex=61ms
[INFO] [05-03|06:59:20.722] Tables freelist=147.4Mb PlainState=64.9Gb AccountChangeSet=148.9Gb StorageChangeSet=216.2Gb BlockTransaction=21.3Gb TransactionLog=387.0Gb
[INFO] [05-03|06:59:42.755] Commit cycle in=22.033207657s
[INFO] [05-03|06:59:42.755] RPC Daemon notified of new headers from=14703187 to=14703188 header sending=17.114µs log sending=798ns
[INFO] [05-03|06:59:42.755] [1/16 Headers] Waiting for headers... from=14703188
[INFO] [05-03|06:59:42.768] [1/16 Headers] Processed highest inserted=14703191 age=12s
[INFO] [05-03|06:59:47.245] [6/16 Execution] Completed on block=14703191
[INFO] [05-03|06:59:47.566] Timings (slower than 50ms) Bodies=4.26s Execution=199ms HashState=56ms IntermediateHashes=107ms StorageHistoryIndex=62ms
[INFO] [05-03|06:59:47.566] Tables freelist=147.4Mb PlainState=64.9Gb AccountChangeSet=148.9Gb StorageChangeSet=216.2Gb BlockTransaction=21.3Gb TransactionLog=387.0Gb
[INFO] [05-03|06:59:56.692] [txpool] stat block=14703188 pending=709 baseFee=30000 queued=30000 alloc=6.9Gb sys=10.1Gb
[INFO] [05-03|07:00:20.367] Commit cycle in=32.801061581s
[INFO] [05-03|07:00:20.367] RPC Daemon notified of new headers from=14703188 to=14703191 header sending=9.605µs log sending=270ns
[INFO] [05-03|07:00:20.367] [1/16 Headers] Waiting for headers... from=14703191
[INFO] [05-03|07:00:20.379] [1/16 Headers] Processed highest inserted=14703194 age=33s
[INFO] [05-03|07:00:20.681] [6/16 Execution] Completed on block=14703194
[INFO] [05-03|07:00:21.390] Timings (slower than 50ms) Execution=269ms HashState=120ms IntermediateHashes=241ms CallTraces=80ms AccountHistoryIndex=51ms StorageHistoryIndex=113ms LogIndex=73ms
[INFO] [05-03|07:00:21.390] Tables freelist=147.4Mb PlainState=64.9Gb AccountChangeSet=148.9Gb StorageChangeSet=216.2Gb BlockTransaction=21.3Gb TransactionLog=387.0Gb
[INFO] [05-03|07:00:55.478] Commit cycle in=34.088086606s
[INFO] [05-03|07:00:55.478] RPC Daemon notified of new headers from=14703191 to=14703194 header sending=11.451µs log sending=346ns
[INFO] [05-03|07:00:55.478] [1/16 Headers] Waiting for headers... from=14703194
[INFO] [05-03|07:00:55.498] [1/16 Headers] Processed highest inserted=14703199 age=10s
[INFO] [05-03|07:00:55.829] [6/16 Execution] Completed on block=14703199
[INFO] [05-03|07:00:56.170] [p2p] GoodPeers eth66=26
[INFO] [05-03|07:00:56.538] Timings (slower than 50ms) Execution=292ms HashState=116ms IntermediateHashes=233ms CallTraces=98ms AccountHistoryIndex=56ms StorageHistoryIndex=105ms LogIndex=69ms
[INFO] [05-03|07:00:56.538] Tables freelist=147.4Mb PlainState=64.9Gb AccountChangeSet=148.9Gb StorageChangeSet=216.2Gb BlockTransaction=21.3Gb TransactionLog=387.0Gb
[INFO] [05-03|07:00:56.702] [txpool] stat block=14703194 pending=979 baseFee=30000 queued=29993 alloc=7.2Gb sys=10.1Gb
[INFO] [05-03|07:01:30.581] Commit cycle in=34.042788546s
[INFO] [05-03|07:01:30.581] RPC Daemon notified of new headers from=14703194 to=14703199 header sending=15.222µs log sending=381ns
[INFO] [05-03|07:01:30.582] [1/16 Headers] Waiting for headers... from=14703199
[INFO] [05-03|07:01:30.594] [1/16 Headers] Processed highest inserted=14703202 age=19s
[INFO] [05-03|07:01:31.050] [6/16 Execution] Completed on block=14703202
[INFO] [05-03|07:01:32.267] Timings (slower than 50ms) Execution=424ms HashState=192ms IntermediateHashes=431ms CallTraces=153ms AccountHistoryIndex=105ms StorageHistoryIndex=193ms LogIndex=99ms
[INFO] [05-03|07:01:32.267] Tables freelist=147.4Mb PlainState=64.9Gb AccountChangeSet=148.9Gb StorageChangeSet=216.2Gb BlockTransaction=21.3Gb TransactionLog=387.0Gb
[INFO] [05-03|07:01:56.692] [txpool] stat block=14703199 pending=1145 baseFee=30000 queued=30000 alloc=6.9Gb sys=10.1Gb
[INFO] [05-03|07:02:06.737] Commit cycle in=34.469093939s
[INFO] [05-03|07:02:06.737] RPC Daemon notified of new headers from=14703199 to=14703202 header sending=10.275µs log sending=355ns
[INFO] [05-03|07:02:06.737] [1/16 Headers] Waiting for headers... from=14703202
[INFO] [05-03|07:02:06.756] [1/16 Headers] Processed highest inserted=14703207 age=1s
[INFO] [05-03|07:02:07.238] [6/16 Execution] Completed on block=14703207
[INFO] [05-03|07:02:07.956] Timings (slower than 50ms) Bodies=182ms Execution=271ms HashState=121ms IntermediateHashes=228ms CallTraces=72ms AccountHistoryIndex=63ms StorageHistoryIndex=127ms LogIndex=76ms
[INFO] [05-03|07:02:07.956] Tables freelist=147.4Mb PlainState=64.9Gb AccountChangeSet=148.9Gb StorageChangeSet=216.2Gb BlockTransaction=21.3Gb TransactionLog=387.0Gb
[INFO] [05-03|07:02:41.838] Commit cycle in=33.881767132s
[INFO] [05-03|07:02:41.838] RPC Daemon notified of new headers from=14703202 to=14703207 header sending=13.808µs log sending=348ns
[INFO] [05-03|07:02:41.839] [1/16 Headers] Waiting for headers... from=14703207
[INFO] [05-03|07:02:41.843] [1/16 Headers] Processed highest inserted=14703208 age=35s
[INFO] [05-03|07:02:42.047] [6/16 Execution] Completed on block=14703208
[INFO] [05-03|07:02:42.528] Timings (slower than 50ms) Execution=170ms HashState=77ms IntermediateHashes=167ms CallTraces=56ms StorageHistoryIndex=69ms LogIndex=50ms
[INFO] [05-03|07:02:42.528] Tables freelist=147.4Mb PlainState=64.9Gb AccountChangeSet=148.9Gb StorageChangeSet=216.2Gb BlockTransaction=21.3Gb TransactionLog=387.0Gb
[INFO] [05-03|07:02:56.170] [p2p] GoodPeers eth66=24
[INFO] [05-03|07:02:57.543] [txpool] stat block=14703207 pending=943 baseFee=30000 queued=30000 alloc=7.1Gb sys=10.1Gb
[INFO] [05-03|07:03:16.516] Commit cycle in=33.987348461s
[INFO] [05-03|07:03:16.516] RPC Daemon notified of new headers from=14703207 to=14703208 header sending=17.092µs log sending=506ns
[INFO] [05-03|07:03:16.516] [1/16 Headers] Waiting for headers... from=14703208
[INFO] [05-03|07:03:16.530] [1/16 Headers] Processed highest inserted=14703210 age=24s
[INFO] [05-03|07:03:16.951] [6/16 Execution] Completed on block=14703210
[INFO] [05-03|07:03:17.588] Timings (slower than 50ms) Execution=373ms HashState=98ms IntermediateHashes=220ms CallTraces=85ms AccountHistoryIndex=64ms StorageHistoryIndex=85ms LogIndex=52ms
[INFO] [05-03|07:03:17.588] Tables freelist=147.4Mb PlainState=64.9Gb AccountChangeSet=148.9Gb StorageChangeSet=216.2Gb BlockTransaction=21.3Gb TransactionLog=387.0Gb
[INFO] [05-03|07:03:27.582] Commit cycle in=9.99355529s
[INFO] [05-03|07:03:27.582] RPC Daemon notified of new headers from=14703208 to=14703210 header sending=14.194µs log sending=389ns
[INFO] [05-03|07:03:27.582] [1/16 Headers] Waiting for headers... from=14703210
[INFO] [05-03|07:03:27.587] [1/16 Headers] Processed highest inserted=14703211 age=23s
[INFO] [05-03|07:03:27.797] [6/16 Execution] Completed on block=14703211
[INFO] [05-03|07:03:28.225] Timings (slower than 50ms) Execution=180ms HashState=75ms IntermediateHashes=151ms StorageHistoryIndex=67ms
[INFO] [05-03|07:03:28.225] Tables freelist=147.4Mb PlainState=64.9Gb AccountChangeSet=148.9Gb StorageChangeSet=216.2Gb BlockTransaction=21.3Gb TransactionLog=387.0Gb
[INFO] [05-03|07:03:56.692] [txpool] stat block=14703210 pending=980 baseFee=30000 queued=30000 alloc=6.9Gb sys=10.1Gb
[INFO] [05-03|07:04:02.731] Commit cycle in=34.505762563s
[INFO] [05-03|07:04:02.731] RPC Daemon notified of new headers from=14703210 to=14703211 header sending=14.145µs log sending=496ns
[INFO] [05-03|07:04:02.731] [1/16 Headers] Waiting for headers... from=14703211
[INFO] [05-03|07:04:02.736] [1/16 Headers] Processed highest inserted=14703212 age=39s
[INFO] [05-03|07:04:02.925] [6/16 Execution] Completed on block=14703212
[INFO] [05-03|07:04:03.353] Timings (slower than 50ms) Execution=157ms HashState=62ms IntermediateHashes=146ms CallTraces=50ms StorageHistoryIndex=65ms
[INFO] [05-03|07:04:03.353] Tables freelist=147.4Mb PlainState=64.9Gb AccountChangeSet=148.9Gb StorageChangeSet=216.2Gb BlockTransaction=21.3Gb TransactionLog=387.0Gb
[INFO] [05-03|07:04:37.196] Commit cycle in=33.843631406s
[INFO] [05-03|07:04:37.197] RPC Daemon notified of new headers from=14703211 to=14703212 header sending=9.677µs log sending=373ns
[INFO] [05-03|07:04:37.197] [1/16 Headers] Waiting for headers... from=14703212
[INFO] [05-03|07:04:37.209] [1/16 Headers] Processed highest inserted=14703215 age=9s
[INFO] [05-03|07:04:37.412] [6/16 Execution] Completed on block=14703215
[INFO] [05-03|07:04:37.885] Timings (slower than 50ms) Execution=171ms HashState=82ms IntermediateHashes=160ms CallTraces=55ms StorageHistoryIndex=68ms
[INFO] [05-03|07:04:37.885] Tables freelist=147.4Mb PlainState=64.9Gb AccountChangeSet=148.9Gb StorageChangeSet=216.2Gb BlockTransaction=21.3Gb TransactionLog=387.0Gb
[INFO] [05-03|07:04:51.277] Commit cycle in=13.392450755s
[INFO] [05-03|07:04:51.278] RPC Daemon notified of new headers from=14703212 to=14703215 header sending=13.144µs log sending=393ns
[INFO] [05-03|07:04:51.278] [1/16 Headers] Waiting for headers... from=14703215
[INFO] [05-03|07:04:51.282] [1/16 Headers] Processed highest inserted=14703216 age=18s
[INFO] [05-03|07:04:51.367] [6/16 Execution] Completed on block=14703216
[INFO] [05-03|07:04:51.513] Timings (slower than 50ms) Execution=69ms IntermediateHashes=50ms
[INFO] [05-03|07:04:51.513] Tables freelist=147.4Mb PlainState=64.9Gb AccountChangeSet=148.9Gb StorageChangeSet=216.2Gb BlockTransaction=21.3Gb TransactionLog=387.0Gb
[INFO] [05-03|07:04:51.674] Commit cycle in=160.995375ms
[INFO] [05-03|07:04:51.674] RPC Daemon notified of new headers from=14703215 to=14703216 header sending=13.64µs log sending=425ns
[INFO] [05-03|07:04:51.674] [1/16 Headers] Waiting for headers... from=14703216
[INFO] [05-03|07:04:56.170] [p2p] GoodPeers eth66=25
[INFO] [05-03|07:04:56.705] [txpool] stat block=14703216 pending=477 baseFee=30000 queued=30000 alloc=7.1Gb sys=10.1Gb
[INFO] [05-03|07:04:57.730] [1/16 Headers] Processed highest inserted=14703217 age=16s
[INFO] [05-03|07:04:57.872] [6/16 Execution] Completed on block=14703217
[INFO] [05-03|07:04:58.126] Timings (slower than 50ms) Headers=6.056s Execution=118ms IntermediateHashes=91ms
[INFO] [05-03|07:04:58.126] Tables freelist=147.4Mb PlainState=64.9Gb AccountChangeSet=148.9Gb StorageChangeSet=216.2Gb BlockTransaction=21.3Gb TransactionLog=387.0Gb
mdbx_stat v0.11.6-4-ga6b506be (2022-03-25T13:54:34+03:00, T-48c2c9f4cfff32e32d043427a7c46b342ddf988f)
Running for /mnt/data/erigon/chaindata...
Environment Info
Pagesize: 4096
Dynamic datafile: 12288..6597069766656 bytes (+2147483648/-4294967296), 3..1610612736 pages (+524288/-1048576)
Current mapsize: 6597069766656 bytes, 1610612736 pages
Current datafile: 1363652116480 bytes, 332922880 pages
Last transaction ID: 3247
Latter reader transaction ID: 3247 (0)
Max readers: 118
Number of reader slots uses: 1
Garbage Collection
Pagesize: 4096
Tree depth: 2
Branch pages: 1
Leaf pages: 2
Overflow pages: 37723
Entries: 293
Page Usage
Total: 1610612736 100%
Backed: 332922880 20.7%
Allocated: 332444625 20.6%
Remained: 1278168111 79.4%
Used: 293823623 18.2%
GC: 38621002 2.4%
Retained: 58190 0.0%
Reclaimable: 38562812 2.4%
Available: 1316730923 81.8%
Status of Main DB
Pagesize: 4096
Tree depth: 1
Branch pages: 0
Leaf pages: 1
Overflow pages: 0
Entries: 55
GC: 38621002 2.4% = 150Gb - quite big number - probably it causing Commit cycle in=33.843631406s
It will get better in 1-3 days.
Why it happend:
- May be related to stucked mdbx_stat (usually don't need to stop Erigon). So, why it stuck...
- What are your Erigon's cli flags?
- Do you do any hand-crafted scripts to read DB? Or to periodically big db checks? Or high read load? (on json-rpc or on grpc).
May be related to stucked mdbx_stat (usually don't need to stop Erigon). So, why it stuck...
I just started erigon again, and tried mdbx. It still hangs when erigon is running. Could it be some permission issue between my UID and whatever UID docker is using to access the XDG_DATA_HOME directory?
What are your Erigon's cli flags?
I'm just using the default docker-compose file which has this:
command: erigon ${ERIGON_FLAGS-} --datadir=/home/erigon/.local/share/erigon --private.api.addr=0.0.0.0:9090 --dow
nloader.api.addr=downloader:9093 --metrics --metrics.addr=0.0.0.0 --metrics.port=6060 --pprof --pprof.addr=0.0.0.0 --
pprof.port=6061
Do you do any hand-crafted scripts to read DB? Or to periodically big db checks?
Not anymore. I directed a one off script at it for a few minutes, which is how I noticed that the sync was behind. Nothing is hitting it now, except when i use geth attach to check the block number. Could prometheus/grafana could be causing issues?
Or high read load? (on json-rpc or on grpc).
I'm sorry, not really sure what you're asking here?
Prometheus/Grafana - no
Geth attach - i don’t remember how it works under the hood - probably websocket subscription - then also must be not a reason
Your custom script - how it works?
OS is ubuntu 20.04, and im running mdbx_stat outside the container
Custom script that I ran was mainly to test the node's RPC daemon. It just pulls balances/state from various contracts. Nothing intense, maybe 20-30 RPC requests from the head of the chain, and I ran it a few times by hand. Nothing is automated yet, so nothing is hitting the rpc server right now, except for whatever happens in the docker-compose file.
Eventually I plan on doing more intensive RPC queries, but I can't until the block height catches up.
Have been watching the commit cycles, but I don't think it's really improved much.. maybe a few more in ms, but still a bunch are 30+ seconds:
erigon@Ubuntu-2004-focal-64-minimal-hwe:~/erigon$ docker logs -f -n 100 erigon_erigon_1 2>&1 | grep "in="
[INFO] [05-04|03:07:33.961] Commit cycle in=21.006432055s
[INFO] [05-04|03:08:09.567] Commit cycle in=35.168169437s
[INFO] [05-04|03:08:25.799] Commit cycle in=15.387039377s
[INFO] [05-04|03:09:00.137] Commit cycle in=33.854958038s
[INFO] [05-04|03:09:09.125] Commit cycle in=7.804620236s
[INFO] [05-04|03:09:09.356] Commit cycle in=83.060341ms
[INFO] [05-04|03:09:10.265] Commit cycle in=163.58967ms
[INFO] [05-04|03:09:17.182] Commit cycle in=173.479352ms
[INFO] [05-04|03:09:22.343] Commit cycle in=88.531712ms
[INFO] [05-04|03:10:42.390] Commit cycle in=31.979935935s
[INFO] [05-04|03:10:45.663] Commit cycle in=2.85372495s
[INFO] [05-04|03:11:18.833] Commit cycle in=30.636462164s
[INFO] [05-04|03:11:58.720] Commit cycle in=9.653238221s
[INFO] [05-04|03:12:33.843] Commit cycle in=32.222493179s
[INFO] [05-04|03:12:41.308] Commit cycle in=7.031926314s
[INFO] [05-04|03:13:20.430] Commit cycle in=31.764387134s
[INFO] [05-04|03:13:54.462] Commit cycle in=33.560091576s
[INFO] [05-04|03:14:30.271] Commit cycle in=34.588915253s
[INFO] [05-04|03:15:05.351] Commit cycle in=33.944777583s
Thanks for your help so far, hopefully in a day or two it can catch up!
Check that GC: 38621002 2.4% section of mdb_stat reducing with time. If yes - then it will get better and better.
But you have no obvious reasons - why it did grow in the beginning. It happening in 2 cases:
- if some "long-living read DB transaction" open for hours
- if big amount of data were deleted (it happening only with --prune flag)
I haven't checked lately because I have to stop erigon each time, but I did confirm it's reducing earlier today. It was at 2.3%
Does stopping/starting the erigon service slow the GC progress?
@godsflaw It's -very slowly- getting better, but 2 weeks later its still sometimes up to 8 seconds behind. GC is now at ~1.5%.
Also not sure if it's related, but im running into similar issues with the rpc daemon as @zzh1996 describes in this issue: https://github.com/ledgerwatch/erigon/issues/2245
@AskAlexSharov Do you think the GC % being high could have an effect on the rpcdaemon performance? A script hitting it with 20-30 requests every 10 seconds seesm to be too much for it to handle and I start getting timeouts. I have --datadir set on the rpcdaemon, running the stock docker-compose file. The script is pretty simple, just reading the current state from a few contracts.
- It must not affect rpcdaemon
- what method you get timeout?
- 10K rps is fine
I created branch: mdbx_gc_test (based on latest devel) - please try and say if it preventing 8 seconds spikes of Commit cycle for you.
@AskAlexSharov Yesterday I restarted the server to test some firewall changes. After revisiting it today, everything seems to have resolved itself after the reboot. Haven't seen any spikes latetly. I think we can probably close this issue for now, will reopen and try your branch if it happens again.
The RPC timeouts were caused by intermittent network issues at my provider, which could possibly explain my syncing delays as well.
[INFO] [05-18|21:12:18.754] Commit cycle in=187.603576ms
[INFO] [05-18|21:12:26.435] Commit cycle in=155.145604ms
[INFO] [05-18|21:12:33.236] Commit cycle in=125.892575ms
[INFO] [05-18|21:12:54.383] Commit cycle in=126.129471ms
[INFO] [05-18|21:13:01.327] Commit cycle in=275.427798ms
[INFO] [05-18|21:13:04.343] Commit cycle in=62.737928ms
[INFO] [05-18|21:13:11.544] Commit cycle in=217.527634ms
[INFO] [05-18|21:13:26.167] Commit cycle in=333.619102ms
[INFO] [05-18|21:13:35.067] Commit cycle in=34.053266ms
[INFO] [05-18|21:13:36.894] Commit cycle in=129.781485ms
[INFO] [05-18|21:14:04.186] Commit cycle in=395.193345ms
[INFO] [05-18|21:14:09.720] Commit cycle in=212.536368ms
[INFO] [05-18|21:14:18.272] Commit cycle in=156.311684ms
[INFO] [05-18|21:14:31.626] Commit cycle in=229.989084ms
[INFO] [05-18|21:14:31.857] Commit cycle in=80.791098ms
[INFO] [05-18|21:14:38.902] Commit cycle in=166.494222ms
[INFO] [05-18|21:14:39.117] Commit cycle in=2.14769ms
[INFO] [05-18|21:14:52.254] Commit cycle in=244.251475ms
[INFO] [05-18|21:15:12.579] Commit cycle in=491.579964ms
[INFO] [05-18|21:15:20.393] Commit cycle in=616.359815ms
[INFO] [05-18|21:15:29.179] Commit cycle in=292.245828ms
[INFO] [05-18|21:15:29.732] Commit cycle in=36.300816ms
Thanks for your help!
@AskAlexSharov This is still a problem, it seems to flap between taking up to 8s sometimes and at other times its consistently 100-400ms for a few hours at a time. What sort of commit times should be expected?
I setup a new server with an NVMe harddrive and synced from scratch. The same behavior is happening to this server too. They're located in different countries/datacenters but it is the same ISP and both are running ubuntu 20.04. I didnt use docker as I was having issues with permissions on the older server. The new server is just running this command via a tmux session:
./build/bin/erigon --datadir=/mnt/data/erigon --private.api.addr=0.0.0.0:9090
erigon version 2022.99.99-dev-66248c4b
I only have port 30303 and 22 open, so nothing else should be hitting it.
./build/bin/mdbx_stat -e -f /mnt/data/erigon/chaindata
mdbx_stat v0.11.7-35-g5d2eb580 (2022-05-19T13:11:25+03:00, T-43e6c3f611860f9ee55106fa7e5cd9cd8d2e6853)
Running for /mnt/data/erigon/chaindata...
Environment Info
Pagesize: 4096
Dynamic datafile: 12288..8796093022208 bytes (+2147483648/-4294967296), 3..2147483648 pages (+524288/-1048576)
Current mapsize: 8796093022208 bytes, 2147483648 pages
Current datafile: 1262720385024 bytes, 308281344 pages
Last transaction ID: 12788
Latter reader transaction ID: 12788 (0)
Max readers: 32118
Number of reader slots uses: 3
Garbage Collection
Pagesize: 4096
Tree depth: 2
Branch pages: 1
Leaf pages: 3
Overflow pages: 8424
Entries: 392
Page Usage
Total: 2147483648 100%
Backed: 308281344 14.4%
Allocated: 307806127 14.3%
Remained: 1839677521 85.7%
Used: 299183699 13.9%
GC: 8622428 0.4%
Retained: 14525 0.0%
Reclaimable: 8607903 0.4%
Available: 1848285424 86.1%
Status of Main DB
Pagesize: 4096
Tree depth: 1
Branch pages: 0
Leaf pages: 1
Overflow pages: 0
Entries: 55
[INFO] [05-31|21:47:46.581] Commit cycle in=5.879013584s
[INFO] [05-31|21:48:06.582] Req/resp stats req=0 reqMin=0 reqMax=0 skel=0 skelMin=0 skelMax=0 resp=111 respMin=14880574 respMax=14880587
[INFO] [05-31|21:48:13.225] Commit cycle in=5.101122083s
[INFO] [05-31|21:48:18.742] Commit cycle in=3.093739567s
[INFO] [05-31|21:48:39.827] Req/resp stats req=0 reqMin=0 reqMax=0 skel=0 skelMin=0 skelMax=0 resp=26 respMin=14880587 respMax=14880589
[INFO] [05-31|21:48:54.992] Commit cycle in=2.005722783s
[INFO] [05-31|21:48:54.998] Commit cycle in=518.827µs
[INFO] [05-31|21:49:08.115] Commit cycle in=8.858244454s
[INFO] [05-31|21:49:26.794] Commit cycle in=5.334296148s
[INFO] [05-31|21:49:46.796] Req/resp stats req=0 reqMin=0 reqMax=0 skel=0 skelMin=0 skelMax=0 resp=32 respMin=14694000 respMax=14880593
[INFO] [05-31|21:49:52.163] Commit cycle in=1.360619896s
[INFO] [05-31|21:50:12.165] Req/resp stats req=0 reqMin=0 reqMax=0 skel=0 skelMin=0 skelMax=0 resp=4 respMin=884928 respMax=14880594
[INFO] [05-31|21:50:16.178] Commit cycle in=3.31607128s
[INFO] [05-31|21:50:16.224] Commit cycle in=12.069087ms
[INFO] [05-31|21:50:20.227] Commit cycle in=16.244614ms
[INFO] [05-31|21:50:40.228] Req/resp stats req=0 reqMin=0 reqMax=0 skel=0 skelMin=0 skelMax=0 resp=27 respMin=13773035 respMax=14880597
[INFO] [05-31|21:50:47.522] Commit cycle in=1.554166187s
[INFO] [05-31|21:50:52.145] Commit cycle in=19.785248ms
[INFO] [05-31|21:51:12.146] Req/resp stats req=0 reqMin=0 reqMax=0 skel=0 skelMin=0 skelMax=0 resp=16 respMin=14880598 respMax=14880599
[INFO] [05-31|21:51:32.147] Req/resp stats req=0 reqMin=0 reqMax=0 skel=0 skelMin=0 skelMax=0 resp=0 respMin=0 respMax=0
[INFO] [05-31|21:51:52.147] Req/resp stats req=0 reqMin=0 reqMax=0 skel=0 skelMin=0 skelMax=0 resp=0 respMin=0 respMax=0
[INFO] [05-31|21:51:56.267] [1/16 Headers] DONE in=1m4.12245707s
[INFO] [05-31|21:52:00.069] Commit cycle in=3.44626293s
[INFO] [05-31|21:52:20.071] Req/resp stats req=0 reqMin=0 reqMax=0 skel=0 skelMin=0 skelMax=0 resp=7 respMin=14880600 respMax=14880600
[INFO] [05-31|21:52:28.434] Commit cycle in=5.343065208s
[INFO] [05-31|21:52:32.381] Commit cycle in=1.424496357s
[INFO] [05-31|21:52:37.695] Commit cycle in=86.577037ms
[INFO] [05-31|21:52:42.168] Commit cycle in=3.189368648s
[INFO] [05-31|21:52:50.394] Commit cycle in=43.859362ms
[INFO] [05-31|21:53:10.395] Req/resp stats req=0 reqMin=0 reqMax=0 skel=0 skelMin=0 skelMax=0 resp=40 respMin=14880601 respMax=14880605
[INFO] [05-31|21:53:13.807] Commit cycle in=1.499887476s
[INFO] [05-31|21:53:15.407] Commit cycle in=16.234608ms
I should add that im still running the old server and the slow commits are happening at different times between each server. So I don't think its network related.
Right now the old server is running fine, but the new one is falling behind.
Hi. Esterday merged to devel branch solution for this problem:
- existing nodes need work couple days with this fix to fully fix "slow commit cycle" problem (during this time you will periodically see "slow commit cycle")
This issue is stale because it has been open for 40 days with no activity. Remove stale label or comment, or this will be closed in 7 days.
![github-actions[bot] avatar](https://avatars.githubusercontent.com/in/15368?v=4 "Published by a pub.dev verified publisher"){kind=small}
This issue was closed because it has been stalled for 7 days with no activity.