ethdb: storage pebble uses high io

J1a-wei commented 1 year ago

System information

Geth version: v1.1.0 db.engine: pebble. fullnode with snapshot CL client & version: prysm v3.2.1 OS & Version: Docker (aws kubernetes)

aws instance: r5.xlarge(4c-32GiB) Exclusive use of this machine. Disk type: gp2 800GiB

geth args:

exec geth --authrpc.jwtsecret=/secret/jwtsecret --authrpc.addr=0.0.0.0 --authrpc.port=8551 --authrpc.vhosts=* --http --http.addr=0.0.0.0 --http.port=8599 --http.corsdomain= --http.vhosts=* --http.api=web3,eth,net,engine --nat=extip:$(POD_IP) --port=30303 --ws --ws.addr=0.0.0.0 --ws.port=8546 --ws.origins=* --ws.api=web3,eth,net,engine --datadir=/data/ethereum --ethash.dagdir=/data/ethereum/.ethash --ipcdisable --mainnet "--syncmode=snap" "--cache=12288" "--db.engine=pebble" "--metrics" "--pprof" "--pprof.addr=0.0.0.0" "--pprof.port=6060"

Scenario

At the beginning, the synchronization speed is fast. When it is about to synchronize. Now it's stuck in 0xfe0600(5min). Slow sync speed, too much difference from previous v.1.10.26

{"jsonrpc":"2.0","id":1,"result":{"currentBlock":"0xfe0600","healedBytecodeBytes":"0x7c6e7","healedBytecodes":"0x45","healedTrienodeBytes":"0x8737562","healedTrienodes":"0x9b921","healingBytecode":"0x0","healingTrienodes":"0x454","highestBlock":"0xfe0653","startingBlock":"0xfdfcf3","syncedAccountBytes":"0xb86436128","syncedAccounts":"0xc1e42e3","syncedBytecodeBytes":"0x14e2b1bbb","syncedBytecodes":"0xcb4a9","syncedStorage":"0x36583a3a","syncedStorageBytes":"0x2d9574d1e5"}}

snapshot

Disk

MariusVanDerWijden commented 1 year ago

Could you post some more logs? Would be good to know what your node is doing right now

J1a-wei commented 1 year ago

