runtime: heap fragmentation leads to high HeapInUse usage

[t3rm1n4l]

Please answer these questions before submitting your issue. Thanks!

What version of Go are you using (go version)?

go version go1.7.4 linux/amd64

What operating system and processor architecture are you using (go env)?

GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH=""
GORACE=""
GOROOT="/usr/local/go"
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
CC="gcc"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0"
CXX="g++"
CGO_ENABLED="1"

What did you do?

My program allocates 22G of objects. But, the HeapInUse is 35G as per MemStats and process RSS. Process is idle after the allocations. A gc+scavenger run has been executed using os.FreeOSMemory() to free memory back to OS. Also, heap profile was tried with sampling rate of 1KB as well. Then I tried an application level accounting of the memory consumed. That also accounts only 22GB usage. But, go is using 35GB.

Here is the gctrace=1:
gc 1 @0.011s 1%: 0.13+16+0.24 ms clock, 0.41+16/1.4/18+0.74 ms cpu, 16->16->16 MB, 17 MB goal, 40 P
gc 2 @0.031s 2%: 0.076+22+0.28 ms clock, 0.83+14/9.4/15+3.1 ms cpu, 31->31->31 MB, 32 MB goal, 40 P
gc 3 @0.538s 0%: 0.088+23+0.28 ms clock, 1.2+0.032/25/1.3+3.9 ms cpu, 32->33->32 MB, 63 MB goal, 40 P
gc 4 @1.550s 0%: 2.1+37+0.33 ms clock, 27+16/40/0.29+4.3 ms cpu, 47->48->47 MB, 64 MB goal, 40 P
gc 5 @1.722s 0%: 0.15+11+0.33 ms clock, 3.0+0.93/30/16+6.3 ms cpu, 81->83->76 MB, 95 MB goal, 40 P
gc 6 @1.844s 0%: 0.094+31+0.30 ms clock, 1.9+4.1/65/19+6.3 ms cpu, 140->142->126 MB, 152 MB goal, 40 P
gc 7 @2.053s 0%: 0.13+52+0.31 ms clock, 3.2+9.2/128/15+7.5 ms cpu, 241->242->213 MB, 253 MB goal, 40 P
gc 8 @2.423s 0%: 0.096+77+0.36 ms clock, 2.5+1.7/250/32+9.4 ms cpu, 415->420->369 MB, 427 MB goal, 40 P
gc 9 @3.059s 0%: 0.12+99+0.37 ms clock, 3.7+3.3/417/40+11 ms cpu, 719->721->633 MB, 738 MB goal, 40 P
gc 10 @3.963s 1%: 0.062+188+0.38 ms clock, 2.0+0/701/105+12 ms cpu, 1235->1241->1093 MB, 1267 MB goal, 40 P
gc 11 @5.673s 1%: 0.066+111+0.33 ms clock, 2.1+0.28/1052/807+10 ms cpu, 2131->2137->1874 MB, 2186 MB goal, 40 P
gc 12 @8.371s 1%: 0.11+296+0.34 ms clock, 3.6+7.0/1781/344+11 ms cpu, 3655->3662->3197 MB, 3749 MB goal, 40 P
gc 1 @0.011s 1%: 0.12+10+0.23 ms clock, 0.49+0.27/11/0.88+0.94 ms cpu, 16->16->16 MB, 17 MB goal, 40 P
gc 2 @0.025s 2%: 0.058+22+0.28 ms clock, 0.58+11/24/0.82+2.8 ms cpu, 31->31->31 MB, 32 MB goal, 40 P
gc 3 @0.496s 0%: 0.069+12+0.25 ms clock, 0.89+0.024/14/0.85+3.3 ms cpu, 32->33->32 MB, 63 MB goal, 40 P
gc 4 @1.511s 0%: 3.3+27+0.39 ms clock, 46+0.34/46/0.23+5.5 ms cpu, 47->49->47 MB, 64 MB goal, 40 P
gc 5 @1.611s 0%: 0.027+0+11 ms clock, 0.45+0.34/46/0.23+201 ms cpu, 49->49->47 MB, 49 MB goal, 40 P (forced)
gc 6 @1.630s 0%: 0.099+0+10 ms clock, 1.6+0.34/46/0.23+186 ms cpu, 47->47->47 MB, 47 MB goal, 40 P (forced)
gc 7 @2.354s 0%: 0.21+20+0.48 ms clock, 2.3+14/31/0.48+5.2 ms cpu, 81->84->78 MB, 95 MB goal, 40 P
gc 8 @2.879s 0%: 0.17+13+0.58 ms clock, 3.7+42/13/0.75+12 ms cpu, 142->143->82 MB, 156 MB goal, 40 P
gc 9 @2.962s 0%: 0.076+10+0.64 ms clock, 0.30+26/20/0.26+2.5 ms cpu, 156->158->119 MB, 164 MB goal, 40 P
gc 10 @3.071s 0%: 0.15+27+0.69 ms clock, 3.4+49/43/3.2+15 ms cpu, 229->232->157 MB, 238 MB goal, 40 P
gc 11 @3.224s 0%: 0.12+18+1.0 ms clock, 0.25+46/28/0.23+2.1 ms cpu, 308->309->219 MB, 315 MB goal, 40 P
gc 12 @3.503s 0%: 0.18+19+1.1 ms clock, 0.72+38/48/0.10+4.4 ms cpu, 427->430->266 MB, 438 MB goal, 40 P
gc 13 @3.790s 0%: 0.13+15+0.87 ms clock, 1.7+79/60/3.3+11 ms cpu, 520->522->284 MB, 533 MB goal, 40 P
gc 14 @4.122s 0%: 0.13+13+0.69 ms clock, 1.0+92/74/0+5.5 ms cpu, 554->556->302 MB, 568 MB goal, 40 P
gc 15 @4.471s 0%: 0.084+11+0.89 ms clock, 1.3+97/75/36+14 ms cpu, 590->592->321 MB, 605 MB goal, 40 P
gc 16 @4.752s 0%: 0.057+11+0.86 ms clock, 1.2+44/74/78+19 ms cpu, 627->629->342 MB, 643 MB goal, 40 P
gc 17 @5.061s 1%: 0.10+20+0.73 ms clock, 2.2+182/125/0.031+15 ms cpu, 668->673->372 MB, 685 MB goal, 40 P
gc 18 @5.363s 1%: 0.19+16+0.89 ms clock, 3.6+58/118/175+17 ms cpu, 726->731->395 MB, 744 MB goal, 40 P
gc 19 @5.668s 1%: 0.13+17+0.98 ms clock, 0.66+202/116/7.5+4.9 ms cpu, 771->776->418 MB, 791 MB goal, 40 P
gc 20 @6.028s 1%: 0.18+15+0.67 ms clock, 0.75+266/126/0.010+2.7 ms cpu, 816->821->449 MB, 837 MB goal, 40 P
gc 21 @6.435s 1%: 0.095+23+0.98 ms clock, 1.1+128/174/183+11 ms cpu, 875->882->483 MB, 898 MB goal, 40 P
gc 22 @6.857s 1%: 0.14+25+0.81 ms clock, 3.2+48/214/357+18 ms cpu, 942->949->520 MB, 967 MB goal, 40 P
gc 23 @7.298s 1%: 0.034+24+0.94 ms clock, 1.0+126/238/278+30 ms cpu, 1014->1021->553 MB, 1040 MB goal, 40 P
gc 24 @7.748s 1%: 0.17+25+0.89 ms clock, 1.0+373/251/0.10+5.3 ms cpu, 1079->1088->587 MB, 1107 MB goal, 40 P
gc 25 @8.255s 1%: 0.052+31+0.99 ms clock, 1.6+195/263/248+31 ms cpu, 1146->1152->624 MB, 1175 MB goal, 40 P
gc 26 @8.811s 1%: 0.13+30+0.98 ms clock, 2.7+283/293/238+20 ms cpu, 1216->1224->668 MB, 1248 MB goal, 40 P
gc 27 @9.428s 1%: 0.15+41+0.99 ms clock, 1.4+555/362/0.16+8.9 ms cpu, 1303->1312->720 MB, 1336 MB goal, 40 P
gc 28 @10.062s 1%: 0.14+44+0.79 ms clock, 1.1+719/387/0+6.3 ms cpu, 1404->1414->774 MB, 1440 MB goal, 40 P
gc 29 @10.742s 2%: 0.17+45+0.92 ms clock, 1.6+768/423/0.28+8.3 ms cpu, 1510->1520->827 MB, 1549 MB goal, 40 P
gc 30 @11.434s 2%: 0.15+45+0.84 ms clock, 1.2+458/420/365+6.7 ms cpu, 1613->1624->876 MB, 1654 MB goal, 40 P
gc 31 @12.174s 2%: 0.16+46+0.75 ms clock, 1.5+784/458/66+6.8 ms cpu, 1709->1721->935 MB, 1753 MB goal, 40 P
gc 32 @12.997s 2%: 0.13+48+0.91 ms clock, 1.2+489/478/391+8.2 ms cpu, 1825->1839->1000 MB, 1871 MB goal, 40 P
gc 33 @13.904s 2%: 0.28+58+1.0 ms clock, 2.5+1030/534/0+9.2 ms cpu, 1950->1963->1071 MB, 2000 MB goal, 40 P
gc 34 @14.846s 2%: 0.16+66+0.88 ms clock, 1.3+812/626/435+7.0 ms cpu, 2089->2103->1149 MB, 2143 MB goal, 40 P
gc 35 @15.888s 2%: 0.15+71+0.98 ms clock, 1.2+934/705/567+7.8 ms cpu, 2241->2255->1234 MB, 2298 MB goal, 40 P
gc 36 @16.992s 2%: 0.17+91+0.93 ms clock, 1.3+1308/880/305+7.4 ms cpu, 2406->2424->1325 MB, 2468 MB goal, 40 P
gc 37 @18.141s 2%: 0.12+91+0.89 ms clock, 2.4+1701/906/0+17 ms cpu, 2584->2602->1418 MB, 2650 MB goal, 40 P
gc 38 @19.353s 3%: 0.13+97+1.0 ms clock, 1.0+1275/962/522+8.4 ms cpu, 2765->2783->1507 MB, 2836 MB goal, 40 P
gc 39 @20.653s 3%: 0.12+91+0.96 ms clock, 2.1+1354/903/593+16 ms cpu, 2940->2957->1601 MB, 3015 MB goal, 40 P
gc 40 @22.059s 3%: 0.078+98+0.80 ms clock, 1.8+1778/977/268+19 ms cpu, 3122->3141->1707 MB, 3202 MB goal, 40 P
gc 41 @23.569s 3%: 0.13+110+1.0 ms clock, 0.93+1893/1096/359+7.2 ms cpu, 3330->3352->1826 MB, 3415 MB goal, 40 P
gc 42 @25.216s 3%: 0.13+127+0.80 ms clock, 1.0+2442/1259/246+6.4 ms cpu, 3562->3586->1962 MB, 3653 MB goal, 40 P
gc 43 @26.981s 3%: 0.14+156+0.94 ms clock, 2.0+3059/1558/0.16+13 ms cpu, 3826->3854->2117 MB, 3924 MB goal, 40 P
gc 44 @28.935s 3%: 0.33+167+1.0 ms clock, 5.6+3179/1660/364+17 ms cpu, 4128->4159->2274 MB, 4234 MB goal, 40 P
gc 45 @30.015s 4%: 0.18+0+250 ms clock, 1.8+3179/1660/364+2504 ms cpu, 3377->3377->2328 MB, 3377 MB goal, 40 P (forced)
gc 46 @32.229s 4%: 0.19+176+0.88 ms clock, 1.7+3231/1754/749+7.9 ms cpu, 4540->4567->2511 MB, 4656 MB goal, 40 P
gc 47 @34.435s 4%: 0.15+198+0.89 ms clock, 1.3+2896/1938/1438+8.0 ms cpu, 4897->4931->2677 MB, 5022 MB goal, 40 P
gc 48 @36.732s 4%: 0.18+211+1.0 ms clock, 1.7+3604/2075/872+9.2 ms cpu, 5220->5256->2858 MB, 5354 MB goal, 40 P
gc 49 @39.268s 4%: 0.15+208+0.85 ms clock, 1.2+3429/2077/1169+6.8 ms cpu, 5574->5613->3049 MB, 5716 MB goal, 40 P
gc 50 @41.963s 4%: 0.14+229+1.1 ms clock, 1.6+3687/2286/1274+12 ms cpu, 5945->5986->3265 MB, 6098 MB goal, 40 P
gc 51 @44.954s 4%: 0.38+253+0.98 ms clock, 9.1+3334/2531/2324+23 ms cpu, 6366->6409->3500 MB, 6530 MB goal, 40 P
gc 52 @48.229s 4%: 0.18+301+1.2 ms clock, 1.6+5171/2999/1391+11 ms cpu, 6825->6874->3763 MB, 7000 MB goal, 40 P
gc 53 @51.833s 4%: 0.15+340+1.0 ms clock, 1.4+5239/3389/2211+9.5 ms cpu, 7339->7392->4042 MB, 7527 MB goal, 40 P
gc 54 @55.672s 4%: 0.16+380+1.0 ms clock, 1.4+5925/3791/2477+9.5 ms cpu, 7882->7939->4338 MB, 8084 MB goal, 40 P
gc 55 @59.723s 5%: 0.17+394+0.80 ms clock, 1.7+6988/3939/2153+8.0 ms cpu, 8459->8520->4647 MB, 8676 MB goal, 40 P
gc 56 @64.025s 5%: 0.18+0+644 ms clock, 1.8+6988/3939/2153+6446 ms cpu, 9006->9006->4898 MB, 9006 MB goal, 40 P (forced)
gc 57 @68.819s 5%: 0.082+426+1.0 ms clock, 1.8+7977/4257/1957+24 ms cpu, 9551->9604->5266 MB, 9796 MB goal, 40 P
gc 58 @73.605s 5%: 0.14+450+0.85 ms clock, 1.3+6836/4484/3281+7.7 ms cpu, 10269->10344->5637 MB, 10532 MB goal, 40 P
gc 59 @75.595s 6%: 0.15+0+588 ms clock, 4.8+6836/4484/3281+18818 ms cpu, 7581->7581->5705 MB, 7581 MB goal, 40 P (forced)
gc 60 @81.107s 6%: 0.26+477+0.86 ms clock, 2.3+8641/4774/2425+7.8 ms cpu, 11126->11190->6147 MB, 11411 MB goal, 40 P
gc 61 @86.889s 6%: 0.22+522+0.96 ms clock, 1.7+8098/5215/3963+7.7 ms cpu, 11988->12074->6605 MB, 12295 MB goal, 40 P
gc 62 @93.185s 6%: 0.20+600+0.98 ms clock, 1.8+10098/5995/3617+8.8 ms cpu, 12879->12975->7093 MB, 13210 MB goal, 40 P
gc 63 @100.127s 6%: 0.71+684+0.94 ms clock, 7.8+11351/6836/4322+10 ms cpu, 13832->13937->7627 MB, 14187 MB goal, 40 P
gc 64 @107.592s 6%: 0.15+760+1.1 ms clock, 1.4+12778/7592/4697+10 ms cpu, 14873->14986->8186 MB, 15254 MB goal, 40 P
gc 65 @115.488s 6%: 0.14+838+1.1 ms clock, 2.6+13070/8376/5952+19 ms cpu, 15964->16087->8779 MB, 16373 MB goal, 40 P
gc 66 @123.875s 6%: 0.19+870+1.1 ms clock, 1.7+13812/8699/6428+10 ms cpu, 17120->17251->9385 MB, 17559 MB goal, 40 P
gc 67 @132.692s 6%: 0.23+908+1.0 ms clock, 2.0+13867/9076/6879+9.2 ms cpu, 18301->18440->10017 MB, 18771 MB goal, 40 P
gc 68 @141.986s 6%: 0.21+943+0.90 ms clock, 2.1+15513/9425/6103+9.0 ms cpu, 19534->19681->10700 MB, 20035 MB goal, 40 P
gc 69 @152.183s 6%: 0.98+994+1.0 ms clock, 7.8+16252/9939/6191+8.6 ms cpu, 20865->21021->11430 MB, 21400 MB goal, 40 P
gc 70 @163.113s 6%: 0.16+1072+0.97 ms clock, 1.4+16385/10716/7800+8.7 ms cpu, 22289->22456->12233 MB, 22860 MB goal, 40 P
gc 71 @174.825s 6%: 0.15+1189+1.0 ms clock, 1.5+18064/11891/8555+10 ms cpu, 23854->24034->13134 MB, 24466 MB goal, 40 P
gc 72 @187.784s 6%: 0.20+1300+0.95 ms clock, 2.0+20416/13004/9765+9.5 ms cpu, 25611->25807->14111 MB, 26268 MB goal, 40 P
gc 73 @201.840s 6%: 0.18+1480+1.1 ms clock, 1.6+21708/14802/12639+10 ms cpu, 27518->27729->15164 MB, 28223 MB goal, 40 P
gc 74 @216.824s 6%: 1.2+1658+0.97 ms clock, 9.6+25467/16581/12611+7.7 ms cpu, 29571->29801->16283 MB, 30329 MB goal, 40 P
gc 75 @232.919s 6%: 0.22+1776+1.0 ms clock, 2.0+27884/17758/13280+9.7 ms cpu, 31753->31999->17430 MB, 32567 MB goal, 40 P
gc 76 @249.894s 6%: 0.20+1867+1.1 ms clock, 1.8+29144/18664/14436+9.9 ms cpu, 33989->34251->18641 MB, 34861 MB goal, 40 P
gc 77 @267.846s 6%: 0.24+1939+1.2 ms clock, 2.1+30795/19392/14116+11 ms cpu, 36350->36627->19883 MB, 37282 MB goal, 40 P
gc 78 @286.855s 6%: 0.062+2008+1.1 ms clock, 1.9+32958/20077/13490+37 ms cpu, 38772->39065->21211 MB, 39766 MB goal, 40 P
gc 79 @307.403s 6%: 0.22+2081+1.1 ms clock, 2.0+32514/20814/15847+10 ms cpu, 41362->41673->22696 MB, 42423 MB goal, 40 P
gc 80 @327.541s 6%: 0.14+2047+1.1 ms clock, 1.1+34404/20472/12886+9.4 ms cpu, 44257->44577->22703 MB, 45392 MB goal, 40 P
gc 81 @332.510s 7%: 0.46+0+2448 ms clock, 12+34404/20472/12886+66105 ms cpu, 26518->26518->22377 MB, 26518 MB goal, 40 P (forced)
gc 82 @352.715s 7%: 0.54+1960+1.2 ms clock, 4.9+38039/19601/9184+11 ms cpu, 43637->43891->22633 MB, 44755 MB goal, 40 P
gc 83 @371.353s 7%: 0.42+1991+1.1 ms clock, 3.8+32692/19909/13747+10 ms cpu, 44134->44469->22637 MB, 45266 MB goal, 40 P
gc 84 @378.478s 7%: 0.39+0+2595 ms clock, 3.5+32692/19909/13747+23362 ms cpu, 29596->29596->22313 MB, 29596 MB goal, 40 P (forced)
gc 85 @397.356s 7%: 0.40+1916+1.2 ms clock, 3.6+33428/19160/13324+10 ms cpu, 43512->43774->22521 MB, 44627 MB goal, 40 P
gc 86 @415.144s 7%: 0.36+2190+2.6 ms clock, 2.9+33125/21904/10777+21 ms cpu, 43917->44270->22599 MB, 45043 MB goal, 40 P
gc 87 @432.327s 7%: 0.47+1950+1.1 ms clock, 4.2+32376/19490/12770+10 ms cpu, 44069->44428->22559 MB, 45199 MB goal, 40 P
gc 88 @448.837s 7%: 0.35+1930+1.1 ms clock, 11+35219/19301/9008+35 ms cpu, 43991->44357->22625 MB, 45119 MB goal, 40 P
gc 89 @465.169s 7%: 0.47+1932+1.0 ms clock, 4.7+36112/19322/7974+10 ms cpu, 44118->44490->22650 MB, 45250 MB goal, 40 P
gc 90 @480.826s 7%: 0.80+1890+1.1 ms clock, 8.0+34525/18898/8574+11 ms cpu, 44168->44545->22675 MB, 45300 MB goal, 40 P
gc 91 @496.337s 7%: 0.57+1887+1.1 ms clock, 5.7+33143/18867/10430+11 ms cpu, 44217->44602->22835 MB, 45350 MB goal, 40 P
gc 92 @510.959s 7%: 0.43+1915+1.1 ms clock, 4.3+35319/19150/8385+11 ms cpu, 44529->44922->22977 MB, 45670 MB goal, 40 P
gc 93 @525.947s 7%: 0.44+1933+1.1 ms clock, 4.9+33138/19327/11548+13 ms cpu, 44806->45206->23199 MB, 45955 MB goal, 40 P
gc 94 @540.676s 7%: 0.42+1936+1.2 ms clock, 4.6+33285/19357/11308+13 ms cpu, 45238->45654->23522 MB, 46398 MB goal, 40 P
gc 95 @556.581s 7%: 0.32+1906+1.1 ms clock, 10+29314/19052/14546+35 ms cpu, 45868->46312->24180 MB, 47045 MB goal, 40 P
gc 96 @572.110s 7%: 0.42+1878+1.1 ms clock, 13+22568/18785/20358+36 ms cpu, 47151->47602->24269 MB, 48360 MB goal, 40 P
gc 97 @587.830s 7%: 0.49+1827+1.2 ms clock, 4.9+20290/18273/20787+12 ms cpu, 47326->47778->24267 MB, 48539 MB goal, 40 P
gc 98 @602.741s 7%: 0.52+4370+1.8 ms clock, 4.6+755/43677/0+16 ms cpu, 47320->47560->24138 MB, 48534 MB goal, 40 P
gc 99 @609.616s 7%: 0.39+0+2175 ms clock, 3.9+755/43677/0+21754 ms cpu, 25981->25981->23901 MB, 25981 MB goal, 40 P (forced)
gc 100 @626.925s 7%: 0.33+1655+1.2 ms clock, 9.6+22311/16550/17933+35 ms cpu, 46607->46937->24212 MB, 47802 MB goal, 40 P
gc 101 @631.924s 8%: 0.37+0+2341 ms clock, 3.3+22311/16550/17933+21070 ms cpu, 30305->30305->23880 MB, 30305 MB goal, 40 P (forced)
gc 102 @646.647s 8%: 0.46+1620+1.1 ms clock, 4.1+23844/16187/15629+10 ms cpu, 46567->46891->24191 MB, 47761 MB goal, 40 P
gc 103 @661.356s 8%: 0.42+1684+1.1 ms clock, 3.7+19858/16821/18350+9.9 ms cpu, 47173->47631->24302 MB, 48382 MB goal, 40 P
gc 104 @676.780s 8%: 0.38+0+2771 ms clock, 3.8+19858/16821/18350+27716 ms cpu, 47006->47006->23882 MB, 47006 MB goal, 40 P (forced)
gc 105 @692.904s 8%: 0.46+1561+1.0 ms clock, 4.6+23200/15567/14917+10 ms cpu, 46571->46900->24146 MB, 47765 MB goal, 40 P
gc 106 @707.653s 7%: 0.26+1611+1.1 ms clock, 8.4+16782/16078/20007+35 ms cpu, 47086->47544->24193 MB, 48293 MB goal, 40 P
gc 107 @724.326s 7%: 0.48+1384+1.0 ms clock, 4.8+7469/13789/23380+10 ms cpu, 47177->47588->22868 MB, 48386 MB goal, 40 P
gc 108 @761.567s 7%: 0.31+0+2136 ms clock, 9.9+7469/13789/23380+68371 ms cpu, 30527->30527->22183 MB, 30527 MB goal, 40 P (forced)
gc 109 @794.249s 7%: 0.29+0+1678 ms clock, 9.3+7469/13789/23380+53722 ms cpu, 24338->24338->22183 MB, 24338 MB goal, 40 P (forced)
gc 110 @810.190s 7%: 0.49+0+1729 ms clock, 15+7469/13789/23380+55357 ms cpu, 23115->23115->22183 MB, 23115 MB goal, 40 P (forced)
gc 111 @930.292s 7%: 0.19+0+2100 ms clock, 6.2+7469/13789/23380+67225 ms cpu, 30635->30635->22184 MB, 30635 MB goal, 40 P (forced)
gc 112 @976.647s 6%: 0.14+0+1692 ms clock, 4.5+7469/13789/23380+54161 ms cpu, 25466->25466->22189 MB, 25466 MB goal, 40 P (forced)

