Skip to main content

Problems with GC - BigPauses

6 replies [Last post]
javiergalindo
Offline
Joined: 2007-05-21
Points: 0

I have an online banking JEE application and the application works perfectly with good response time (less than a second). But sometimes (see the verbose gc output at the end) the GC runs for 12 to 14 seconds and obviously the app shows a slowdown. We have tuned the gc parameters in order to get better performance, also We have three instances of the app server in cluster in the same physical machine to prevent pauses of the application because of the GC; this way, when one instance pauses the other two still works and most of the customers don't see the problem.

The application pauses from time to time and spent 12 secs (average) to free memory; but, sometimes the gc does pause three times in a row, see 77924 second with 13.44 seconds pause, followed by 77937 second with 13.02 seconds pause and a full gc in 77950 sec with 8.27 seconds pause. After this three consecutive pauses, gc pauses every 400 - 600 secs (average)... after some time the gc does the same (three pauses in a row)

These are the relevant parameters of the JVM We are using.

-XX:NewRatio=2
-XX:SoftRefLRUPolicyMSPerMB=1
-Xmx1024m -Xms768m
-XX:MaxPermSize=256m
-XX:+UseParallelGC -XX:ParallelGCThreads=8

* The operating system is Solaris 10
* The hardware used is a T2000 with 6 cores (each do 4 threads)
* The app server is Sun Java System Application Server 8.1

Here is the fragment of the verbose gc output

Alot of lines..... of 0.xxxx secs

