Skip to main content

Understanding GC Logs

2 replies [Last post]
crystalcracker
Offline
Joined: 2009-06-01
Points: 0

I am just trying to learn and understand the GC logs. I did read the sun's Hotspot docs.

jdk1.6.0_07
-Xms2g -Xmx2g -Xss256k
-XX:+UseLargePages -XX:+PrintGCDetails
-verbose:gc -Xloggc:/var/log/gc.log
-Dsun.rmi.dgc.client.gcInterval=3600000 -Dsun.rmi.dgc.server.gcInterval=3600000
-XX:PermSize=512m -XX:MaxPermSize=512m

The full GC usually runs in every 20-30 minutes (takes 2 seconds), and the minor collections occur every 40-50 seconds. But after running for a few days, the GC sometimes starts occuring more frequently (and takes upto 4 secs) and during this time, the app slows down noticeably. I have done heap dumps, and didn't notice any major memory leaks.

I have pasted the snipped from my GC logs. Does the logs in themselves indicates any possible problems? Thanks in advance.

322241.484: [GC [PSYoungGen: 493731K->50938K(578816K)] 1617970K->1175624K(1977600K), 0.0761440 secs] [Times: user=0.23 sys=0.00, real=0.07 secs]
322264.254: [GC [PSYoungGen: 508730K->78771K(581568K)] 1633416K->1203628K(1980352K), 0.1524060 secs] [Times: user=0.26 sys=0.01, real=0.16 secs]
322283.883: [GC [PSYoungGen: 543155K->118014K(582400K)] 1668012K->1249096K(1981184K), 0.2397130 secs] [Times: user=0.49 sys=0.00, real=0.24 secs]
322301.402: [GC [PSYoungGen: 582398K->118007K(495360K)] 1713480K->1289473K(1894144K), 0.2343380 secs] [Times: user=0.64 sys=0.01, real=0.24 secs]
322317.408: [GC [PSYoungGen: 495351K->161534K(538880K)] 1666817K->1357597K(1937664K), 0.3078690 secs] [Times: user=0.70 sys=0.00, real=0.31 secs]
322338.991: [GC [PSYoungGen: 538878K->161533K(426240K)] 1734941K->1379949K(1825024K), 0.1890400 secs] [Times: user=0.86 sys=0.00, real=0.19 secs]
322352.173: [GC [PSYoungGen: 426237K->156891K(421632K)] 1644653K->1376348K(1820416K), 0.1314940 secs] [Times: user=0.83 sys=0.00, real=0.13 secs]
322353.537: [GC [PSYoungGen: 421595K->149135K(464320K)] 1641052K->1368592K(1863104K), 0.1075660 secs] [Times: user=0.78 sys=0.01, real=0.11 secs]
322358.922: [GC [PSYoungGen: 385935K->192657K(429504K)] 1605392K->1412114K(1828288K), 0.4118000 secs] [Times: user=1.10 sys=1.27, real=0.41 secs]
322382.445: [GC [PSYoungGen: 429457K->162415K(466944K)] 1648914K->1391845K(1865728K), 0.1753080 secs] [Times: user=0.93 sys=0.13, real=0.18 secs]
322389.711: [GC [PSYoungGen: 395887K->175021K(466944K)] 1625317K->1404944K(1865728K), 0.1825450 secs] [Times: user=0.83 sys=0.01, real=0.18 secs]
322400.876: [GC [PSYoungGen: 408493K->163512K(466944K)] 1638416K->1397305K(1865728K), 0.1612630 secs] [Times: user=0.87 sys=0.01, real=0.16 secs]
322411.500: [GC [PSYoungGen: 396239K->111767K(466944K)] 1630032K->1412129K(1865728K), 0.2211210 secs] [Times: user=1.04 sys=0.11, real=0.23 secs]
322427.250: [GC [PSYoungGen: 345239K->35751K(466944K)] 1645601K->1401444K(1865728K), 0.1585970 secs] [Times: user=0.65 sys=0.14, real=0.16 secs]
322427.409: [Full GC [PSYoungGen: 35751K->0K(466944K)] [PSOldGen: 1365693K->695195K(1398784K)] 1401444K->695195K(1865728K) [PSPermGen: 180694K->180694K(524288K)], 2
.3017070 secs] [Times: user=2.09 sys=0.21, real=2.30 secs]
322431.641: [GC [PSYoungGen: 233472K->3639K(466944K)] 928667K->698834K(1865728K), 0.0171480 secs] [Times: user=0.05 sys=0.00, real=0.02 secs]
322432.659: [GC [PSYoungGen: 237111K->4086K(466944K)] 932306K->699281K(1865728K), 0.0150920 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]
322438.955: [GC [PSYoungGen: 237558K->10227K(466944K)] 932753K->705422K(1865728K), 0.0291110 secs] [Times: user=0.06 sys=0.01, real=0.03 secs]
322441.277: [GC [PSYoungGen: 243699K->7492K(466944K)] 938894K->702688K(1865728K), 0.0213000 secs] [Times: user=0.05 sys=0.01, real=0.03 secs]
322442.216: [GC [PSYoungGen: 240964K->15236K(466944K)] 936160K->711474K(1865728K), 0.0242510 secs] [Times: user=0.11 sys=0.00, real=0.03 secs]
322449.748: [GC [PSYoungGen: 248708K->22608K(466944K)] 944946K->723379K(1865728K), 0.0357610 secs] [Times: user=0.19 sys=0.01, real=0.04 secs]
322451.245: [GC [PSYoungGen: 256080K->2982K(466944K)] 956851K->724151K(1865728K), 0.0365930 secs] [Times: user=0.20 sys=0.04, real=0.04 secs]
322452.165: [GC [PSYoungGen: 236454K->6013K(472000K)] 957623K->728651K(1870784K), 0.0160030 secs] [Times: user=0.07 sys=0.01, real=0.02 secs]
322457.810: [GC [PSYoungGen: 244541K->14396K(466944K)] 967179K->737034K(1865728K), 0.0434880 secs] [Times: user=0.14 sys=0.09, real=0.05 secs]
322463.141: [GC [PSYoungGen: 252924K->19285K(492928K)] 975562K->741923K(1891712K), 0.0314660 secs] [Times: user=0.15 sys=0.03, real=0.04 secs]
322471.247: [GC [PSYoungGen: 293781K->70034K(481984K)] 1016419K->792671K(1880768K), 0.1132550 secs] [Times: user=0.48 sys=0.15, real=0.11 secs]
322472.328: [GC [PSYoungGen: 344530K->156662K(452672K)] 1067167K->879300K(1851456K), 0.1949290 secs] [Times: user=0.98 sys=0.40, real=0.20 secs]
322476.209: [GC [PSYoungGen: 409974K->188250K(441600K)] 1132612K->918748K(1840384K), 0.1994430 secs] [Times: user=1.11 sys=0.19, real=0.20 secs]
322478.163: [GC [PSYoungGen: 441562K->200628K(466944K)] 1172060K->967015K(1865728K), 0.2025900 secs] [Times: user=1.30 sys=0.10, real=0.21 secs]
322490.419: [GC [PSYoungGen: 434100K->74230K(466944K)] 1200487K->977926K(1865728K), 0.2434280 secs] [Times: user=1.45 sys=0.26, real=0.24 secs]
322500.207: [GC [PSYoungGen: 307702K->19063K(466944K)] 1211398K->988857K(1865728K), 0.1174350 secs] [Times: user=0.61 sys=0.16, real=0.12 secs]
322516.727: [GC [PSYoungGen: 252535K->13813K(466944K)] 1222329K->992270K(1865728K), 0.0407700 secs] [Times: user=0.16 sys=0.01, real=0.04 secs]
322522.356: [GC [PSYoungGen: 247285K->14703K(466944K)] 1225742K->997935K(1865728K), 0.0329300 secs] [Times: user=0.14 sys=0.01, real=0.03 secs]
322523.443: [GC [PSYoungGen: 248175K->2459K(466944K)] 1231407K->993685K(1865728K), 0.0206480 secs] [Times: user=0.09 sys=0.03, real=0.02 secs]
322526.367: [GC [PSYoungGen: 235931K->2363K(471104K)] 1227157K->994187K(1869888K), 0.0145060 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]
322534.335: [GC [PSYoungGen: 239995K->19995K(466944K)] 1231819K->1011819K(1865728K), 0.0344650 secs] [Times: user=0.12 sys=0.01, real=0.03 secs]
322535.528: [GC [PSYoungGen: 257627K->10542K(492480K)] 1249451K->1002366K(1891264K), 0.0131540 secs] [Times: user=0.08 sys=0.00, real=0.01 secs]
322542.365: [GC [PSYoungGen: 285294K->31599K(482688K)] 1277118K->1023424K(1881472K), 0.0467950 secs] [Times: user=0.18 sys=0.00, real=0.05 secs]
322558.565: [GC [PSYoungGen: 306351K->49034K(519488K)] 1298176K->1040859K(1918272K), 0.1007430 secs] [Times: user=0.20 sys=0.00, real=0.10 secs]
322589.756: [GC [PSYoungGen: 374026K->28928K(505920K)] 1365851K->1020752K(1904704K), 0.0517350 secs] [Times: user=0.15 sys=0.00, real=0.05 secs]
322591.328: [GC [PSYoungGen: 353920K->14669K(537728K)] 1345744K->1006493K(1936512K), 0.0201290 secs] [Times: user=0.14 sys=0.01, real=0.02 secs]
322609.059: [GC [PSYoungGen: 382093K->31668K(530112K)] 1373917K->1023492K(1928896K), 0.0569300 secs] [Times: user=0.16 sys=0.00, real=0.05 secs]
322635.658: [GC [PSYoungGen: 399092K->44012K(558016K)] 1390916K->1035837K(1956800K), 0.0846950 secs] [Times: user=0.21 sys=0.00, real=0.09 secs]
322655.120: [GC [PSYoungGen: 449836K->55694K(548224K)] 1441661K->1047518K(1947008K), 0.1188740 secs] [Times: user=0.24 sys=0.00, real=0.12 secs]
322675.927: [GC [PSYoungGen: 461518K->42262K(572160K)] 1453342K->1034086K(1970944K), 0.0765000 secs] [Times: user=0.20 sys=0.00, real=0.08 secs]
322701.366: [GC [PSYoungGen: 476630K->69756K(562624K)] 1468454K->1061580K(1961408K), 0.1431620 secs] [Times: user=0.28 sys=0.01, real=0.14 secs]
322728.067: [GC [PSYoungGen: 504124K->76720K(564032K)] 1495948K->1068545K(1962816K), 0.1561180 secs] [Times: user=0.29 sys=0.01, real=0.16 secs]
322752.441: [GC [PSYoungGen: 510896K->66058K(567296K)] 1502721K->1057883K(1966080K), 0.1327220 secs] [Times: user=0.29 sys=0.01, real=0.14 secs]
322781.314: [GC [PSYoungGen: 500234K->67865K(570624K)] 1492059K->1059690K(1969408K), 0.1186740 secs] [Times: user=0.26 sys=0.01, real=0.12 secs]
322829.533: [GC [PSYoungGen: 507225K->85832K(525248K)] 1499050K->1078721K(1924032K), 0.1730840 secs] [Times: user=0.32 sys=0.00, real=0.17 secs]
322866.001: [GC [PSYoungGen: 525192K->58280K(572544K)] 1518081K->1059348K(1971328K), 0.1326220 secs] [Times: user=0.31 sys=0.02, real=0.14 secs]
322890.766: [GC [PSYoungGen: 496168K->54803K(565760K)] 1497236K->1055894K(1964544K), 0.1104310 secs] [Times: user=0.19 sys=0.00, real=0.11 secs]
322917.448: [GC [PSYoungGen: 492691K->120685K(533632K)] 1493782K->1136394K(1932416K), 0.3038630 secs] [Times: user=0.51 sys=0.01, real=0.30 secs]
322922.917: [GC [PSYoungGen: 533613K->143731K(556672K)] 1549322K->1264701K(1955456K), 0.5189320 secs] [Times: user=0.95 sys=0.02, real=0.52 secs]
322936.465: [GC [PSYoungGen: 556659K->143736K(385024K)] 1677629K->1304001K(1783808K), 0.2551210 secs] [Times: user=0.95 sys=0.01, real=0.26 secs]
322958.608: [GC [PSYoungGen: 385016K->163990K(405312K)] 1545281K->1327575K(1804096K), 0.1697340 secs] [Times: user=0.88 sys=0.01, real=0.17 secs]
322971.424: [GC [PSYoungGen: 405270K->180108K(466944K)] 1568855K->1344171K(1865728K), 0.2198790 secs] [Times: user=0.94 sys=0.00, real=0.22 secs]
322989.368: [GC [PSYoungGen: 413580K->161897K(466944K)] 1577643K->1326936K(1865728K), 0.1699440 secs] [Times: user=0.85 sys=0.01, real=0.17 secs]
322997.435: [GC [PSYoungGen: 395369K->157054K(466944K)] 1560408K->1325917K(1865728K), 0.1559920 secs] [Times: user=0.87 sys=0.01, real=0.16 secs]
323003.346: [GC [PSYoungGen: 390526K->170750K(466944K)] 1559389K->1343029K(1865728K), 0.1931240 secs] [Times: user=0.95 sys=0.01, real=0.20 secs]
323018.586: [GC [PSYoungGen: 404222K->45008K(466944K)] 1576501K->1333050K(1865728K), 0.2247840 secs] [Times: user=1.28 sys=0.21, real=0.22 secs]
323021.963: [GC [PSYoungGen: 278480K->18990K(466944K)] 1566522K->1317294K(1865728K), 0.0515410 secs] [Times: user=0.23 sys=0.01, real=0.05 secs]
323027.294: [GC [PSYoungGen: 252462K->10843K(466944K)] 1550766K->1312297K(1865728K), 0.0283880 secs] [Times: user=0.09 sys=0.01, real=0.02 secs]
323058.250: [GC [PSYoungGen: 244315K->23304K(466944K)] 1545769K->1327611K(1865728K), 0.0590130 secs] [Times: user=0.13 sys=0.01, real=0.06 secs]
323071.013: [GC [PSYoungGen: 256776K->34628K(466944K)] 1561083K->1340318K(1865728K), 0.0871820 secs] [Times: user=0.15 sys=0.01, real=0.08 secs]
323086.457: [GC [PSYoungGen: 268100K->22608K(466944K)] 1573790K->1330972K(1865728K), 0.0595810 secs] [Times: user=0.12 sys=0.01, real=0.06 secs]
323102.586: [GC [PSYoungGen: 256080K->14084K(466944K)] 1564444K->1325018K(1865728K), 0.0437710 secs] [Times: user=0.10 sys=0.01, real=0.04 secs]
323116.811: [GC [PSYoungGen: 247556K->14308K(466944K)] 1558490K->1326400K(1865728K), 0.0393450 secs] [Times: user=0.09 sys=0.00, real=0.04 secs]
323127.480: [GC [PSYoungGen: 247780K->18847K(474944K)] 1559872K->1334015K(1873728K), 0.0339540 secs] [Times: user=0.15 sys=0.00, real=0.04 secs]
323151.554: [GC [PSYoungGen: 260319K->26904K(466944K)] 1575487K->1342073K(1865728K), 0.0509790 secs] [Times: user=0.15 sys=0.01, real=0.05 secs]
323177.028: [GC [PSYoungGen: 268376K->25444K(496128K)] 1583545K->1340613K(1894912K), 0.0426770 secs] [Times: user=0.17 sys=0.00, real=0.05 secs]
323186.675: [GC [PSYoungGen: 306916K->65740K(485760K)] 1622085K->1380908K(1884544K), 0.1271680 secs] [Times: user=0.31 sys=0.00, real=0.13 secs]
323205.823: [GC [PSYoungGen: 347212K->55268K(520576K)] 1662380K->1370436K(1919360K), 0.1111500 secs] [Times: user=0.24 sys=0.00, real=0.11 secs]
323222.428: [GC [PSYoungGen: 382180K->45670K(506752K)] 1697348K->1360839K(1905536K), 0.0827940 secs] [Times: user=0.24 sys=0.00, real=0.08 secs]
323238.957: [GC [PSYoungGen: 372582K->50150K(542208K)] 1687751K->1365319K(1940992K), 0.0804830 secs] [Times: user=0.30 sys=0.00, real=0.08 secs]
323255.631: [GC [PSYoungGen: 423398K->109349K(531456K)] 1738567K->1424518K(1930240K), 0.2414430 secs] [Times: user=0.40 sys=0.01, real=0.24 secs]
323283.477: [GC [PSYoungGen: 482597K->60570K(542528K)] 1797766K->1375739K(1941312K), 0.1122140 secs] [Times: user=0.29 sys=0.00, real=0.12 secs]
323333.229: [GC [PSYoungGen: 434778K->61338K(532096K)] 1749947K->1376506K(1930880K), 0.1161560 secs] [Times: user=0.30 sys=0.00, real=0.11 secs]
323392.788: [GC [PSYoungGen: 435546K->73262K(555584K)] 1750714K->1388431K(1954368K), 0.1254400 secs] [Times: user=0.33 sys=0.00, real=0.12 secs]
323431.425: [GC [PSYoungGen: 480110K->86961K(551680K)] 1795279K->1402129K(1950464K), 0.1783510 secs] [Times: user=0.36 sys=0.00, real=0.17 secs]
323479.595: [GC [PSYoungGen: 493809K->62182K(562368K)] 1808977K->1377351K(1961152K), 0.1137420 secs] [Times: user=0.29 sys=0.00, real=0.11 secs]
323517.693: [GC [PSYoungGen: 478502K->61309K(554368K)] 1793671K->1376477K(1953152K), 0.1158700 secs] [Times: user=0.29 sys=0.00, real=0.11 secs]
323560.831: [GC [PSYoungGen: 477629K->60467K(575744K)] 1792797K->1375636K(1974528K), 0.1121620 secs] [Times: user=0.30 sys=0.00, real=0.11 secs]
323595.243: [GC [PSYoungGen: 505203K->59488K(569408K)] 1820372K->1385703K(1968192K), 0.1393450 secs] [Times: user=0.35 sys=0.01, real=0.14 secs]
323617.023: [GC [PSYoungGen: 504224K->56419K(585920K)] 1830439K->1383116K(1984704K), 0.1189780 secs] [Times: user=0.20 sys=0.00, real=0.12 secs]
323655.136: [GC [PSYoungGen: 523235K->38747K(581312K)] 1849932K->1366156K(1980096K), 0.0679390 secs] [Times: user=0.18 sys=0.01, real=0.06 secs]
323698.394: [GC [PSYoungGen: 505563K->79559K(583104K)] 1832972K->1407621K(1981888K), 0.1777660 secs] [Times: user=0.26 sys=0.01, real=0.17 secs]
323743.124: [GC [PSYoungGen: 549447K->50013K(585152K)] 1877509K->1378973K(1983936K), 0.1049510 secs] [Times: user=0.18 sys=0.01, real=0.10 secs]
323798.216: [GC [PSYoungGen: 519901K->57246K(593152K)] 1848861K->1386765K(1991936K), 0.1111480 secs] [Times: user=0.24 sys=0.01, real=0.11 secs]
323820.190: [GC [PSYoungGen: 538526K->71805K(588544K)] 1868045K->1402401K(1987328K), 0.1551640 secs] [Times: user=0.26 sys=0.00, real=0.16 secs]
323865.202: [GC [PSYoungGen: 553085K->48376K(595904K)] 1883681K->1379654K(1994688K), 0.0961960 secs] [Times: user=0.19 sys=0.00, real=0.10 secs]
323897.201: [GC [PSYoungGen: 537400K->60439K(593536K)] 1868678K->1392055K(1992320K), 0.1270440 secs] [Times: user=0.22 sys=0.00, real=0.12 secs]
323925.899: [GC [PSYoungGen: 549463K->70022K(600512K)] 1881079K->1401973K(1999296K), 0.1484500 secs] [Times: user=0.23 sys=0.00, real=0.15 secs]
323955.328: [GC [PSYoungGen: 570310K->46121K(600192K)] 1902261K->1378640K(1998976K), 0.0868260 secs] [Times: user=0.18 sys=0.00, real=0.09 secs]
323984.848: [GC [PSYoungGen: 546409K->59900K(605632K)] 1878928K->1393240K(2004416K), 0.1281400 secs] [Times: user=0.22 sys=0.00, real=0.13 secs]
324012.618: [GC [PSYoungGen: 566972K->45421K(601856K)] 1900312K->1379232K(2000640K), 0.0906720 secs] [Times: user=0.18 sys=0.00, real=0.09 secs]
324040.012: [GC [PSYoungGen: 552493K->74259K(601984K)] 1886304K->1408303K(2000768K), 0.1577690 secs] [Times: user=0.26 sys=0.00, real=0.16 secs]
324065.714: [GC [PSYoungGen: 582547K->79641K(587968K)] 1916591K->1413891K(1986752K), 0.1596390 secs] [Times: user=0.29 sys=0.01, real=0.16 secs]
324082.497: [GC-- [PSYoungGen: 587929K->587929K(587968K)] 1922179K->1986708K(1986752K), 0.6533600 secs] [Times: user=0.77 sys=0.02, real=0.65 secs]
324083.151: [Full GC [PSYoungGen: 587929K->0K(587968K)] [PSOldGen: 1398778K->1072526K(1398784K)] 1986708K->1072526K(1986752K) [PSPermGen: 181824K->181824K(524288K)]
, 3.6355870 secs] [Times: user=3.49 sys=0.15, real=3.64 secs]
324105.975: [GC [PSYoungGen: 508288K->68310K(601984K)] 1580814K->1140836K(2000768K), 0.0962700 secs] [Times: user=0.36 sys=0.01, real=0.10 secs]
324133.261: [GC [PSYoungGen: 570518K->98413K(600640K)] 1643044K->1192218K(1999424K), 0.2107020 secs] [Times: user=0.47 sys=0.00, real=0.22 secs]
324158.308: [GC [PSYoungGen: 600621K->99748K(525376K)] 1694426K->1232717K(1924160K), 0.2046650 secs] [Times: user=0.61 sys=0.00, real=0.20 secs]
324195.063: [GC [PSYoungGen: 525348K->137398K(563008K)] 1658317K->1324730K(1961792K), 0.3435200 secs] [Times: user=0.73 sys=0.01, real=0.34 secs]
324198.293: [GC [PSYoungGen: 562998K->137400K(370880K)] 1750330K->1513934K(1769664K), 0.3376470 secs] [Times: user=2.36 sys=0.03, real=0.33 secs]
324198.631: [Full GC [PSYoungGen: 137400K->0K(370880K)] [PSOldGen: 1376534K->845248K(1398784K)] 1513934K->845248K(1769664K) [PSPermGen: 182317K->178611K(524288K)],
3.1647390 secs] [Times: user=3.10 sys=0.07, real=3.17 secs]
324203.335: [GC [PSYoungGen: 233472K->17153K(466944K)] 1078720K->862402K(1865728K), 0.0427080 secs] [Times: user=0.16 sys=0.01, real=0.04 secs]
324212.075: [GC [PSYoungGen: 250625K->44700K(466944K)] 1095874K->889949K(1865728K), 0.0406120 secs] [Times: user=0.19 sys=0.00, real=0.04 secs]
324221.287: [GC [PSYoungGen: 275345K->54553K(466944K)] 1120594K->899802K(1865728K), 0.0654580 secs] [Times: user=0.20 sys=0.00, real=0.06 secs]
324231.070: [GC [PSYoungGen: 288025K->58214K(468032K)] 1133274K->903463K(1866816K), 0.0667860 secs] [Times: user=0.22 sys=0.00, real=0.06 secs]
324240.661: [GC [PSYoungGen: 292774K->67125K(466944K)] 1138023K->912374K(1865728K), 0.0867780 secs] [Times: user=0.22 sys=0.00, real=0.08 secs]
324258.384: [GC [PSYoungGen: 301685K->55940K(487232K)] 1146934K->901189K(1886016K), 0.0564020 secs] [Times: user=0.21 sys=0.01, real=0.05 secs]
324285.560: [GC [PSYoungGen: 321604K->61109K(478848K)] 1166853K->906358K(1877632K), 0.0676010 secs] [Times: user=0.22 sys=0.00, real=0.06 secs]
324320.708: [GC [PSYoungGen: 324552K->63420K(505792K)] 1169801K->908669K(1904576K), 0.0707240 secs] [Times: user=0.31 sys=0.00, real=0.07 secs]
324322.700: [GC [PSYoungGen: 306777K->194599K(496448K)] 1152025K->1057585K(1895232K), 0.2203910 secs] [Times: user=1.61 sys=0.04, real=0.22 secs]
324324.720: [GC [PSYoungGen: 496423K->203951K(437440K)] 1359409K->1155392K(1836224K), 0.2475840 secs] [Times: user=1.69 sys=0.03, real=0.25 secs]
324326.670: [GC [PSYoungGen: 437423K->233450K(466944K)] 1388864K->1187155K(1865728K), 0.2029690 secs] [Times: user=1.18 sys=0.00, real=0.20 secs]
324345.435: [GC [PSYoungGen: 466922K->220293K(466944K)] 1420627K->1203351K(1865728K), 0.2795770 secs] [Times: user=1.64 sys=0.01, real=0.28 secs]
324362.485: [GC [PSYoungGen: 453765K->223734K(466944K)] 1436823K->1208915K(1865728K), 0.2415800 secs] [Times: user=1.12 sys=0.00, real=0.24 secs]
324367.639: [GC [PSYoungGen: 442426K->233444K(466944K)] 1427607K->1239335K(1865728K), 0.2695830 secs] [Times: user=1.72 sys=0.01, real=0.27 secs]
324374.091: [GC [PSYoungGen: 466916K->233449K(466944K)] 1472807K->1271414K(1865728K), 0.3730560 secs] [Times: user=1.56 sys=0.01, real=0.37 secs]
324385.957: [GC [PSYoungGen: 466914K->122456K(466944K)] 1504879K->1308889K(1865728K), 0.2637000 secs] [Times: user=1.07 sys=0.01, real=0.26 secs]
324397.995: [GC [PSYoungGen: 355928K->76362K(466944K)] 1542361K->1289820K(1865728K), 0.1091590 secs] [Times: user=0.47 sys=0.00, real=0.11 secs]
324422.766: [GC [PSYoungGen: 309834K->43295K(466944K)] 1523292K->1283994K(1865728K), 0.0673610 secs] [Times: user=0.38 sys=0.01, real=0.07 secs]
324437.481: [GC [PSYoungGen: 276767K->21509K(466944K)] 1517466K->1292069K(1865728K), 0.0729420 secs] [Times: user=0.20 sys=0.00, real=0.07 secs]
324440.714: [GC [PSYoungGen: 254981K->118031K(466944K)] 1525541K->1393971K(1865728K), 0.1572440 secs] [Times: user=0.94 sys=0.03, real=0.16 secs]
324442.280: [GC [PSYoungGen: 351503K->35083K(466944K)] 1627443K->1419308K(1865728K), 0.1505540 secs] [Times: user=1.12 sys=0.02, real=0.15 secs]
324442.431: [Full GC [PSYoungGen: 35083K->0K(466944K)] [PSOldGen: 1384225K->1330342K(1398784K)] 1419308K->1330342K(1865728K) [PSPermGen: 178817K->178817K(524288K)],
3.6474370 secs] [Times: user=3.63 sys=0.01, real=3.65 secs]
324457.743: [Full GC [PSYoungGen: 233472K->0K(466944K)] [PSOldGen: 1330342K->795610K(1398784K)] 1563814K->795610K(1865728K) [PSPermGen: 178862K->178862K(524288K)],
2.3725420 secs] [Times: user=2.36 sys=0.01, real=2.37 secs]
324476.337: [GC [PSYoungGen: 233472K->34145K(466944K)] 1029082K->829756K(1865728K), 0.0440460 secs] [Times: user=0.21 sys=0.00, real=0.04 secs]
324499.938: [GC [PSYoungGen: 267617K->20681K(466944K)] 1063228K->844307K(1865728K), 0.0683370 secs] [Times: user=0.24 sys=0.00, real=0.06 secs]
324528.575: [GC [PSYoungGen: 254153K->17201K(466944K)] 1077779K->841860K(1865728K), 0.0449280 secs] [Times: user=0.08 sys=0.00, real=0.04 secs]
324545.906: [GC [PSYoungGen: 250673K->20476K(466944K)] 1075332K->846607K(1865728K), 0.0417380 secs] [Times: user=0.08 sys=0.00, real=0.04 secs]
324572.854: [GC [PSYoungGen: 253948K->23670K(466944K)] 1080079K->856478K(1865728K), 0.0423200 secs] [Times: user=0.17 sys=0.01, real=0.04 secs]
324578.040: [GC [PSYoungGen: 257142K->88498K(466944K)] 1089950K->933893K(1865728K), 0.1008300 secs] [Times: user=0.76 sys=0.01, real=0.10 secs]
324582.281: [GC [PSYoungGen: 321970K->92416K(466944K)] 1167365K->1025140K(1865728K), 0.1350770 secs] [Times: user=0.96 sys=0.00, real=0.14 secs]
324586.255: [GC [PSYoungGen: 325888K->85024K(466944K)] 1258612K->1110332K(1865728K), 0.1329020 secs] [Times: user=0.97 sys=0.00, real=0.13 secs]
324599.494: [GC [PSYoungGen: 318496K->20857K(466944K)] 1343804K->1131237K(1865728K), 0.1077450 secs] [Times: user=0.67 sys=0.01, real=0.11 secs]
324617.569: [GC [PSYoungGen: 254329K->25907K(466944K)] 1364709K->1148412K(1865728K), 0.0552510 secs] [Times: user=0.20 sys=0.00, real=0.05 secs]
324646.898: [GC [PSYoungGen: 259379K->33081K(479744K)] 1381884K->1155586K(1878528K), 0.0618660 secs] [Times: user=0.16 sys=0.00, real=0.06 secs]
324676.476: [GC [PSYoungGen: 282681K->25590K(470272K)] 1405186K->1148095K(1869056K), 0.0424290 secs] [Times: user=0.17 sys=0.00, real=0.04 secs]
324693.472: [GC [PSYoungGen: 275190K->45124K(499904K)] 1397695K->1167629K(1898688K), 0.0732930 secs] [Times: user=0.22 sys=0.00, real=0.07 secs]
324710.632: [GC [PSYoungGen: 332612K->52201K(488000K)] 1455117K->1174706K(1886784K), 0.0861790 secs] [Times: user=0.23 sys=0.00, real=0.09 secs]
324755.627: [GC [PSYoungGen: 339689K->46101K(522624K)] 1462194K->1168606K(1921408K), 0.0715190 secs] [Times: user=0.22 sys=0.00, real=0.07 secs]
324776.232: [GC [PSYoungGen: 380565K->80881K(512256K)] 1503070K->1203386K(1911040K), 0.1314480 secs] [Times: user=0.35 sys=0.01, real=0.13 secs]
324790.096: [GC [PSYoungGen: 415345K->97974K(521664K)] 1537850K->1220479K(1920448K), 0.1926240 secs] [Times: user=0.34 sys=0.00, real=0.19 secs]
324806.775: [GC [PSYoungGen: 445622K->65645K(524032K)] 1568127K->1188150K(1922816K), 0.1139580 secs] [Times: user=0.30 sys=0.00, real=0.11 secs]
324828.192: [GC [PSYoungGen: 413293K->65227K(544832K)] 1535798K->1187732K(1943616K), 0.1071800 secs] [Times: user=0.29 sys=0.00, real=0.11 secs]
324855.653: [GC [PSYoungGen: 444555K->90535K(534912K)] 1567060K->1213040K(1933696K), 0.1666050 secs] [Times: user=0.37 sys=0.00, real=0.16 secs]
324876.274: [GC [PSYoungGen: 469863K->63599K(552576K)] 1592368K->1186104K(1951360K), 0.1148960 secs] [Times: user=0.27 sys=0.00, real=0.12 secs]
324896.379: [GC [PSYoungGen: 460143K->83411K(544384K)] 1582648K->1205916K(1943168K), 0.1623960 secs] [Times: user=0.34 sys=0.00, real=0.16 secs]
324929.275: [GC [PSYoungGen: 479955K->65005K(561728K)] 1602460K->1187510K(1960512K), 0.1105050 secs] [Times: user=0.31 sys=0.00, real=0.11 secs]
324969.637: [GC [PSYoungGen: 480941K->67773K(554624K)] 1603446K->1190278K(1953408K), 0.1200790 secs] [Times: user=0.31 sys=0.00, real=0.12 secs]
324980.638: [GC [PSYoungGen: 483709K->82178K(569856K)] 1606214K->1215021K(1968640K), 0.1776470 secs] [Times: user=0.35 sys=0.00, real=0.18 secs]
325013.546: [GC [PSYoungGen: 520258K->51453K(568640K)] 1653101K->1185513K(1967424K), 0.0933800 secs] [Times: user=0.19 sys=0.00, real=0.10 secs]
325069.106: [GC [PSYoungGen: 489533K->55897K(576768K)] 1623593K->1190435K(1975552K), 0.0948710 secs] [Times: user=0.23 sys=0.00, real=0.10 secs]
325128.690: [GC [PSYoungGen: 505049K->59380K(572800K)] 1639587K->1194580K(1971584K), 0.1088070 secs] [Times: user=0.23 sys=0.01, real=0.10 secs]
325185.990: [GC [PSYoungGen: 508532K->72394K(584128K)] 1643732K->1208261K(1982912K), 0.1418940 secs] [Times: user=0.25 sys=0.01, real=0.14 secs]
325221.351: [GC [PSYoungGen: 537354K->73564K(581248K)] 1673221K->1210026K(1980032K), 0.1436810 secs] [Times: user=0.25 sys=0.00, real=0.14 secs]
325237.360: [GC [PSYoungGen: 538524K->56351K(589312K)] 1674986K->1194382K(1988096K), 0.0982660 secs] [Times: user=0.22 sys=0.00, real=0.09 secs]
325270.308: [GC [PSYoungGen: 531807K->92350K(567808K)] 1669838K->1231070K(1966592K), 0.1839390 secs] [Times: user=0.31 sys=0.00, real=0.18 secs]
325307.352: [GC [PSYoungGen: 567806K->60688K(587520K)] 1706526K->1202490K(1986304K), 0.1151360 secs] [Times: user=0.23 sys=0.00, real=0.11 secs]
325336.099: [GC [PSYoungGen: 531920K->55433K(584128K)] 1673722K->1197855K(1982912K), 0.1009010 secs] [Times: user=0.20 sys=0.00, real=0.10 secs]
325385.050: [GC [PSYoungGen: 526665K->57345K(592640K)] 1669087K->1204877K(1991424K), 0.1109780 secs] [Times: user=0.23 sys=0.01, real=0.11 secs]
325432.400: [GC [PSYoungGen: 539457K->52853K(589888K)] 1686989K->1200582K(1988672K), 0.1008930 secs] [Times: user=0.19 sys=0.00, real=0.10 secs]
325482.039: [GC [PSYoungGen: 534965K->60170K(598016K)] 1682694K->1208147K(1996800K), 0.1204090 secs] [Times: user=0.20 sys=0.00, real=0.12 secs]
325508.717: [GC [PSYoungGen: 552394K->92912K(585152K)] 1700371K->1241274K(1983936K), 0.2038690 secs] [Times: user=0.29 sys=0.00, real=0.21 secs]
325561.239: [GC [PSYoungGen: 585136K->78741K(590912K)] 1733498K->1228604K(1989696K), 0.1667600 secs] [Times: user=0.25 sys=0.01, real=0.16 secs]
325592.245: [GC [PSYoungGen: 560405K->78197K(591040K)] 1710268K->1228338K(1989824K), 0.1488170 secs] [Times: user=0.29 sys=0.01, real=0.15 secs]
325626.653: [GC [PSYoungGen: 559861K->66327K(594944K)] 1710002K->1218304K(1993728K), 0.1359000 secs] [Times: user=0.21 sys=0.00, real=0.14 secs]
325674.095: [GC [PSYoungGen: 552279K->46489K(591424K)] 1704256K->1199064K(1990208K), 0.0875290 secs] [Times: user=0.17 sys=0.01, real=0.09 secs]
325714.214: [GC [PSYoungGen: 532382K->51217K(596096K)] 1684957K->1207790K(1994880K), 0.0972370 secs] [Times: user=0.21 sys=0.01, real=0.10 secs]
325743.217: [GC [PSYoungGen: 541615K->82928K(573440K)] 1698187K->1240093K(1972224K), 0.1723980 secs] [Times: user=0.28 sys=0.00, real=0.17 secs]
325768.885: [GC [PSYoungGen: 573424K->76851K(593728K)] 1730589K->1234360K(1992512K), 0.1593620 secs] [Times: user=0.24 sys=0.01, real=0.15 secs]
325812.379: [GC [PSYoungGen: 563571K->96435K(583168K)] 1721080K->1254441K(1981952K), 0.1967570 secs] [Times: user=0.36 sys=0.00, real=0.20 secs]
325866.633: [GC [PSYoungGen: 583155K->70531K(591232K)] 1741161K->1228768K(1990016K), 0.1443960 secs] [Times: user=0.23 sys=0.00, real=0.14 secs]
325893.387: [GC [PSYoungGen: 548355K->82296K(587008K)] 1706592K->1242057K(1985792K), 0.1715400 secs] [Times: user=0.25 sys=0.01, real=0.17 secs]
325927.209: [GC [PSYoungGen: 560120K->60662K(592704K)] 1719881K->1220954K(1991488K), 0.1232450 secs] [Times: user=0.21 sys=0.00, real=0.12 secs]
325950.177: [GC [PSYoungGen: 543734K->71093K(590784K)] 1704026K->1231765K(1989568K), 0.1451510 secs] [Times: user=0.23 sys=0.00, real=0.14 secs]
325974.878: [GC [PSYoungGen: 554165K->71510K(599296K)] 1714837K->1233417K(1998080K), 0.1469950 secs] [Times: user=0.24 sys=0.00, real=0.15 secs]
326003.354: [GC [PSYoungGen: 566614K->45166K(596224K)] 1728521K->1210011K(1995008K), 0.0834500 secs] [Times: user=0.18 sys=0.01, real=0.09 secs]
326041.767: [GC [PSYoungGen: 540270K->59886K(599936K)] 1705115K->1225652K(1998720K), 0.1228870 secs] [Times: user=0.21 sys=0.00, real=0.12 secs]
326095.159: [GC [PSYoungGen: 557358K->81640K(597952K)] 1723124K->1249596K(1996736K), 0.1635030 secs] [Times: user=0.30 sys=0.00, real=0.17 secs]
326128.390: [GC [PSYoungGen: 579112K->80263K(596224K)] 1747068K->1248530K(1995008K), 0.1543430 secs] [Times: user=0.28 sys=0.01, real=0.15 secs]
326170.312: [GC [PSYoungGen: 574087K->89090K(582976K)] 1742354K->1257581K(1981760K), 0.1770060 secs] [Times: user=0.30 sys=0.00, real=0.18 secs]
326213.594: [GC [PSYoungGen: 582914K->101355K(578560K)] 1751405K->1270257K(1977344K), 0.1774210 secs] [Times: user=0.39 sys=0.00, real=0.18 secs]
326227.090: [GC [PSYoungGen: 572907K->111983K(583552K)] 1741809K->1281315K(1982336K), 0.2339600 secs] [Times: user=0.37 sys=0.00, real=0.23 secs]
326257.095: [GC [PSYoungGen: 583535K->69906K(575104K)] 1752867K->1239554K(1973888K), 0.1213560 secs] [Times: user=0.28 sys=0.00, real=0.12 secs]
326292.392: [GC [PSYoungGen: 528146K->54766K(579328K)] 1697794K->1225078K(1978112K), 0.0950700 secs] [Times: user=0.21 sys=0.00, real=0.09 secs]
326314.178: [GC [PSYoungGen: 513006K->78374K(583168K)] 1683318K->1248944K(1981952K), 0.1521660 secs] [Times: user=0.25 sys=0.00, real=0.15 secs]
326341.380: [GC [PSYoungGen: 540902K->89219K(579776K)] 1711472K->1260656K(1978560K), 0.1812150 secs] [Times: user=0.28 sys=0.00, real=0.18 secs]
326358.880: [GC [PSYoungGen: 551747K->98346K(574784K)] 1723184K->1271902K(1973568K), 0.2013120 secs] [Times: user=0.32 sys=0.01, real=0.21 secs]
326378.971: [GC [PSYoungGen: 555050K->57405K(578560K)] 1728606K->1232674K(1977344K), 0.1028040 secs] [Times: user=0.22 sys=0.00, real=0.11 secs]
326400.568: [GC [PSYoungGen: 514109K->96324K(573632K)] 1689378K->1274812K(1972416K), 0.2047490 secs] [Times: user=0.31 sys=0.00, real=0.20 secs]
326432.426: [GC [PSYoungGen: 548676K->70392K(576384K)] 1727164K->1249791K(1975168K), 0.1394860 secs] [Times: user=0.23 sys=0.01, real=0.14 secs]
326469.634: [GC [PSYoungGen: 522744K->62224K(581056K)] 1702143K->1241982K(1979840K), 0.1178280 secs] [Times: user=0.22 sys=0.00, real=0.12 secs]
326522.963: [GC [PSYoungGen: 522320K->60844K(579456K)] 1702078K->1241668K(1978240K), 0.1251950 secs] [Times: user=0.21 sys=0.00, real=0.12 secs]
326539.740: [GC [PSYoungGen: 520940K->77277K(586048K)] 1701764K->1258935K(1984832K), 0.1634480 secs] [Times: user=0.27 sys=0.00, real=0.17 secs]
326587.454: [GC [PSYoungGen: 545565K->55148K(582656K)] 1727223K->1240084K(1981440K), 0.1119080 secs] [Times: user=0.21 sys=0.00, real=0.11 secs]
326618.837: [GC [PSYoungGen: 523436K->78029K(588864K)] 1708372K->1264532K(1987648K), 0.1493930 secs] [Times: user=0.29 sys=0.00, real=0.15 secs]