Fri, Feb 17 2023 6:31:52 pm | WARN [02-17\|18:31:52.116] Unexpected trienode heal packet peer=b20c6846 reqid=6,108,423,096,952,279,624
Fri, Feb 17 2023 6:31:52 pm | WARN [02-17\|18:31:52.120] Unexpected trienode heal packet peer=5135ca5f reqid=8,126,057,170,332,444,039
Fri, Feb 17 2023 6:31:52 pm | WARN [02-17\|18:31:52.281] Unexpected trienode heal packet peer=16020a10 reqid=6,733,235,765,668,670,119
Fri, Feb 17 2023 6:31:52 pm | WARN [02-17\|18:31:52.282] Unexpected trienode heal packet peer=d4604660 reqid=2,321,384,339,333,534,718
Fri, Feb 17 2023 6:31:52 pm | WARN [02-17\|18:31:52.378] Unexpected trienode heal packet peer=84038154 reqid=385,691,552,320,037,210
Fri, Feb 17 2023 6:31:52 pm | WARN [02-17\|18:31:52.762] Unexpected trienode heal packet peer=4f71e3ac reqid=6,402,596,182,220,032,265
Fri, Feb 17 2023 6:31:57 pm | WARN [02-17\|18:31:57.278] Unexpected trienode heal packet peer=55f90d94 reqid=1,377,321,756,170,368,633
Fri, Feb 17 2023 6:31:59 pm | INFO [02-17\|18:31:59.842] Forkchoice requested sync to new head number=16,647,860 hash=7c36de..2e481a
Fri, Feb 17 2023 6:32:00 pm | INFO [02-17\|18:32:00.083] Syncing: state healing in progress accounts=63012@3.14MiB slots=294,288@21.22MiB codes=89@645.79KiB nodes=959,536@207.95MiB pending=18853
Fri, Feb 17 2023 6:32:00 pm | INFO [02-17\|18:32:00.172] Imported new block headers count=1 elapsed="131.125µs" number=16,647,860 hash=7c36de..2e481a
Fri, Feb 17 2023 6:32:08 pm | INFO [02-17\|18:32:08.522] Syncing: state healing in progress accounts=63017@3.14MiB slots=294,288@21.22MiB codes=89@645.79KiB nodes=960,772@208.55MiB pending=21405
Fri, Feb 17 2023 6:32:12 pm | INFO [02-17\|18:32:12.034] Forkchoice requested sync to new head number=16,647,861 hash=a40122..ca8714
Fri, Feb 17 2023 6:32:12 pm | INFO [02-17\|18:32:12.178] Imported new block headers count=1 elapsed="143.973µs" number=16,647,861 hash=a40122..ca8714
Fri, Feb 17 2023 6:32:17 pm | INFO [02-17\|18:32:17.216] Syncing: state healing in progress accounts=63079@3.15MiB slots=294,288@21.22MiB codes=89@645.79KiB nodes=962,134@209.10MiB pending=23433
Fri, Feb 17 2023 6:32:24 pm | INFO [02-17\|18:32:24.029] Forkchoice requested sync to new head number=16,647,862 hash=416076..1b6e7a
Fri, Feb 17 2023 6:32:24 pm | INFO [02-17\|18:32:24.180] Imported new block headers count=1 elapsed="133.704µs" number=16,647,862 hash=416076..1b6e7a
Fri, Feb 17 2023 6:32:25 pm | INFO [02-17\|18:32:25.631] Syncing: state healing in progress accounts=63418@3.17MiB slots=294,288@21.22MiB codes=89@645.79KiB nodes=963,975@209.64MiB pending=24078
Fri, Feb 17 2023 6:32:26 pm | INFO [02-17\|18:32:26.883] Downloader queue stats receiptTasks=0 blockTasks=0 itemSize=264.38KiB throttle=992
Fri, Feb 17 2023 6:32:33 pm | INFO [02-17\|18:32:33.777] Syncing: state healing in progress accounts=64034@3.20MiB slots=294,304@21.22MiB codes=91@660.63KiB nodes=966,149@210.23MiB pending=24311
Fri, Feb 17 2023 6:32:36 pm | INFO [02-17\|18:32:36.360] Forkchoice requested sync to new head number=16,647,863 hash=11a716..5c9ffc
Fri, Feb 17 2023 6:32:39 pm | INFO [02-17\|18:32:39.185] Imported new block headers count=1 elapsed="192.193µs" number=16,647,863 hash=11a716..5c9ffc
Fri, Feb 17 2023 6:32:41 pm | INFO [02-17\|18:32:41.860] Syncing: state healing in progress accounts=64391@3.22MiB slots=294,392@21.23MiB codes=92@672.95KiB nodes=967,897@210.78MiB pending=24609
Fri, Feb 17 2023 6:32:48 pm | INFO [02-17\|18:32:48.224] Forkchoice requested sync to new head number=16,647,864 hash=3f8919..911279
Fri, Feb 17 2023 6:32:50 pm | INFO [02-17\|18:32:50.023] Syncing: state healing in progress accounts=64628@3.23MiB slots=294,669@21.25MiB codes=92@672.95KiB nodes=969,921@211.33MiB pending=25001
Fri, Feb 17 2023 6:32:51 pm | INFO [02-17\|18:32:51.190] Imported new block headers count=1 elapsed="133.593µs" number=16,647,864 hash=3f8919..911279
Fri, Feb 17 2023 6:32:58 pm | INFO [02-17\|18:32:58.024] Syncing: state healing in progress accounts=64937@3.25MiB slots=294,936@21.27MiB codes=92@672.95KiB nodes=971,932@211.85MiB pending=24685
Fri, Feb 17 2023 6:33:01 pm | INFO [02-17\|18:33:01.032] Forkchoice requested sync to new head number=16,647,865 hash=0984d6..d5c319
Fri, Feb 17 2023 6:33:03 pm | INFO [02-17\|18:33:03.196] Imported new block headers count=1 elapsed="144.205µs" number=16,647,865 hash=0984d6..d5c319
Fri, Feb 17 2023 6:33:06 pm | INFO [02-17\|18:33:06.228] Syncing: state healing in progress accounts=65218@3.26MiB slots=295,262@21.30MiB codes=92@672.95KiB nodes=974,030@212.39MiB pending=24393
Fri, Feb 17 2023 6:33:12 pm | INFO [02-17\|18:33:12.550] Forkchoice requested sync to new head number=16,647,866 hash=1745fa..b45ccb
Fri, Feb 17 2023 6:33:14 pm | INFO [02-17\|18:33:14.271] Syncing: state healing in progress accounts=65432@3.27MiB slots=295,649@21.33MiB codes=93@673.31KiB nodes=976,125@212.95MiB pending=24078
Fri, Feb 17 2023 6:33:15 pm | INFO [02-17\|18:33:15.201] Imported new block headers count=1 elapsed="129.846µs" number=16,647,866 hash=1745fa..b45ccb
Fri, Feb 17 2023 6:33:22 pm | INFO [02-17\|18:33:22.420] Syncing: state healing in progress accounts=65571@3.28MiB slots=296,094@21.36MiB codes=93@673.31KiB nodes=978,301@213.54MiB pending=23656
Fri, Feb 17 2023 6:33:25 pm | INFO [02-17\|18:33:25.686] Forkchoice requested sync to new head number=16,647,867 hash=8ca107..dfacef
Fri, Feb 17 2023 6:33:27 pm | INFO [02-17\|18:33:27.208] Imported new block headers count=1 elapsed="128.385µs" number=16,647,867 hash=8ca107..dfacef
Fri, Feb 17 2023 6:33:29 pm | INFO [02-17\|18:33:29.940] Downloader queue stats receiptTasks=0 blockTasks=0 itemSize=241.82KiB throttle=1085
Fri, Feb 17 2023 6:33:30 pm | INFO [02-17\|18:33:30.433] Syncing: state healing in progress accounts=65722@3.29MiB slots=296,429@21.38MiB codes=93@673.31KiB nodes=980,136@214.05MiB pending=23499
Fri, Feb 17 2023 6:33:36 pm | INFO [02-17\|18:33:36.940] Forkchoice requested sync to new head number=16,647,868 hash=66fa4a..34e4e5
Fri, Feb 17 2023 6:33:38 pm | INFO [02-17\|18:33:38.490] Syncing: state healing in progress accounts=65937@3.30MiB slots=296,726@21.40MiB codes=93@673.31KiB nodes=981,961@214.55MiB pending=23282
Fri, Feb 17 2023 6:33:39 pm | INFO [02-17\|18:33:39.211] Imported new block headers count=1 elapsed="139.71µs" number=16,647,868 hash=66fa4a..34e4e5
Fri, Feb 17 2023 6:33:46 pm | INFO [02-17\|18:33:46.993] Syncing: state healing in progress accounts=66126@3.31MiB slots=297,029@21.43MiB codes=93@673.31KiB nodes=983,907@215.07MiB pending=23057
Fri, Feb 17 2023 6:33:48 pm | INFO [02-17\|18:33:48.308] Forkchoice requested sync to new head number=16,647,869 hash=eb62f7..62cb7b
Fri, Feb 17 2023 6:33:51 pm | INFO [02-17\|18:33:51.213] Imported new block headers count=1 elapsed="256.731µs" number=16,647,869 hash=eb62f7..62cb7b
Fri, Feb 17 2023 6:33:55 pm | INFO [02-17\|18:33:55.238] Syncing: state healing in progress accounts=66375@3.32MiB slots=297,312@21.45MiB codes=94@697.07KiB nodes=985,821@215.58MiB pending=22854
Fri, Feb 17 2023 6:34:00 pm | INFO [02-17\|18:34:00.010] Forkchoice requested sync to new head number=16,647,870 hash=f75813..db9988
Fri, Feb 17 2023 6:34:00 pm | INFO [02-17\|18:34:00.214] Imported new block headers count=1 elapsed="147.097µs" number=16,647,870 hash=f75813..db9988
Fri, Feb 17 2023 6:34:03 pm | INFO [02-17\|18:34:03.421] Syncing: state healing in progress accounts=66705@3.34MiB slots=297,569@21.47MiB codes=96@704.37KiB nodes=987,773@216.08MiB pending=22318
Fri, Feb 17 2023 6:34:11 pm | INFO [02-17\|18:34:11.535] Syncing: state healing in progress accounts=66990@3.35MiB slots=297,737@21.48MiB codes=97@704.41KiB nodes=989,512@216.57MiB pending=22851
Fri, Feb 17 2023 6:34:12 pm | INFO [02-17\|18:34:12.267] Forkchoice requested sync to new head number=16,647,871 hash=18ef54..3f5198
Fri, Feb 17 2023 6:34:15 pm | INFO [02-17\|18:34:15.221] Imported new block headers count=1 elapsed="138.863µs" number=16,647,871 hash=18ef54..3f5198
Fri, Feb 17 2023 6:34:19 pm | INFO [02-17\|18:34:19.902] Syncing: state healing in progress accounts=67327@3.37MiB slots=297,948@21.50MiB codes=97@704.41KiB nodes=991,413@217.09MiB pending=22760
Fri, Feb 17 2023 6:34:25 pm | INFO [02-17\|18:34:25.074] Forkchoice requested sync to new head number=16,647,872 hash=69c378..d18c50
Fri, Feb 17 2023 6:34:27 pm | INFO [02-17\|18:34:27.228] Imported new block headers count=1 elapsed=1.103ms number=16,647,872 hash=69c378..d18c50
Fri, Feb 17 2023 6:34:28 pm | INFO [02-17\|18:34:28.044] Syncing: state healing in progress accounts=67508@3.38MiB slots=298,164@21.52MiB codes=99@733.02KiB nodes=993,067@217.57MiB pending=22966
Fri, Feb 17 2023 6:34:36 pm | INFO [02-17\|18:34:36.054] Syncing: state healing in progress accounts=67702@3.39MiB slots=298,460@21.54MiB codes=99@733.02KiB nodes=994,922@218.05MiB pending=22796
Fri, Feb 17 2023 6:34:36 pm | INFO [02-17\|18:34:36.807] Forkchoice requested sync to new head number=16,647,873 hash=880ff0..d34c7a
Fri, Feb 17 2023 6:34:39 pm | INFO [02-17\|18:34:39.230] Imported new block headers count=1 elapsed="133.378µs" number=16,647,873 hash=880ff0..d34c7a
Fri, Feb 17 2023 6:34:41 pm | INFO [02-17\|18:34:41.009] Downloader queue stats receiptTasks=0 blockTasks=0 itemSize=263.56KiB throttle=995
Fri, Feb 17 2023 6:34:44 pm | INFO [02-17\|18:34:44.168] Syncing: state healing in progress accounts=68011@3.40MiB slots=298,830@21.57MiB codes=99@733.02KiB nodes=997,058@218.55MiB pending=22130
Fri, Feb 17 2023 6:34:48 pm | INFO [02-17\|18:34:48.292] Forkchoice requested sync to new head number=16,647,874 hash=f4a85a..82022f
Fri, Feb 17 2023 6:34:51 pm | INFO [02-17\|18:34:51.233] Imported new block headers count=1 elapsed="131.895µs" number=16,647,874 hash=f4a85a..82022f
Fri, Feb 17 2023 6:34:52 pm | INFO [02-17\|18:34:52.368] Syncing: state healing in progress accounts=68267@3.42MiB slots=299,278@21.60MiB codes=99@733.02KiB nodes=999,232@219.04MiB pending=21692
Fri, Feb 17 2023 6:34:59 pm | INFO [02-17\|18:34:59.831] Forkchoice requested sync to new head number=16,647,875 hash=30255c..1b95cf
Fri, Feb 17 2023 6:35:00 pm | INFO [02-17\|18:35:00.237] Imported new block headers count=1 elapsed="158.304µs" number=16,647,875 hash=30255c..1b95cf
Fri, Feb 17 2023 6:35:00 pm | INFO [02-17\|18:35:00.426] Syncing: state healing in progress accounts=68439@3.42MiB slots=299,628@21.63MiB codes=99@733.02KiB nodes=1,001,010@219.52MiB pending=21738
Fri, Feb 17 2023 6:35:08 pm | INFO [02-17\|18:35:08.461] Syncing: state healing in progress accounts=68670@3.44MiB slots=299,948@21.65MiB codes=100@754.61KiB nodes=1,002,729@219.99MiB pending=21463
Fri, Feb 17 2023 6:35:12 pm | INFO [02-17\|18:35:12.513] Forkchoice requested sync to new head number=16,647,876 hash=1db580..04105f
Fri, Feb 17 2023 6:35:15 pm | INFO [02-17\|18:35:15.241] Imported new block headers count=1 elapsed="130.925µs" number=16,647,876 hash=1db580..04105f
Fri, Feb 17 2023 6:35:16 pm | INFO [02-17\|18:35:16.534] Syncing: state healing in progress accounts=68883@3.45MiB slots=300,105@21.66MiB codes=100@754.61KiB nodes=1,004,317@220.46MiB pending=21635
Fri, Feb 17 2023 6:35:24 pm | INFO [02-17\|18:35:24.592] Syncing: state healing in progress accounts=69127@3.46MiB slots=300,287@21.68MiB codes=100@754.61KiB nodes=1,006,067@220.93MiB pending=21602
Fri, Feb 17 2023 6:35:25 pm | INFO [02-17\|18:35:25.280] Forkchoice requested sync to new head number=16,647,877 hash=a02aae..904356
Fri, Feb 17 2023 6:35:27 pm | INFO [02-17\|18:35:27.248] Imported new block headers count=1 elapsed="132.49µs" number=16,647,877 hash=a02aae..904356
Fri, Feb 17 2023 6:35:32 pm | INFO [02-17\|18:35:32.846] Syncing: state healing in progress accounts=69442@3.47MiB slots=300,542@21.70MiB codes=100@754.61KiB nodes=1,008,037@221.42MiB pending=21290
Fri, Feb 17 2023 6:35:37 pm | INFO [02-17\|18:35:37.808] Forkchoice requested sync to new head number=16,647,878 hash=711cab..8f217a
Fri, Feb 17 2023 6:35:39 pm | INFO [02-17\|18:35:39.250] Imported new block headers count=1 elapsed="149.991µs" number=16,647,878 hash=711cab..8f217a
Fri, Feb 17 2023 6:35:41 pm | INFO [02-17\|18:35:41.073] Downloader queue stats receiptTasks=0 blockTasks=0 itemSize=257.48KiB throttle=1019
Fri, Feb 17 2023 6:35:41 pm | INFO [02-17\|18:35:41.214] Syncing: state healing in progress accounts=69765@3.49MiB slots=300,795@21.72MiB codes=101@754.90KiB nodes=1,009,902@221.92MiB pending=21005
Fri, Feb 17 2023 6:35:49 pm | INFO [02-17\|18:35:49.491] Syncing: state healing in progress accounts=69998@3.50MiB slots=300,972@21.73MiB codes=101@754.90KiB nodes=1,011,575@222.40MiB pending=20905
Fri, Feb 17 2023 6:35:57 pm | INFO [02-17\|18:35:57.528] Syncing: state healing in progress accounts=70248@3.51MiB slots=301,217@21.75MiB codes=102@764.25KiB nodes=1,013,360@222.88MiB pending=20939
Fri, Feb 17 2023 6:36:01 pm | INFO [02-17\|18:36:01.115] Forkchoice requested sync to new head number=16,647,879 hash=105765..5bd807
Fri, Feb 17 2023 6:36:03 pm | INFO [02-17\|18:36:03.255] Imported new block headers count=1 elapsed="127.676µs" number=16,647,879 hash=105765..5bd807
Fri, Feb 17 2023 6:36:05 pm | INFO [02-17\|18:36:05.892] Syncing: state healing in progress accounts=70449@3.52MiB slots=301,367@21.76MiB codes=102@764.25KiB nodes=1,014,954@223.36MiB pending=21560
Fri, Feb 17 2023 6:36:13 pm | INFO [02-17\|18:36:13.451] Forkchoice requested sync to new head number=16,647,880 hash=84feae..88ba3e
Fri, Feb 17 2023 6:36:13 pm | INFO [02-17\|18:36:13.910] Syncing: state healing in progress accounts=70648@3.53MiB slots=301,588@21.77MiB codes=102@764.25KiB nodes=1,016,600@223.82MiB pending=21776
Fri, Feb 17 2023 6:36:15 pm | INFO [02-17\|18:36:15.261] Imported new block headers count=1 elapsed="220.182µs" number=16,647,880 hash=84feae..88ba3e
Fri, Feb 17 2023 6:36:22 pm | INFO [02-17\|18:36:22.090] Syncing: state healing in progress accounts=70860@3.55MiB slots=301,846@21.79MiB codes=102@764.25KiB nodes=1,018,397@224.30MiB pending=21607
Fri, Feb 17 2023 6:36:25 pm | INFO [02-17\|18:36:25.249] Forkchoice requested sync to new head number=16,647,881 hash=0c7873..c7a58f
Fri, Feb 17 2023 6:36:27 pm | INFO [02-17\|18:36:27.263] Imported new block headers count=1 elapsed="171.293µs" number=16,647,881 hash=0c7873..c7a58f
Fri, Feb 17 2023 6:36:30 pm | INFO [02-17\|18:36:30.377] Syncing: state healing in progress accounts=71063@3.56MiB slots=302,255@21.82MiB codes=102@764.25KiB nodes=1,020,444@224.80MiB pending=21127
Fri, Feb 17 2023 6:36:36 pm | INFO [02-17\|18:36:36.167] Forkchoice requested sync to new head number=16,647,882 hash=578b8c..46a47e
Fri, Feb 17 2023 6:36:36 pm | INFO [02-17\|18:36:36.269] Imported new block headers count=1 elapsed="135.478µs" number=16,647,882 hash=578b8c..46a47e
Fri, Feb 17 2023 6:36:38 pm | INFO [02-17\|18:36:38.447] Syncing: state healing in progress accounts=71185@3.56MiB slots=302,624@21.85MiB codes=102@764.25KiB nodes=1,022,207@225.26MiB pending=21542
Fri, Feb 17 2023 6:36:46 pm | INFO [02-17\|18:36:46.835] Syncing: state healing in progress accounts=71252@3.57MiB slots=304,634@21.99MiB codes=102@764.25KiB nodes=1,026,216@225.82MiB pending=22664
Fri, Feb 17 2023 6:36:48 pm | INFO [02-17\|18:36:48.761] Forkchoice requested sync to new head number=16,647,883 hash=a93625..824495
Fri, Feb 17 2023 6:36:51 pm | INFO [02-17\|18:36:51.273] Imported new block headers count=1 elapsed="151.023µs" number=16,647,883 hash=a93625..824495
Fri, Feb 17 2023 6:36:52 pm | INFO [02-17\|18:36:52.132] Downloader queue stats receiptTasks=0 blockTasks=0 itemSize=249.54KiB throttle=1051
Fri, Feb 17 2023 6:36:55 pm | INFO [02-17\|18:36:55.019] Syncing: state healing in progress accounts=71352@3.57MiB slots=306,472@22.12MiB codes=102@764.25KiB nodes=1,029,947@226.37MiB pending=23899
Fri, Feb 17 2023 6:37:00 pm | INFO [02-17\|18:37:00.644] Forkchoice requested sync to new head number=16,647,884 hash=ad6a83..d556c0
Fri, Feb 17 2023 6:37:03 pm | INFO [02-17\|18:37:03.275] Imported new block headers count=1 elapsed="137.626µs" number=16,647,884 hash=ad6a83..d556c0
Fri, Feb 17 2023 6:37:03 pm | INFO [02-17\|18:37:03.353] Syncing: state healing in progress accounts=71380@3.57MiB slots=309,823@22.36MiB codes=102@764.25KiB nodes=1,035,148@226.98MiB pending=22107
Fri, Feb 17 2023 6:37:12 pm | INFO [02-17\|18:37:12.532] Syncing: state healing in progress accounts=71519@3.58MiB slots=310,642@22.42MiB codes=103@764.75KiB nodes=1,037,599@227.53MiB pending=21926
Fri, Feb 17 2023 6:37:12 pm | INFO [02-17\|18:37:12.985] Forkchoice requested sync to new head number=16,647,885 hash=bcd74e..e86b4f
Fri, Feb 17 2023 6:37:15 pm | INFO [02-17\|18:37:15.279] Imported new block headers count=1 elapsed="146.576µs" number=16,647,885 hash=bcd74e..e86b4f
Fri, Feb 17 2023 6:37:20 pm | INFO [02-17\|18:37:20.779] Syncing: state healing in progress accounts=71591@3.58MiB slots=310,911@22.44MiB codes=103@764.75KiB nodes=1,039,060@228.00MiB pending=22583
Fri, Feb 17 2023 6:37:27 pm | INFO [02-17\|18:37:27.664] Forkchoice requested sync to new head number=16,647,886 hash=151ccc..01e486
Fri, Feb 17 2023 6:37:28 pm | INFO [02-17\|18:37:28.841] Syncing: state healing in progress accounts=71603@3.58MiB slots=311,308@22.47MiB codes=103@764.75KiB nodes=1,040,798@228.47MiB pending=22659
Fri, Feb 17 2023 6:37:30 pm | INFO [02-17\|18:37:30.287] Imported new block headers count=1 elapsed="142.307µs" number=16,647,886 hash=151ccc..01e486
Fri, Feb 17 2023 6:37:36 pm | INFO [02-17\|18:37:36.553] Forkchoice requested sync to new head number=16,647,887 hash=ccdfe0..00b12a
Fri, Feb 17 2023 6:37:37 pm | INFO [02-17\|18:37:37.085] Syncing: state healing in progress accounts=71894@3.60MiB slots=311,847@22.51MiB codes=103@764.75KiB nodes=1,043,077@228.97MiB pending=22365
Fri, Feb 17 2023 6:37:39 pm | INFO [02-17\|18:37:39.290] Imported new block headers count=1 elapsed="222.827µs" number=16,647,887 hash=ccdfe0..00b12a
Fri, Feb 17 2023 6:37:45 pm | INFO [02-17\|18:37:45.305] Syncing: state healing in progress accounts=71946@3.60MiB slots=312,235@22.53MiB codes=103@764.75KiB nodes=1,044,779@229.44MiB pending=22594
Fri, Feb 17 2023 6:37:48 pm | INFO [02-17\|18:37:48.572] Forkchoice requested sync to new head number=16,647,888 hash=d949f9..f80cef
Fri, Feb 17 2023 6:37:51 pm | INFO [02-17\|18:37:51.294] Imported new block headers count=1 elapsed="129.784µs" number=16,647,888 hash=d949f9..f80cef
Fri, Feb 17 2023 6:37:52 pm | INFO [02-17\|18:37:52.188] Downloader queue stats receiptTasks=0 blockTasks=0 itemSize=265.63KiB throttle=987
Fri, Feb 17 2023 6:37:53 pm | INFO [02-17\|18:37:53.389] Syncing: state healing in progress accounts=71972@3.60MiB slots=312,705@22.57MiB codes=103@764.75KiB nodes=1,046,622@229.90MiB pending=22686
Fri, Feb 17 2023 6:38:00 pm | INFO [02-17\|18:38:00.510] Forkchoice requested sync to new head number=16,647,889 hash=923a31..852b55
Fri, Feb 17 2023 6:38:01 pm | INFO [02-17\|18:38:01.716] Syncing: state healing in progress accounts=72100@3.61MiB slots=313,506@22.64MiB codes=103@764.75KiB nodes=1,049,045@230.42MiB pending=22121
Fri, Feb 17 2023 6:38:03 pm | INFO [02-17\|18:38:03.300] Imported new block headers count=1 elapsed="128.579µs" number=16,647,889 hash=923a31..852b55
Fri, Feb 17 2023 6:38:09 pm | INFO [02-17\|18:38:09.763] Syncing: state healing in progress accounts=72179@3.61MiB slots=314,079@22.69MiB codes=103@764.75KiB nodes=1,051,037@230.90MiB pending=21980
Fri, Feb 17 2023 6:38:12 pm | INFO [02-17\|18:38:12.638] Forkchoice requested sync to new head number=16,647,890 hash=57af2b..2ec226
Fri, Feb 17 2023 6:38:15 pm | INFO [02-17\|18:38:15.306] Imported new block headers count=1 elapsed="155.176µs" number=16,647,890 hash=57af2b..2ec226
Fri, Feb 17 2023 6:38:17 pm | INFO [02-17\|18:38:17.777] Syncing: state healing in progress accounts=72223@3.61MiB slots=314,698@22.75MiB codes=103@764.75KiB nodes=1,053,043@231.38MiB pending=21694
Fri, Feb 17 2023 6:38:23 pm | INFO [02-17\|18:38:23.806] Forkchoice requested sync to new head number=16,647,891 hash=28e3ca..67b5f4
Fri, Feb 17 2023 6:38:24 pm | INFO [02-17\|18:38:24.311] Imported new block headers count=1 elapsed="129.023µs" number=16,647,891 hash=28e3ca..67b5f4
Fri, Feb 17 2023 6:38:25 pm | INFO [02-17\|18:38:25.877] Syncing: state healing in progress accounts=72295@3.62MiB slots=315,303@22.79MiB codes=103@764.75KiB nodes=1,055,078@231.86MiB pending=21305
Fri, Feb 17 2023 6:38:34 pm | INFO [02-17\|18:38:34.208] Syncing: state healing in progress accounts=72371@3.62MiB slots=315,886@22.84MiB codes=103@764.75KiB nodes=1,057,150@232.36MiB pending=20983
Fri, Feb 17 2023 6:38:37 pm | INFO [02-17\|18:38:37.468] Forkchoice requested sync to new head number=16,647,892 hash=0a85fb..cc7a89
Fri, Feb 17 2023 6:38:39 pm | INFO [02-17\|18:38:39.319] Imported new block headers count=1 elapsed="280.901µs" number=16,647,892 hash=0a85fb..cc7a89
Fri, Feb 17 2023 6:38:42 pm | INFO [02-17\|18:38:42.543] Syncing: state healing in progress accounts=72453@3.63MiB slots=316,590@22.89MiB codes=105@797.98KiB nodes=1,059,434@232.86MiB pending=21076
Fri, Feb 17 2023 6:38:48 pm | INFO [02-17\|18:38:48.128] Forkchoice requested sync to new head number=16,647,893 hash=63cc30..83aab5
Fri, Feb 17 2023 6:38:48 pm | INFO [02-17\|18:38:48.321] Imported new block headers count=1 elapsed="129.71µs" number=16,647,893 hash=63cc30..83aab5
Fri, Feb 17 2023 6:38:50 pm | INFO [02-17\|18:38:50.895] Syncing: state healing in progress accounts=72569@3.63MiB slots=317,865@22.99MiB codes=105@797.98KiB nodes=1,063,022@233.42MiB pending=21731
Fri, Feb 17 2023 6:38:58 pm | INFO [02-17\|18:38:58.897] Syncing: state healing in progress accounts=72713@3.64MiB slots=319,188@23.09MiB codes=105@797.98KiB nodes=1,066,281@233.95MiB pending=27901
Fri, Feb 17 2023 6:39:00 pm | INFO [02-17\|18:39:00.848] Forkchoice requested sync to new head number=16,647,894 hash=af8ee5..afdc80
Fri, Feb 17 2023 6:39:03 pm | INFO [02-17\|18:39:03.328] Imported new block headers count=1 elapsed="178.031µs" number=16,647,894 hash=af8ee5..afdc80
Fri, Feb 17 2023 6:39:05 pm | INFO [02-17\|18:39:05.236] Downloader queue stats receiptTasks=0 blockTasks=0 itemSize=261.89KiB throttle=1001
Fri, Feb 17 2023 6:39:07 pm | INFO [02-17\|18:39:07.012] Syncing: state healing in progress accounts=72715@3.64MiB slots=328,032@23.74MiB codes=105@797.98KiB nodes=1,078,801@234.71MiB pending=25634
Fri, Feb 17 2023 6:39:11 pm | INFO [02-17\|18:39:11.995] Forkchoice requested sync to new head number=16,647,895 hash=b17463..779d80
Fri, Feb 17 2023 6:39:12 pm | INFO [02-17\|18:39:12.331] Imported new block headers count=1 elapsed="125.022µs" number=16,647,895 hash=b17463..779d80
Fri, Feb 17 2023 6:39:15 pm | INFO [02-17\|18:39:15.142] Syncing: state healing in progress accounts=72801@3.64MiB slots=333,313@24.12MiB codes=105@797.98KiB nodes=1,087,723@235.48MiB pending=28142
Fri, Feb 17 2023 6:39:24 pm | INFO [02-17\|18:39:24.139] Forkchoice requested sync to new head number=16,647,896 hash=12e920..5f0280
Fri, Feb 17 2023 6:39:24 pm | INFO [02-17\|18:39:24.335] Imported new block headers count=1 elapsed="143.912µs" number=16,647,896 hash=12e920..5f0280
Fri, Feb 17 2023 6:39:25 pm | INFO [02-17\|18:39:25.266] Syncing: state healing in progress accounts=72965@3.65MiB slots=336,749@24.37MiB codes=105@797.98KiB nodes=1,093,603@236.22MiB pending=28333
Fri, Feb 17 2023 6:39:36 pm | INFO [02-17\|18:39:36.142] Forkchoice requested sync to new head number=16,647,897 hash=8cc5cf..30fea6
Fri, Feb 17 2023 6:39:36 pm | INFO [02-17\|18:39:36.341] Imported new block headers count=1 elapsed="128.904µs" number=16,647,897 hash=8cc5cf..30fea6
Fri, Feb 17 2023 6:39:36 pm | INFO [02-17\|18:39:36.820] Syncing: state healing in progress accounts=73073@3.66MiB slots=337,582@24.43MiB codes=105@797.98KiB nodes=1,095,952@236.88MiB pending=30554
Fri, Feb 17 2023 6:39:45 pm | INFO [02-17\|18:39:45.589] Syncing: state healing in progress accounts=73084@3.66MiB slots=338,180@24.48MiB codes=105@797.98KiB nodes=1,097,538@237.38MiB pending=32077
Fri, Feb 17 2023 6:39:48 pm | INFO [02-17\|18:39:48.663] Forkchoice requested sync to new head number=16,647,898 hash=34c11f..784e9d
Fri, Feb 17 2023 6:39:51 pm | INFO [02-17\|18:39:51.346] Imported new block headers count=1 elapsed="162.227µs" number=16,647,898 hash=34c11f..784e9d
Fri, Feb 17 2023 6:39:53 pm | INFO [02-17\|18:39:53.601] Syncing: state healing in progress accounts=73116@3.66MiB slots=340,985@24.68MiB codes=105@797.98KiB nodes=1,102,034@237.95MiB pending=30460
Fri, Feb 17 2023 6:40:01 pm | INFO [02-17\|18:40:01.310] Forkchoice requested sync to new head number=16,647,899 hash=23159d..a75470
Fri, Feb 17 2023 6:40:01 pm | INFO [02-17\|18:40:01.760] Syncing: state healing in progress accounts=73273@3.67MiB slots=344,023@24.91MiB codes=106@810.96KiB nodes=1,107,185@238.57MiB pending=27850
Fri, Feb 17 2023 6:40:03 pm | INFO [02-17\|18:40:03.352] Imported new block headers count=1 elapsed="129.855µs" number=16,647,899 hash=23159d..a75470
Fri, Feb 17 2023 6:40:09 pm | INFO [02-17\|18:40:09.864] Syncing: state healing in progress accounts=73458@3.68MiB slots=344,475@24.94MiB codes=106@810.96KiB nodes=1,109,070@239.05MiB pending=27759
Fri, Feb 17 2023 6:40:13 pm | INFO [02-17\|18:40:13.773] Forkchoice requested sync to new head number=16,647,900 hash=8171b0..bf5e55
Fri, Feb 17 2023 6:40:15 pm | INFO [02-17\|18:40:15.361] Imported new block headers count=1 elapsed="145.751µs" number=16,647,900 hash=8171b0..bf5e55
Fri, Feb 17 2023 6:40:16 pm | INFO [02-17\|18:40:16.300] Downloader queue stats receiptTasks=0 blockTasks=0 itemSize=251.40KiB throttle=1043
Fri, Feb 17 2023 6:40:17 pm | INFO [02-17\|18:40:17.998] Syncing: state healing in progress accounts=73696@3.69MiB slots=344,954@24.98MiB codes=106@810.96KiB nodes=1,111,255@239.55MiB pending=27191
Fri, Feb 17 2023 6:40:23 pm | INFO [02-17\|18:40:23.954] Forkchoice requested sync to new head number=16,647,901 hash=1e1437..1be1a2
Fri, Feb 17 2023 6:40:24 pm | INFO [02-17\|18:40:24.364] Imported new block headers count=1 elapsed="145.664µs" number=16,647,901 hash=1e1437..1be1a2
Fri, Feb 17 2023 6:40:25 pm | WARN [02-17\|18:40:25.350] Checkpoint challenge timed out, dropping id=3513fbfdacc4fa54 conn=dyndial addr=167.235.34.105:31425 type=
Fri, Feb 17 2023 6:40:26 pm | INFO [02-17\|18:40:26.007] Syncing: state healing in progress accounts=73858@3.70MiB slots=345,299@25.00MiB codes=107@815.21KiB nodes=1,112,980@240.02MiB pending=26909
Fri, Feb 17 2023 6:40:28 pm | WARN [02-17\|18:40:28.953] Dropping unsynced node during sync id=3547736859519b1b conn=dyndial addr=3.67.180.94:30303 type=Geth/v1.10.25-stable...
Fri, Feb 17 2023 6:40:34 pm | INFO [02-17\|18:40:34.069] Syncing: state healing in progress accounts=74074@3.71MiB slots=345,709@25.03MiB codes=107@815.21KiB nodes=1,115,085@240.50MiB pending=26434
Fri, Feb 17 2023 6:40:35 pm | INFO [02-17\|18:40:35.999] Forkchoice requested sync to new head number=16,647,902 hash=8b3cce..884c5a
Fri, Feb 17 2023 6:40:36 pm | INFO [02-17\|18:40:36.367] Imported new block headers count=1 elapsed="130.958µs" number=16,647,902 hash=8b3cce..884c5a
Fri, Feb 17 2023 6:40:42 pm | INFO [02-17\|18:40:42.156] Syncing: state healing in progress accounts=74370@3.72MiB slots=345,959@25.05MiB codes=107@815.21KiB nodes=1,116,943@240.98MiB pending=26144
Fri, Feb 17 2023 6:40:48 pm | INFO [02-17\|18:40:48.764] Forkchoice requested sync to new head number=16,647,903 hash=891770..6eb11a
Fri, Feb 17 2023 6:40:50 pm | INFO [02-17\|18:40:50.179] Syncing: state healing in progress accounts=74780@3.74MiB slots=346,234@25.07MiB codes=108@829.03KiB nodes=1,119,089@241.48MiB pending=25545
Fri, Feb 17 2023 6:40:51 pm | INFO [02-17\|18:40:51.374] Imported new block headers count=1 elapsed="146.748µs" number=16,647,903 hash=891770..6eb11a
Fri, Feb 17 2023 6:40:58 pm | INFO [02-17\|18:40:58.291] Syncing: state healing in progress accounts=75164@3.76MiB slots=346,427@25.09MiB codes=110@840.34KiB nodes=1,121,026@241.97MiB pending=25551
Fri, Feb 17 2023 6:41:00 pm | INFO [02-17\|18:41:00.917] Forkchoice requested sync to new head number=16,647,904 hash=3616d0..c57db8
Fri, Feb 17 2023 6:41:03 pm | INFO [02-17\|18:41:03.378] Imported new block headers count=1 elapsed="125.172µs" number=16,647,904 hash=3616d0..c57db8
Fri, Feb 17 2023 6:41:06 pm | INFO [02-17\|18:41:06.889] Syncing: state healing in progress accounts=75599@3.78MiB slots=346,921@25.13MiB codes=111@852.65KiB nodes=1,123,483@242.51MiB pending=25284
Fri, Feb 17 2023 6:41:13 pm | INFO [02-17\|18:41:13.056] Forkchoice requested sync to new head number=16,647,905 hash=1f0c52..1ccf38
Fri, Feb 17 2023 6:41:15 pm | INFO [02-17\|18:41:15.237] Syncing: state healing in progress accounts=75972@3.80MiB slots=347,484@25.17MiB codes=111@852.65KiB nodes=1,125,947@243.03MiB pending=24704
Fri, Feb 17 2023 6:41:15 pm | INFO [02-17\|18:41:15.382] Imported new block headers count=1 elapsed="137.424µs" number=16,647,905 hash=1f0c52..1ccf38
Fri, Feb 17 2023 6:41:16 pm | INFO [02-17\|18:41:16.366] Downloader queue stats receiptTasks=0 blockTasks=0 itemSize=241.98KiB throttle=1084
Fri, Feb 17 2023 6:41:23 pm | INFO [02-17\|18:41:23.309] Syncing: state healing in progress accounts=76182@3.81MiB slots=347,793@25.19MiB codes=111@852.65KiB nodes=1,127,723@243.50MiB pending=24739
Fri, Feb 17 2023 6:41:25 pm | INFO [02-17\|18:41:25.672] Forkchoice requested sync to new head number=16,647,906 hash=7e9e25..f3dd6d
Fri, Feb 17 2023 6:41:27 pm | INFO [02-17\|18:41:27.386] Imported new block headers count=1 elapsed="146.26µs" number=16,647,906 hash=7e9e25..f3dd6d
Fri, Feb 17 2023 6:41:31 pm | INFO [02-17\|18:41:31.429] Syncing: state healing in progress accounts=76468@3.82MiB slots=348,229@25.23MiB codes=112@865.18KiB nodes=1,129,843@244.00MiB pending=24313
Fri, Feb 17 2023 6:41:36 pm | INFO [02-17\|18:41:36.222] Forkchoice requested sync to new head number=16,647,907 hash=883016..254d46
Fri, Feb 17 2023 6:41:36 pm | INFO [02-17\|18:41:36.389] Imported new block headers count=1 elapsed="134.086µs" number=16,647,907 hash=883016..254d46
Fri, Feb 17 2023 6:41:39 pm | INFO [02-17\|18:41:39.496] Syncing: state healing in progress accounts=76664@3.83MiB slots=348,672@25.26MiB codes=112@865.18KiB nodes=1,132,099@244.51MiB pending=25461
Fri, Feb 17 2023 6:41:39 pm | WARN [02-17\|18:41:39.903] Unexpected trienode heal packet peer=55f90d94 reqid=3,446,169,489,554,705,428
Fri, Feb 17 2023 6:41:47 pm | INFO [02-17\|18:41:47.634] Syncing: state healing in progress accounts=77032@3.85MiB slots=349,943@25.35MiB codes=112@865.18KiB nodes=1,135,863@245.09MiB pending=24588
Fri, Feb 17 2023 6:41:48 pm | INFO [02-17\|18:41:48.018] Forkchoice requested sync to new head number=16,647,908 hash=492aa0..d6e49c
Fri, Feb 17 2023 6:41:48 pm | INFO [02-17\|18:41:48.392] Imported new block headers count=1 elapsed="135.762µs" number=16,647,908 hash=492aa0..d6e49c
Fri, Feb 17 2023 6:41:56 pm | INFO [02-17\|18:41:56.131] Syncing: state healing in progress accounts=77311@3.86MiB slots=350,655@25.41MiB codes=112@865.18KiB nodes=1,138,274@245.62MiB pending=23866
Fri, Feb 17 2023 6:42:00 pm | INFO [02-17\|18:42:00.245] Forkchoice requested sync to new head number=16,647,909 hash=41a961..b25d14
Fri, Feb 17 2023 6:42:00 pm | INFO [02-17\|18:42:00.396] Imported new block headers count=1 elapsed="154.623µs" number=16,647,909 hash=41a961..b25d14
Fri, Feb 17 2023 6:42:02 pm | WARN [02-17\|18:42:02.348] Snapshot extension registration failed peer=a4da81c9 err="peer connected on snap without compatible eth support"
Fri, Feb 17 2023 6:42:04 pm | INFO [02-17\|18:42:04.299] Syncing: state healing in progress accounts=77559@3.88MiB slots=351,312@25.46MiB codes=113@881.35KiB nodes=1,140,540@246.12MiB pending=23050
Fri, Feb 17 2023 6:42:12 pm | INFO [02-17\|18:42:12.367] Syncing: state healing in progress accounts=77809@3.89MiB slots=351,636@25.48MiB codes=114@887.95KiB nodes=1,142,580@246.60MiB pending=22959
Fri, Feb 17 2023 6:42:12 pm | INFO [02-17\|18:42:12.511] Forkchoice requested sync to new head number=16,647,910 hash=7cdc35..6036ef
Fri, Feb 17 2023 6:42:15 pm | INFO [02-17\|18:42:15.400] Imported new block headers count=1 elapsed="130.41µs" number=16,647,910 hash=7cdc35..6036ef
Fri, Feb 17 2023 6:42:16 pm | INFO [02-17\|18:42:16.424] Downloader queue stats receiptTasks=0 blockTasks=0 itemSize=244.71KiB throttle=1072
Fri, Feb 17 2023 6:42:20 pm | INFO [02-17\|18:42:20.786] Syncing: state healing in progress accounts=78129@3.90MiB slots=351,887@25.50MiB codes=115@896.35KiB nodes=1,144,557@247.10MiB pending=22752
Fri, Feb 17 2023 6:42:23 pm | INFO [02-17\|18:42:23.921] Forkchoice requested sync to new head number=16,647,911 hash=5a9a42..cbddf5
Fri, Feb 17 2023 6:42:24 pm | INFO [02-17\|18:42:24.402] Imported new block headers count=1 elapsed="151.715µs" number=16,647,911 hash=5a9a42..cbddf5
Fri, Feb 17 2023 6:42:28 pm | INFO [02-17\|18:42:28.801] Syncing: state healing in progress accounts=78388@3.92MiB slots=352,204@25.52MiB codes=116@916.76KiB nodes=1,146,414@247.58MiB pending=22678
Fri, Feb 17 2023 6:42:36 pm | INFO [02-17\|18:42:36.839] Syncing: state healing in progress accounts=78691@3.93MiB slots=352,837@25.57MiB codes=116@916.76KiB nodes=1,148,983@248.09MiB pending=22782
Fri, Feb 17 2023 6:42:37 pm | INFO [02-17\|18:42:37.295] Forkchoice requested sync to new head number=16,647,912 hash=c932c6..22d6a3
Fri, Feb 17 2023 6:42:39 pm | INFO [02-17\|18:42:39.408] Imported new block headers count=1 elapsed="165.022µs" number=16,647,912 hash=c932c6..22d6a3
Fri, Feb 17 2023 6:42:44 pm | INFO [02-17\|18:42:44.854] Syncing: state healing in progress accounts=79030@3.95MiB slots=354,061@25.66MiB codes=116@916.76KiB nodes=1,152,275@248.62MiB pending=21636
Fri, Feb 17 2023 6:42:48 pm | INFO [02-17\|18:42:48.020] Forkchoice requested sync to new head number=16,647,913 hash=19b7a0..340f2c
Fri, Feb 17 2023 6:42:48 pm | INFO [02-17\|18:42:48.414] Imported new block headers count=1 elapsed="168.112µs" number=16,647,913 hash=19b7a0..340f2c
Fri, Feb 17 2023 6:42:53 pm | INFO [02-17\|18:42:53.486] Syncing: state healing in progress accounts=79175@3.95MiB slots=354,479@25.70MiB codes=117@938.38KiB nodes=1,154,188@249.12MiB pending=21925
Fri, Feb 17 2023 6:42:55 pm | WARN [02-17\|18:42:55.571] Unexpected trienode heal packet peer=55f90d94 reqid=5,342,914,672,103,140,961
Fri, Feb 17 2023 6:43:01 pm | INFO [02-17\|18:43:01.509] Syncing: state healing in progress accounts=79475@3.97MiB slots=355,225@25.75MiB codes=117@938.38KiB nodes=1,156,661@249.62MiB pending=20863
Fri, Feb 17 2023 6:43:01 pm | INFO [02-17\|18:43:01.914] Forkchoice requested sync to new head number=16,647,914 hash=0bf540..804dde
Fri, Feb 17 2023 6:43:03 pm | INFO [02-17\|18:43:03.421] Imported new block headers count=1 elapsed="171.257µs" number=16,647,914 hash=0bf540..804dde
Fri, Feb 17 2023 6:43:09 pm | INFO [02-17\|18:43:09.549] Syncing: state healing in progress accounts=79775@3.98MiB slots=355,659@25.79MiB codes=117@938.38KiB nodes=1,158,861@250.11MiB pending=20348
Fri, Feb 17 2023 6:43:12 pm | INFO [02-17\|18:43:12.424] Forkchoice requested sync to new head number=16,647,915 hash=6e2305..858d1d
Fri, Feb 17 2023 6:43:12 pm | INFO [02-17\|18:43:12.427] Imported new block headers count=1 elapsed="123.861µs" number=16,647,915 hash=6e2305..858d1d
Fri, Feb 17 2023 6:43:17 pm | INFO [02-17\|18:43:17.710] Syncing: state healing in progress accounts=80179@4.00MiB slots=355,980@25.81MiB codes=117@938.38KiB nodes=1,161,023@250.62MiB pending=19835
Fri, Feb 17 2023 6:43:25 pm | INFO [02-17\|18:43:25.419] Forkchoice requested sync to new head number=16,647,916 hash=959ab5..a60408
Fri, Feb 17 2023 6:43:25 pm | INFO [02-17\|18:43:25.774] Syncing: state healing in progress accounts=80489@4.02MiB slots=356,216@25.83MiB codes=117@938.38KiB nodes=1,162,808@251.10MiB pending=19556
Fri, Feb 17 2023 6:43:27 pm | WARN [02-17\|18:43:27.432] Pivot seemingly stale, moving old=16,647,795 new=16,647,852
Fri, Feb 17 2023 6:43:27 pm | INFO [02-17\|18:43:27.432] Imported new block headers count=1 elapsed="148.186µs" number=16,647,916 hash=959ab5..a60408
Fri, Feb 17 2023 6:43:27 pm | INFO [02-17\|18:43:27.586] Imported new block receipts count=57 elapsed=96.631ms number=16,647,851 hash=5f6402..4132e4 age=13m16s size=8.84MiB
Fri, Feb 17 2023 6:43:27 pm | INFO [02-17\|18:43:27.741] Syncing: state healing in progress accounts=80562@4.02MiB slots=356,268@25.83MiB codes=117@938.38KiB nodes=1,163,276@251.22MiB pending=19515
Fri, Feb 17 2023 6:43:27 pm | WARN [02-17\|18:43:27.867] Unexpected trienode heal packet peer=d7c5f8df reqid=5,843,214,429,261,774,692
Fri, Feb 17 2023 6:43:27 pm | WARN [02-17\|18:43:27.951] Unexpected trienode heal packet peer=16020a10 reqid=1,910,236,984,925,850,599
Fri, Feb 17 2023 6:43:27 pm | WARN [02-17\|18:43:27.988] Unexpected trienode heal packet peer=541c8345 reqid=7,731,867,665,713,563,580
Fri, Feb 17 2023 6:43:28 pm | WARN [02-17\|18:43:28.000] Unexpected trienode heal packet peer=84fabfcb reqid=7,383,456,479,500,448,929
Fri, Feb 17 2023 6:43:28 pm | WARN [02-17\|18:43:28.020] Unexpected trienode heal packet peer=5135ca5f reqid=443,459,435,697,705,952
Fri, Feb 17 2023 6:43:28 pm | WARN [02-17\|18:43:28.031] Unexpected trienode heal packet peer=8520a169 reqid=8,059,835,022,314,062,612
Fri, Feb 17 2023 6:43:28 pm | WARN [02-17\|18:43:28.213] Unexpected trienode heal packet peer=ce8ed81a reqid=4,468,173,491,870,674,197
Fri, Feb 17 2023 6:43:28 pm | WARN [02-17\|18:43:28.263] Unexpected trienode heal packet peer=b20c6846 reqid=3,488,217,616,769,868,082
Fri, Feb 17 2023 6:43:28 pm | WARN [02-17\|18:43:28.278] Unexpected trienode heal packet peer=d4604660 reqid=8,581,154,076,006,886,389
Fri, Feb 17 2023 6:43:28 pm | WARN [02-17\|18:43:28.286] Unexpected trienode heal packet peer=84038154 reqid=8,834,665,636,191,569,428
Fri, Feb 17 2023 6:43:28 pm | WARN [02-17\|18:43:28.403] Unexpected trienode heal packet peer=a426ff5e reqid=4,974,979,623,944,799,151
Fri, Feb 17 2023 6:43:28 pm | INFO [02-17\|18:43:28.743] Downloader queue stats receiptTasks=0 blockTasks=0 itemSize=245.16KiB throttle=1070
Fri, Feb 17 2023 6:43:29 pm | WARN [02-17\|18:43:29.187] Unexpected trienode heal packet peer=55f90d94 reqid=324,338,752,667,271,917
Fri, Feb 17 2023 6:43:35 pm | INFO [02-17\|18:43:35.998] Syncing: state healing in progress accounts=80562@4.02MiB slots=356,268@25.83MiB codes=117@938.38KiB nodes=1,164,285@251.73MiB pending=8278
Fri, Feb 17 2023 6:43:38 pm | INFO [02-17\|18:43:38.506] Forkchoice requested sync to new head number=16,647,917 hash=99f1b8..1da848
Fri, Feb 17 2023 6:43:39 pm | INFO [02-17\|18:43:39.440] Imported new block headers count=1 elapsed="145.267µs" number=16,647,917 hash=99f1b8..1da848
Fri, Feb 17 2023 6:43:44 pm | INFO [02-17\|18:43:44.024] Syncing: state healing in progress accounts=80570@4.02MiB slots=356,268@25.83MiB codes=117@938.38KiB nodes=1,165,293@252.22MiB pending=11941
Fri, Feb 17 2023 6:43:48 pm | INFO [02-17\|18:43:48.366] Forkchoice requested sync to new head number=16,647,918 hash=dfd172..5abede
Fri, Feb 17 2023 6:43:48 pm | INFO [02-17\|18:43:48.442] Imported new block headers count=1 elapsed="127.824µs" number=16,647,918 hash=dfd172..5abede
Fri, Feb 17 2023 6:43:52 pm | INFO [02-17\|18:43:52.468] Syncing: state healing in progress accounts=80639@4.03MiB slots=356,268@25.83MiB codes=117@938.38KiB nodes=1,166,491@252.71MiB pending=13816
Fri, Feb 17 2023 6:44:00 pm | INFO [02-17\|18:44:00.604] Syncing: state healing in progress accounts=80790@4.03MiB slots=356,268@25.83MiB codes=117@938.38KiB nodes=1,167,828@253.19MiB pending=15173
Fri, Feb 17 2023 6:44:01 pm | INFO [02-17\|18:44:01.237] Forkchoice requested sync to new head number=16,647,919 hash=9d9dc2..141769
Fri, Feb 17 2023 6:44:03 pm | INFO [02-17\|18:44:03.449] Imported new block headers count=1 elapsed="140.63µs" number=16,647,919 hash=9d9dc2..141769
Fri, Feb 17 2023 6:44:08 pm | INFO [02-17\|18:44:08.667] Syncing: state healing in progress accounts=81114@4.05MiB slots=356,270@25.83MiB codes=118@952.63KiB nodes=1,169,473@253.67MiB pending=15850
Fri, Feb 17 2023 6:44:13 pm | INFO [02-17\|18:44:13.225] Forkchoice requested sync to new head number=16,647,920 hash=129c7a..c8a246
Fri, Feb 17 2023 6:44:15 pm | INFO [02-17\|18:44:15.459] Imported new block headers count=1 elapsed=2.494ms number=16,647,920 hash=129c7a..c8a246
Fri, Feb 17 2023 6:44:16 pm | INFO [02-17\|18:44:16.852] Syncing: state healing in progress accounts=81583@4.07MiB slots=356,292@25.83MiB codes=118@952.63KiB nodes=1,171,324@254.17MiB pending=16032
Fri, Feb 17 2023 6:44:24 pm | INFO [02-17\|18:44:24.542] Forkchoice requested sync to new head number=16,647,921 hash=f66e14..816b1a
Fri, Feb 17 2023 6:44:25 pm | INFO [02-17\|18:44:25.092] Syncing: state healing in progress accounts=82084@4.10MiB slots=356,349@25.84MiB codes=118@952.63KiB nodes=1,173,278@254.68MiB pending=16035
Fri, Feb 17 2023 6:44:27 pm | INFO [02-17\|18:44:27.461] Imported new block headers count=1 elapsed="134.342µs" number=16,647,921 hash=f66e14..816b1a
Fri, Feb 17 2023 6:44:33 pm | INFO [02-17\|18:44:33.284] Syncing: state healing in progress accounts=82494@4.12MiB slots=356,465@25.85MiB codes=118@952.63KiB nodes=1,175,173@255.19MiB pending=16074
Fri, Feb 17 2023 6:44:37 pm | INFO [02-17\|18:44:37.461] Forkchoice requested sync to new head number=16,647,922 hash=d54033..105707
Fri, Feb 17 2023 6:44:39 pm | INFO [02-17\|18:44:39.467] Imported new block headers count=1 elapsed="143.153µs" number=16,647,922 hash=d54033..105707
Fri, Feb 17 2023 6:44:39 pm | INFO [02-17\|18:44:39.808] Downloader queue stats receiptTasks=0 blockTasks=0 itemSize=260.28KiB throttle=1008
Fri, Feb 17 2023 6:44:41 pm | INFO [02-17\|18:44:41.515] Syncing: state healing in progress accounts=82812@4.14MiB slots=356,724@25.87MiB codes=118@952.63KiB nodes=1,177,117@255.69MiB pending=15733
Fri, Feb 17 2023 6:44:48 pm | INFO [02-17\|18:44:48.342] Forkchoice requested sync to new head number=16,647,923 hash=248783..1e2cbb
Fri, Feb 17 2023 6:44:48 pm | INFO [02-17\|18:44:48.470] Imported new block headers count=1 elapsed="131.276µs" number=16,647,923 hash=248783..1e2cbb
Fri, Feb 17 2023 6:44:49 pm | INFO [02-17\|18:44:49.633] Syncing: state healing in progress accounts=83007@4.15MiB slots=357,125@25.90MiB codes=118@952.63KiB nodes=1,179,112@256.17MiB pending=15300
Fri, Feb 17 2023 6:44:57 pm | INFO [02-17\|18:44:57.637] Syncing: state healing in progress accounts=83174@4.16MiB slots=357,384@25.92MiB codes=118@952.63KiB nodes=1,180,813@256.65MiB pending=15599
Fri, Feb 17 2023 6:45:01 pm | INFO [02-17\|18:45:01.740] Forkchoice requested sync to new head number=16,647,924 hash=78e76d..18d68e
Fri, Feb 17 2023 6:45:03 pm | INFO [02-17\|18:45:03.474] Imported new block headers count=1 elapsed="136.788µs" number=16,647,924 hash=78e76d..18d68e
Fri, Feb 17 2023 6:45:05 pm | INFO [02-17\|18:45:05.712] Syncing: state healing in progress accounts=83308@4.16MiB slots=357,721@25.94MiB codes=118@952.63KiB nodes=1,182,518@257.13MiB pending=15570
Fri, Feb 17 2023 6:45:12 pm | INFO [02-17\|18:45:12.974] Forkchoice requested sync to new head number=16,647,925 hash=c6fbef..381127
Fri, Feb 17 2023 6:45:13 pm | INFO [02-17\|18:45:13.814] Syncing: state healing in progress accounts=83525@4.17MiB slots=358,151@25.97MiB codes=119@961.03KiB nodes=1,184,594@257.62MiB pending=15074
Fri, Feb 17 2023 6:45:15 pm | INFO [02-17\|18:45:15.476] Imported new block headers count=1 elapsed="151.392µs" number=16,647,925 hash=c6fbef..381127
Fri, Feb 17 2023 6:45:21 pm | INFO [02-17\|18:45:21.857] Syncing: state healing in progress accounts=83670@4.18MiB slots=358,510@26.00MiB codes=121@969.06KiB nodes=1,186,375@258.10MiB pending=14936
Fri, Feb 17 2023 6:45:24 pm | INFO [02-17\|18:45:24.455] Forkchoice requested sync to new head number=16,647,926 hash=4ef204..ae838c
Fri, Feb 17 2023 6:45:24 pm | INFO [02-17\|18:45:24.480] Imported new block headers count=1 elapsed="204.898µs" number=16,647,926 hash=4ef204..ae838c
Fri, Feb 17 2023 6:45:29 pm | INFO [02-17\|18:45:29.888] Syncing: state healing in progress accounts=83808@4.19MiB slots=359,006@26.04MiB codes=121@969.06KiB nodes=1,188,265@258.58MiB pending=14625
Fri, Feb 17 2023 6:45:36 pm | INFO [02-17\|18:45:36.107] Forkchoice requested sync to new head number=16,647,927 hash=f9a1d0..b71073
Fri, Feb 17 2023 6:45:36 pm | INFO [02-17\|18:45:36.485] Imported new block headers count=1 elapsed="135.392µs" number=16,647,927 hash=f9a1d0..b71073
Fri, Feb 17 2023 6:45:37 pm | INFO [02-17\|18:45:37.952] Syncing: state healing in progress accounts=83919@4.19MiB slots=359,301@26.06MiB codes=121@969.06KiB nodes=1,190,034@259.07MiB pending=14974
Fri, Feb 17 2023 6:45:46 pm | INFO [02-17\|18:45:46.220] Syncing: state healing in progress accounts=84191@4.21MiB slots=359,772@26.09MiB codes=121@969.06KiB nodes=1,192,374@259.61MiB pending=14465
Fri, Feb 17 2023 6:45:48 pm | INFO [02-17\|18:45:48.191] Forkchoice requested sync to new head number=16,647,928 hash=958975..d71faa
Fri, Feb 17 2023 6:45:48 pm | INFO [02-17\|18:45:48.488] Imported new block headers count=1 elapsed="194.16µs" number=16,647,928 hash=958975..d71faa
Fri, Feb 17 2023 6:45:48 pm | INFO [02-17\|18:45:48.870] Downloader queue stats receiptTasks=0 blockTasks=0 itemSize=268.67KiB throttle=976

