Memory leak during State Sync

[GAtom22]

Description

Trying to perform the state sync on an Evmos node noticed that the process runs OOM.

Using GODEBUG=gctrace=1 can be observed that the heap used increases while applying the snapshot chunks. Filtering only the gctrace logs when fetching and applying the snapshot chunks we can see the size of the heap continues to grow over time:

gc 34 @23.159s 0%: 0.046+1.5+0.004 ms clock, 0.37+1.4/2.6/5.7+0.037 ms cpu, 4650->4650->4650 MB, 4650 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 35 @23.172s 0%: 0.093+678+0.025 ms clock, 0.74+0/2.9/520+0.20 ms cpu, 5803->5803->3497 MB, 5803 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 36 @24.396s 0%: 0.047+1.7+0.008 ms clock, 0.38+0/3.2/7.2+0.067 ms cpu, 4201->4201->2706 MB, 4201 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 37 @24.841s 0%: 0.048+1.6+0.008 ms clock, 0.38+0/2.7/7.0+0.067 ms cpu, 3261->3261->2984 MB, 3261 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 38 @25.315s 0%: 0.045+1.7+0.008 ms clock, 0.36+0/3.1/6.8+0.066 ms cpu, 3581->3581->3282 MB, 3581 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 39 @25.874s 0%: 0.042+5.3+0.004 ms clock, 0.33+0/3.7/11+0.036 ms cpu, 3944->3944->3602 MB, 3944 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 40 @40.751s 0%: 0.10+2.3+0.009 ms clock, 0.87+0.21/4.4/10+0.075 ms cpu, 5347->5347->2349 MB, 5347 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 41 @40.912s 1%: 0.044+344+298 ms clock, 0.35+0.25/195/10+2390 ms cpu, 3502->4655->3502 MB, 3502 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 42 @41.557s 1%: 11+6.3+0.031 ms clock, 89+1.4/11/4.5+0.24 ms cpu, 4656->4656->4654 MB, 4656 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 43 @41.687s 1%: 0.049+397+0.094 ms clock, 0.39+0.45/259/9.0+0.75 ms cpu, 5808->5829->3522 MB, 5808 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 44 @42.667s 1%: 0.039+3.5+0.003 ms clock, 0.31+0.91/5.6/8.8+0.028 ms cpu, 4228->4228->2710 MB, 4228 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 45 @43.080s 1%: 0.044+1.8+0.009 ms clock, 0.35+0.19/3.3/8.5+0.074 ms cpu, 3244->3244->2988 MB, 3253 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 46 @43.559s 1%: 0.043+2.0+0.007 ms clock, 0.34+0/3.7/8.4+0.058 ms cpu, 3586->3586->3286 MB, 3586 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 47 @44.133s 1%: 0.041+5.8+0.004 ms clock, 0.33+0.60/7.8/9.1+0.039 ms cpu, 3948->3948->3607 MB, 3948 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 48 @44.629s 1%: 0.085+2.9+0.011 ms clock, 0.68+0.17/4.7/10+0.090 ms cpu, 5318->5318->3885 MB, 5318 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 49 @54.534s 0%: 0.042+243+0.016 ms clock, 0.33+0.22/246/12+0.13 ms cpu, 5065->5066->5041 MB, 5065 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 50 @54.784s 0%: 2.3+320+0.018 ms clock, 19+0/5.2/327+0.14 ms cpu, 6195->6196->3888 MB, 6195 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 51 @65.110s 0%: 15+2.7+0.011 ms clock, 127+2.6/5.2/8.6+0.095 ms cpu, 5152->5152->3898 MB, 5152 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 52 @74.244s 0%: 0.083+24+0.011 ms clock, 0.66+0.37/49/72+0.093 ms cpu, 4674->4679->4053 MB, 4678 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 53 @75.445s 0%: 6.4+264+0.005 ms clock, 51+75/297/77+0.047 ms cpu, 5515->5515->5251 MB, 5515 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 54 @75.728s 0%: 3.7+598+0.007 ms clock, 29+38/628/109+0.060 ms cpu, 6406->6406->4088 MB, 6406 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 55 @80.441s 0%: 0.071+42+0.013 ms clock, 0.56+24/85/164+0.11 ms cpu, 4902->4908->3045 MB, 4906 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 56 @84.383s 0%: 0.078+57+0.009 ms clock, 0.62+2.3/115/239+0.077 ms cpu, 3645->3655->3137 MB, 3655 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 57 @88.445s 0%: 0.069+62+0.054 ms clock, 0.55+0.85/124/300+0.43 ms cpu, 3736->3737->3221 MB, 3765 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 58 @95.243s 0%: 0.088+79+0.012 ms clock, 0.70+0.42/158/340+0.097 ms cpu, 3845->3855->3298 MB, 3865 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 59 @100.459s 0%: 0.069+98+0.011 ms clock, 0.55+0.49/195/403+0.089 ms cpu, 3939->3953->3373 MB, 3959 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 60 @106.173s 0%: 0.078+110+0.010 ms clock, 0.62+0.55/220/450+0.081 ms cpu, 4007->4025->3457 MB, 4048 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 61 @112.821s 0%: 0.074+122+0.008 ms clock, 0.59+1.1/245/506+0.070 ms cpu, 4097->4119->3544 MB, 4149 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 62 @119.337s 0%: 0.079+137+0.008 ms clock, 0.63+0.43/274/543+0.066 ms cpu, 4191->4218->3635 MB, 4253 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 63 @125.927s 0%: 0.058+127+0.008 ms clock, 0.46+0.28/254/639+0.071 ms cpu, 4287->4289->3691 MB, 4363 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 64 @131.762s 0%: 0.083+164+0.010 ms clock, 0.66+0.64/327/649+0.081 ms cpu, 4381->4412->3800 MB, 4430 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 65 @138.807s 0%: 0.075+262+0.014 ms clock, 0.60+0.75/524/1024+0.11 ms cpu, 4511->4543->3907 MB, 4560 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 66 @148.783s 0%: 0.093+276+0.013 ms clock, 0.75+0.83/549/1133+0.10 ms cpu, 4590->4622->3985 MB, 4688 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 67 @155.389s 0%: 0.080+237+0.058 ms clock, 0.64+0.53/472/972+0.47 ms cpu, 4682->4714->4076 MB, 4783 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 68 @164.051s 0%: 0.065+191+0.014 ms clock, 0.52+0/381/950+0.11 ms cpu, 4791->4796->4151 MB, 4891 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 69 @171.536s 0%: 0.077+231+0.011 ms clock, 0.61+1.9/462/974+0.093 ms cpu, 4922->4963->4268 MB, 4982 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 70 @178.723s 0%: 0.064+239+0.011 ms clock, 0.51+0.42/478/1036+0.091 ms cpu, 5049->5089->4369 MB, 5122 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 71 @188.916s 0%: 0.059+230+0.009 ms clock, 0.47+0.27/457/1146+0.079 ms cpu, 5112->5118->4425 MB, 5243 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 72 @198.280s 0%: 0.086+280+0.008 ms clock, 0.69+0.55/561/1161+0.069 ms cpu, 5234->5286->4558 MB, 5311 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 73 @206.035s 0%: 0.071+267+0.008 ms clock, 0.57+13/531/1273+0.070 ms cpu, 5380->5396->4626 MB, 5470 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 74 @219.151s 0%: 0.11+314+0.009 ms clock, 0.90+0.49/627/1274+0.079 ms cpu, 5440->5506->4759 MB, 5551 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 75 @226.700s 0%: 0.066+324+0.011 ms clock, 0.52+1.1/648/1343+0.095 ms cpu, 5582->5641->4864 MB, 5711 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 76 @238.312s 0%: 0.062+293+0.003 ms clock, 0.49+0.41/583/1488+0.031 ms cpu, 5641->5655->4908 MB, 5837 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 77 @245.408s 0%: 0.082+359+0.010 ms clock, 0.66+0.88/718/1510+0.087 ms cpu, 5771->5850->5083 MB, 5889 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 78 @257.264s 0%: 0.063+394+0.024 ms clock, 0.50+0.35/787/1625+0.19 ms cpu, 5951->6026->5186 MB, 6100 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 79 @264.319s 0%: 0.059+374+0.009 ms clock, 0.47+0.17/747/1703+0.077 ms cpu, 5981->6031->5273 MB, 6224 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 80 @275.961s 0%: 0.13+440+0.011 ms clock, 1.0+1.4/880/1751+0.090 ms cpu, 6126->6191->5389 MB, 6328 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 81 @287.060s 0%: 0.11+530+0.015 ms clock, 0.91+0.64/1059/2634+0.12 ms cpu, 6286->6293->5445 MB, 6468 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 82 @300.823s 0%: 0.80+476+0.013 ms clock, 6.4+85/950/1824+0.11 ms cpu, 6420->6499->5618 MB, 6535 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 83 @314.230s 0%: 0.098+472+0.010 ms clock, 0.78+0.92/944/1921+0.087 ms cpu, 6607->6672->5717 MB, 6742 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 84 @322.314s 0%: 0.066+423+0.009 ms clock, 0.53+0.23/844/2160+0.073 ms cpu, 6637->6645->5786 MB, 6861 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 85 @335.338s 0%: 0.077+513+0.012 ms clock, 0.62+11/1027/2080+0.10 ms cpu, 6826->6912->5973 MB, 6944 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 86 @349.102s 0%: 0.091+539+0.009 ms clock, 0.73+1.9/1078/2141+0.077 ms cpu, 7023->7116->6101 MB, 7168 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 87 @363.824s 0%: 0.078+784+0.018 ms clock, 0.62+0.87/1566/3192+0.14 ms cpu, 7047->7159->6223 MB, 7322 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 88 @374.108s 0%: 0.10+737+0.004 ms clock, 0.86+9.2/1472/3418+0.036 ms cpu, 7155->7208->6296 MB, 7468 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 89 @387.640s 0%: 0.085+587+0.009 ms clock, 0.68+0.34/1171/2436+0.072 ms cpu, 7294->7398->6462 MB, 7556 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 90 @401.000s 0%: 0.064+620+0.011 ms clock, 0.51+0.44/1240/2546+0.090 ms cpu, 7502->7607->6585 MB, 7755 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 91 @414.072s 0%: 0.11+654+0.018 ms clock, 0.94+0.90/1308/2667+0.14 ms cpu, 7577->7694->6721 MB, 7903 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 92 @427.782s 0%: 0.12+684+0.013 ms clock, 0.97+1.2/1367/2692+0.10 ms cpu, 7722->7851->6854 MB, 8065 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 93 @438.798s 0%: 0.063+581+0.004 ms clock, 0.50+0.16/1163/2939+0.039 ms cpu, 7850->7868->6882 MB, 8225 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 94 @452.471s 0%: 0.078+885+0.012 ms clock, 0.63+0.44/1769/4207+0.098 ms cpu, 8029->8072->7036 MB, 8258 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 95 @471.864s 0%: 0.066+624+0.008 ms clock, 0.52+0.87/1247/3164+0.068 ms cpu, 8337->8344->7143 MB, 8443 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 96 @489.228s 0%: 0.092+739+0.003 ms clock, 0.73+262/1477/3069+0.030 ms cpu, 8489->8573->7366 MB, 8572 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 97 @504.172s 0%: 0.086+761+0.012 ms clock, 0.68+0.56/1522/3195+0.10 ms cpu, 8681->8799->7568 MB, 8839 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 98 @518.563s 0%: 0.096+728+0.004 ms clock, 0.77+0.35/1454/3432+0.037 ms cpu, 8748->8806->7661 MB, 9082 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 99 @536.946s 0%: 0.13+1008+0.004 ms clock, 1.0+1.2/2015/5059+0.034 ms cpu, 8907->8922->7761 MB, 9193 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 100 @558.763s 0%: 0.078+833+0.009 ms clock, 0.62+228/1665/3310+0.072 ms cpu, 9188->9319->8019 MB, 9313 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 101 @574.903s 0%: 0.13+864+0.009 ms clock, 1.0+0.23/1727/3627+0.076 ms cpu, 9383->9523->8206 MB, 9624 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 102 @590.392s 1%: 0.073+791+0.008 ms clock, 0.59+0.35/1581/3898+0.069 ms cpu, 9408->9449->8255 MB, 9848 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 103 @610.433s 1%: 0.095+808+0.003 ms clock, 0.76+0.47/1613/4002+0.030 ms cpu, 9613->9638->8373 MB, 9907 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 104 @632.511s 1%: 0.083+1350+0.012 ms clock, 0.66+190/2700/5756+0.10 ms cpu, 9930->10053->8648 MB, 10048 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 105 @655.573s 1%: 0.071+980+0.018 ms clock, 0.57+1.5/1960/4101+0.15 ms cpu, 10131->10289->8847 MB, 10378 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 106 @672.146s 1%: 0.064+972+0.009 ms clock, 0.51+0.16/1943/4346+0.076 ms cpu, 10165->10287->8974 MB, 10617 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 107 @691.765s 1%: 0.078+901+0.009 ms clock, 0.63+0.51/1803/4548+0.074 ms cpu, 10320->10347->9028 MB, 10769 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 108 @710.742s 1%: 0.098+1092+0.010 ms clock, 0.78+4.9/2180/4446+0.087 ms cpu, 10586->10777->9362 MB, 10834 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 109 @734.275s 1%: 1.8+1404+0.016 ms clock, 14+3.2/2808/5676+0.12 ms cpu, 10896->11074->9521 MB, 11234 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 110 @757.485s 1%: 0.092+1609+0.017 ms clock, 0.74+0.64/3218/6489+0.14 ms cpu, 10861->11079->9705 MB, 11426 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 111 @776.913s 1%: 0.072+1051+0.004 ms clock, 0.57+0.70/2100/4984+0.032 ms cpu, 11070->11153->9739 MB, 11646 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 112 @800.882s 1%: 0.092+1023+0.003 ms clock, 0.73+0.22/2046/5156+0.026 ms cpu, 11209->11240->9832 MB, 11687 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 113 @824.320s 1%: 0.069+1169+0.004 ms clock, 0.55+2.8/2337/5141+0.038 ms cpu, 11603->11753->10135 MB, 11799 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 114 @852.399s 1%: 0.098+1786+0.014 ms clock, 0.79+1.4/3572/7152+0.11 ms cpu, 11868->12074->10370 MB, 12162 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 115 @875.807s 1%: 0.071+1082+0.005 ms clock, 0.57+0.16/2163/5457+0.041 ms cpu, 11895->11912->10372 MB, 12444 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 116 @899.307s 1%: 3.5+1186+0.004 ms clock, 28+9.3/2372/5538+0.035 ms cpu, 12101->12210->10639 MB, 12446 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 117 @932.409s 1%: 0.077+1168+0.003 ms clock, 0.61+1.3/2333/5810+0.025 ms cpu, 12556->12599->10730 MB, 12768 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 118 @956.998s 1%: 0.072+1341+0.003 ms clock, 0.57+23/2682/5691+0.031 ms cpu, 12616->12824->11105 MB, 12876 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 119 @984.653s 1%: 0.10+1781+0.012 ms clock, 0.83+0.72/3560/8535+0.099 ms cpu, 12925->13015->11190 MB, 13326 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 120 @1011.853s 1%: 0.084+1245+0.003 ms clock, 0.67+0.95/2489/6240+0.029 ms cpu, 12948->12979->11316 MB, 13428 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 121 @1038.751s 1%: 0.068+1432+0.011 ms clock, 0.54+240/2861/5955+0.089 ms cpu, 13370->13583->11716 MB, 13580 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 122 @1069.287s 1%: 0.14+1905+0.016 ms clock, 1.1+52/3809/7714+0.13 ms cpu, 13660->13914->11960 MB, 14060 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 123 @1091.746s 1%: 0.14+1910+0.011 ms clock, 1.1+15/3819/9403+0.094 ms cpu, 13642->13693->11986 MB, 14353 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 124 @1118.109s 1%: 0.24+1375+0.009 ms clock, 1.9+6.9/2750/6939+0.076 ms cpu, 13899->13930->12171 MB, 14383 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 125 @1150.245s 1%: 0.12+1400+0.013 ms clock, 0.99+7.4/2799/7125+0.11 ms cpu, 14459->14496->12393 MB, 14605 MB goal, 0 MB stacks, 1 MB globals, 8 P