Reply viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.
sumit_only
Offline
Joined: 2003-06-10
Points: 0

I am of the opinion that you have to tune your young and tenured generation spaces. I also think that in your case you could be having the Young generation guarantee violation which you would probably be already knowing because you have gone through SUN docs.

Here is what I notice from your GC output:

324082.497: [GC-- [PSYoungGen: 587929K->587929K(587968K)] 1922179K->1986708K(1986752K), 0.6533600 secs] [Times: user=0.77 sys=0.02, real=0.65 secs]
324083.151: [Full GC [PSYoungGen: 587929K->0K(587968K)] [PSOldGen: 1398778K->1072526K(1398784K)] 1986708K->1072526K(1986752K) [PSPermGen: 181824K->181824K(524288K)]

Notice how the FullGC immediately follows the minor collection. Notice that young generation did not reduce at all even after first minor collection was through. This means you either have long-lived objects or your young generation is too small to fit in all of those. Then notice how FullGC causes young generation to reduce to size 0K. However then notice that your tenured gen was also full to its capacity i.e. 1398778K/ 1398784K), hence meaning that a lot of young generation objects got promoted to tenured generation as a part of minor collection.

Now consider another FullGC which happened in immediate succession:

324442.280: [GC [PSYoungGen: 351503K->35083K(466944K)] 1627443K->1419308K(1865728K), 0.1505540 secs] [Times: user=1.12 sys=0.02, real=0.15 secs]
324442.431: [Full GC [PSYoungGen: 35083K->0K(466944K)] [PSOldGen: 1384225K->1330342K(1398784K)] 1419308K->1330342K(1865728K) [PSPermGen: 178817K->178817K(524288K)],
3.6474370 secs] [Times: user=3.63 sys=0.01, real=3.65 secs]
324457.743: [Full GC [PSYoungGen: 233472K->0K(466944K)] [PSOldGen: 1330342K->795610K(1398784K)] 1563814K->795610K(1865728K) [PSPermGen: 178862K->178862K(524288K)],
2.3725420 secs] [Times: user=2.36 sys=0.01, real=2.37 secs]

