avalanchego icon indicating copy to clipboard operation
avalanchego copied to clipboard

Bootstrap never finishes due to constantly increasing C-Chain job execution ETA

Open ssg opened this issue 2 years ago • 5 comments

Describe the bug Bootstrap doesn't finish for weeks, and ETA for executing C-Chain operations constantly increases (now at 1509 hours). The node is regarded as "unresponsive." Do the minimum requirements need an update?

To Reproduce Start Avalanchego 1.7.5 or later.

Expected behavior A node should bootstrap in a reasonable time.

Logs Excerpt that shows increasing ETA:

INFO [03-02|05:34:25.957] committed atomic trie                    c=atomicTrie hash=0x82863b5aabd388b40ec60c3cc52e43b983e4bfaec2f86b038ca89246aa764061 height=7,200,768
INFO [03-02|05:40:40.394] <C Chain> snow/engine/common/queue/jobs.go#173: executed 2500 of 4375509 operations. ETA = 1187h45m56.061520188s
INFO [03-02|05:50:41.868] Persisted trie from memory database      nodes=99184    size=25.02MiB time=2.522534826s gcnodes=419,048 gcsize=150.31MiB gctime=2.713474992s livenodes=5539 livesize=1.66MiB
INFO [03-02|06:35:34.255] <C Chain> snow/engine/common/queue/jobs.go#173: executed 5000 of 4375509 operations. ETA = 1393h18m13.835962908s
INFO [03-02|06:58:40.264] Persisted trie from memory database      nodes=249,061  size=55.69MiB time=18.045501545s gcnodes=1,477,257 gcsize=526.17MiB gctime=11.219218165s livenodes=6670 livesize=1.88MiB
INFO [03-02|06:58:40.289] committed atomic trie                    c=atomicTrie hash=0x7e5f2e283aece2a2c9b19c49df3259c679071dc835d34314b7ebde9bc31dd723 height=7,204,864
INFO [03-02|07:24:43.173] <C Chain> snow/engine/common/queue/jobs.go#173: executed 7500 of 4375509 operations. ETA = 1405h23m54.312944576s
INFO [03-02|07:43:41.767] Persisted trie from memory database      nodes=191,356  size=43.61MiB time=4.794538655s  gcnodes=1,035,386 gcsize=369.11MiB gctime=7.457448036s  livenodes=5827 livesize=1.48MiB
INFO [03-02|08:18:19.660] <C Chain> snow/engine/common/queue/jobs.go#173: executed 10000 of 4375509 operations. ETA = 1443h29m22.172409684s
INFO [03-02|08:24:45.002] Persisted trie from memory database      nodes=184,560  size=42.25MiB time=4.459677899s  gcnodes=941,542   gcsize=337.47MiB gctime=6.779400396s  livenodes=6982 livesize=1.81MiB
INFO [03-02|08:24:45.025] committed atomic trie                    c=atomicTrie hash=0x80ebf8734432d13fa9431959649c73beb36c423232d011fe9796f7832ae2d50c height=7,208,960
INFO [03-02|09:11:57.879] <C Chain> snow/engine/common/queue/jobs.go#173: executed 12500 of 4375509 operations. ETA = 1466h9m40.348872835s
INFO [03-02|09:35:41.941] Persisted trie from memory database      nodes=281,483  size=60.63MiB time=7.483482783s  gcnodes=1,642,917 gcsize=589.40MiB gctime=12.678415843s livenodes=8136 livesize=2.06MiB
INFO [03-02|09:52:52.230] Persisted trie from memory database      nodes=92600    size=23.24MiB time=2.59879136s   gcnodes=336,108   gcsize=121.29MiB gctime=2.205812837s  livenodes=7598 livesize=1.83MiB
INFO [03-02|09:52:52.245] committed atomic trie                    c=atomicTrie hash=0xff1907ffaea64aafb538e5b6d3e643a73cfddb90acb14b976a2d76caed036aa4 height=7,213,056
INFO [03-02|10:06:02.503] <C Chain> snow/engine/common/queue/jobs.go#173: executed 15000 of 4375509 operations. ETA = 1483h6m17.371793208s
INFO [03-02|10:57:56.012] <C Chain> snow/engine/common/queue/jobs.go#173: executed 17500 of 4375509 operations. ETA = 1485h52m26.869763021s
INFO [03-02|11:20:06.313] Persisted trie from memory database      nodes=290,399  size=63.52MiB time=17.269150458s gcnodes=1,800,760 gcsize=644.76MiB gctime=14.006990205s livenodes=6229 livesize=1.18MiB
INFO [03-02|11:20:06.329] committed atomic trie                    c=atomicTrie hash=0xfef111072b14a6e0aa81016eb37d3f4f381bee9c1b4af977a36983ca2146bd55 height=7,217,152
INFO [03-02|11:29:16.999] Persisted trie from memory database      nodes=48084    size=13.12MiB time=2.010726863s  gcnodes=158,541   gcsize=57.16MiB  gctime=983.40184ms   livenodes=3732 livesize=203.96KiB
INFO [03-02|11:53:24.209] <C Chain> snow/engine/common/queue/jobs.go#173: executed 20000 of 4375509 operations. ETA = 1500h43m51.075303993s
INFO [03-02|13:01:07.762] <C Chain> snow/engine/common/queue/jobs.go#173: executed 22500 of 4375509 operations. ETA = 1551h35m44.91396112s
INFO [03-02|13:03:33.501] Persisted trie from memory database      nodes=247,911  size=54.89MiB time=14.384092719s gcnodes=1,694,554 gcsize=599.84MiB gctime=12.87754616s  livenodes=6919 livesize=1.19MiB
INFO [03-02|13:03:33.555] committed atomic trie                    c=atomicTrie hash=0x516f19a58d8c66ad6f5d22ba880444eeb096572589ecea7b3217836254f84ccc height=7,221,248
INFO [03-02|13:35:21.278] Persisted trie from memory database      nodes=137,374  size=33.49MiB time=4.156749953s  gcnodes=647,153   gcsize=232.81MiB gctime=4.451416525s  livenodes=6164 livesize=872.39KiB
INFO [03-02|13:51:11.763] <C Chain> snow/engine/common/queue/jobs.go#173: executed 25000 of 4375509 operations. ETA = 1540h50m39.750452128s
INFO [03-02|14:22:09.154] Persisted trie from memory database      nodes=192,057  size=44.49MiB time=4.661797657s  gcnodes=1,122,174 gcsize=400.79MiB gctime=7.946666507s  livenodes=6736 livesize=969.03KiB
INFO [03-02|14:22:09.173] committed atomic trie                    c=atomicTrie hash=0x93ea7409959f869fe65c74250078fe93b9bb64197efd79e2e19d3a5f1df2c912 height=7,225,344
INFO [03-02|14:40:29.699] <C Chain> snow/engine/common/queue/jobs.go#173: executed 27500 of 4375509 operations. ETA = 1529h52m24.10375867s
INFO [03-02|15:20:37.335] Persisted trie from memory database      nodes=213,991  size=48.75MiB time=5.560857193s  gcnodes=1,276,518 gcsize=455.97MiB gctime=9.334655447s  livenodes=7570 livesize=1.07MiB
INFO [03-02|15:30:59.121] <C Chain> snow/engine/common/queue/jobs.go#173: executed 30000 of 4375509 operations. ETA = 1523h28m4.139837293s
INFO [03-02|15:44:55.264] Persisted trie from memory database      nodes=120,956  size=29.80MiB time=2.932364362s  gcnodes=546,214   gcsize=194.98MiB gctime=3.612248492s  livenodes=6439 livesize=596.67KiB
INFO [03-02|15:44:55.277] committed atomic trie                    c=atomicTrie hash=0xef670338ede0bab3e6ac6362a2d6d2680ad8a2eb706bedce764216c448d44918 height=7,229,440
INFO [03-02|16:13:21.774] <C Chain> snow/engine/common/queue/jobs.go#173: executed 32500 of 4375509 operations. ETA = 1499h51m13.08030345s
INFO [03-02|16:50:12.762] Persisted trie from memory database      nodes=277,736  size=61.15MiB time=25.000444759s gcnodes=1,744,129 gcsize=621.17MiB gctime=13.005017372s livenodes=5901 livesize=232.94KiB
INFO [03-02|16:52:29.197] Persisted trie from memory database      nodes=23947    size=6.98MiB  time=694.217277ms  gcnodes=44426     gcsize=16.18MiB  gctime=254.419078ms  livenodes=4542 livesize=-282226.00B
INFO [03-02|16:52:29.209] committed atomic trie                    c=atomicTrie hash=0xd58b41b89b7ce394f7b3c2dc2d48e7c30cc87f343f31d3b44f407bfbf003f4d7 height=7,233,536
INFO [03-02|16:54:15.266] <C Chain> snow/engine/common/queue/jobs.go#173: executed 35000 of 4375509 operations. ETA = 1476h26m19.673029261s
INFO [03-02|17:43:05.758] <C Chain> snow/engine/common/queue/jobs.go#173: executed 37500 of 4375509 operations. ETA = 1471h23m1.855897962s
INFO [03-02|18:12:28.754] Persisted trie from memory database      nodes=268,595  size=59.29MiB time=15.665462286s gcnodes=1,724,980 gcsize=613.97MiB gctime=12.985298786s livenodes=5906 livesize=89.46KiB
INFO [03-02|18:12:28.776] committed atomic trie                    c=atomicTrie hash=0xeb5b6eeaeb6c2d560361c268811a82fcc468262ad2c6852326cf0ece00f30f79 height=7,237,632
INFO [03-02|18:40:39.622] <C Chain> snow/engine/common/queue/jobs.go#173: executed 40000 of 4375509 operations. ETA = 1482h36m50.979827441s
INFO [03-02|18:41:25.553] Persisted trie from memory database      nodes=109,940  size=27.62MiB time=3.690021236s  gcnodes=470,026   gcsize=168.01MiB gctime=3.191457604s  livenodes=6653 livesize=263.32KiB
INFO [03-02|19:38:03.176] <C Chain> snow/engine/common/queue/jobs.go#173: executed 42500 of 4375509 operations. ETA = 1492h7m4.800887399s
INFO [03-02|19:49:49.813] Persisted trie from memory database      nodes=254,563  size=56.59MiB time=8.830572683s  gcnodes=1,627,438 gcsize=579.86MiB gctime=12.137101457s livenodes=7979 livesize=526.89KiB
INFO [03-02|19:49:49.839] committed atomic trie                    c=atomicTrie hash=0x6fc0fe094fd6ad01fca3c38fffab32ecba90ab339453a5cbedbd99c6215f8adb height=7,241,728
INFO [03-02|20:33:05.807] <C Chain> snow/engine/common/queue/jobs.go#173: executed 45000 of 4375509 operations. ETA = 1496h41m41.879907686s
INFO [03-02|20:40:34.060] Persisted trie from memory database      nodes=206,186  size=47.29MiB time=4.454883427s  gcnodes=1,164,626 gcsize=413.79MiB gctime=8.454354086s  livenodes=7567 livesize=323.08KiB
INFO [03-02|21:26:44.931] Persisted trie from memory database      nodes=180,241  size=42.34MiB time=3.73332623s   gcnodes=950,189   gcsize=339.23MiB gctime=6.828456553s  livenodes=7791 livesize=226.12KiB
INFO [03-02|21:26:44.953] committed atomic trie                    c=atomicTrie hash=0xdad5c0e50d6c9c1b8cdd2d66bfcccd59cbc3698bb31bc515a9bac4683dd98dff height=7,245,824
INFO [03-02|21:33:37.298] <C Chain> snow/engine/common/queue/jobs.go#173: executed 47500 of 4375509 operations. ETA = 1509h0m57.150201492s

Operating System Linux 3.10.108 x64_64 - Intel N3710 Braswell 4-core CPU @ 1.6Ghz

Additional context This is a system below the latest minimum RAM requirements: It only has 8GB. But, the Docker container only uses 2GB at most. So, the issue must be irrelevant of RAM availability.

The CPU meets the min spec (8 AWS vCPUs = 4 cores), but it doesn't support the newer instruction set required for RocksDB, so the code falls back to LevelDB.

By submitting this issue I agree to the Terms and Conditions of the Developer Accelerator Program.

ssg avatar Mar 02 '22 22:03 ssg

same one

Comolli avatar Mar 22 '22 02:03 Comolli

Same problem here

Qlimnos avatar Mar 24 '22 00:03 Qlimnos

same one

Maybe this is not a bug, just wait until the number of jobs that need to be scheduled is enough.

Comolli avatar Apr 02 '22 17:04 Comolli

same one

xinxurockx avatar Jun 24 '22 07:06 xinxurockx

Same issue here as well. Using AVADO i7 node bought for AVAX staking and can't bootstrap.

johnjersey avatar Aug 04 '22 16:08 johnjersey