5 Replies Latest reply: Apr 2, 2009 5:53 AM by 843829 RSS

    Unreasonable full GC's

    843829
      hi,

      we're experiencing very (IMHO!) unreasonable/unexpected full GCs after some time in a jboss webapplication. Here is an example:
      11113.762: [Full GC {Heap before gc invocations=863:
       par new generation   total 235968K, used 212112K [0xfffffffe20000000, 0xfffffffe30000000, 0xfffffffe30000000)
        eden space 209792K, 100% used [0xfffffffe20000000, 0xfffffffe2cce0000, 0xfffffffe2cce0000)
        from space 26176K,   8% used [0xfffffffe2e670000, 0xfffffffe2e8b43e8, 0xfffffffe30000000)
        to   space 26176K,   0% used [0xfffffffe2cce0000, 0xfffffffe2cce0000, 0xfffffffe2e670000)
       concurrent mark-sweep generation total 3932160K, used 464922K [0xfffffffe30000000, 0xffffffff20000000, 0xffffffff20000000)
       concurrent-mark-sweep perm gen total 131072K, used 91372K [0xffffffff20000000, 0xffffffff28000000, 0xffffffff40000000)
      11113.763: [ParNew: 212112K->3048K(235968K), 0.0205527 secs] 677035K->467972K(4168128K)Heap after gc invocations=864:
       par new generation   total 235968K, used 3048K [0xfffffffe20000000, 0xfffffffe30000000, 0xfffffffe30000000)
        eden space 209792K,   0% used [0xfffffffe20000000, 0xfffffffe20000000, 0xfffffffe2cce0000)
        from space 26176K,  11% used [0xfffffffe2cce0000, 0xfffffffe2cfda2f0, 0xfffffffe2e670000)
        to   space 26176K,   0% used [0xfffffffe2e670000, 0xfffffffe2e670000, 0xfffffffe30000000)
       concurrent mark-sweep generation total 3932160K, used 464923K [0xfffffffe30000000, 0xffffffff20000000, 0xffffffff20000000)
       concurrent-mark-sweep perm gen total 131072K, used 91372K [0xffffffff20000000, 0xffffffff28000000, 0xffffffff40000000)
      }
      As you see the heap is far away from being full (600 mb to 700 mb while the heap size is actually 4gb). Such full gcs happen like 5 to 10 times in a day which aren't critical but since most of our caches are soft referenced they would, afaik understood soft-references and full gcs, be removed on a full gc. I don't see any endless loops or similar in thread dumps which may lead to excessive full gc's.

      I'd like to know why the JVM decides to do these full gc's, is there any possibility to get this information by special vm parameters or some analysis tool?

      The VM actually runs with the following parameters:
      -d64 -Djava.net.preferIPv4Stack=true -Djava.awt.headless=true 
      -Xms4g -Xmx4g -XX:PermSize=128M -XX:MaxPermSize=512m -XX:ThreadStackSize=256 -XX:NewSize=256M 
      -XX:+DisableExplicitGC -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+CMSClassUnloadingEnabled -XX:SurvivorRatio=8  -XX:ParallelGCThreads=8 -XX:LargePageSizeInBytes=256m  
      -XX:+PrintHeapAtGC -Xloggc:[...] -XX:+PrintHeapAtGC
      Most of the heap size parameters were taken from http://www.sun.com/bigadmin/features/articles/jboss_sf_t2000.jsp since the machine is a sun fire t2000 and we're running jboss on it. Also all of the kernel parameters were adopted.

      Java version:
      java version "1.5.0_17"
      Java(TM) 2 Runtime Environment, Standard Edition (build 1.5.0_17-b04)
      Java HotSpot(TM) 64-Bit Server VM (build 1.5.0_17-b04, mixed mode
      regards,
      stefan

      Edited by: slotties on Mar 26, 2009 2:23 AM
        • 1. Re: Unreasonable full GC's
          843829
          As far as I can remember, a generation will be fully collected when it's full - as I can see, the eden space has used 100% of its memory - a full gc can run also, when the total heap has used 700MB of its 4GB.

          >
          Most of the heap size parameters were taken from http://www.sun.com/bigadmin/features/articles/jboss_sf_t2000.jsp since the machine is a sun fire t2000 and we're running jboss on it. Also all of the kernel parameters were adopted.
          >
          I know, configuring the gc is not easy, because you usually have no fu*ing clue what the result would be on your productive environment. On large and powerful applications, in my opinion, gc parametrization is a continious process. Check out JConsole, monitor your application server, understand the charts and change the configuration if needed. And monitor again.

          regards
          slowfly
          • 2. Re: Unreasonable full GC's
            843829
            Thanks for your reply! I've checked the gc log again and found pretty many collections where the eden is completely full which didn't end in full collections, like this here (right before the full gc):
            11111.795: [GC {Heap before gc invocations=862:
             par new generation   total 235968K, used 211098K [0xfffffffe20000000, 0xfffffffe30000000, 0xfffffffe30000000)
              eden space 209792K, 100% used [0xfffffffe20000000, 0xfffffffe2cce0000, 0xfffffffe2cce0000)
              from space 26176K,   4% used [0xfffffffe2cce0000, 0xfffffffe2ce26970, 0xfffffffe2e670000)
              to   space 26176K,   0% used [0xfffffffe2e670000, 0xfffffffe2e670000, 0xfffffffe30000000)
             concurrent mark-sweep generation total 3932160K, used 464652K [0xfffffffe30000000, 0xffffffff20000000, 0xffffffff20000000)
             concurrent-mark-sweep perm gen total 131072K, used 91372K [0xffffffff20000000, 0xffffffff28000000, 0xffffffff40000000)
            11111.796: [ParNew: 211098K->2320K(235968K), 0.0197844 secs] 675750K->467243K(4168128K)Heap after gc invocations=863:
             par new generation   total 235968K, used 2320K [0xfffffffe20000000, 0xfffffffe30000000, 0xfffffffe30000000)
              eden space 209792K,   0% used [0xfffffffe20000000, 0xfffffffe20000000, 0xfffffffe2cce0000)
              from space 26176K,   8% used [0xfffffffe2e670000, 0xfffffffe2e8b4370, 0xfffffffe30000000)
              to   space 26176K,   0% used [0xfffffffe2cce0000, 0xfffffffe2cce0000, 0xfffffffe2e670000)
             concurrent mark-sweep generation total 3932160K, used 464922K [0xfffffffe30000000, 0xffffffff20000000, 0xffffffff20000000)
             concurrent-mark-sweep perm gen total 131072K, used 91372K [0xffffffff20000000, 0xffffffff28000000, 0xffffffff40000000)
            }
            , 0.0210968 secs]
            I'll check out jconsole then. I already tried jvmstat but still haven't seen any reason why the full gc was invoked.
            • 3. Re: Unreasonable full GC's
              843829
              Which version of the JRE are you running?

              Note that you didn't capture the entire GC event log in your quote: you are missing the statement of how long the full collection took, e.g., up through the closing "]" that matches the one that starts "[Full GC ".

              You have -XX:+DisableExplicitGC, so the full GC's are *not* caused by calls to System.gc(), which also rules out RMI, a usual source of otherwise unexplained full collections.  Is there some periodicity to the full collections?  (You only say "5 to 10 times in a day".)

              The right answer is to work through your Sun Support Engineer to figure out why these collections are happening and to get help in tuning the collector to avoid them (if they are a problem).  If you are not willing to go to that much effort, you could post a day's GC log to hotspot-gc-use@openjdk.java.net and see if anyone there had some suggestions.                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                   
              • 4. Re: Unreasonable full GC's
                843829
                Which version of the JRE are you running?
                see my first post (1.5.0_17 64 bit on solaris)

                >
                11113.762: [Full GC {Heap before gc invocations=863:
                [...]
                1113.763: [ParNew: 212112K->3048K(235968K), 0.0205527 secs] 677035K->467972K(4168128K)Heap after gc invocations=864:
                [...]
                }
                , 0.0218688 secs]
                {code}

                All the full GC's were pretty quick done:

                {code}
                11113.762: [Full GC {Heap before gc invocations=863:
                [...]
                11113.763: [ParNew: 212112K->3048K(235968K), 0.0205527 secs] 677035K->467972K(4168128K)Heap after gc invocations=864:
                [...]
                }
                , 0.0218688 secs]
                {code}
                {code}
                11307.359: [Full GC {Heap before gc invocations=924:
                [...]
                11307.359: [ParNew: 210488K->678K(235968K), 0.0143949 secs] 680029K->470224K(4168128K)Heap after gc invocations=925:
                [...]
                }
                , 0.0157222 secs
                {code}
                {code}
                12628.233: [Full GC {Heap before gc invocations=1484:
                [...]
                12628.233: [ParNew: 210683K->1164K(235968K), 0.0157089 secs] 707645K->498127K(4168128K)Heap after gc invocations=1485:
                [...]
                }
                , 0.0170155 secs]
                {code}
                {code}
                15523.060: [Full GC {Heap before gc invocations=2673:
                [...]
                15523.060: [ParNew: 210955K->702K(235968K), 0.0159088 secs] 773298K->563286K(4168128K)Heap after gc invocations=2674:
                [...]
                }
                , 0.0172477 secs]
                {code}
                {code}
                17269.336: [Full GC {Heap before gc invocations=3511:
                [...]
                17269.337: [ParNew: 213282K->3190K(235968K), 0.0218450 secs] 811041K->600972K(4168128K)Heap after gc invocations=3512:
                [...]
                }
                , 0.0234213 secs]
                {code}
                {code}
                18241.611: [Full GC {Heap before gc invocations=3951:
                [...]
                18241.611: [ParNew: 211166K->2221K(235968K), 0.0174486 secs] 830239K->621297K(4168128K)Heap after gc invocations=3952:
                [...]
                }
                , 0.0187901 secs]
                {code}
                {code}
                19148.914: [Full GC {Heap before gc invocations=4297:
                [...]
                19148.915: [ParNew: 211723K->1703K(235968K), 0.0186568 secs] 848583K->638604K(4168128K)Heap after gc invocations=4298:
                [...]
                }
                , 0.0200058 secs]
                {code}
                {code}
                19878.205: [Full GC {Heap before gc invocations=4620:
                [...]
                19878.206: [ParNew: 211311K->1999K(235968K), 0.0195760 secs] 861711K->652685K(4168128K)Heap after gc invocations=4621:
                [...]
                }
                , 0.0209131 secs]
                {code}

                I don't see any periodicity except the times between full gc's shrink a little bit.

                As you see the heap grows from 400 MB when the first full gc occured up to 650 MB when the last one was done. The last gc (not full) before even shows a heap of 740 MB:

                {code}
                66684.776: [GC {Heap before gc invocations=5513:
                [...]
                66684.776: [ParNew: 222494K->13907K(235968K), 0.0553122 secs] 951700K->743113K(4168128K)Heap after gc invocations=5514:
                [...]
                }
                , 0.0568477 secs]
                {code}

                This is totally okay and wanted that the heap grows (what else do we have 4 gig of ram for? ;) as we have some caches (soft-referenced). Somehow I've got the feeling that, since the tenured space seems to grow, the full GC's don't collect much from the tenured but just cleaned the eden which has about 200 MB of space while the gc's (including full) always remove about 200 MB (+/- 10-20 MB).

                From testing around with stand alone applications that create lots of garbage I noticed that the eden might not be used if it's growing too fast and the whole objects were put into the tenured. I wonder if something similar is happening here too, but according the gc logs the eden is used.
                • 5. Re: Unreasonable full GC's
                  843829
                  We also have the same issue. Full GC are invoked even when the heap is only half full. We also use the same jdk version as reported above. And we too have SoftReferences in our environment. We have around 4 app servers of which only 1 or 2 experience the Full GC.