Notice that 1st FullGC in this case brings young gen to zero size, however tenured gen is already full and despite first FullGC, it is not collected enough. And then when immediate second FullGC happens, by then young gen is again half full, which then reduced to zero after the second Full collection. The second FullGC has happened because even after first FullGC the tenured gen is not cleared.

Hence, I think you should tune young and tenured generation spaces and see if the results are any better.

varuntyagi86
Offline
Joined: 2012-10-22
Points: 0

Thanks Sumit for sharing the info.

I am also facing an issue that after FULL GC runs it seems it doesnot releases the memory.

Below are the GC logs, can you help me if there is anything that is suspicious or needs to be tuned.

13305.165: [Full GC [PSYoungGen: 62631K->0K(381376K)] [PSOldGen: 978538K->531840K(1048576K)] 1041169K->531840K(1429952K) [PSPermGen: 165331K->164998K(262144K)], 1.9362920 secs] [Times: user=1.94 sys=0.00, real=1.94 secs]
13307.450: [GC [PSYoungGen: 236544K->64502K(379456K)] 768384K->596343K(1428032K), 0.0372660 secs] [Times: user=0.09 sys=0.00, real=0.03 secs]
13312.730: [GC [PSYoungGen: 301046K->64390K(387008K)] 832887K->658797K(1435584K), 0.0638430 secs] [Times: user=0.20 sys=0.00, real=0.06 secs]
13322.024: [GC [PSYoungGen: 311174K->66854K(384064K)] 905581K->723381K(1432640K), 0.0645350 secs] [Times: user=0.18 sys=0.00, real=0.06 secs]
13332.092: [GC [PSYoungGen: 313612K->66267K(393920K)] 970139K->787456K(1442496K), 0.0628120 secs] [Times: user=0.24 sys=0.00, real=0.06 secs]
13341.657: [GC [PSYoungGen: 326427K->130353K(390528K)] 1047616K->857292K(1439104K), 0.0631830 secs] [Times: user=0.20 sys=0.00, real=0.07 secs]
13342.108: [GC [PSYoungGen: 390513K->71171K(372992K)] 1117452K->924431K(1421568K), 0.0868190 secs] [Times: user=0.35 sys=0.00, real=0.09 secs]
13350.790: [GC [PSYoungGen: 310403K->64913K(381760K)] 1163663K->987172K(1430336K), 0.0715440 secs] [Times: user=0.28 sys=0.00, real=0.07 secs]
13350.862: [Full GC [PSYoungGen: 64913K->0K(381760K)] [PSOldGen: 922259K->617099K(1048576K)] 987172K->617099K(1430336K) [PSPermGen: 164999K->164999K(262144K)], 1.6091860 secs] [Times: user=1.61 sys=0.00, real=1.61 secs]
13359.171: [GC [PSYoungGen: 239232K->65001K(388224K)] 856331K->682100K(1436800K), 0.0349650 secs] [Times: user=0.11 sys=0.00, real=0.03 secs]
13366.642: [GC [PSYoungGen: 313833K->67262K(384896K)] 930932K->747262K(1433472K), 0.0582500 secs] [Times: user=0.21 sys=0.01, real=0.06 secs]
13367.067: [GC [PSYoungGen: 316094K->68228K(395840K)] 996094K->813297K(1444416K), 0.0601190 secs] [Times: user=0.23 sys=0.00, real=0.06 secs]
13375.394: [GC [PSYoungGen: 331780K->70967K(392000K)] 1076849K->882115K(1440576K), 0.0616310 secs] [Times: user=0.24 sys=0.00, real=0.06 secs]
13384.042: [GC [PSYoungGen: 334519K->71447K(404032K)] 1145667K->950981K(1452608K), 0.0813670 secs] [Times: user=0.22 sys=0.00, real=0.08 secs]
13391.770: [GC [PSYoungGen: 351191K->75837K(400000K)] 1230725K->1024539K(1448576K), 0.0689210 secs] [Times: user=0.20 sys=0.00, real=0.07 secs]
13391.840: [Full GC [PSYoungGen: 75837K->0K(400000K)] [PSOldGen: 948702K->594260K(1048576K)] 1024539K->594260K(1448576K) [PSPermGen: 164999K->164999K(262144K)], 1.5783520 secs] [Times: user=1.57 sys=0.00, real=1.56 secs]
13400.062: [GC [PSYoungGen: 279744K->71568K(411776K)] 874004K->665828K(1460352K), 0.0366980 secs] [Times: user=0.12 sys=0.00, real=0.04 secs]
13400.564: [GC [PSYoungGen: 367504K->112508K(408448K)] 961764K->744716K(1457024K), 0.0650720 secs] [Times: user=0.25 sys=0.00, real=0.07 secs]
13408.233: [GC [PSYoungGen: 408444K->72730K(374144K)] 1040652K->813492K(1422720K), 0.0919650 secs] [Times: user=0.35 sys=0.00, real=0.09 secs]
13618.035: [GC [PSYoungGen: 331034K->33921K(292288K)] 1071796K->844550K(1340864K), 0.0703640 secs] [Times: user=0.19 sys=0.00, real=0.07 secs]
13894.652: [GC [PSYoungGen: 292225K->7970K(376640K)] 1102854K->849648K(1425216K), 0.0472990 secs] [Times: user=0.12 sys=0.00, real=0.04 secs]
14761.651: [GC [PSYoungGen: 248610K->8317K(248960K)] 1090288K->849995K(1297536K), 0.0358610 secs] [Times: user=0.09 sys=0.00, real=0.04 secs]
14840.134: [GC [PSYoungGen: 248957K->11139K(377472K)] 1090635K->852817K(1426048K), 0.0408100 secs] [Times: user=0.09 sys=0.00, real=0.04 secs]
15083.261: [GC [PSYoungGen: 243459K->14277K(378304K)] 1085137K->855955K(1426880K), 0.0372230 secs] [Times: user=0.09 sys=0.00, real=0.04 secs]
15171.585: [GC [PSYoungGen: 246597K->18403K(382464K)] 1088275K->860081K(1431040K), 0.0388320 secs] [Times: user=0.08 sys=0.01, real=0.04 secs]
15310.038: [GC [PSYoungGen: 256035K->21798K(379456K)] 1097713K->863476K(1428032K), 0.0336560 secs] [Times: user=0.09 sys=0.00, real=0.04 secs]
15760.606: [GC [PSYoungGen: 259430K->22842K(391424K)] 1101108K->864520K(1440000K), 0.0336470 secs] [Times: user=0.09 sys=0.00, real=0.03 secs]
15915.037: [GC [PSYoungGen: 276666K->24076K(386688K)] 1118344K->865754K(1435264K), 0.0338890 secs] [Times: user=0.12 sys=0.00, real=0.03 secs]
16207.811: [GC [PSYoungGen: 277900K->26436K(402176K)] 1119578K->868114K(1450752K), 0.0511190 secs] [Times: user=0.11 sys=0.00, real=0.05 secs]
16498.360: [GC [PSYoungGen: 300868K->26750K(396544K)] 1142546K->868428K(1445120K), 0.0494860 secs] [Times: user=0.11 sys=0.00, real=0.05 secs]
16993.829: [GC [PSYoungGen: 266699K->27780K(413312K)] 1108377K->869458K(1461888K), 0.0526590 secs] [Times: user=0.14 sys=0.00, real=0.05 secs]
16993.882: [Full GC (System) [PSYoungGen: 27780K->0K(413312K)] [PSOldGen: 841677K->428886K(1048576K)] 869458K->428886K(1461888K) [PSPermGen: 165877K->165877K(262144K)], 1.9206450 secs] [Times: user=1.89 sys=0.00, real=1.92 secs]
17193.051: [GC [PSYoungGen: 296768K->10735K(407744K)] 725654K->439622K(1456320K), 0.0285860 secs] [Times: user=0.05 sys=0.01, real=0.03 secs]
17867.508: [GC [PSYoungGen: 307503K->12217K(419008K)] 736390K->441104K(1467584K), 0.0256560 secs] [Times: user=0.07 sys=0.00, real=0.03 secs]
18593.165: [GC [PSYoungGen: 322681K->21465K(415744K)] 751568K->450352K(1464320K), 0.0446620 secs] [Times: user=0.11 sys=0.00, real=0.05 secs]
19078.031: [GC [PSYoungGen: 331929K->22471K(429184K)] 760816K->451358K(1477760K), 0.0456730 secs] [Times: user=0.10 sys=0.00, real=0.04 secs]
19828.503: [GC [PSYoungGen: 351431K->20786K(424064K)] 780318K->449673K(1472640K), 0.0328040 secs] [Times: user=0.10 sys=0.00, real=0.03 secs]
20271.513: [GC [PSYoungGen: 349746K->18447K(437760K)] 778633K->447334K(1486336K), 0.0391400 secs] [Times: user=0.09 sys=0.00, real=0.04 secs]
20596.367: [GC [PSYoungGen: 232286K->18655K(433728K)] 661173K->447542K(1482304K), 0.0396360 secs] [Times: user=0.08 sys=0.00, real=0.04 secs]
20596.407: [Full GC (System) [PSYoungGen: 18655K->0K(433728K)] [PSOldGen: 428886K->369057K(1048576K)] 447542K->369057K(1482304K) [PSPermGen: 166937K->166630K(262144K)], 1.8226650 secs] [Times: user=1.83 sys=0.00, real=1.82 secs]
21162.172: [GC [PSYoungGen: 347192K->10067K(444096K)] 716249K->379124K(1492672K), 0.0304140 secs] [Times: user=0.07 sys=0.00, real=0.03 secs]
21709.389: [GC [PSYoungGen: 371603K->14326K(441728K)] 740660K->383384K(1490304K), 0.0405270 secs] [Times: user=0.07 sys=0.00, real=0.04 secs]
22899.086: [GC [PSYoungGen: 375862K->13367K(450624K)] 744920K->382425K(1499200K), 0.0410990 secs] [Times: user=0.07 sys=0.00, real=0.05 secs]
24198.804: [GC [PSYoungGen: 296615K->9831K(447424K)] 665673K->378888K(1496000K), 0.0284320 secs] [Times: user=0.06 sys=0.00, real=0.02 secs]
24198.833: [Full GC (System) [PSYoungGen: 9831K->0K(447424K)] [PSOldGen: 369057K->377622K(1048576K)] 378888K->377622K(1496000K) [PSPermGen: 166801K->166801K(262144K)], 1.6428140 secs] [Times: user=1.62 sys=0.01, real=1.65 secs]
26495.848: [GC [PSYoungGen: 373760K->11031K(456128K)] 751382K->388653K(1504704K), 0.0362300 secs] [Times: user=0.10 sys=0.00, real=0.03 secs]
27801.051: [GC [PSYoungGen: 187902K->8664K(453184K)] 565524K->386286K(1501760K), 0.0396030 secs] [Times: user=0.08 sys=0.00, real=0.04 secs]
27801.091: [Full GC (System) [PSYoungGen: 8664K->0K(453184K)] [PSOldGen: 377622K->382746K(1048576K)] 386286K->382746K(1501760K) [PSPermGen: 167519K->167519K(262144K)], 1.5606760 secs]