Tried out gctrace=2 and force scavenger:
gc 119 @1483.234s 9%: 0.78+0+3421 ms clock, 25+30/11050/31875+109489 ms cpu, 27931->27931->22194 MB, 27931 MB goal, 40 P (forced)
scvg-1: 5852 MB released
scvg-1: inuse: 33906, idle: 13640, sys: 47547, released: 13640, consumed: 33906 (MB)

HeapProfile:
https://raw.githubusercontent.com/t3rm1n4l/misc-tools/master/debug_junk/h.svg

http/debug/pprof/heap?debug=1
https://github.com/t3rm1n4l/misc-tools/blob/master/debug_junk/h.hprof

Ref:
https://groups.google.com/forum/#!topic/golang-nuts/ts_UKImP_b0

[bradfitz]

Please try with Go 1.8 and report back.

[t3rm1n4l]

I had tried the test with go1.8rc3 as well. I observed the same problem.

[davecheney]

I'm not sure there is a problem here, the scavenger has returned plenty of memory to your operating system (note: operating systems often ignore this advice) and it doesn't look like you're leaking memory as you're not under constant GC pressure.

…

On Thu, 2 Feb 2017, 17:35 Sarath Lakshman ***@***.***> wrote: I had tried the test with go1.8rc3 as well. I observed the same problem. — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#18896 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAAcA2Qt_GDS_azUu78Ud_qb0uobaYBlks5rYXlFgaJpZM4L0wk2> .