@MariusVanDerWijden

holiman commented 1 year ago

Now it's stuck in 0xfe0600(5min).

You're at 0xfe0600 == 16647680, head right now is 16647959. So you have downloaded all the blocks (for now), but it's not yet finished with the state healing. That the IO is high is natural, this stage is involves a lot of db lookups.

J1a-wei commented 1 year ago

Is this the same high io situation that happened before with levelDB? I forget what the previous sync speed was, but in my own intuition, this sync time is a bit too long. It's rare to get stuck in a certain place before . Btw, can I use levelDB all the time in the future? Even if geth is upgraded to 1.2 1.3, it should be able to work properly. We still have many nodes with v1.10.26, so we may not use pebble if we consider upgrading. @holiman

karalabe commented 1 year ago

Your IOPs seems to be brutally capped. A consumer SSD can do 100K iops, your setup seems to be limited to 3K. That will cause state heal to take an enormous time.

J1a-wei commented 1 year ago

Yes, for fast migration(kubernetes) we are using aws ebs with disk type gp2. The iops calculation formula is 3 * GB. The minimum iops is 3000 and the maximum is 16000. iops is indeed a problem, but this was not the case before with levelDB. I am curious what advantages does pebbleDB have over levelDB? Does it reduce latency, we deploy a lot of staking operations and often the balance is reduced due to slow synchronization @karalabe

