CODEWITHSUNDEEP
javatomcatgarbage-collection
Daehee Han
Daehee Han

Reputation: 526

Intensive GC activity shuts down the service temporariliy

I got a report that my service sometimes not responding.

I found out that a java process fully occupies one core (only one core among 4),

so I searched through web, and found this : Hung JVM consuming 100% CPU

I started to log every GC activity, and found weird logs.

26149.891: [GC [PSYoungGen: 138048K->37757K(184512K)] 360110K->295763K(1495232K), 0.0749820 secs] [Times: user=0.53 sys=0.02, real=0.07 secs] 
26150.173: [GC [PSYoungGen: 143741K->37312K(183616K)] 401747K->333115K(1494336K), 0.0706090 secs] [Times: user=0.50 sys=0.02, real=0.07 secs] 
26150.450: [GC [PSYoungGen: 143296K->37280K(187328K)] 439099K->370363K(1498048K), 0.1557100 secs] [Times: user=1.07 sys=0.02, real=0.15 secs] 
26150.818: [GC [PSYoungGen: 148320K->42028K(185856K)] 481403K->412407K(1496576K), 0.0835340 secs] [Times: user=0.60 sys=0.03, real=0.08 secs] 
26151.121: [GC [PSYoungGen: 153068K->39040K(188416K)] 523447K->451423K(1499136K), 0.0831170 secs] [Times: user=0.58 sys=0.02, real=0.08 secs] 
26151.436: [GC [PSYoungGen: 152448K->39872K(187136K)] 564831K->491311K(1497856K), 0.1627710 secs] [Times: user=1.22 sys=0.03, real=0.17 secs] 
26151.832: [GC [PSYoungGen: 153280K->39744K(190720K)] 604719K->531063K(1501440K), 0.1741030 secs] [Times: user=1.30 sys=0.03, real=0.17 secs] 
26152.230: [GC [PSYoungGen: 157760K->46130K(189440K)] 649079K->577265K(1500160K), 0.0940570 secs] [Times: user=0.66 sys=0.03, real=0.09 secs] 
26152.554: [GC [PSYoungGen: 164146K->41504K(190784K)] 695281K->618785K(1501504K), 0.0948330 secs] [Times: user=0.68 sys=0.02, real=0.10 secs] 
26152.879: [GC [PSYoungGen: 159840K->41440K(189696K)] 737121K->660233K(1500416K), 0.1807870 secs] [Times: user=1.37 sys=0.02, real=0.18 secs] 
26153.296: [GC [PSYoungGen: 159776K->41568K(193280K)] 778569K->701849K(1504000K), 0.1802040 secs] [Times: user=1.22 sys=0.03, real=0.18 secs] 
26153.721: [GC [PSYoungGen: 164768K->43168K(192064K)] 825049K->745065K(1502784K), 0.1874250 secs] [Times: user=1.42 sys=0.02, real=0.19 secs] 
26154.134: [GC [PSYoungGen: 159404K->40352K(195840K)] 861301K->785481K(1506560K), 0.1758760 secs] [Times: user=1.30 sys=0.02, real=0.18 secs] 
26154.546: [GC [PSYoungGen: 168032K->51803K(179520K)] 913161K->837348K(1490240K), 0.1128670 secs] [Times: user=0.76 sys=0.02, real=0.12 secs] 
26154.910: [GC [PSYoungGen: 179483K->44768K(194112K)] 965028K->882164K(1504832K), 0.1198690 secs] [Times: user=0.88 sys=0.03, real=0.12 secs] 
26155.275: [GC [PSYoungGen: 170080K->44064K(193344K)] 1007476K->926252K(1504064K), 0.2003860 secs] [Times: user=1.51 sys=0.02, real=0.20 secs] 
26155.722: [GC [PSYoungGen: 169376K->43968K(196352K)] 1051564K->970212K(1507072K), 0.2186830 secs] [Times: user=1.67 sys=0.03, real=0.22 secs] 
26156.194: [GC [PSYoungGen: 173376K->45472K(195200K)] 1099620K->1015700K(1505920K), 0.1993740 secs] [Times: user=1.40 sys=0.04, real=0.20 secs] 
26156.647: [GC [PSYoungGen: 174880K->45440K(197696K)] 1145108K->1061172K(1508416K), 0.2208800 secs] [Times: user=1.64 sys=0.03, real=0.23 secs] 
26157.125: [GC [PSYoungGen: 177984K->45984K(196992K)] 1193716K->1107220K(1507712K), 0.2207530 secs] [Times: user=1.62 sys=0.02, real=0.22 secs] 
26157.580: [GC [PSYoungGen: 178528K->56664K(191680K)] 1239764K->1163988K(1502400K), 0.1383820 secs] [Times: user=0.98 sys=0.04, real=0.14 secs] 
26157.966: [GC [PSYoungGen: 184408K->44768K(194944K)] 1291732K->1208844K(1505664K), 0.1331440 secs] [Times: user=0.94 sys=0.03, real=0.14 secs] 
26158.457: [GC [PSYoungGen: 172512K->44928K(198336K)] 1336588K->1253828K(1509056K), 0.2231800 secs] [Times: user=1.68 sys=0.03, real=0.23 secs] 
26158.963: [GC [PSYoungGen: 177856K->46624K(196736K)] 1386756K->1300436K(1507456K), 0.2182210 secs] [Times: user=1.65 sys=0.03, real=0.22 secs] 
26159.181: [Full GC [PSYoungGen: 46624K->0K(196736K)] [PSOldGen: 1253812K->1300242K(1310720K)] 1300436K->1300242K(1507456K) [PSPermGen: 55231K->55231K(262144K)], 3.4748620 secs] [Times: user=3.43 sys=0.03, real=3.47 secs] 
26163.002: [Full GC [PSYoungGen: 132928K->35639K(196736K)] [PSOldGen: 1300242K->1310720K(1310720K)] 1433170K->1346359K(1507456K) [PSPermGen: 55231K->55231K(262144K)], 3.5303910 secs] [Times: user=3.51 sys=0.02, real=3.53 secs] 
26166.802: [Full GC [PSYoungGen: 132928K->76010K(196736K)] [PSOldGen: 1310720K->1310720K(1310720K)] 1443648K->1386730K(1507456K) [PSPermGen: 55231K->55231K(262144K)], 3.4764380 secs] [Times: user=3.48 sys=0.00, real=3.47 secs] 
26170.464: [Full GC [PSYoungGen: 132928K->41991K(196736K)] [PSOldGen: 1310720K->1310720K(1310720K)] 1443648K->1352711K(1507456K) [PSPermGen: 55231K->55211K(262144K)], 4.6156250 secs] [Times: user=4.57 sys=0.04, real=4.61 secs] 
26175.372: [Full GC [PSYoungGen: 132928K->80309K(196736K)] [PSOldGen: 1310720K->1310720K(1310720K)] 1443648K->1391029K(1507456K) [PSPermGen: 55211K->55211K(262144K)], 3.5159220 secs] [Times: user=3.51 sys=0.00, real=3.51 secs] 
26179.074: [Full GC [PSYoungGen: 132928K->98592K(196736K)] [PSOldGen: 1310720K->1310720K(1310720K)] 1443648K->1409312K(1507456K) [PSPermGen: 55211K->55211K(262144K)], 3.5558960 secs] [Times: user=3.55 sys=0.00, real=3.55 secs] 
26182.700: [Full GC [PSYoungGen: 132928K->110146K(196736K)] [PSOldGen: 1310720K->1310720K(1310720K)] 1443648K->1420866K(1507456K) [PSPermGen: 55211K->55211K(262144K)], 3.8777130 secs] [Times: user=3.87 sys=0.00, real=3.88 secs] 
26186.663: [Full GC [PSYoungGen: 132928K->111368K(196736K)] [PSOldGen: 1310720K->1310720K(1310720K)] 1443648K->1422088K(1507456K) [PSPermGen: 55211K->55211K(262144K)], 4.5746670 secs] [Times: user=4.57 sys=0.00, real=4.57 secs] 
26191.321: [Full GC [PSYoungGen: 132928K->125449K(196736K)] [PSOldGen: 1310720K->1310720K(1310720K)] 1443648K->1436169K(1507456K) [PSPermGen: 55211K->55211K(262144K)], 3.6080590 secs] [Times: user=3.56 sys=0.04, real=3.61 secs] 
26194.954: [Full GC [PSYoungGen: 132928K->127668K(196736K)] [PSOldGen: 1310720K->1310720K(1310720K)] 1443648K->1438388K(1507456K) [PSPermGen: 55211K->55211K(262144K)], 3.5435640 secs] [Times: user=3.54 sys=0.00, real=3.54 secs] 
26198.517: [Full GC [PSYoungGen: 132928K->129407K(196736K)] [PSOldGen: 1310720K->1310720K(1310720K)] 1443648K->1440127K(1507456K) [PSPermGen: 55211K->55211K(262144K)], 3.5862840 secs] [Times: user=3.57 sys=0.02, real=3.58 secs] 
26202.117: [Full GC [PSYoungGen: 132928K->123893K(196736K)] [PSOldGen: 1310720K->1310720K(1310720K)] 1443648K->1434613K(1507456K) [PSPermGen: 55211K->55211K(262144K)], 4.7643840 secs] [Times: user=4.73 sys=0.03, real=4.76 secs] 
26206.912: [Full GC [PSYoungGen: 132928K->132928K(196736K)] [PSOldGen: 1310720K->1310720K(1310720K)] 1443648K->1443648K(1507456K) [PSPermGen: 55214K->55214K(262144K)], 3.6269220 secs] [Times: user=3.62 sys=0.00, real=3.63 secs] 
26210.539: [Full GC [PSYoungGen: 132928K->126271K(196736K)] [PSOldGen: 1310720K->1310719K(1310720K)] 1443648K->1436991K(1507456K) [PSPermGen: 55214K->55151K(262144K)], 4.6103030 secs] [Times: user=4.61 sys=0.00, real=4.61 secs] 
26215.191: [Full GC [PSYoungGen: 132928K->132928K(196736K)] [PSOldGen: 1310719K->1310719K(1310720K)] 1443647K->1443647K(1507456K) [PSPermGen: 55202K->55202K(262144K)], 3.5856180 secs] [Times: user=3.59 sys=0.00, real=3.59 secs] 
26218.777: [Full GC [PSYoungGen: 132928K->128287K(196736K)] [PSOldGen: 1310719K->1310719K(1310720K)] 1443647K->1439007K(1507456K) [PSPermGen: 55202K->55151K(262144K)], 4.6097420 secs] [Times: user=4.60 sys=0.00, real=4.60 secs] 
26223.406: [Full GC [PSYoungGen: 132926K->132926K(196736K)] [PSOldGen: 1310719K->1310719K(1310720K)] 1443646K->1443646K(1507456K) [PSPermGen: 55202K->55202K(262144K)], 3.6066240 secs] [Times: user=3.60 sys=0.00, real=3.61 secs] 
26227.012: [Full GC [PSYoungGen: 132926K->129377K(196736K)] [PSOldGen: 1310719K->1310719K(1310720K)] 1443646K->1440097K(1507456K) [PSPermGen: 55202K->55184K(262144K)], 4.6120400 secs] [Times: user=4.61 sys=0.00, real=4.61 secs] 
26231.653: [Full GC [PSYoungGen: 132928K->132928K(196736K)] [PSOldGen: 1310719K->1310719K(1310720K)] 1443647K->1443647K(1507456K) [PSPermGen: 55199K->55199K(262144K)], 3.5711710 secs] [Times: user=3.59 sys=0.00, real=3.57 secs] 
26235.225: [Full GC [PSYoungGen: 132928K->130479K(196736K)] [PSOldGen: 1310719K->1310720K(1310720K)] 1443647K->1441199K(1507456K) [PSPermGen: 55199K->55199K(262144K)], 4.4967450 secs] [Times: user=4.49 sys=0.00, real=4.50 secs] 
26239.732: [Full GC [PSYoungGen: 132928K->132928K(196736K)] [PSOldGen: 1310720K->1310720K(1310720K)] 1443648K->1443648K(1507456K) [PSPermGen: 55202K->55202K(262144K)], 3.5474400 secs] [Times: user=3.54 sys=0.00, real=3.54 secs] 
26243.279: [Full GC [PSYoungGen: 132928K->131113K(196736K)] [PSOldGen: 1310720K->1310720K(1310720K)] 1443648K->1441833K(1507456K) [PSPermGen: 55202K->55184K(262144K)], 3.5526010 secs] [Times: user=3.55 sys=0.00, real=3.56 secs] 
26246.838: [Full GC [PSYoungGen: 132928K->132928K(196736K)] [PSOldGen: 1310720K->1310720K(1310720K)] 1443648K->1443648K(1507456K) [PSPermGen: 55202K->55202K(262144K)], 3.5478440 secs] [Times: user=3.54 sys=0.01, real=3.55 secs] 
26250.386: [Full GC [PSYoungGen: 132928K->131392K(196736K)] [PSOldGen: 1310720K->1310719K(1310720K)] 1443648K->1442112K(1507456K) [PSPermGen: 55202K->55157K(262144K)], 3.6749040 secs] [Times: user=3.67 sys=0.00, real=3.67 secs] 
26254.067: [Full GC [PSYoungGen: 132928K->132928K(196736K)] [PSOldGen: 1310719K->1310719K(1310720K)] 1443647K->1443647K(1507456K) [PSPermGen: 55178K->55178K(262144K)], 3.5833210 secs] [Times: user=3.59 sys=0.00, real=3.58 secs] 
26257.650: [Full GC [PSYoungGen: 132928K->131782K(196736K)] [PSOldGen: 1310719K->1310719K(1310720K)] 1443647K->1442502K(1507456K) [PSPermGen: 55178K->55166K(262144K)], 3.5557440 secs] [Times: user=3.55 sys=0.00, real=3.56 secs] 
26261.211: [Full GC [PSYoungGen: 132928K->132928K(196736K)] [PSOldGen: 1310719K->1310719K(1310720K)] 1443647K->1443647K(1507456K) [PSPermGen: 55175K->55175K(262144K)], 3.5458550 secs] [Times: user=3.55 sys=0.00, real=3.55 secs] 
26264.757: [Full GC [PSYoungGen: 132928K->132082K(196736K)] [PSOldGen: 1310719K->1310720K(1310720K)] 1443647K->1442802K(1507456K) [PSPermGen: 55175K->55154K(262144K)], 4.5970920 secs] [Times: user=4.60 sys=0.00, real=4.59 secs] 
26269.357: [Full GC [PSYoungGen: 132928K->132928K(196736K)] [PSOldGen: 1310720K->1310720K(1310720K)] 1443648K->1443648K(1507456K) [PSPermGen: 55157K->55157K(262144K)], 3.5443640 secs] [Times: user=3.55 sys=0.00, real=3.54 secs] 
26272.901: [Full GC [PSYoungGen: 132928K->132206K(196736K)] [PSOldGen: 1310720K->1310720K(1310720K)] 1443648K->1442926K(1507456K) [PSPermGen: 55157K->55157K(262144K)], 4.6007130 secs] [Times: user=4.60 sys=0.00, real=4.60 secs] 
26277.504: [Full GC [PSYoungGen: 132928K->132928K(196736K)] [PSOldGen: 1310720K->1310720K(1310720K)] 1443648K->1443648K(1507456K) [PSPermGen: 55169K->55169K(262144K)], 3.5481120 secs] [Times: user=3.55 sys=0.00, real=3.55 secs] 
26281.052: [Full GC [PSYoungGen: 132928K->132330K(196736K)] [PSOldGen: 1310720K->1310720K(1310720K)] 1443648K->1443050K(1507456K) [PSPermGen: 55169K->55160K(262144K)], 3.5732500 secs] [Times: user=3.57 sys=0.00, real=3.57 secs] 
26284.628: [Full GC [PSYoungGen: 132928K->132928K(196736K)] [PSOldGen: 1310720K->1310720K(1310720K)] 1443648K->1443648K(1507456K) [PSPermGen: 55163K->55163K(262144K)], 3.5440330 secs] [Times: user=3.55 sys=0.00, real=3.54 secs] 
26288.173: [Full GC [PSYoungGen: 132928K->132396K(196736K)] [PSOldGen: 1310720K->1310720K(1310720K)] 1443648K->1443116K(1507456K) [PSPermGen: 55163K->55154K(262144K)], 3.5533020 secs] [Times: user=3.55 sys=0.00, real=3.55 secs] 
26291.728: [Full GC [PSYoungGen: 132928K->132928K(196736K)] [PSOldGen: 1310720K->1310720K(1310720K)] 1443648K->1443648K(1507456K) [PSPermGen: 55156K->55156K(262144K)], 3.5478580 secs] [Times: user=3.55 sys=0.00, real=3.55 secs] 
26295.276: [Full GC [PSYoungGen: 132928K->132554K(196736K)] [PSOldGen: 1310720K->1310720K(1310720K)] 1443648K->1443274K(1507456K) [PSPermGen: 55156K->55153K(262144K)], 3.5612690 secs] [Times: user=3.56 sys=0.00, real=3.56 secs] 
26298.840: [Full GC [PSYoungGen: 132928K->132928K(196736K)] [PSOldGen: 1310720K->1310720K(1310720K)] 1443648K->1443648K(1507456K) [PSPermGen: 55163K->55163K(262144K)], 3.5476290 secs] [Times: user=3.54 sys=0.00, real=3.54 secs] 
26302.387: [Full GC [PSYoungGen: 132928K->132630K(196736K)] [PSOldGen: 1310720K->1310720K(1310720K)] 1443648K->1443350K(1507456K) [PSPermGen: 55163K->55163K(262144K)], 3.5523880 secs] [Times: user=3.56 sys=0.00, real=3.55 secs] 
26305.941: [Full GC [PSYoungGen: 132928K->132928K(196736K)] [PSOldGen: 1310720K->1310720K(1310720K)] 1443648K->1443648K(1507456K) [PSPermGen: 55166K->55166K(262144K)], 3.5477250 secs] [Times: user=3.55 sys=0.00, real=3.54 secs] 
26309.489: [Full GC [PSYoungGen: 132928K->132694K(196736K)] [PSOldGen: 1310720K->1310720K(1310720K)] 1443648K->1443414K(1507456K) [PSPermGen: 55166K->55160K(262144K)], 3.5517750 secs] [Times: user=3.55 sys=0.00, real=3.55 secs] 
26313.042: [Full GC [PSYoungGen: 132928K->132928K(196736K)] [PSOldGen: 1310720K->1310720K(1310720K)] 1443648K->1443648K(1507456K) [PSPermGen: 55164K->55164K(262144K)], 3.6786080 secs] [Times: user=3.66 sys=0.01, real=3.67 secs] 
26316.721: [Full GC [PSYoungGen: 132928K->132761K(196736K)] [PSOldGen: 1310720K->1310720K(1310720K)] 1443648K->1443481K(1507456K) [PSPermGen: 55164K->55164K(262144K)], 3.5701210 secs] [Times: user=3.57 sys=0.00, real=3.57 secs] 
26320.293: [Full GC [PSYoungGen: 132928K->132928K(196736K)] [PSOldGen: 1310720K->1310720K(1310720K)] 1443648K->1443648K(1507456K) [PSPermGen: 55169K->55169K(262144K)], 3.5485590 secs] [Times: user=3.55 sys=0.00, real=3.54 secs] 
26323.842: [Full GC [PSYoungGen: 132928K->132815K(196736K)] [PSOldGen: 1310720K->1310720K(1310720K)] 1443648K->1443535K(1507456K) [PSPermGen: 55169K->55169K(262144K)], 3.5526530 secs] [Times: user=3.55 sys=0.00, real=3.56 secs] 
26327.396: [Full GC [PSYoungGen: 132928K->132928K(196736K)] [PSOldGen: 1310720K->1310720K(1310720K)] 1443648K->1443648K(1507456K) [PSPermGen: 55169K->55169K(262144K)], 3.5483590 secs] [Times: user=3.55 sys=0.00, real=3.54 secs] 
26330.944: [Full GC [PSYoungGen: 132928K->132833K(196736K)] [PSOldGen: 1310720K->1310720K(1310720K)] 1443648K->1443553K(1507456K) [PSPermGen: 55169K->55166K(262144K)], 3.5551080 secs] [Times: user=3.55 sys=0.00, real=3.56 secs] 
26334.501: [Full GC [PSYoungGen: 132928K->132928K(196736K)] [PSOldGen: 1310720K->1310720K(1310720K)] 1443648K->1443648K(1507456K) [PSPermGen: 55172K->55172K(262144K)], 3.6050900 secs] [Times: user=3.59 sys=0.01, real=3.61 secs] 
26338.106: [Full GC [PSYoungGen: 132928K->132833K(196736K)] [PSOldGen: 1310720K->1310719K(1310720K)] 1443648K->1443553K(1507456K) [PSPermGen: 55172K->55172K(262144K)], 4.6456700 secs] [Times: user=4.63 sys=0.01, real=4.64 secs] 
26342.754: [Full GC [PSYoungGen: 132928K->132928K(196736K)] [PSOldGen: 1310719K->1310719K(1310720K)] 1443647K->1443647K(1507456K) [PSPermGen: 55178K->55178K(262144K)], 3.6874260 secs] [Times: user=3.69 sys=0.00, real=3.69 secs] 
26346.442: [Full GC [PSYoungGen: 132928K->132859K(196736K)] [PSOldGen: 1310719K->1310719K(1310720K)] 1443647K->1443579K(1507456K) [PSPermGen: 55178K->55178K(262144K)], 4.6572880 secs] [Times: user=4.65 sys=0.00, real=4.66 secs] 
26351.100: [Full GC [PSYoungGen: 132928K->132928K(196736K)] [PSOldGen: 1310719K->1310719K(1310720K)] 1443647K->1443647K(1507456K) [PSPermGen: 55178K->55178K(262144K)], 3.5457670 secs] [Times: user=3.54 sys=0.00, real=3.54 secs] 
26354.646: [Full GC [PSYoungGen: 132928K->132854K(196736K)] [PSOldGen: 1310719K->1310719K(1310720K)] 1443647K->1443574K(1507456K) [PSPermGen: 55178K->55178K(262144K)], 3.8780600 secs] [Times: user=3.88 sys=0.00, real=3.88 secs] 
26358.525: [Full GC [PSYoungGen: 132928K->132928K(196736K)] [PSOldGen: 1310719K->1310719K(1310720K)] 1443647K->1443647K(1507456K) [PSPermGen: 55178K->55178K(262144K)], 3.6869670 secs] [Times: user=3.68 sys=0.00, real=3.69 secs] 
26362.212: [Full GC [PSYoungGen: 132928K->132870K(196736K)] [PSOldGen: 1310719K->1310719K(1310720K)] 1443647K->1443590K(1507456K) [PSPermGen: 55178K->55178K(262144K)], 3.6601190 secs] [Times: user=3.65 sys=0.00, real=3.66 secs] 
26365.874: [Full GC [PSYoungGen: 132928K->132928K(196736K)] [PSOldGen: 1310719K->1310719K(1310720K)] 1443647K->1443647K(1507456K) [PSPermGen: 55178K->55178K(262144K)], 3.5784780 secs] [Times: user=3.57 sys=0.01, real=3.58 secs] 
26369.452: [Full GC [PSYoungGen: 132928K->132893K(196736K)] [PSOldGen: 1310719K->1310719K(1310720K)] 1443647K->1443613K(1507456K) [PSPermGen: 55178K->55178K(262144K)], 3.5865440 secs] [Times: user=3.56 sys=0.02, real=3.58 secs] 
26373.040: [Full GC [PSYoungGen: 132928K->132928K(196736K)] [PSOldGen: 1310719K->1310719K(1310720K)] 1443647K->1443647K(1507456K) [PSPermGen: 55178K->55178K(262144K)], 3.5989820 secs] [Times: user=3.57 sys=0.03, real=3.60 secs] 
26376.639: [Full GC [PSYoungGen: 132928K->132897K(196736K)] [PSOldGen: 1310719K->1310719K(1310720K)] 1443647K->1443617K(1507456K) [PSPermGen: 55178K->55178K(262144K)], 3.5529890 secs] [Times: user=3.55 sys=0.00, real=3.56 secs] 
26380.193: [Full GC [PSYoungGen: 132928K->132928K(196736K)] [PSOldGen: 1310719K->1310719K(1310720K)] 1443647K->1443647K(1507456K) [PSPermGen: 55178K->55178K(262144K)], 3.5474210 secs] [Times: user=3.55 sys=0.00, real=3.54 secs] 
26383.740: [Full GC [PSYoungGen: 132928K->132915K(196736K)] [PSOldGen: 1310719K->1310719K(1310720K)] 1443647K->1443635K(1507456K) [PSPermGen: 55178K->55178K(262144K)], 3.5972640 secs] [Times: user=3.58 sys=0.01, real=3.60 secs] 
26387.339: [Full GC [PSYoungGen: 132928K->132928K(196736K)] [PSOldGen: 1310719K->1310719K(1310720K)] 1443647K->1443647K(1507456K) [PSPermGen: 55178K->55178K(262144K)], 3.6116590 secs] [Times: user=3.59 sys=0.02, real=3.61 secs] 
26390.950: [Full GC [PSYoungGen: 132928K->132912K(196736K)] [PSOldGen: 1310719K->1310719K(1310720K)] 1443647K->1443632K(1507456K) [PSPermGen: 55178K->55178K(262144K)], 3.6188690 secs] [Times: user=3.58 sys=0.04, real=3.62 secs] 
26394.570: [Full GC [PSYoungGen: 132928K->132928K(196736K)] [PSOldGen: 1310719K->1310719K(1310720K)] 1443647K->1443647K(1507456K) [PSPermGen: 55178K->55178K(262144K)], 3.6132870 secs] [Times: user=3.59 sys=0.01, real=3.61 secs] 
26398.184: [Full GC [PSYoungGen: 132928K->132916K(196736K)] [PSOldGen: 1310719K->1310719K(1310720K)] 1443647K->1443636K(1507456K) [PSPermGen: 55178K->55178K(262144K)], 3.5736670 secs] [Times: user=3.57 sys=0.01, real=3.58 secs] 
26401.759: [Full GC [PSYoungGen: 132928K->132928K(196736K)] [PSOldGen: 1310719K->1310719K(1310720K)] 1443647K->1443647K(1507456K) [PSPermGen: 55178K->55178K(262144K)], 3.5491540 secs] [Times: user=3.54 sys=0.00, real=3.55 secs] 
26405.308: [Full GC [PSYoungGen: 132928K->132919K(196736K)] [PSOldGen: 1310719K->1310719K(1310720K)] 1443647K->1443639K(1507456K) [PSPermGen: 55178K->55178K(262144K)], 3.5484790 secs] [Times: user=3.55 sys=0.00, real=3.55 secs] 
26408.857: [Full GC [PSYoungGen: 132928K->132928K(196736K)] [PSOldGen: 1310719K->1310719K(1310720K)] 1443647K->1443647K(1507456K) [PSPermGen: 55178K->55178K(262144K)], 3.5489760 secs] [Times: user=3.55 sys=0.00, real=3.54 secs] 
26412.406: [Full GC [PSYoungGen: 132928K->132922K(196736K)] [PSOldGen: 1310719K->1310719K(1310720K)] 1443647K->1443642K(1507456K) [PSPermGen: 55178K->55178K(262144K)], 3.5474050 secs] [Times: user=3.55 sys=0.00, real=3.55 secs] 
26415.955: [Full GC [PSYoungGen: 132928K->132928K(196736K)] [PSOldGen: 1310719K->1310719K(1310720K)] 1443647K->1443647K(1507456K) [PSPermGen: 55178K->55178K(262144K)], 3.5476430 secs] [Times: user=3.54 sys=0.00, real=3.55 secs] 
26419.502: [Full GC [PSYoungGen: 132928K->132922K(196736K)] [PSOldGen: 1310719K->1310719K(1310720K)] 1443647K->1443642K(1507456K) [PSPermGen: 55178K->55178K(262144K)], 3.5518040 secs] [Times: user=3.56 sys=0.00, real=3.55 secs] 
26423.055: [Full GC [PSYoungGen: 132928K->132928K(196736K)] [PSOldGen: 1310719K->1310719K(1310720K)] 1443647K->1443647K(1507456K) [PSPermGen: 55178K->55178K(262144K)], 3.5467870 secs] [Times: user=3.54 sys=0.00, real=3.55 secs] 
26426.602: [Full GC [PSYoungGen: 132928K->132924K(196736K)] [PSOldGen: 1310719K->1310719K(1310720K)] 1443647K->1443644K(1507456K) [PSPermGen: 55178K->55178K(262144K)], 3.5525280 secs] [Times: user=3.55 sys=0.00, real=3.55 secs] 
26430.156: [Full GC [PSYoungGen: 132928K->132928K(196736K)] [PSOldGen: 1310719K->1310719K(1310720K)] 1443647K->1443647K(1507456K) [PSPermGen: 55178K->55178K(262144K)], 3.6035060 secs] [Times: user=3.60 sys=0.00, real=3.61 secs] 
26433.760: [Full GC [PSYoungGen: 132928K->132920K(196736K)] [PSOldGen: 1310719K->1310719K(1310720K)] 1443647K->1443640K(1507456K) [PSPermGen: 55178K->55172K(262144K)], 3.5433380 secs] [Times: user=3.54 sys=0.00, real=3.54 secs] 
26437.304: [Full GC [PSYoungGen: 132928K->0K(196736K)] [PSOldGen: 1310719K->53875K(1310720K)] 1443647K->53875K(1507456K) [PSPermGen: 55172K->55172K(262144K)], 0.6250820 secs] [Times: user=0.63 sys=0.00, real=0.62 secs] 
26723.816: [GC [PSYoungGen: 132928K->4016K(189504K)] 186803K->57891K(1500224K), 0.0123520 secs] [Times: user=0.06 sys=0.00, real=0.01 secs] 
27069.299: [GC [PSYoungGen: 130608K->8368K(134976K)] 184483K->62243K(1445696K), 0.0219260 secs] [Times: user=0.14 sys=0.00, real=0.02 secs] 
myScheduler-2> [2012-07-17 17:35:00] [AlarmService] [110] [INFO] issue alarm mail sent, contract_id = 10, tweet_id = 225111165720735745 
27436.179: [GC [PSYoungGen: 134960K->12816K(190400K)] 188835K->66692K(1501120K), 0.0323320 secs] [Times: user=0.23 sys=0.00, real=0.03 secs] 
27782.840: [GC [PSYoungGen: 132880K->16976K(191104K)] 186756K->70852K(1501824K), 0.0416410 secs] [Times: user=0.31 sys=0.00, real=0.04 secs]