[t3rm1n4l]

The live heap size is 22GB, process is almost idle. MemStats.HeapInUse is 35G. If there is OS memory pressure, I expect OS to reclaim memory. It doesn't happen and OOM killer kills the program.
My understanding is that MemStats.HeapInUse will report liveheapsize + memory allocator overhead bytes after a GC run while the process is not generating garbage. So I am expecting HeapInUse approximately 23G or around.
I have seen this problem getting worse when I allocate more memory.

[davecheney]

The scavenger can only inform the is that certain pages in the address space can be discarded if the operating system needs them (effectively they are replaced with zeros rather than being swapped and restored if needed). Th scavenger has done this, down 5gb based on one of your posts, so that's all the go runtime can do. The oom killer will usually target the largest non root process and it may be basing that on incorrect statistics. This doesn't look like something the runtime is doing wrong here.

…

On Thu, 2 Feb 2017, 17:47 Sarath Lakshman ***@***.***> wrote: The live heap size is 22GB, process is almost idle. MemStats.HeapInUse is 35G. If there is OS memory pressure, I expect OS to reclaim memory. It doesn't happen and OOM killer kills the program. My understanding is that MemStats.HeapInUse will report liveheapsize + memory allocator overhead bytes after a GC run while the process is not generating garbage. So I am expecting HeapInUse < 23G I have seen this problem getting worse when I allocate more memory. — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#18896 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAAcA4emLj-WFER97_OD4PK7Rem5ggU_ks5rYXv1gaJpZM4L0wk2> .