holiman commented 1 year ago

Btw, can I use levelDB all the time in the future? Even if geth is upgraded to 1.2 1.3, it should be able to work properly. We still have many nodes with v1.10.26, so we may not use pebble if we consider upgrading.

You can stay with leveldb for now. Long-term, that might not always be the case. Pebble is now being evaluated.

Tadouh commented 1 year ago

I would say its using 10% more of each of my system resources when synced and a ton more cpu on initial sync. That would be awesome if it actually protected against unclean shutdowns. I just ran some tests doing unclean shutdowns with pebble db and its no different than leveldb in that its ruined with an unclean shutdown and needs to resync. I am no where near as knowledgeable on the subject, just telling you real world use. Is there a reason why we can not use bolt db that prysm uses? I have ran the same exact database on my beacon node since genesis. I have had so many unclean shutdowns, most on purpose during setting up my node to harden it, but i have never had to re sync my prysm node ever. Every time it boots back up by itself and runs clean. Guess what, geth has never ever. Even on restarts that are clean some times i have to re sync from ancient. I have rysynced my geth at least a 25 to 50 times over the same time frame. In real world tests bolt is super resilient to unclean shutdowns. Is there a reason we cannot use this database ?

karalabe commented 1 year ago

@Tadouh Geth caches a lot of trie nodes in RAM, as in dirty trie nodes that were never written to disk. If you murder Geth, all that data is lost and it needs to rerun a lot of past blocks to recover it. That's not a resync, it jsut needs to go back in time to get the data. Doesn't matter what database you use, it has to do the same.