As you can see, for some period of time, Full GC activities are performed and tomcat hangs.

It recovers eventually, but it paralyzes my service meanwhile.

Anybody knows what is happening in my machine?

Upvotes: 2

Views: 692

Answers (2)

Tomasz Nurkiewicz
Tomasz Nurkiewicz

Reputation: 340713

For around 5 minutes your application isn't doing almost anything except running major GC. Each GC takes around 3-4 seconds (in that time JVM is unresponsive) immediately followed by another. Also GC is consuming 100% of CPU (one core?)

Important to note that each major GC is not really collecting any garbage, both in young:

PSYoungGen: 132928K->132922K(196736K)

and in old generation:

PSOldGen: 1310719K->1310719K(1310720K)

and because the JVM was unable to find any free memory, it runs GC again, and again, and...

However your application didn't just crash. Instead it suddenly somehow recovered after these few minutes (split lines for clarity):

26437.304: [Full GC 
    [PSYoungGen: 132928K->0K(196736K)] 
    [PSOldGen: 1310719K->53875K(1310720K)] 1443647K->53875K(1507456K) 
    [PSPermGen: 55172K->55172K(262144K)], 0.6250820 secs] 
    [Times: user=0.63 sys=0.00, real=0.62 secs]

Not only the whole young generation was released, but also the amount of old generation dropped from 1280 MB to 52 MB. Please watch closely this chart (zoom). Blue line shows your heap usage that suddenly sky-rockets and drops after few minutes. Also green line shows average GC time - from tolerable milliseconds to disastrous seconds. Finally black vertical bars represent major GC. They should not appear more often then every other minute (hour?), not every other second.

GCViewer

This tells me that for this short period of time you kept a lot of data in memory. Probably some huge collection of objects. Somehow JVM didn't crashed but managed to continue processing. When your job was done, the whole collection was simply GCed.

It's hard to tell without seeing the code (I see AlarmService dangling in the logs...), but before you use cannons like memory dump and profiling, examine your code, especially unbounded collections you load from DB or fetch from outside (do I see Twitter?)

Upvotes: 5

Tomer
Tomer

Reputation: 17930

Objects in memmory are devided roughly in to two heaps (in GC perspective): Young generation and Old generation.

Most of the time GC would run short iterations on the Young gen objects and those iteration are usually run in parallel to the application flow (the application is not stopped).

Every now and then the young generation heap is filled and GC perform whats called a "stop the world" clean, meaning, the application stops completley and GC cleans all unneccessary objects in both heaps. Obviously this iteration takes a bit more time then the usual short iterations.

You need to check several things:

  1. Try profiling your application and make sure you don't have a memmory leak that causes your heap to grow rapidly and thus enforcing a full GC very often.
  2. GC have several algorithms that cause it to behave differently (run in parallel, run serial etc.), you might want to investigate it and see which one is better for your needs.

You can look here for a pointer, and also use google.

Upvotes: 2

Related Questions