[bradfitz]

Have you seen the new Go 1.8 docs on Memstats?

https://beta.golang.org/pkg/runtime/#MemStats.HeapInuse

What is your HeapInuse minus HeapAlloc?

[t3rm1n4l]

Thanks for the url. I will read up the new documentation.

Heapinuse - HeapAlloc
35515482112-23444472008
12071010104

[t3rm1n4l]

Memstats output for ref:

{"Alloc":23423919704,"TotalAlloc":1021522114616,"Sys":51983561336,"Lookups":2631,"Mallocs":12287636284,"Frees":12148314232,"HeapAlloc":23423919704,"HeapSys":49444618240,"HeapIdle":13928579072,"HeapInuse":35516039168,"HeapReleased":13927563264,"HeapObjects":139322052,"StackInuse":9961472,"StackSys":9961472,"MSpanInuse":550743200,"MSpanSys":617414656,"MCacheInuse":48000,"MCacheSys":65536,"BuckHashSys":1729640,"GCSys":1797158912,"OtherSys":112612880,"NextGC":45384441616,"LastGC":1486019415218754799,"PauseTotalNs":209438599029,"PauseNs":[12914625,24658834,24480199,35555908,34061609,23955621,13880224,17579117,15400402,15258171,17819290,20909569,24837772,32733958,22595070,30046726,32068053,34040348,33904277,32538546,36884636,38995686,57285539,47885991,56649830,56931702,74809439,71048405,83679399,83180457,91730799,95617296,104300575,118143297,125557713,150058822,154554164,163990977,180853491,182977025,190366937,214857661,238021198,408783911,279606182,303541078,338388327,342733985,356469011,376660160,419987452,460598023,494861235,566548710,865832544,620451250,660102836,1019204429,699958351,738062449,776525291,848813620,957011860,1057165561,1178253071,1255900859,1347107638,1414633854,1459788776,1544419000,1644807331,1789941403,2000649071,2191774211,2419725020,2641300191,2793968138,2908895602,5059927586,3116399724,3212337143,4766448657,3220403354,3275399388,3273719851,3307507295,3273125123,3241437563,3217412982,3132612772,3083761791,3072945542,3156764921,5128783000,3174760804,3131707889,4580835163,3071719393,3060204486,2982633631,2885504412,2888531407,2846492760,2787548391,2762309061,2784255734,2653170528,2542728981,3707071926,3244753096,3326127023,2130208845,3545668810,3374970224,2131589038,2139190957,3181100567,3380617060,2152903414,3672715494,3240598963,3283154820,3326989934,2127136006,3299053706,3256739912,2129594053,2093787266,3179922329,3355910451,3167316015,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0],"PauseEnd":[1486016930389820349,1486016930443506748,1486016930980983055,1486016932016357479,1486016932126128144,1486016932152798104,1486016933269533001,1486016933800617590,1486016933921009156,1486016934048620991,1486016934179455118,1486016934490283362,1486016934792080715,1486016935134343658,1486016935480002339,1486016935772941765,1486016936079943128,1486016936404109625,1486016936722146943,1486016937069583827,1486016937455762596,1486016937893773267,1486016938347061644,1486016938798098308,1486016939282654265,1486016939815314137,1486016940432495613,1486016941067180256,1486016941762991266,1486016942477724978,1486016943221229595,1486016944028829065,1486016944960599140,1486016945979457551,1486016947079877926,1486016948269783347,1486016949512064211,1486016950845357004,1486016952265370480,1486016953800203463,1486016955448714953,1486016957283316652,1486016959298396739,1486016960765275382,1486016962981408512,1486016965412637994,1486016968358186191,1486016970769560927,1486016973596413231,1486016976686419404,1486016980003820299,1486016983758504988,1486016987796831485,1486016992249624393,1486016994238365056,1486016998897201175,1486017003962572898,1486017006766976039,1486017012040614730,1486017017850524149,1486017024116582000,1486017030993802682,1486017038493181395,1486017046718991088,1486017055639545855,1486017065052458529,1486017075014389459,1486017085466688352,1486017096628069066,1486017108362646283,1486017121189154771,1486017135127113153,1486017150380757469,1486017166753030002,1486017184674242899,1486017203568019605,1486017224146395461,1486017244997886403,1486017265859456248,1486017288768044302,1486017312714363916,1486017317481201989,1486017339924865319,1486017363426751178,1486017385306295465,1486017407297940226,1486017429024645961,1486017449793735860,1486017470247055740,1486017489809410161,1486017509137962775,1486017528104249317,1486017551699125725,1486017565931477646,1486017585367590382,1486017605941160404,1486017612465903945,1486017631498093315,1486017651729228350,1486017672216879707,1486017690732926917,1486017709023438456,1486017727170414638,1486017744710999168,1486017762294680470,1486017782077841381,1486017799973726371,1486017819433536695,1486017854058250637,1486017864044344899,1486017939352950581,1486018062594310289,1486018164345239367,1486018210551869297,1486018333805171095,1486018457057300517,1486018463980684106,1486018510557224352,1486018633829673664,1486018719818277033,1486018764040166703,1486018810444739928,1486018881673954016,1486019004916720064,1486019064098658514,1486019110432486460,1486019233726048004,1486019356939197020,1486019363979504550,1486019410460551366,1486019415218754799,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0],"NumGC":131,"GCCPUFraction":0.06830669929065548,"EnableGC":true,"DebugGC":false,"BySize":[{"Size":0,"Mallocs":0,"Frees":0},{"Size":8,"Mallocs":768705289,"Frees":768701586},{"Size":16,"Mallocs":2103392192,"Frees":2094848877},{"Size":32,"Mallocs":1979332665,"Frees":1979295278},{"Size":48,"Mallocs":1421893435,"Frees":1362414462},{"Size":64,"Mallocs":3274046690,"Frees":3204876287},{"Size":80,"Mallocs":245490786,"Frees":245388554},{"Size":96,"Mallocs":1106554776,"Frees":1106529036},{"Size":112,"Mallocs":524837,"Frees":518023},{"Size":128,"Mallocs":22988455,"Frees":22986812},{"Size":144,"Mallocs":1111730,"Frees":1111261},{"Size":160,"Mallocs":21910384,"Frees":21909934},{"Size":176,"Mallocs":251292243,"Frees":251288823},{"Size":192,"Mallocs":14393,"Frees":14344},{"Size":208,"Mallocs":2655707,"Frees":2655361},{"Size":224,"Mallocs":6364,"Frees":6206},{"Size":240,"Mallocs":12975,"Frees":12930},{"Size":256,"Mallocs":22876695,"Frees":22876583},{"Size":288,"Mallocs":97899,"Frees":97032},{"Size":320,"Mallocs":9652,"Frees":9446},{"Size":352,"Mallocs":39075,"Frees":38981},{"Size":384,"Mallocs":5209,"Frees":5184},{"Size":416,"Mallocs":13863,"Frees":10495},{"Size":448,"Mallocs":231,"Frees":188},{"Size":480,"Mallocs":982605,"Frees":982597},{"Size":512,"Mallocs":29423091,"Frees":29423023},{"Size":576,"Mallocs":5015,"Frees":4918},{"Size":640,"Mallocs":3579,"Frees":3552},{"Size":704,"Mallocs":7793,"Frees":7749},{"Size":768,"Mallocs":1476,"Frees":1469},{"Size":896,"Mallocs":6847,"Frees":6772},{"Size":1024,"Mallocs":22801877,"Frees":22801748},{"Size":1152,"Mallocs":4279,"Frees":4054},{"Size":1280,"Mallocs":2909275,"Frees":2865038},{"Size":1408,"Mallocs":1990,"Frees":1958},{"Size":1536,"Mallocs":3278512,"Frees":3226681},{"Size":1664,"Mallocs":3633857,"Frees":3114185},{"Size":2048,"Mallocs":26228082,"Frees":26011361},{"Size":2304,"Mallocs":1930250,"Frees":1915092},{"Size":2560,"Mallocs":1502232,"Frees":1455507},{"Size":2816,"Mallocs":2033,"Frees":2026},{"Size":3072,"Mallocs":3966,"Frees":3962},{"Size":3328,"Mallocs":1844176,"Frees":1781556},{"Size":4096,"Mallocs":4847373,"Frees":4836518},{"Size":4608,"Mallocs":3507,"Frees":3498},{"Size":5376,"Mallocs":56375,"Frees":54415},{"Size":6144,"Mallocs":357,"Frees":346},{"Size":6400,"Mallocs":93,"Frees":93},{"Size":6656,"Mallocs":169,"Frees":168},{"Size":6912,"Mallocs":92,"Frees":92},{"Size":8192,"Mallocs":1139098,"Frees":1137957},{"Size":8448,"Mallocs":94,"Frees":94},{"Size":8704,"Mallocs":104,"Frees":104},{"Size":9472,"Mallocs":51110,"Frees":51104},{"Size":10496,"Mallocs":2858980,"Frees":2814763},{"Size":12288,"Mallocs":6950412,"Frees":6373556},{"Size":13568,"Mallocs":2399300,"Frees":2269905},{"Size":14080,"Mallocs":962732,"Frees":946273},{"Size":16384,"Mallocs":2958100,"Frees":2892088},{"Size":16640,"Mallocs":2633,"Frees":2633},{"Size":17664,"Mallocs":2144465,"Frees":2100944}]}