The point behind this operation is to limit the amount of data we write to disk. Rather we keep new things in RAM until they turn out to be "probably" necessary to write out.

karalabe commented 1 year ago

If in your case Geth does indeed do a full resync, please provide some logs. I doubt it though.

karalabe commented 1 year ago

We're slowly merging in a new trie data model though, that won't require in memory garbage collection and will forever solve this issue of losing trie nodes and having to go back in time.

Tadouh commented 1 year ago

@Tadouh Geth caches a lot of trie nodes in RAM, as in dirty trie nodes that were never written to disk. If you murder Geth, all that data is lost and it needs to rerun a lot of past blocks to recover it. That's not a resync, it jsut needs to go back in time to get the data. Doesn't matter what database you use, it has to do the same.

The point behind this operation is to limit the amount of data we write to disk. Rather we keep new things in RAM until they turn out to be "probably" necessary to write out.

Why do i have to "re run" 8 hours worth of blocks with geth due to power failure or some other unclean shutdown, but never have to with my prysm data base running on bolt db... Like in my test the other day, the bolt db was perfectly fine and booted up with no need to catch up anything, while geth had to spend hours catching its breath and i have a meaty system. Not trying to complain about it, just wondering why we dont use a database like prysm uses, its written in go and i have never once since genesis had to do any re sync, any re run, with that database, every single time my system went down, bolt db is fine, leveldb and now pebble db are damaged. So, something matters, i am not sure if it the database cause bolt handles it perfectly, or some other code. I cannot get bolt/prysm to take a crap on me. No matter how many times i have tried and over the years its still running like it was from day one. Geth i have repaired re synced re run so many times I lost count. I am certainly not tech savvy like you devs, just something i noticed and since i saw you guys were doing work on changing from leveldb, i thought i would through out the option of bolt because its super resilent to the number 1 problem geth has. If prysm can handle any unclean shutdown, it would be nice if geth could too seeing how they are 1 to 1 now. Pebble does not do this. It needed to be re run just like geth. Maybe its something else they use that its protection against this data not being written to disk, I am assuming its bolt, when it could be many things. Ill post some logs next time it takes a dive, wont be long. But it usually re runs from the last time I restarted the computer taking 6 hours on a 16 core i9 with 64gb ram even with cache flag to 32000. I have better luck and can sync faster nuking the leveldb and letting ancient rebuild. Glad to hear you guys working on solving the issue already as its my own beef with geth.