The heap profile shows that the iavl (*Importer) Add and types (*SnapshotIAVLItem) Unmarshal functions are involved in this issue

Portion of the raw log:

8:46PM INF Ensure peers module=pex numDialing=0 numInPeers=0 numOutPeers=19 numToDial=11 server=node
8:46PM INF Fetching snapshot chunk chunk=53 format=2 height=13335000 module=statesync server=node total=1324
8:46PM INF Applied snapshot chunk to ABCI app chunk=46 format=2 height=13335000 module=statesync server=node total=1324
gc 89 @387.640s 0%: 0.085+587+0.009 ms clock, 0.68+0.34/1171/2436+0.072 ms cpu, 7294->7398->6462 MB, 7556 MB goal, 0 MB stacks, 1 MB globals, 8 P
8:46PM INF Fetching snapshot chunk chunk=52 format=2 height=13335000 module=statesync server=node total=1324
8:46PM INF Fetching snapshot chunk chunk=51 format=2 height=13335000 module=statesync server=node total=1324
8:46PM INF Fetching snapshot chunk chunk=50 format=2 height=13335000 module=statesync server=node total=1324
8:46PM INF Applied snapshot chunk to ABCI app chunk=47 format=2 height=13335000 module=statesync server=node total=1324
8:46PM INF Fetching snapshot chunk chunk=54 format=2 height=13335000 module=statesync server=node total=1324
8:46PM INF Fetching snapshot chunk chunk=53 format=2 height=13335000 module=statesync server=node total=1324
8:46PM INF Fetching snapshot chunk chunk=52 format=2 height=13335000 module=statesync server=node total=1324
8:46PM INF Fetching snapshot chunk chunk=51 format=2 height=13335000 module=statesync server=node total=1324
gc 90 @401.000s 0%: 0.064+620+0.011 ms clock, 0.51+0.44/1240/2546+0.090 ms cpu, 7502->7607->6585 MB, 7755 MB goal, 0 MB stacks, 1 MB globals, 8 P
8:46PM INF Applied snapshot chunk to ABCI app chunk=48 format=2 height=13335000 module=statesync server=node total=1324
8:46PM INF Fetching snapshot chunk chunk=55 format=2 height=13335000 module=statesync server=node total=1324
8:46PM INF Fetching snapshot chunk chunk=54 format=2 height=13335000 module=statesync server=node total=1324
8:46PM INF Fetching snapshot chunk chunk=53 format=2 height=13335000 module=statesync server=node total=1324
8:46PM INF Fetching snapshot chunk chunk=52 format=2 height=13335000 module=statesync server=node total=1324
8:46PM INF Fetching snapshot chunk chunk=56 format=2 height=13335000 module=statesync server=node total=1324
8:46PM INF Applied snapshot chunk to ABCI app chunk=49 format=2 height=13335000 module=statesync server=node total=1324
gc 91 @414.072s 0%: 0.11+654+0.018 ms clock, 0.94+0.90/1308/2667+0.14 ms cpu, 7577->7694->6721 MB, 7903 MB goal, 0 MB stacks, 1 MB globals, 8 P
8:46PM INF Fetching snapshot chunk chunk=55 format=2 height=13335000 module=statesync server=node total=1324
8:46PM INF Ensure peers module=pex numDialing=0 numInPeers=0 numOutPeers=19 numToDial=11 server=node
8:46PM INF Fetching snapshot chunk chunk=54 format=2 height=13335000 module=statesync server=node total=1324
8:46PM INF Fetching snapshot chunk chunk=53 format=2 height=13335000 module=statesync server=node total=1324
8:46PM INF service start impl="Peer{MConn{66.42.99.246:26656} 81fcc10a216767722326664a8777974472df93da out}" module=p2p msg={} peer={"id":"81fcc10a216767722326664a8777974472df93da","ip":"66.42.99.246","port":26656} server=node
8:46PM INF service start impl=MConn{66.42.99.246:26656} module=p2p msg={} peer={"id":"81fcc10a216767722326664a8777974472df93da","ip":"66.42.99.246","port":26656} server=node
8:46PM INF Applied snapshot chunk to ABCI app chunk=50 format=2 height=13335000 module=statesync server=node total=1324
8:46PM INF Fetching snapshot chunk chunk=57 format=2 height=13335000 module=statesync server=node total=1324
8:46PM INF Fetching snapshot chunk chunk=56 format=2 height=13335000 module=statesync server=node total=1324
8:46PM INF Fetching snapshot chunk chunk=55 format=2 height=13335000 module=statesync server=node total=1324
8:46PM INF Fetching snapshot chunk chunk=54 format=2 height=13335000 module=statesync server=node total=1324
gc 92 @427.782s 0%: 0.12+684+0.013 ms clock, 0.97+1.2/1367/2692+0.10 ms cpu, 7722->7851->6854 MB, 8065 MB goal, 0 MB stacks, 1 MB globals, 8 P
8:46PM INF Applied snapshot chunk to ABCI app chunk=51 format=2 height=13335000 module=statesync server=node total=1324
8:46PM INF Fetching snapshot chunk chunk=58 format=2 height=13335000 module=statesync server=node total=1324
8:46PM INF Fetching snapshot chunk chunk=57 format=2 height=13335000 module=statesync server=node total=1324
8:46PM INF Fetching snapshot chunk chunk=56 format=2 height=13335000 module=statesync server=node total=1324
8:46PM INF Fetching snapshot chunk chunk=55 format=2 height=13335000 module=statesync server=node total=1324
8:46PM INF Applied snapshot chunk to ABCI app chunk=52 format=2 height=13335000 module=statesync server=node total=1324
gc 93 @438.798s 0%: 0.063+581+0.004 ms clock, 0.50+0.16/1163/2939+0.039 ms cpu, 7850->7868->6882 MB, 8225 MB goal, 0 MB stacks, 1 MB globals, 8 P
8:46PM INF Fetching snapshot chunk chunk=59 format=2 height=13335000 module=statesync server=node total=1324
8:46PM INF Fetching snapshot chunk chunk=58 format=2 height=13335000 module=statesync server=node total=1324
8:47PM INF Fetching snapshot chunk chunk=57 format=2 height=13335000 module=statesync server=node total=1324
8:47PM INF Applied snapshot chunk to ABCI app chunk=53 format=2 height=13335000 module=statesync server=node total=1324
8:47PM INF Fetching snapshot chunk chunk=56 format=2 height=13335000 module=statesync server=node total=1324
8:47PM INF Ensure peers module=pex numDialing=0 numInPeers=0 numOutPeers=20 numToDial=10 server=node
8:47PM INF Fetching snapshot chunk chunk=60 format=2 height=13335000 module=statesync server=node total=1324
8:47PM INF Fetching snapshot chunk chunk=59 format=2 height=13335000 module=statesync server=node total=1324
8:47PM INF Fetching snapshot chunk chunk=58 format=2 height=13335000 module=statesync server=node total=1324
8:47PM INF Fetching snapshot chunk chunk=57 format=2 height=13335000 module=statesync server=node total=1324
gc 94 @452.471s 0%: 0.078+885+0.012 ms clock, 0.63+0.44/1769/4207+0.098 ms cpu, 8029->8072->7036 MB, 8258 MB goal, 0 MB stacks, 1 MB globals, 8 P
8:47PM INF Fetching snapshot chunk chunk=61 format=2 height=13335000 module=statesync server=node total=1324
8:47PM INF Fetching snapshot chunk chunk=60 format=2 height=13335000 module=statesync server=node total=1324
8:47PM INF Fetching snapshot chunk chunk=59 format=2 height=13335000 module=statesync server=node total=1324
8:47PM INF Applied snapshot chunk to ABCI app chunk=54 format=2 height=13335000 module=statesync server=node total=1324
8:47PM INF Fetching snapshot chunk chunk=58 format=2 height=13335000 module=statesync server=node total=1324
8:47PM INF Fetching snapshot chunk chunk=62 format=2 height=13335000 module=statesync server=node total=1324
8:47PM INF Fetching snapshot chunk chunk=61 format=2 height=13335000 module=statesync server=node total=1324
8:47PM INF Fetching snapshot chunk chunk=60 format=2 height=13335000 module=statesync server=node total=1324
8:47PM INF Applied snapshot chunk to ABCI app chunk=55 format=2 height=13335000 module=statesync server=node total=1324
8:47PM INF Fetching snapshot chunk chunk=59 format=2 height=13335000 module=statesync server=node total=1324
gc 95 @471.864s 0%: 0.066+624+0.008 ms clock, 0.52+0.87/1247/3164+0.068 ms cpu, 8337->8344->7143 MB, 8443 MB goal, 0 MB stacks, 1 MB globals, 8 P
8:47PM INF Fetching snapshot chunk chunk=62 format=2 height=13335000 module=statesync server=node total=1324
8:47PM INF Fetching snapshot chunk chunk=63 format=2 height=13335000 module=statesync server=node total=1324
8:47PM INF Fetching snapshot chunk chunk=61 format=2 height=13335000 module=statesync server=node total=1324
8:47PM INF Applied snapshot chunk to ABCI app chunk=56 format=2 height=13335000 module=statesync server=node total=1324
8:47PM INF Ensure peers module=pex numDialing=0 numInPeers=0 numOutPeers=20 numToDial=10 server=node
8:47PM INF service start impl="Peer{MConn{159.69.215.148:26618} 423c5ae6274644068b4a772f5e25985bf35f87ee out}" module=p2p msg={} peer={"id":"423c5ae6274644068b4a772f5e25985bf35f87ee","ip":"159.69.215.148","port":26618} server=node
8:47PM INF service start impl=MConn{159.69.215.148:26618} module=p2p msg={} peer={"id":"423c5ae6274644068b4a772f5e25985bf35f87ee","ip":"159.69.215.148","port":26618} server=node
8:47PM INF Fetching snapshot chunk chunk=60 format=2 height=13335000 module=statesync server=node total=1324
8:47PM INF Applied snapshot chunk to ABCI app chunk=57 format=2 height=13335000 module=statesync server=node total=1324
8:47PM INF Fetching snapshot chunk chunk=64 format=2 height=13335000 module=statesync server=node total=1324
8:47PM INF Fetching snapshot chunk chunk=62 format=2 height=13335000 module=statesync server=node total=1324
8:47PM INF Fetching snapshot chunk chunk=63 format=2 height=13335000 module=statesync server=node total=1324
8:47PM INF Fetching snapshot chunk chunk=61 format=2 height=13335000 module=statesync server=node total=1324
gc 96 @489.228s 0%: 0.092+739+0.003 ms clock, 0.73+262/1477/3069+0.030 ms cpu, 8489->8573->7366 MB, 8572 MB goal, 0 MB stacks, 1 MB globals, 8 P
8:47PM INF Fetching snapshot chunk chunk=65 format=2 height=13335000 module=statesync server=node total=1324
8:47PM INF Fetching snapshot chunk chunk=64 format=2 height=13335000 module=statesync server=node total=1324
8:47PM INF Fetching snapshot chunk chunk=62 format=2 height=13335000 module=statesync server=node total=1324
8:47PM INF Fetching snapshot chunk chunk=63 format=2 height=13335000 module=statesync server=node total=1324
8:47PM INF Applied snapshot chunk to ABCI app chunk=58 format=2 height=13335000 module=statesync server=node total=1324
8:47PM ERR Failed to read request err="websocket: close 1006 (abnormal closure): unexpected EOF" module=rpc-server protocol=websocket remote={"IP":"127.0.0.1","Port":59462,"Zone":""} server=node
8:47PM INF service stop impl={"Logger":{}} module=rpc-server msg={} protocol=websocket remote={"IP":"127.0.0.1","Port":59462,"Zone":""} server=node
8:47PM ERR error while stopping connection error="already stopped" module=rpc-server protocol=websocket server=node
8:47PM INF Fetching snapshot chunk chunk=65 format=2 height=13335000 module=statesync server=node total=1324
8:48PM INF Fetching snapshot chunk chunk=64 format=2 height=13335000 module=statesync server=node total=1324
8:48PM INF Applied snapshot chunk to ABCI app chunk=59 format=2 height=13335000 module=statesync server=node total=1324
8:48PM INF Fetching snapshot chunk chunk=62 format=2 height=13335000 module=statesync server=node total=1324
8:48PM INF Fetching snapshot chunk chunk=66 format=2 height=13335000 module=statesync server=node total=1324