[aclements]

@t3rm1n4l, perhaps I'm misunderstanding the problem here, but have you read up on GOGC (near the top of https://godoc.org/runtime)? With the default GOGC value of 100, the allocator is expected to keep a head room equal to the live heap size following the previous GC. So, given a live heap of 22GB, your RSS should be somewhere between 22GB and 44GB depending on how much it was able to directly scavenge.

In some sense the 12GB you're seeing is fragmentation, but if you were to continue allocating you could allocate roughly 12GB more without your process growing.

This default policy is good for a lot of applications, but it's not so good for huge heaps or memory limits (we're working on it, but it's a very multifaceted problem). For your application, you may want to reduce GOGC, at least during some phases of it. This trades off CPU for RAM: it will make GC run more often so it will be more expensive overall (we're working on that, too :), but it will keep the heap smaller.

[t3rm1n4l]

I am generally okay to have 2x usage by golang. But, I am worried about the 12GB fragmentation. While my program continues to operate, I have seen fragmentation growing further even up to > 20GB. This significantly limits the usable memory. Given that go uses a port of tcmalloc, is it possible that the fragmentation problem is also inherited from tcmalloc ?

We had a in-memory KV storage engine where we allocate up to 500GB and 1.6 M insert op/sec. The gogc was not able to keep up. Finally we ended up implementing a manual memory manager which uses cgo to allocate through jemalloc.

Currently, we have another storage engine where we do not require large number of ops/sec and GC could keep up. Hence, I thought I would try go1.7. But, 50% heap fragmentation really makes it unusable.

[aclements]

The 12GB of "fragmentation" is part of the 2x, so I'm afraid I don't understand your concern. If you reduce GOGC, that will decrease, too. If you allocate, you will use those 12GB of memory before getting more from the OS.

[t3rm1n4l]

If 2x (GOGC=100) includes the fragmentation as well, that's good. If I remember correctly, I have observed that instead of allocations happening from 12GB, my heap size increases further and fragmentation also increases. Anyway, let me try it out again with GOGC=20. So, I would expect max heap size = 1.2x. Is that correct ?