karalabe commented 1 year ago

If this was true, every time I had to "re run" 8 hours worth of blocks with geth due to power failure or some other unclean shutdown, I would also have to do the same to my prysm data base running on bolt db...

How did you arrive to that conclusion. Geth and Prysm are two different projects and they do their thing differently. The becaon chain has an insignificant tiny state, you can just shove it to disk and be done with it. Geth's state is insane.

holiman commented 1 year ago

That would be awesome if it actually protected against unclean shutdowns.

@Tadouh if that is your primary pain-point, then you should run with gcmode=archive. That way, geth doesn't keep as much in memory, and is not as dependent on an orderly shutdown.

The price to pay is that more 'junk' is accumulated over time, but it should give less problems due to unclean shutdowns.

Tadouh commented 1 year ago

Its not a conclusion its facts. Geth dies looking at it the wrong way, prysm never does. Geth was dying just like this back when it was only 100gbs so that's not a valid excuse for Prysms resiliency and geths lack of it. Seeing how these are 1 to 1 now. It would be nice if we could get Ol faithful as reliable as the new kid in town. Geth is the superior client hands down, but this one issue handicaps it. Its not just me, its the top complaint with geth node operators. Most of us just re sync and thats that. But with a validator attached now. We pay for geth resyncing.

Tadouh commented 1 year ago

