6 Replies Latest reply on May 28, 2009 5:13 PM by vony jon

    Too may FullGC

    vony jon Newbie

      Hi,

      I am seeing too many Full GC on our UAT jboss server

      Our environment detail is

      Jboss 4.2.0, RHEL Linux, JDK 1.5 update 12

      We are using following switches with JVM

      JAVA_OPTS="-server -Xms1500m -Xmx1500m -Xss128k -verbose:gc -Xloggc:GC.log -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -XX:+UseLargePages -XX:PermSize=512m -XX:MaxPermSize=512m -XX:ThreadStackSize=512 -XX:+UseParallelGC -XX:+AggressiveHeap -XX:CompileThreshold=100 -XX:SurvivorRatio=8 -XX:TargetSurvivorRatio=90 -XX:MaxTenuringThreshold=31"
      



      I am not sure about all the switch since they were set by a earlier guy on the environment.

      It should not have that many Full GC atleast.


      These are the excerpts from GC.log

      3.233: [Full GC [PSYoungGen: 47467K->0K(505344K)] [PSOldGen: 0K->3913K(960512K)] 47467K->3913K(1465856K) [PSPermGen: 10353K->10353K(524288K)], 0.0826630 secs]
      20.516: [GC [PSYoungGen: 433152K->37159K(505344K)] 437065K->41073K(1465856K), 0.0479740 secs]
      26.509: [GC [PSYoungGen: 470311K->55349K(505344K)] 474225K->59263K(1465856K), 0.0718930 secs]
      63.336: [Full GC [PSYoungGen: 231313K->0K(505344K)] [PSOldGen: 3913K->70244K(960512K)] 235227K->70244K(1465856K) [PSPermGen: 60120K->60120K(524288K)], 0.6276220 secs]
      124.003: [Full GC [PSYoungGen: 12615K->0K(505344K)] [PSOldGen: 70244K->70698K(960512K)] 82860K->70698K(1465856K) [PSPermGen: 60284K->60284K(524288K)], 0.4507880 secs]
      184.480: [Full GC [PSYoungGen: 12679K->0K(505344K)] [PSOldGen: 70698K->69983K(960512K)] 83378K->69983K(1465856K) [PSPermGen: 60348K->60199K(524288K)], 0.5425070 secs]
      245.062: [Full GC [PSYoungGen: 14884K->0K(505344K)] [PSOldGen: 69983K->70499K(960512K)] 84868K->70499K(1465856K) [PSPermGen: 60240K->60240K(524288K)], 0.4373220 secs]
      305.534: [Full GC [PSYoungGen: 13311K->0K(505344K)] [PSOldGen: 70499K->70948K(960512K)] 83811K->70948K(1465856K) [PSPermGen: 60320K->60320K(524288K)], 0.4404290 secs]
      366.015: [Full GC [PSYoungGen: 19158K->0K(505344K)] [PSOldGen: 70948K->71326K(960512K)] 90107K->71326K(1465856K) [PSPermGen: 60626K->60626K(524288K)], 0.4434450 secs]
      426.492: [Full GC [PSYoungGen: 298711K->0K(505344K)] [PSOldGen: 71326K->79680K(960512K)] 370038K->79680K(1465856K) [PSPermGen: 63711K->63704K(524288K)], 0.6969270 secs]
      487.235: [Full GC [PSYoungGen: 113471K->0K(505344K)] [PSOldGen: 79680K->81257K(960512K)] 193152K->81257K(1465856K) [PSPermGen: 64029K->64029K(524288K)], 0.5384320 secs]
      547.798: [Full GC [PSYoungGen: 50512K->0K(505344K)] [PSOldGen: 81257K->82307K(960512K)] 131769K->82307K(1465856K) [PSPermGen: 64102K->64102K(524288K)], 0.5207440 secs]
      608.354: [Full GC [PSYoungGen: 20435K->0K(505344K)] [PSOldGen: 82307K->82894K(960512K)] 102743K->82894K(1465856K) [PSPermGen: 64113K->64113K(524288K)], 0.5209310 secs]
      668.918: [Full GC [PSYoungGen: 20048K->0K(505344K)] [PSOldGen: 82894K->81159K(960512K)] 102943K->81159K(1465856K) [PSPermGen: 64119K->64116K(524288K)], 0.5797770 secs]
      729.540: [Full GC [PSYoungGen: 18845K->0K(505344K)] [PSOldGen: 81159K->81862K(960512K)] 100005K->81862K(1465856K) [PSPermGen: 64123K->64123K(524288K)], 0.5061830 secs]
      790.082: [Full GC [PSYoungGen: 17355K->0K(505344K)] [PSOldGen: 81862K->82468K(960512K)] 99218K->82468K(1465856K) [PSPermGen: 64157K->64157K(524288K)], 0.5156910 secs]
      850.640: [Full GC [PSYoungGen: 21532K->0K(505344K)] [PSOldGen: 82468K->82883K(960512K)] 104001K->82883K(1465856K) [PSPermGen: 64166K->64166K(524288K)], 0.5069440 secs]
      911.190: [Full GC [PSYoungGen: 39172K->0K(505344K)] [PSOldGen: 82883K->82313K(960512K)] 122056K->82313K(1465856K) [PSPermGen: 64416K->64415K(524288K)], 0.5833240 secs]
      971.798: [Full GC [PSYoungGen: 42793K->0K(505344K)] [PSOldGen: 82313K->83650K(960512K)] 125106K->83650K(1465856K) [PSPermGen: 65044K->65044K(524288K)], 0.5328580 secs]
      1032.366: [Full GC [PSYoungGen: 79362K->0K(505344K)] [PSOldGen: 83650K->85485K(960512K)] 163013K->85485K(1465856K) [PSPermGen: 65067K->65067K(524288K)], 0.5602910 secs]
      1092.971: [Full GC [PSYoungGen: 19971K->0K(505344K)] [PSOldGen: 85485K->85872K(960512K)] 105457K->85872K(1465856K) [PSPermGen: 65071K->65071K(524288K)], 0.5192250 secs]
      1153.514: [Full GC [PSYoungGen: 41284K->0K(505344K)] [PSOldGen: 85872K->84748K(960512K)] 127156K->84748K(1465856K) [PSPermGen: 65145K->65143K(524288K)], 0.5955200 secs]
      1214.134: [Full GC [PSYoungGen: 26565K->0K(505344K)] [PSOldGen: 84748K->85414K(960512K)] 111314K->85414K(1465856K) [PSPermGen: 65267K->65267K(524288K)], 0.5293840 secs]
      1274.699: [Full GC [PSYoungGen: 19038K->0K(505344K)] [PSOldGen: 85414K->85902K(960512K)] 104453K->85902K(1465856K) [PSPermGen: 65275K->65275K(524288K)], 0.5349830 secs]
      1335.259: [Full GC [PSYoungGen: 28956K->0K(505344K)] [PSOldGen: 85902K->86588K(960512K)] 114859K->86588K(1465856K) [PSPermGen: 65287K->65287K(524288K)], 0.5304630 secs]
      1395.814: [Full GC [PSYoungGen: 58454K->0K(505344K)] [PSOldGen: 86588K->90846K(960512K)] 145043K->90846K(1465856K) [PSPermGen: 65489K->65485K(524288K)], 0.6308820 secs]
      1456.490: [Full GC [PSYoungGen: 17463K->0K(505344K)] [PSOldGen: 90846K->91146K(960512K)] 108310K->91146K(1465856K) [PSPermGen: 65489K->65489K(524288K)], 0.5279640 secs]
      1517.053: [Full GC [PSYoungGen: 21551K->0K(505344K)] [PSOldGen: 91146K->88091K(960512K)] 112697K->88091K(1465856K) [PSPermGen: 65490K->65490K(524288K)], 0.6676840 secs]
      1577.765: [Full GC [PSYoungGen: 17617K->0K(505344K)] [PSOldGen: 88091K->88316K(960512K)] 105709K->88316K(1465856K) [PSPermGen: 65490K->65490K(524288K)], 0.5269980 secs]
      1638.317: [Full GC [PSYoungGen: 16328K->0K(505344K)] [PSOldGen: 88316K->82510K(960512K)] 104644K->82510K(1465856K) [PSPermGen: 65495K->65068K(524288K)], 0.6246950 secs]
      1698.977: [Full GC [PSYoungGen: 18979K->0K(505344K)] [PSOldGen: 82510K->82693K(960512K)] 101489K->82693K(1465856K) [PSPermGen: 65071K->65071K(524288K)], 0.5276440 secs]
      1759.549: [Full GC [PSYoungGen: 20763K->0K(505344K)] [PSOldGen: 82693K->83137K(960512K)] 103456K->83137K(1465856K) [PSPermGen: 65086K->65086K(524288K)], 0.5161060 secs]
      1820.111: [Full GC [PSYoungGen: 150814K->0K(505344K)] [PSOldGen: 83137K->84225K(960512K)] 233951K->84225K(1465856K) [PSPermGen: 65134K->65134K(524288K)], 0.6056400 secs]
      1836.570: [GC [PSYoungGen: 433152K->11264K(505344K)] 517377K->95489K(1465856K), 0.0111670 secs]
      1880.761: [Full GC [PSYoungGen: 115732K->0K(505344K)] [PSOldGen: 84225K->87439K(960512K)] 199957K->87439K(1465856K) [PSPermGen: 65349K->65279K(524288K)], 0.7114030 secs]
      1941.509: [Full GC [PSYoungGen: 430910K->0K(505344K)] [PSOldGen: 87439K->89011K(960512K)] 518349K->89011K(1465856K) [PSPermGen: 65306K->65306K(524288K)], 0.6858490 secs]
      2002.221: [Full GC [PSYoungGen: 109493K->0K(505344K)] [PSOldGen: 89011K->90356K(960512K)] 198505K->90356K(1465856K) [PSPermGen: 65546K->65546K(524288K)], 0.6933410 secs]
      2062.957: [Full GC [PSYoungGen: 27659K->0K(505344K)] [PSOldGen: 90356K->90880K(960512K)] 118015K->90880K(1465856K) [PSPermGen: 65549K->65549K(524288K)], 0.5455710 secs]
      2123.529: [Full GC [PSYoungGen: 42855K->0K(505344K)] [PSOldGen: 90880K->88179K(960512K)] 133736K->88179K(1465856K) [PSPermGen: 65550K->65526K(524288K)], 0.6687030 secs]
      2184.244: [Full GC [PSYoungGen: 414946K->0K(505344K)] [PSOldGen: 88179K->89130K(960512K)] 503125K->89130K(1465856K) [PSPermGen: 65526K->65526K(524288K)], 0.6813070 secs]
      2244.950: [Full GC [PSYoungGen: 18271K->0K(505344K)] [PSOldGen: 89130K->89556K(960512K)] 107401K->89556K(1465856K) [PSPermGen: 65527K->65527K(524288K)], 0.5417160 secs]
      2305.538: [Full GC [PSYoungGen: 23252K->0K(505344K)] [PSOldGen: 89556K->92276K(960512K)] 112809K->92276K(1465856K) [PSPermGen: 65527K->65527K(524288K)], 0.5528190 secs
      
      Please advise on the same


        • 1. Re: Too may FullGC
          Peter Johnson Master

          Get rid of the AggressiveHeap setting - that setting sets a whole set of options (possibly overwriting some of the options you set before it). This option was primarily used by Sun for running the SPECjbb benchmark and is often not appropriate within a production environment.

          It looks like your young gen is taking up over 1/3 of the heap (probably due to AggressiveHeap being set). Try setting -XX:NewSize=400M and -XX:MaxNewSize=400M.

          • 2. Re: Too may FullGC
            vony jon Newbie

            Hi Peter,

            I am not sure that it was due to AggressiveHeap.

            I did try to set the -XX:NewSize=400M -XX:MaxNewSize=400M, Full GC is happening every minute

            So now options are

            JAVA_OPTS="-server -Xms1500m -Xmx1500m -Xss128k -XX:NewSize=400M -XX:MaxNewSize=400M -verbose:gc -Xloggc:/opt/jboss-4.2.0.GA/logs/GC.log -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -XX:+UseLargePages -XX:PermSize=512m -XX:MaxPermSize=512m -XX:ThreadStackSize=512 -XX:+UseParallelGC -XX:CompileThreshold=100 -XX:SurvivorRatio=8 -XX:TargetSurvivorRatio=90 -XX:MaxTenuringThreshold=31"
            


            see the excerpts from GC.log

            4.083: [GC [PSYoungGen: 92161K->4011K(358400K)] 92161K->4011K(1484800K), 0.0105160 secs]
            4.093: [Full GC [PSYoungGen: 4011K->0K(358400K)] [PSOldGen: 0K->3912K(1126400K)] 4011K->3912K(1484800K) [PSPermGen: 10442K->10442K(524288K)], 0.0647090 secs]
            14.868: [GC [PSYoungGen: 307200K->16084K(358400K)] 311112K->19996K(1484800K), 0.0257470 secs]
            24.043: [GC [PSYoungGen: 323284K->35371K(358400K)] 327196K->39283K(1484800K), 0.0585670 secs]
            29.813: [GC [PSYoungGen: 342571K->46513K(358400K)] 346483K->50425K(1484800K), 0.0626800 secs]
            64.215: [GC [PSYoungGen: 267394K->51194K(358400K)] 271306K->68206K(1484800K), 0.0918350 secs]
            64.307: [Full GC [PSYoungGen: 51194K->0K(358400K)] [PSOldGen: 17011K->67462K(1126400K)] 68206K->67462K(1484800K) [PSPermGen: 56403K->56403K(524288K)], 0.5361080 secs]
            124.906: [GC [PSYoungGen: 151055K->4753K(358400K)] 218518K->72216K(1484800K), 0.0107620 secs]
            124.916: [Full GC [PSYoungGen: 4753K->0K(358400K)] [PSOldGen: 67462K->72103K(1126400K)] 72216K->72103K(1484800K) [PSPermGen: 62877K->62877K(524288K)], 0.5240890 secs]
            185.465: [GC [PSYoungGen: 18961K->306K(358400K)] 91065K->72410K(1484800K), 0.0044300 secs]
            185.470: [Full GC [PSYoungGen: 306K->0K(358400K)] [PSOldGen: 72103K->70911K(1126400K)] 72410K->70911K(1484800K) [PSPermGen: 62898K->62728K(524288K)], 0.5783190 secs]
            246.080: [GC [PSYoungGen: 17583K->321K(358400K)] 88495K->71233K(1484800K), 0.0043550 secs]
            246.084: [Full GC [PSYoungGen: 321K->0K(358400K)] [PSOldGen: 70911K->71137K(1126400K)] 71233K->71137K(1484800K) [PSPermGen: 62754K->62754K(524288K)], 0.4824640 secs]
            
            


            • 3. Re: Too may FullGC
              Peter Johnson Master

              A full GC every minute? That is because you removed the following options from the JAVA_OPTS that came with JBoss AS:

              set JAVA_OPTS=%JAVA_OPTS% -Dsun.rmi.dgc.client.gcInterval=3600000 -Dsun.rmi.dgc.server.gcInterval=3600000

              By default, the rmi code calls System.gc() every minute. The above options delay that to once an hour. Actually, I'd set it for once a month!

              • 4. Re: Too may FullGC
                vony jon Newbie

                Hi Peter,

                Is that bug in JDK 1.5, that it does System.gc() every minute if you disable it.

                but -XX:+DisableExplicitGC should also prevent all calls to System.gc().
                So if i use that , that should be fine.

                • 5. Re: Too may FullGC
                  Peter Johnson Master

                  It is not a bug, it is the way that RMI works.

                  I don't know if using DisableExplicitGC will work for this, it all depends on how RMI goes about causing a GC, and whether it does it via C code or via Java code.

                  • 6. Re: Too may FullGC
                    vony jon Newbie

                    Hi Peter,

                    After putting -XX:+DisableExplicitGC switch, so far i am not able to see any FUll GC yet.

                    Which means RMI is doing it via Java code i.e. System.gc()

                    So what is preferable option to set, DisableExplicitGC or one should set RMI gcInterval on higher side