2 Replies Latest reply on Dec 7, 2011 9:18 PM by 424634

    CMS GC Not Executing

      Hi all,

      I have an issue where the CMS garbage collector is not executing, and I wonder if someone can clue me in on what could possibly cause such behavior. I'm running my program (using java 1.6.0_29) with the following JVM parameters:

      CATALINA_OPTS="-d64 -server -Xmx4g -Xms4g -XX:MaxPermSize=128m -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:NewSize=512m -XX:CMSInitiatingOccupancyFraction=75 -XX:+UseCMSInitiatingOccupancyOnly -XX:+UseCMSCompactAtFullCollection -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:PrintCMSStatistics=3 -XX:+PrintCMSInitiationStatistics -XX:+PrintAdaptiveSizePolicy -XX:+PrintCompilation -XX:+PrintConcurrentLocks -XX:+PrintGCTaskTimeStamps -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime -XX:+PrintSharedSpaces -XX:+PrintTenuringDistribution -XX:+PrintVMQWaitTime -Xloggc:/dpz/ems-ws/bin/gc.log -verbose:gc"

      In my gc.log file, I see the following CMS Entries:

      2011-11-14T09:47:24.660-0500: 1104.878: [GC [1 CMS-initial-mark: 2758057K(3670016K)] 2796390K(4141888K), 0.0550771 secs] [Times: user=0.02 sys=0.03, real=0.06 secs]
      Total time for which application threads were stopped: 0.0711610 seconds
      2011-11-14T09:47:24.718-0500: 1104.936: [CMS-concurrent-mark-start]

      So it looks like the CMS initiated. However, that's the last I ever heard from it. Memory kept expanding for the next 15 minutes or so until the heap was completely full, at which time the app hung on the following statement:

      2011-11-14T10:01:18.041-0500: 1939.377: [GC 1939.377: [ParNew: 471872K->471872K(471872K), 0.0000399 secs]1939.377: [CMS

      for many minutes until I finally just killed the JVM. So that last statement seems to indicate that the CMS wanted to do something...but at this point it was kinda too late.

      If I change -XX:CMSInitiatingOccupancyFraction=75 to -XX:CMSInitiatingOccupancyFraction=30, this seems to work. However, I don't understand why.

      Note that my program is running a Berkeley DB which I am giving 60% of the JVM memory to for cache. Thus, after a warmup period, 60% of the total heap will always be considered "live" for the cache alone.
        • 1. Re: CMS GC Not Executing
          Further update.

          So I tried again with -XX:CMSInitiatingOccupancyFraction=30, this time with a 6G heap.

          As with 4G, the CMS kicked in and was working for awhile. However, after some time, the CMS simply stopped executing (or at least logging), and the memory once again filled up.

          I dont see anything in the GC logging indicating why the CMS is not executing. It worked up until this statement:

          2011-11-14T19:43:09.235-0500: 1243.280: [CMS-concurrent-mark-start]

          and then the JVM locked indefinitely at the following statement:

          2011-11-14T20:30:55.947-0500: 4113.838: [GC 4113.853: [ParNew: 461969K->461969K(471872K), 0.0000395 secs]4113.853: [CMS

          Anyone have any suggestions as to why this would happen?
          • 2. Re: CMS GC Not Executing
            It's probably due to fragmentation of the tenured space meaning that it has no more contiguous areas of memory to put objects it wants to store. However, I'm surprised it doesn't try to do a full GC to compact at this point. That's what we're experiencing at least and then the JVM crashes.

            One setting we're trying is -XX:+CMSClassUnloadingEnabled and so far it seems to be helping. Next we plan to use this as well: -XX:CMSFullGCsBeforeCompaction=1.