That would be awesome if it actually protected against unclean shutdowns.

@Tadouh if that is your primary pain-point, then you should run with gcmode=archive. That way, geth doesn't keep as much in memory, and is not as dependent on an orderly shutdown.

The price to pay is that more 'junk' is accumulated over time, but it should give less problems due to unclean shutdowns.

Thanks for that ill try running this now. I would sacrifice some space for that protection any day.

karalabe commented 1 year ago

Thanks for that ill try running this now. I would sacrifice some space for that protection any day.

An archive node is 13TB, have fun

holiman commented 1 year ago

Not trying to complain about it, just wondering why we dont use a database like prysm use

So, something matters, i am not sure if it the database cause bolt handles it perfectly,

I am certainly not tech savvy like you dev

@Tadouh we are telling you facts. It does not matter what the backend is. We are not persisting to disk, we are maintaining data in memory, in order to do pruning. If we crash in that time, we need to recover that, it takes hours. Regardless of what data-backend we did not write to.

An archive node is 13TB, have fun

@karalabe come on, it isn't, there's no need to do archive from genesis. It just grows faster.

Tadouh commented 1 year ago

Thanks for that ill try running this now. I would sacrifice some space for that protection any day.

An archive node is 13TB, have fun

lmao i didnt even notice what the code said yet. So if thats the only solution you got you guys got alot of work ahead. Nobody is gonna run archive nodes they will just use another more resilient client. 10 years later and geth still cannot restart properly from a power failure or any other unclean shutdown.