74015.419: [GC [PSYoungGen: 274368K->26335K(311296K)] 366934K->118902K(1011712K), 0.3048878 secs]
74531.058: [GC [PSYoungGen: 300895K->28926K(311488K)] 393462K->121492K(1011904K), 0.3135269 secs]
75165.773: [GC [PSYoungGen: 303678K->30149K(311168K)] 396244K->122715K(1011584K), 0.3250893 secs]
75653.826: [GC [PSYoungGen: 305093K->32660K(310848K)] 397659K->125227K(1011264K), 0.3760514 secs]
76180.729: [GC [PSYoungGen: 307796K->31681K(311552K)] 400363K->124248K(1011968K), 0.3753367 secs]
76763.048: [GC [PSYoungGen: 307009K->32439K(311680K)] 399576K->125005K(1012096K), 0.3748320 secs]
77105.290: [GC [PSYoungGen: 208138K->23361K(311936K)] 300705K->115927K(1012352K), 0.2268541 secs]
77105.517: [Full GC [PSYoungGen: 23361K->0K(311936K)] [PSOldGen: 92566K->93471K(700416K)] 115927K->93471K(1012352K) [PSPermGen: 53198K->53198K(57344K)], 2.2944293 secs]
77607.591: [GC [PSYoungGen: 275520K->28975K(312768K)] 368991K->122447K(1013184K), 0.3139634 secs]
77823.255: [GC [PSYoungGen: 290734K->16780K(293184K)] 384205K->199713K(993600K), 1.6595497 secs]
77924.473: [GC [PSYoungGen: 242046K->10329K(310080K)] 802397K->570680K(1010496K), 13.4424549 secs]
77937.916: [GC [PSYoungGen: 10329K->9705K(281856K)] 570680K->570055K(982272K), 13.0209511 secs]
77950.937: [Full GC [PSYoungGen: 9705K->0K(281856K)] [PSOldGen: 560350K->311418K(700416K)] 570055K->311418K(982272K) [PSPermGen: 54355K->54355K(61440K)], 8.2782314 secs]
78020.975: [GC [PSYoungGen: 36421K->3961K(306944K)] 687514K->655054K(1007360K), 15.4772227 secs]
78036.452: [Full GC [PSYoungGen: 3961K->0K(306944K)] [PSOldGen: 651093K->386080K(700416K)] 655054K->386080K(1007360K) [PSPermGen: 54452K->50015K(57344K)], 11.0670344 secs]
78047.519: [GC [PSYoungGen: 0K->0K(265408K)] 386080K->386080K(965824K), 11.6197814 secs]
78059.139: [Full GC [PSYoungGen: 0K->0K(265408K)] [PSOldGen: 386080K->386080K(700416K)] 386080K->386080K(965824K) [PSPermGen: 50015K->50015K(57344K)], 9.3389433 secs]
78468.393: [GC [PSYoungGen: 265344K->24961K(307840K)] 651424K->411042K(1008256K), 11.9879116 secs]
79019.989: [GC [PSYoungGen: 287553K->28424K(307008K)] 673634K->414505K(1007424K), 12.0081197 secs]
79443.071: [GC [PSYoungGen: 291016K->30417K(305600K)] 677097K->416498K(1006016K), 11.9811863 secs]
79867.994: [GC [PSYoungGen: 291153K->30428K(291200K)] 677234K->416509K(991616K), 11.9111942 secs]
80374.610: [GC [PSYoungGen: 291164K->31414K(304512K)] 677245K->417495K(1004928K), 12.1629326 secs]
80822.307: [GC [PSYoungGen: 289590K->28597K(305216K)] 675671K->414678K(1005632K), 11.7339430 secs]
81303.452: [GC [PSYoungGen: 286773K->31729K(304960K)] 672854K->417809K(1005376K), 12.1451709 secs]
81668.705: [GC [PSYoungGen: 281106K->30260K(305408K)] 667187K->416341K(1005824K), 11.9329286 secs]
81680.639: [Full GC [PSYoungGen: 30260K->0K(305408K)] [PSOldGen: 386080K->71477K(700416K)] 416341K->71477K(1005824K) [PSPermGen: 51888K->5188881781.118: [GC [PSYoungGen: 82019.742: [GC [PSYoungGen: 258560K->26114K(301312K)] 330037K->97591K82281.383: [GC [PSYoungGen: 82471.531: [GC [PSYoungGen: 284994K->29972K(303552K)] 356471K->101449K(1003968K), 0.3305681 secs]
82840.490: [GC [PSYoungGen: 288916K->29033K(307648K)] 360393K->100511K(1008064K), 0.2727202 secs]
83398.170: [GC [PSYoungGen: 292457K->31850K(308032K)] 363935K->103328K(1008448K), 0.3135350 secs]
83840.102: [GC [PSYoungGen: 296426K->30089K(308800K)] 367904K->101567K(1009216K), 0.3043730 secs]
84392.663: [GC [PSYoungGen: 295113K->31182K(308480K)] 366591K->102660K(1008896K), 0.2955012 secs]
85072.618: [GC [PSYoungGen: 296462K->31800K(309056K)] 367940K->103278K(1009472K), 0.3239527 secs]

Alot of lines..... of 0.0000xxx secs

222323.992: [GC [PSYoungGen: 294225K->31278K(309760K)] 367428K->104481K(1010176K), 0.3187622 secs]
222326.675: [GC [PSYoungGen: 297824K->8952K(275584K)] 371028K->82156K(976000K), 0.0476338 secs]
222366.025: [GC [PSYoungGen: 275576K->19340K(305728K)] 348780K->92544K(1006144K), 0.1598758 secs]
222459.745: [GC [PSYoungGen: 279436K->34026K(306176K)] 352640K->107230K(1006592K), 0.3364734 secs]
222535.917: [GC [PSYoungGen: 294122K->33390K(306176K)] 367326K->106594K(1006592K), 0.3020610 secs]
222612.668: [GC [PSYoungGen: 293486K->42198K(302656K)] 366690K->115402K(1003072K), 0.5263807 secs]
222638.831: [GC [PSYoungGen: 302614K->18929K(302784K)] 375818K->159229K(1003200K), 1.9945164 secs]
222682.929: [GC [PSYoungGen: 273137K->26189K(303232K)] 564404K->317456K(1003648K), 8.5012921 secs]
222747.519: [GC [PSYoungGen: 280397K->36483K(303040K)] 798114K->554199K(1003456K), 16.1670955 secs]
222781.622: [GC [PSYoungGen: 152033K->26627K(303744K)] 669750K->544344K(1004160K), 17.8912589 secs]
222799.513: [GC [PSYoungGen: 26627K->26075K(303744K)] 544344K->543792K(1004160K), 18.4837229 secs]
222817.997: [Full GC [PSYoungGen: 26075K->0K(303744K)] [PSOldGen: 517716K->317561K(700416K)] 543792K->317561K(1004160K) [PSPermGen: 55903K->55903K(61440K)], 9.0446464 secs]
222868.320: [Full GC [PSYoungGen: 256354K->0K(303744K)] [PSOldGen: 657237K->449679K(700416K)] 913591K->449679K(1004160K) [PSPermGen: 56549K->56549K(61440K)], 11.2793390 secs]
222911.770: [GC [PSYoungGen: 177018K->15476K(304896K)] 626697K->465155K(1005312K), 13.0184553 secs]
222924.789: [GC [PSYoungGen: 15476K->15252K(304512K)] 465155K->464931K(1004928K), 12.4717949 secs]
222937.261: [Full GC [PSYoungGen: 15252K->0K(304512K)] [PSOldGen: 449679K->421259K(700416K)] 464931K->421259K(1004928K) [PSPermGen: 56854K->50671K(57344K)], 11.9218657 secs]
222949.183: [GC [PSYoungGen: 0K->0K(257472K)] 421259K->421259K(957888K), 14.7738195 secs]
222963.957: [Full GC [PSYoungGen: 0K->0K(257472K)] [PSOldGen: 421259K->421259K(700416K)] 421259K->421259K(957888K) [PSPermGen: 50671K->50671K(57344K)], 9.8559225 secs]
223015.578: [GC [PSYoungGen: 257408K->25320K(304448K)] 678667K->446579K(1004864K), 9.6098416 secs]
223071.193: [GC [PSYoungGen: 279781K->32376K(302272K)] 701041K->453635K(1002688K), 13.1119476 secs]
223141.360: [GC [PSYoungGen: 286819K->40438K(297216K)] 708078K->461697K(997632K), 15.7915173 secs]
223223.326: [GC [PSYoungGen: 289270K->38862K(287744K)] 710529K->460121K(988160K), 13.1859231 secs]
223285.213: [GC [PSYoungGen: 287694K->41990K(293248K)] 708953K->463249K(993664K), 13.1054030 secs]
223341.371: [GC [PSYoungGen: 281478K->42056K(281600K)] 702737K->463315K(982016K), 13.4031538 secs]
223409.464: [GC [PSYoungGen: 281544K->43271K(290048K)] 702803K->464530K(990464K), 13.1313753 secs]
223475.485: [GC [PSYoungGen: 274947K->43915K(275648K)] 696206K->465174K(976064K), 12.9747631 secs]
223535.880: [GC [PSYoungGen: 275588K->46242K(286400K)] 696847K->467501K(986816K), 15.0634676 secs]
223599.792: [GC [PSYoungGen: 270754K->46319K(270848K)] 692013K->467578K(971264K), 15.3102673 secs]
223667.116: [GC [PSYoungGen: 270831K->47921K(283712K)] 692090K->469180K(984128K), 15.0051786 secs]
223727.195: [GC [PSYoungGen: 266269K->47660K(266048K)] 687528K->468919K(966464K), 15.4090815 secs]
223798.857: [GC [PSYoungGen: 266028K->46257K(284160K)] 687287K->467516K(984576K), 14.3828056 secs]
223858.689: [GC [PSYoungGen: 262448K->47625K(263872K)] 683707K->468884K(964288K), 12.8110619 secs]
223919.691: [GC [PSYoungGen: 263817K->49540K(282304K)] 685076K->470799K(982720K), 13.2866733 secs]
223988.046: [GC [PSYoungGen: 263428K->49452K(263360K)] 684687K->470711K(963776K), 12.6537619 secs]
224052.400: [GC [PSYoungGen: 263340K->49042K(282688K)] 684599K->470301K(983104K), 13.1864598 secs]
224125.569: [GC [PSYoungGen: 262098K->49305K(282624K)] 683357K->470564K(983040K), 12.7511044 secs]
224208.797: [GC [PSYoungGen: 262361K->49439K(282688K)] 683620K->470698K(983104K), 13.2973637 secs]
224277.752: [GC [PSYoungGen: 262687K->48137K(282816K)] 683946K->469396K(983232K), 12.8137092 secs]
224365.570: [GC [PSYoungGen: 261769K->48874K(283072K)] 683028K->470134K(983488K), 12.7064087 secs]
224433.751: [GC [PSYoungGen: 263594K->49093K(283904K)] 684854K->470352K(984320K), 12.9623813 secs]
224503.370: [GC [PSYoungGen: 265285K->51540K(284544K)] 686544K->472799K(984960K), 13.4094341 secs]
224583.073: [GC [PSYoungGen: 269012K->50663K(284992K)] 690271K->471922K(985408K), 14.0483632 secs]
224653.338: [GC [PSYoungGen: 268364K->51993K(284992K)] 689624K->473253K(985408K), 12.8473280 secs]
224732.386: [GC [PSYoungGen: 270041K->51863K(285184K)] 691301K->473122K(985600K), 13.3212825 secs]
224810.599: [GC [PSYoungGen: 269966K->52167K(285184K)] 691225K->473426K(985600K), 14.9345899 secs]
224892.350: [GC [PSYoungGen: 270407K->50010K(285312K)] 691666K->471269K(985728K), 12.6359581 secs]
224968.517: [GC [PSYoungGen: 268570K->50463K(285504K)] 689829K->471722K(985920K), 13.7913607 secs]
225042.777: [GC [PSYoungGen: 270239K->51816K(286528K)] 691498K->473075K(986944K), 15.4672232 secs]
225123.417: [GC [PSYoungGen: 273435K->52284K(287360K)] 694694K->473543K(987776K), 15.5921312 secs]
225198.510: [GC [PSYoungGen: 275128K->48073K(287744K)] 696387K->475660K(988160K), 14.6034688 secs]
225288.900: [GC [PSYoungGen: 271497K->46269K(287936K)] 699084K->474897K(988352K), 15.9163267 secs]
225360.620: [GC [PSYoungGen: 271293K->45253K(289344K)] 699921K->474266K(989760K), 14.2002714 secs]
225433.516: [GC [PSYoungGen: 272645K->45800K(290304K)] 701658K->475432K(990720K), 13.5428829 secs]
225507.127: [GC [PSYoungGen: 274920K->46574K(291072K)] 704552K->476801K(991488K), 12.9561999 secs]
225574.232: [GC [PSYoungGen: 277294K->45976K(291904K)] 707521K->476667K(992320K), 12.9653753 secs]
225645.094: [GC [PSYoungGen: 278552K->45678K(292928K)] 709243K->476767K(993344K), 13.0371176 secs]
225730.506: [GC [PSYoungGen: 280046K->46012K(293696K)] 711135K->477526K(994112K), 12.9603393 secs]
225800.381: [GC [PSYoungGen: 281916K->45702K(294464K)] 713430K->477601K(994880K), 12.7639847 secs]
225882.533: [GC [PSYoungGen: 283142K->45724K(295232K)] 715041K->477933K(995648K), 13.1265807 secs]
225959.815: [GC [PSYoungGen: 284636K->45352K(295936K)] 716845K->477765K(996352K), 12.8560322 secs]
226028.126: [GC [PSYoungGen: 285606K->44567K(296576K)] 718019K->477173K(996992K), 13.1747649 secs]
226113.721: [GC [PSYoungGen: 286039K->44631K(297152K)] 718645K->477304K(997568K), 12.9761655 secs]
226189.006: [GC [PSYoungGen: 287127K->43171K(297600K)] 719800K->475948K(998016K), 12.7001585 secs]
226272.493: [GC [PSYoungGen: 286563K->46048K(298048K)] 719340K->478945K(998464K), 15.4503877 secs]
226370.698: [GC [PSYoungGen: 290144K->44828K(298304K)] 723041K->477812K(998720K), 15.1513255 secs]
226450.359: [GC [PSYoungGen: 289948K->43477K(299072K)] 722932K->476618K(999488K), 12.4625687 secs]
226526.292: [GC [PSYoungGen: 289798K->42570K(299520K)] 722939K->475803K(999936K), 13.1888912 secs]
226573.820: [GC [PSYoungGen: 195206K->35816K(282880K)] 628438K->469117K(983296K), 13.1857234 secs]
226587.006: [Full GC [PSYoungGen: 35816K->0K(282880K)] [PSOldGen: 433300K->109455K(700416K)] 469117K->109455K(983296K) [PSPermGen: 54328K->54328K(61440K)], 3.5305068 secs]
226661.078: [GC [PSYoungGen: 247040K->24611K(294016K)] 356495K->134066K(994432K), 0.2545354 secs]
226718.220: [GC [PSYoungGen: 265379K->42536K(296512K)] 374834K->151991K(996928K), 0.7517331 secs]
226745.737: [GC [PSYoungGen: 283294K->14113K(290496K)] 392749K->190665K(990912K), 2.1634112 secs]
226779.116: [GC [PSYoungGen: 250145K->20393K(256448K)] 577663K->347911K(956864K), 9.4606675 secs]
226853.298: [GC [PSYoungGen: 256420K->32339K(294016K)] 810389K->586307K(994432K), 14.5663735 secs]
226875.855: [GC [PSYoungGen: 86543K->15025K(249536K)] 640512K->568994K(949952K), 14.5555144 secs]
226890.410: [GC [PSYoungGen: 15025K->14609K(290432K)] 568994K->568578K(990848K), 14.2632312 secs]
226904.674: [Full GC [PSYoungGen: 14609K->0K(290432K)] [PSOldGen: 553968K->336380K(700416K)] 568578K->336380K(990848K) [PSPermGen: 55657K->55657K(61440K)], 8.3742992 secs]
226973.270: [Full GC [PSYoungGen: 230528K->0K(290432K)] [PSOldGen: 676055K->444824K(700416K)] 906583K->444824K(990848K) [PSPermGen: 56423K->51466K(57344K)], 11.8196995 secs]
226995.805: [GC [PSYoungGen: 50508K->5645K(236224K)] 495332K->450469K(936640K), 12.4870149 secs]
227008.292: [GC [PSYoungGen: 5645K->5597K(287616K)] 450469K->450421K(988032K), 12.3637174 secs]
227020.656: [Full GC [PSYoungGen: 5597K->0K(287616K)] [PSOldGen: 444824K->450250K(700416K)] 450421K->450250K(988032K) [PSPermGen: 51562K->51562K(57344K)], 10.2108458 secs]
227030.867: [GC [PSYoungGen: 0K->0K(224960K)] 450250K->450250K(925376K), 8.7146639 secs]
227039.582: [Full GC [PSYoungGen: 0K->0K(224960K)] [PSOldGen: 450250K->429020K(700416K)] 450250K->429020K(925376K) [PSPermGen: 51562K->50743K(57344K)], 11.0929516 secs]
227115.583: [GC [PSYoungGen: 224890K->23965K(291264K)] 653910K->452985K(991680K), 9.0684117 secs]
227184.456: [GC [PSYoungGen: 250461K->27977K(254528K)] 679481K->456998K(954944K), 9.1870795 secs]
227261.043: [GC [PSYoungGen: 254473K->29984K(287104K)] 683494K->459004K(987520K), 9.6195427 secs]
227328.596: [GC [PSYoungGen: 258592K->30615K(285568K)] 687612K->459635K(985984K), 9.3263706 secs]
227390.025: [GC [PSYoungGen: 259202K->31718K(293376K)] 688223K->460738K(993792K), 9.2181260 secs]
227456.630: [GC [PSYoungGen: 269414K->34645K(292480K)] 698434K->463665K(992896K), 9.0907971 secs]
227535.327: [GC [PSYoungGen: 272341K->33713K(297472K)] 701361K->462733K(997888K), 9.1354429 secs]
227614.209: [GC [PSYoungGen: 276273K->35671K(297344K)] 705293K->464692K(997760K), 9.1001188 secs]
227685.765: [GC [PSYoungGen: 278551K->37875K(296064K)] 707572K->466896K(996480K), 9.5112959 secs]
227767.963: [GC [PSYoungGen: 279283K->37669K(279104K)] 708304K->466689K(979520K), 9.0065081 secs]
227839.202: [GC [PSYoungGen: 279077K->40952K(293824K)] 708097K->469973K(994240K), 9.1933889 secs]
227923.826: [GC [PSYoungGen: 279013K->41882K(280000K)] 708033K->470903K(980416K), 8.9542602 secs]
227998.230: [GC [PSYoungGen: 279962K->41795K(292352K)] 708983K->470815K(992768K), 9.0694394 secs]
228071.420: [GC [PSYoungGen: 275779K->41861K(275904K)] 704799K->470881K(976320K), 9.5251693 secs]
228142.867: [GC [PSYoungGen: 275845K->41928K(292032K)] 704865K->470949K(992448K), 9.6910329 secs]
228214.079: [GC [PSYoungGen: 274248K->43901K(276224K)] 703269K->472922K(976640K), 9.2809071 secs]
228299.470: [GC [PSYoungGen: 276221K->42962K(291392K)] 705242K->471982K(991808K), 9.1765844 secs]
228372.383: [GC [PSYoungGen: 273618K->41632K(291456K)] 702638K->470652K(991872K), 9.1600894 secs]
228453.701: [GC [PSYoungGen: 272288K->44217K(291392K)] 701308K->473238K(991808K), 9.4600510 secs]
228542.105: [GC [PSYoungGen: 275385K->42576K(291712K)] 704406K->471596K(992128K), 9.3372926 secs]
228619.365: [GC [PSYoungGen: 273741K->43753K(291712K)] 702762K->472774K(992128K), 9.5144359 secs]
228698.074: [GC [PSYoungGen: 275497K->43800K(292288K)] 704518K->472820K(992704K), 9.6111462 secs]
228786.905: [GC [PSYoungGen: 276248K->45386K(292288K)] 705268K->474406K(992704K), 9.0479735 secs]
228867.705: [GC [PSYoungGen: 278090K->43229K(292480K)] 707110K->472249K(992896K), 9.3947755 secs]
228945.952: [GC [PSYoungGen: 275933K->44503K(292480K)] 704953K->473523K(992896K), 9.1724724 secs]
229033.603: [GC [PSYoungGen: 277975K->43072K(293248K)] 706995K->472093K(993664K), 9.1639680 secs]
229108.605: [GC [PSYoungGen: 277615K->44996K(293568K)] 706635K->474016K(993984K), 9.3007131 secs]
229181.717: [GC [PSYoungGen: 280836K->47256K(284288K)] 709856K->476277K(984704K), 9.5144713 secs]
229267.589: [GC [PSYoungGen: 284236K->45483K(294464K)] 713257K->474503K(994880K), 9.0439900 secs]
229363.230: [GC [PSYoungGen: 281835K->45070K(294144K)] 710855K->474091K(994560K), 9.6142635 secs]
229448.122: [GC [PSYoungGen: 281422K->44277K(294464K)] 710443K->473297K(994880K), 9.2521743 secs]
229538.414: [GC [PSYoungGen: 281461K->45223K(294976K)] 710481K->475509K(995392K), 9.1476948 secs]
229636.165: [GC [PSYoungGen: 283751K->42635K(295808K)] 714037K->473221K(996224K), 9.2946073 secs]
229723.444: [GC [PSYoungGen: 282443K->43479K(296256K)] 713029K->474323K(996672K), 9.1377910 secs]
229800.609: [GC [PSYoungGen: 284951K->46188K(297472K)] 715795K->477156K(997888K), 9.3039539 secs]
229872.534: [GC [PSYoungGen: 289900K->43474K(298368K)] 720868K->474670K(998784K), 9.8688640 secs]
229934.513: [GC [PSYoungGen: 287954K->41390K(298368K)] 719150K->472793K(998784K), 9.9632709 secs]
229997.698: [GC [PSYoungGen: 286890K->44554K(299392K)] 718293K->476221K(999808K), 9.2414924 secs]
230075.570: [GC [PSYoungGen: 291722K->46802K(299520K)] 723389K->478688K(999936K), 9.4285503 secs]
230145.328: [GC [PSYoungGen: 294482K->49320K(297024K)] 726368K->481311K(997440K), 9.2397038 secs]
230223.675: [GC [PSYoungGen: 297000K->47799K(297920K)] 728991K->480183K(998336K), 9.2192642 secs]
230298.534: [GC [PSYoungGen: 292149K->46433K(298304K)] 724533K->479070K(998720K), 9.2239761 secs]
230383.812: [GC [PSYoungGen: 290785K->45781K(298304K)] 723422K->478583K(998720K), 9.1182621 secs]
230471.111: [GC [PSYoungGen: 290389K->45782K(298560K)] 723191K->478851K(998976K), 9.3889543 secs]
230564.243: [GC [PSYoungGen: 291158K->47602K(299072K)] 724227K->480726K(999488K), 9.3119557 secs]
230650.680: [GC [PSYoungGen: 284391K->45584K(299328K)] 717515K->478772K(999744K), 9.2850300 secs]
230659.965: [Full GC [PSYoungGen: 45584K->0K(299328K)] [PSOldGen: 433188K->126855K(700416K)] 478772K->126855K(999744K) [PSPermGen: 54626K->54626K(61440K)], 3.5606335 secs]

Here, for some reason it normalizes

230723.019: [GC [PSYoungGen: 246393K->27265K(295232K)] 373248K->154121K(995648K), 0.3085633 secs]
230811.153: [GC [PSYoungGen: 270209K->29187K(272192K)] 397065K->156043K(972608K), 0.2967067 secs]
230901.345: [GC [PSYoungGen: 272131K->31297K(295424K)] 398987K->158153K(995840K), 0.3067173 secs]
230971.741: [GC [PSYoungGen: 270765K->33045K(295872K)] 397621K->159901K(996288K), 0.2897660 secs]
231046.743: [GC [PSYoungGen: 272533K->32971K(295872K)] 399389K->159827K(996288K), 0.2837683 secs]

Alot of lines..... of 0.xxxx secs

234479.222: [GC [PSYoungGen: 279967K->30133K(299584K)] 380188K->130354K(1000000K), 0.3184770 secs]
234567.575: [GC [PSYoungGen: 278709K->33600K(300416K)] 378930K->133821K(1000832K), 0.3477459 secs]
234634.147: [GC [PSYoungGen: 282176K->46903K(297344K)] 382397K->147124K(997760K), 0.8005909 secs]
234663.689: [GC [PSYoungGen: 261152K->16680K(262336K)] 361373K->251094K(962752K), 2.4014527 secs]

The problem arises again

234709.734: [GC [PSYoungGen: 262312K->24259K(295424K)] 647692K->409639K(995840K), 10.6939254 secs]
234767.259: [Full GC [PSYoungGen: 194344K->0K(295424K)] [PSOldGen: 611830K->340400K(700416K)] 806174K->340400K(995840K) [PSPermGen: 52440K->52440K(57344K)], 8.5968734 secs]
234839.983: [Full GC [PSYoungGen: 218224K->0K(295424K)] [PSOldGen: 680075K->459576K(700416K)] 898300K->459576K(995840K) [PSPermGen: 52512K->52512K(57344K)], 11.5051038 secs]
234851.488: [GC [PSYoungGen: 0K->0K(239552K)] 459576K->459576K(939968K), 9.0407308 secs]
234860.529: [Full GC [PSYoungGen: 0K->0K(239552K)] [PSOldGen: 459576K->443755K(700416K)] 459576K->443755K(939968K) [PSPermGen: 52512K->50987K(57344K)], 12.1328066 secs]
234932.470: [GC [PSYoungGen: 239488K->24935K(293184K)] 683243K->468690K(993600K), 13.0367956 secs]
235030.614: [GC [PSYoungGen: 257571K->27430K(260096K)] 701327K->471185K(960512K), 12.3967718 secs]
235119.815: [GC [PSYoungGen: 260070K->31319K(293568K)] 703825K->475074K(993984K), 12.6346706 secs]
235206.791: [GC [PSYoungGen: 267735K->31905K(291008K)] 711490K->475660K(991424K), 12.7577830 secs]
235306.809: [GC [PSYoungGen: 268321K->32739K(297344K)] 712076K->476494K(997760K), 12.5082607 secs]
235421.934: [GC [PSYoungGen: 277603K->36499K(295680K)] 721358K->480254K(996096K), 13.0245779 secs]
235522.272: [GC [PSYoungGen: 281363K->36071K(301440K)] 725118K->479826K(1001856K), 12.2444468 secs]
235635.049: [GC [PSYoungGen: 286823K->37431K(301568K)] 730578K->481186K(1001984K), 12.6971605 secs]
235738.753: [GC [PSYoungGen: 288695K->38673K(301120K)] 732450K->482429K(1001536K), 12.7670514 secs]
235848.005: [GC [PSYoungGen: 289425K->40848K(291648K)] 733181K->484604K(992064K), 12.8173123 secs]
235962.617: [GC [PSYoungGen: 291600K->42918K(297600K)] 735356K->486673K(998016K), 13.0657047 secs]
236070.822: [GC [PSYoungGen: 288806K->41786K(287680K)] 732561K->485542K(988096K), 12.5850568 secs]
236186.895: [GC [PSYoungGen: 287674K->41868K(297536K)] 731430K->485624K(997952K), 13.8073728 secs]
236320.337: [GC [PSYoungGen: 285580K->41449K(285184K)] 729336K->485204K(985600K), 13.1271165 secs]
236443.900: [GC [PSYoungGen: 285161K->42522K(297280K)] 728916K->486277K(997696K), 13.2454934 secs]
236567.869: [GC [PSYoungGen: 285466K->41210K(297600K)] 729221K->484966K(998016K), 15.3080510 secs]
236687.966: [GC [PSYoungGen: 284154K->41083K(297600K)] 727910K->484838K(998016K), 12.6825608 secs]
236808.156: [GC [PSYoungGen: 284334K->41564K(297920K)] 728089K->485319K(998336K), 14.7419034 secs]
236938.632: [GC [PSYoungGen: 285596K->42379K(298368K)] 729351K->486135K(998784K), 14.6078020 secs]
237065.872: [GC [PSYoungGen: 287179K->42943K(298688K)] 730935K->486698K(999104K), 14.1711610 secs]
237189.513: [GC [PSYoungGen: 288126K->42262K(298752K)] 731881K->486018K(999168K), 12.8384320 secs]
237307.492: [GC [PSYoungGen: 287446K->42750K(298688K)] 731202K->486506K(999104K), 12.5060390 secs]
237428.371: [GC [PSYoungGen: 288254K->42365K(299072K)] 732010K->486120K(999488K), 12.5767819 secs]
237548.774: [GC [PSYoungGen: 288437K->41506K(299264K)] 732192K->485261K(999680K), 12.4783905 secs]
237665.726: [GC [PSYoungGen: 288152K->45267K(299072K)] 731907K->489023K(999488K), 12.4782240 secs]
237790.234: [GC [PSYoungGen: 292435K->43286K(299712K)] 736191K->487041K(1000128K), 12.5324235 secs]
237928.337: [GC [PSYoungGen: 290454K->43694K(299712K)] 734209K->487449K(1000128K), 12.4755974 secs]
238044.219: [GC [PSYoungGen: 291118K->46796K(294656K)] 734873K->490552K(995072K), 12.6228990 secs]
238187.931: [GC [PSYoungGen: 294604K->44534K(299264K)] 738360K->488290K(999680K), 13.4121481 secs]
238302.604: [GC [PSYoungGen: 290678K->44980K(299136K)] 734434K->488736K(999552K), 12.8707811 secs]
238461.832: [GC [PSYoungGen: 291124K->44681K(299264K)] 734880K->488437K(999680K), 14.1901770 secs]
238476.041: [GC [PSYoungGen: 50989K->41870K(299072K)] 494745K->486975K(999488K), 13.0254167 secs]
238489.067: [Full GC [PSYoungGen: 41870K->0K(299072K)] [PSOldGen: 445105K->106661K(700416K)] 486975K->106661K(999488K) [PSPermGen: 53753K->51034K(57344K)], 3.9094349 secs]

Here, for some reason it normalizes

238611.904: [GC [PSYoungGen: 246336K->24930K(296192K)] 352997K->131591K(996608K), 0.2919967 secs]
238720.658: [GC [PSYoungGen: 269282K->29554K(273920K)] 375943K->136215K(974336K), 0.3718844 secs]
238851.399: [GC [PSYoungGen: 273896K->29722K(297344K)] 380558K->136384K(997760K), 0.3336927 secs]
238967.126: [GC [PSYoungGen: 272538K->31845K(297536K)] 379200K->138506K(997952K), 0.2800818 secs]

Alot of lines..... of 0.xxxx secs

250886.147: [GC [PSYoungGen: 286276K->39269K(295616K)] 417943K->170936K(996032K), 0.2977127 secs]
250975.586: [GC [PSYoungGen: 282035K->47679K(296064K)] 413702K->207173K(996480K), 0.9333266 secs]
251004.911: [GC [PSYoungGen: 241080K->21934K(284288K)] 400574K->315620K(984704K), 2.6574647 secs]
251075.679: [Full GC [PSYoungGen: 250030K->0K(284288K)] [PSOldGen: 671103K->325240K(700416K)] 921133K->325240K(984704K) [PSPermGen: 60964K->52083K(57344K)], 9.6272342 secs]
251173.145: [Full GC [PSYoungGen: 214991K->0K(284288K)] [PSOldGen: 664915K->447965K(700416K)] 879906K->447965K(984704K) [PSPermGen: 52247K->52247K(57344K)], 11.5538333 secs]
251184.711: [GC [PSYoungGen: 0K->0K(228160K)] 447965K->447965K(928576K), 8.9564419 secs]
251193.667: [Full GC [PSYoungGen: 0K->0K(228160K)] [PSOldGen: 447965K->444283K(700416K)] 447965K->444283K(928576K) [PSPermGen: 52247K->51119K(57344K)], 12.2150901 secs]
251289.390: [GC [PSYoungGen: 228096K->23088K(286784K)] 672379K->467372K(987200K), 8.7246216 secs]
251393.350: [GC [PSYoungGen: 243376K->26189K(246528K)] 687660K->470472K(946944K), 9.2286775 secs]
251513.605: [GC [PSYoungGen: 246465K->27810K(286528K)] 690748K->472093K(986944K), 8.9831333 secs]
251622.689: [GC [PSYoungGen: 250658K->28841K(284480K)] 694941K->473124K(984896K), 8.8730335 secs]
251740.316: [GC [PSYoungGen: 251689K->29777K(290624K)] 695972K->474060K(991040K), 9.0538100 secs]
251858.282: [GC [PSYoungGen: 261007K->31749K(288768K)] 705291K->476032K(989184K), 9.0425089 secs]
252001.540: [GC [PSYoungGen: 263365K->33701K(295104K)] 707648K->477984K(995520K), 8.8244878 secs]
252133.063: [GC [PSYoungGen: 274055K->34281K(293440K)] 718338K->478564K(993856K), 8.8550737 secs]
252277.660: [GC [PSYoungGen: 274665K->38033K(296320K)] 718948K->482316K(996736K), 9.2063823 secs]
252415.787: [GC [PSYoungGen: 282641K->38733K(296448K)] 726924K->483016K(996864K), 10.8849284 secs]
252547.711: [GC [PSYoungGen: 283341K->37341K(300416K)] 727624K->481625K(1000832K), 10.0203199 secs]
252662.116: [GC [PSYoungGen: 285661K->39058K(300160K)] 729945K->483341K(1000576K), 9.5695960 secs]
252763.453: [GC [PSYoungGen: 287570K->38491K(300608K)] 731853K->482774K(1001024K), 9.6519972 secs]
252883.521: [GC [PSYoungGen: 287323K->39726K(300480K)] 731606K->484009K(1000896K), 9.1038613 secs]
253008.658: [GC [PSYoungGen: 288679K->39170K(300736K)] 732962K->483454K(1001152K), 8.9566591 secs]
253146.027: [GC [PSYoungGen: 288258K->40498K(300608K)] 732542K->484781K(1001024K), 9.1544405 secs]
253263.279: [GC [PSYoungGen: 289650K->41707K(299712K)] 733933K->485991K(1000128K), 9.2706344 secs]
253379.948: [GC [PSYoungGen: 289771K->40247K(300160K)] 734055K->484530K(1000576K), 9.9157192 secs]
253494.466: [GC [PSYoungGen: 288311K->42671K(299200K)] 732594K->486955K(999616K), 8.9437062 secs]
253621.187: [GC [PSYoungGen: 289967K->42678K(289984K)] 734250K->486961K(990400K), 11.3392371 secs]
253755.288: [GC [PSYoungGen: 289974K->43364K(298496K)] 734257K->487647K(998912K), 11.1991525 secs]
253861.457: [GC [PSYoungGen: 288995K->42624K(298944K)] 733278K->486907K(999360K), 11.0143634 secs]
253978.014: [GC [PSYoungGen: 288256K->43962K(298176K)] 732539K->488246K(998592K), 9.2651563 secs]
254100.621: [GC [PSYoungGen: 288826K->44108K(289024K)] 733110K->488391K(989440K), 11.0140091 secs]
254226.662: [GC [PSYoungGen: 288972K->45424K(297152K)] 733255K->489707K(997568K), 9.1401919 secs]
254337.559: [GC [PSYoungGen: 288618K->45053K(288256K)] 732901K->489336K(988672K), 8.7407403 secs]
254484.880: [GC [PSYoungGen: 288253K->45068K(297152K)] 732536K->489351K(997568K), 8.9102518 secs]
254651.629: [GC [PSYoungGen: 287368K->44646K(297280K)] 731651K->488929K(997696K), 8.7556644 secs]
254806.198: [GC [PSYoungGen: 276808K->42675K(297216K)] 721091K->486958K(997632K), 8.9667162 secs]
254815.165: [Full GC [PSYoungGen: 42675K->0K(297216K)] [PSOldGen: 444283K->123894K(700416K)] 486958K->123894K(997632K) [PSPermGen: 53710K->53710K(61440K)], 3.9919282 secs]
254931.168: [GC [PSYoungGen: 242432K->25069K(268736K)] 366326K->148963K(969152K), 0.2393339 secs]
255086.337: [GC [PSYoungGen: 268717K->27530K(295488K)] 392611K->151425K(995904K), 0.2757895 secs]
255253.595: [GC [PSYoungGen: 267530K->28883K(296128K)] 391425K->152777K(996544K), 0.2771545 secs]

Alot of lines..... of 0.xxxx secs

255391.266: [GC [PSYoungGen: 268853K->31158K(296128K)] 392748K->155053K(996544K), 0.2826663 secs]
255540.749: [GC [PSYoungGen: 271222K->31731K(296192K)] 395117K->155625K(996608K), 0.2879763 secs]
255696.157: [GC [PSYoungGen: 272499K->31985K(296832K)] 396393K->155879K(997248K), 0.3223609 secs]

Any ideas?

Thanks in advance!!

Reply viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.
javiergalindo
Offline
Joined: 2007-05-21
Points: 0

Briand,

We change a lot of things in our code trying to find what the problem was.

After this changes We normalize the behavior of the GC. Look how it is working now:

Lots of seconds...

7069.640: [GC [PSYoungGen: 81340K->7915K(84992K)] 319947K->247540K(609280K), 0.1224221 secs]
7094.564: [GC [PSYoungGen: 82667K->8375K(84352K)] 322292K->249461K(608640K), 0.0924930 secs]
7127.480: [GC [PSYoungGen: 82679K->6381K(83840K)] 323765K->248915K(608128K), 0.1013918 secs]
7154.387: [GC [PSYoungGen: 80237K->6478K(79936K)] 322771K->250467K(604224K), 0.0752654 secs]
7180.281: [GC [PSYoungGen: 79886K->5840K(82432K)] 323875K->251195K(606720K), 0.0610664 secs]
7199.909: [GC [PSYoungGen: 78800K->8302K(80896K)] 324155K->255009K(605184K), 0.1141429 secs]
7203.758: [GC [PSYoungGen: 16463K->1194K(82752K)] 263170K->249533K(607040K), 0.0210041 secs]

A full GC, but only 4.3 secs

7203.779: [Full GC [PSYoungGen: 1194K->0K(82752K)] [PSOldGen: 248339K->168033K(524288K)] 249533K->168033K(607040K) [PSPermGen: 56467K->56467K(110592K)], 4.3172162 secs]

Normal small GCs

7240.474: [GC [PSYoungGen: 72576K->7930K(80128K)] 240609K->175963K(604416K), 0.0845752 secs]
7286.810: [GC [PSYoungGen: 80122K->6830K(82752K)] 248155K->177080K(607040K), 0.0620398 secs]
7317.885: [GC [PSYoungGen: 78638K->7550K(81984K)] 248888K->179047K(606272K), 0.0770903 secs]

Lots of seconds..... aproximately 3000 secs then
A full GC, but only 5.6 secs

10808.129: [Full GC [PSYoungGen: 848K->0K(47296K)] [PSOldGen: 353821K->181059K(524288K)] 354670K->181059K(571584K) [PSPermGen: 58976K->51118K(102400K)], 5.6647070 secs]

And this happens all time...

What was the problem? The problem was in code, We were writing many things in HTTPSession object, and only when the session of users expired We think this objects were available for be reclaimed by the GC.

The only question I still have is, why the use of PSYoungGen change so dramatically? any ideas?

Javier

briand
Offline
Joined: 2005-07-11
Points: 0

It seems that you have reduced the life times of objects dramatically by
either disassociating them with the HTTPSession object or by reducing
allocations or whatever. Regardless, the result is overall goodness, so
be happy :-) Also, congratulations on a debugging task well done!

Why such a dramatic difference? Well, it's not immediately obvious to
to me. I suspect that it's probably a result of less slow path promotions to the
old generation due to the shorter life times of the session related objects. It
might also be a result of reduced lock contention on promotion buffer
allocations in the old gen (parallel young gen gc threads allocate promotion
buffers from the old gen, which are used to promote objects to the old gen
and such allocations are protected by a lock).

I suspect you might have gotten a similar result by reducing the life time
of the session itself, though you might have needed to reduce that session
lifetime to such a short period of time as to make session caching utterly
useless.

Regardless, this problem serves as an excellent example of how the life time
of objects can have a dramatic effect on the performance of garbage collection
and the overall application and system. Keeping object life times to a minimum
will likely have positive effects on overall performance; certainly there are
exceptions (such as caching data that is expensive to recreate either from a
computational or I/O perspective), but such exceptions don't devalue the
experience we witness here.

Brian

javiergalindo
Offline
Joined: 2007-05-21
Points: 0

smoov,

I already has this parameters (I omitted them in the post, but the verbose gc has this detail)

-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps

-XX:MaxPermSize=256m is set to 256m because We load many classes using reflection and with less size we get OOME

-XX:SoftRefLRUPolicyMSPerMB=1, is because We do not want that softly reachable objects to remain alive for some amount of time after the last time they were referenced

Javier

briand
Offline
Joined: 2005-07-11
Points: 0

There are several things I can infer from these gc logs. First, minor collection times
of this magnitude with such a small heap are indicative of either paging or of parallel gc
lock contention.

For the paging situation, you need to make sure that the sum of the RSS's of your 3
instances, and anything else running on the system, do not exceed the amount of
physical RAM on the machine; in fact, it should be a good 300MB less, leaving room
for the OS and other system processes.

For the Parallel GC lock contention issue, this typically happens when there are too
many parallel GC threads in the process and you have too small a young generation.
This typically results in excessive work stealing between the GC threads and this work
stealing bangs on a lock. You indicate that there are 8 parallel GC threads - is that 8
per app server instance? If you are setting ParallelGCThreads to 8, you seem to be
ok from a CPU perspective (24 hw threads/3 app instances - 8 hw threads/app), but
we have seen cases where too many parallel GC threads without enough young space
to carve up between them result in this work stealing pathology. I would recommend
that you try fewer parallelGC threads per app instance. Start with 4 and see if that
improves things. If not, move to 2; if so, try 6 and so on.

Note that I suspect the work stealing issue over the paging issue, but both should
really be checked.

You also ask about why there are 'three pauses in a row'. I'm not certain of the exact
cause of this. These seem to happen around full gc events, and I suspect that the
PSYoungGen proceeding the Full GC event are related - i.e. the full gc event does
a young gen collection first followed by the full gc. So, it's really more likely that there
are two in a row, but that's splitting hairs.

Your Full GC events don't always occur with at full old gen or a full perm gen. The
parallel GC does enforce a promotion guarantee, where it needs to make sure that
the old generation can handle a promotion of the average size promotion that it has
observed. If this condition is not met, then the collector will request a full gc. For the
Parallel collector, such decisions are typically marked in the verbose GC output,
and I don't see those markings in this output. These full GC events also don't seem
to occur at a regular period, so that pretty much eliminates RMI related full GCs. So,
I suspect that the application is calling System.gc() at some point, which is generally
not advisable. You might want to try adding -XX:+DisableExplicitGC to the command
line to test this theory out. If the number of Full GC events is greatly reduced with this
option, then you need to figure out who is calling System.gc() and eliminate that call.
Otherwise, I don't have a ready explanation for why you see these Full GC events.

On thing you could do to possibly speed up these Full GC events is to run with
-XX:+UseParallelOldGC. This allows certain phases of a full gc even to be run in
parallel, thus reducing the time of such collections. This feature is available in 1.5.0_08
and later (though I think 1.5.0_10 has some beneficial changes to this feature).

You might also consider running each app server in a separate processor set.
This will keep the 3 instances from interfering with each other with respect to CPU
resources. Depending on how the app server is configured and the load on the system,
there may be some of that going on here as well. One way to check for this type of
interference is to look at the length of the run queue (vmstat) during these long pauses.
If the run queues are deep (more an 3x the number of hw threads, for example), then
there may be sufficient interference between the app servers. The draw back with
processor sets is that idle processors in one processor set can't be used by threads
assigned to another processor set, so if the load on these three instances is not fairly
shared, then you may reduce overall system utilization when using processor sets.

Finally, I would suggest that you set -Xms == -Xmx. For server apps on systems with
sufficient memory, it just eliminates some extra work that the GC needs to do on
full gc events. Your logs don't indicate any growing or shrinking of the heap (at least
not that I noticed), so setting them different probably isn't buying you anything anyway.
This will also reduce any full gc events that are occurring while the heap grows. Note
that when the system is under memory pressure, the mmap() MAP_NORESERVE
operations behind these grow and shrink operations can be costly - particularly the
grow operation, where the OS must commit the physical memory for the grown area.
When -Xms == -Xmx, all the heap memory is committed on startup of the app and
for most server systems, that's usually just after the OS has booted when there's
plenty of free memory in the system. System startup is also a time when we are more
likely to get large pages for the heap, which is something that HotSpot attempts to
do by default on Solaris (on SPARC, the default is 4m large pages). Large page
memory may or may not be available during long term grow operations. Large pages
can have a significant performance impact, as they reduce system wide TLB pressure.

This should give you some things to try.

bethere
Offline
Joined: 2007-01-09
Points: 0

To further support [i]braind[/i] observations you can check the following blog entries
http://blogs.oracle.com/charleslamb/2007/02/22#a50
and
http://forums.oracle.com/forums/thread.jspa?messageID=1849977

Might give you a clue to what is going on.

smoov
Offline
Joined: 2007-05-01
Points: 0

Couple questions: which version of Java? Could be related to this bug: http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6433335, so your Java version might need an upgrade.
why is -XX:SoftRefLRUPolicyMSPerMB=1 set to 1 ms? The default is something like a second (1000) Per MB, 1ms seems low.
why is -XX:MaxPermSize=256m set to 256m? Looks like you fit in 64m now, if so, set both -XX:PermSize=64m and -XX:MaxPermSize=64m to avoid resizing/growing of perm.

Since you are on Sun hardware and software, I'd recommend adding these JVM Options:
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps

and then looking into this:
http://java.sun.com/docs/forms/gc-sendusmail.html

Please report back what you find.