[yihuang]

we've observed similar thing as well, but didn't investigated, I believe https://github.com/cosmos/iavl/pull/773 will fix this, can you give it a try?

[GAtom22]

@yihuang will try, thanks for the prompt reply!

[yihuang]

Just manually created a backport PR to 0.19.x: https://github.com/cosmos/iavl/pull/774, I think that's what evmos using.

[GAtom22]

still waiting to finish the sync, but looks good! The memory issue seems to be resolved! Thanks @yihuang!!

gc 266 @626.403s 0%: 0.068+2.8+0.010 ms clock, 0.54+0.81/5.4/10+0.086 ms cpu, 3116->3116->2844 MB, 3120 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 267 @630.070s 0%: 0.060+2.8+0.009 ms clock, 0.48+0.22/5.5/10+0.078 ms cpu, 3125->3125->2848 MB, 3129 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 268 @631.041s 0%: 0.045+2.5+0.003 ms clock, 0.36+0.33/4.9/10+0.024 ms cpu, 3129->3129->2837 MB, 3133 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 269 @637.667s 0%: 0.081+2.8+0.009 ms clock, 0.65+0.46/5.4/9.9+0.074 ms cpu, 3117->3117->2849 MB, 3121 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 270 @638.373s 0%: 0.067+2.8+0.014 ms clock, 0.53+0.45/5.1/11+0.11 ms cpu, 3132->3132->2840 MB, 3134 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 271 @644.314s 0%: 0.097+3.0+0.004 ms clock, 0.77+0.70/5.8/11+0.037 ms cpu, 3121->3121->2845 MB, 3125 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 272 @646.159s 0%: 0.053+2.6+0.010 ms clock, 0.42+0.55/5.0/11+0.083 ms cpu, 3126->3127->2845 MB, 3130 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 273 @649.257s 0%: 0.056+3.0+0.009 ms clock, 0.45+0.52/5.8/10+0.078 ms cpu, 3126->3127->2849 MB, 3130 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 274 @653.745s 0%: 0.064+4.1+0.015 ms clock, 0.51+0.15/7.9/11+0.12 ms cpu, 3130->3131->2854 MB, 3134 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 275 @654.562s 0%: 0.047+2.4+0.003 ms clock, 0.37+0.14/4.7/10+0.031 ms cpu, 3136->3136->2840 MB, 3140 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 276 @661.407s 0%: 0.055+2.8+0.009 ms clock, 0.44+0.47/5.4/11+0.075 ms cpu, 3122->3122->2844 MB, 3125 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 277 @662.096s 0%: 0.082+2.9+0.012 ms clock, 0.65+0.32/5.5/10+0.096 ms cpu, 3124->3126->2838 MB, 3128 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 278 @667.137s 0%: 0.055+2.3+0.005 ms clock, 0.44+0.23/4.4/11+0.040 ms cpu, 3118->3119->2844 MB, 3122 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 279 @669.601s 0%: 0.047+2.3+0.008 ms clock, 0.37+0.16/4.4/11+0.065 ms cpu, 3125->3125->2851 MB, 3129 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 280 @672.212s 0%: 0.049+2.2+0.003 ms clock, 0.39+0.50/4.3/11+0.024 ms cpu, 3133->3133->2842 MB, 3137 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 281 @677.829s 0%: 0.047+3.7+0.016 ms clock, 0.38+1.9/5.4/9.4+0.13 ms cpu, 3122->3133->2857 MB, 3126 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 282 @678.498s 0%: 0.048+2.5+0.008 ms clock, 0.39+0.25/5.0/11+0.070 ms cpu, 3129->3129->2834 MB, 3143 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 283 @685.982s 0%: 0.053+3.8+0.011 ms clock, 0.43+0.16/7.3/15+0.094 ms cpu, 3103->3104->2847 MB, 3118 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 284 @689.288s 0%: 0.090+3.2+0.020 ms clock, 0.72+3.5/6.1/12+0.16 ms cpu, 3128->3129->2844 MB, 3132 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 285 @691.534s 0%: 0.082+4.2+0.017 ms clock, 0.65+1.4/8.3/12+0.14 ms cpu, 3125->3125->2833 MB, 3129 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 286 @699.978s 0%: 0.080+3.6+0.014 ms clock, 0.64+0.93/7.1/12+0.11 ms cpu, 3113->3113->2846 MB, 3117 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 287 @700.669s 0%: 0.093+2.6+0.024 ms clock, 0.74+0.75/5.1/10+0.19 ms cpu, 3127->3127->2842 MB, 3131 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 288 @704.776s 0%: 0.077+3.5+0.003 ms clock, 0.62+0.24/6.9/14+0.026 ms cpu, 3132->3132->2852 MB, 3132 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 289 @709.676s 0%: 0.051+2.8+0.010 ms clock, 0.40+0.14/5.2/11+0.083 ms cpu, 3133->3134->2847 MB, 3137 MB goal, 0 MB stacks, 1 MB globals, 8 P
gc 290 @710.394s 0%: 0.047+2.3+0.009 ms clock, 0.38+0.50/4.3/11+0.074 ms cpu, 3127->3127->2834 MB, 3131 MB goal, 0 MB stacks, 1 MB globals, 8 P