rjl493456442 commented 1 year ago

Yes, for fast migration(kubernetes) we are using aws ebs with disk type gp2. The iops calculation formula is 3 * GB. The minimum iops is 3000 and the maximum is 16000. iops is indeed a problem, but this was not the case before with levelDB. I am curious what advantages does pebbleDB have over levelDB? Does it reduce latency, we deploy a lot of staking operations and often the balance is reduced due to slow synchronization @karalabe

Pebble and leveldb have the same design concept, both are based on LSM-Tree storage engine. However, go-leveldb is not actively maintained but pebble has a team behind it. It's expected that pebble will bring up more optimizations/features.

And also one obvious advantage pebble has is concurrent compaction. The efficiency of compaction is the bottleneck of storage engine write performance to some extent. However, we found that in the process of compaction, disk reading and writing only takes up a small part of the time, but most of the time is for CPU operations, such as SNAPPY encode/decode, CRC checksum, etc. So introducing concurrent compaction is a straightforward idea. Unfortunately go-leveldb author thought that this project won't accept major change such as concurrent compaction. Unlikely it's supported by pebble. It can be the reason for higher disk ops with pebble. (Note, SSD can offer with high disk ops, but leveldb can't use that capacity but pebble uses more).

Tadouh commented 1 year ago

Not trying to complain about it, just wondering why we dont use a database like prysm use

So, something matters, i am not sure if it the database cause bolt handles it perfectly,

I am certainly not tech savvy like you dev

@Tadouh we are telling you facts. It does not matter what the backend is. We are not persisting to disk, we are maintaining data in memory, in order to do pruning. If we crash in that time, we need to recover that, it takes hours. Regardless of what data-backend we did not write to.

An archive node is 13TB, have fun

If it does not matter, why can a different client handle this without missing a beat, but geth cannot?

karalabe commented 1 year ago

If it does not matter, why can a different client handle this without missing a beat, but geth cannot?

Because one is an apple and the other is an orange which do different things. Prysm's active state is 32KB and Geth's is 90GB.

holiman commented 1 year ago

@Tadouh We have explained, it's up to you if you choose to listen. You are welcome to try a different client, in fact, it's only good for the ecosystem if people use different ones.

You are distracting and this is not going anywhere. Please stop spamming here, or I will block you.

ethereum / go-ethereum