Java heap space, GC, and Promotion Failed

Fri Apr 15 15:19:16 PDT 2011

Hi Rafael,

Perhaps two other observations: You don't appear to have a Young generation size specified (-XX:NewSize=, or -Xmn). From your logs YG is just 29.5Mb which is probably too small with a 2Gb heap and a lot of objects being created. The idea is to get as many objects to die and be collected in the YG, provided ParNew times are OK (I think the adaptive collector tries to keep this around 10-20ms, but most apps can cope with longer ParNew pauses than that). This puts less pressure on Tenured. With a 2Gb heap size, you might try a NewSize of 128m. If ParNew's are taking too long then reduce it (it depends on whether your app is producing lots of small objects, or larger objects).

The other curiosity is that you have CMSInitiatingFraction set to only 5, so effectively you are using only 5% of the Heap (strictly Tenured). It can be helpful to set this parameter (and its companion UseInitiatingOccupancyOnly) to avoid conc-mode failures, but again with a small YG size, and relatively large Heap, that should probably be up around 80% at least.

Maybe try these, and if you are still having problems send some more logs showing the details.

Doug. 

  ----- Original Message ----- 
  From: Rafael Angarita 
  To: Y.S.Ramakrishna at oracle.com 
  Cc: hotspot-gc-use at openjdk.java.net 
  Sent: Friday, April 15, 2011 2:17 AM
  Subject: Re: Java heap space, GC, and Promotion Failed

  Thank you very much!

  I took your advise about the JVM GC parameters and removed some of them.

  I used  -Xmx2500m. My application gets further with the proccesing it needs to do, but the whole computer gets really slow and my application crash anyway.

  I'm trying to get the developers of the framework I'm using for my DSL.

  If any of you guys have more ideas, I'm here to listen and learn.

  Thank you very much.

  On 13 April 2011 14:58, Y. S. Ramakrishna <y.s.ramakrishna at oracle.com> wrote:

    Hi Rafael --

    Looks like you need more heap: size your -Xmx bigger to
    accommodate all of the objects that your Eclipse project creates.
    Here's the state of the old gen in the penultimate display:-

        [Full GC [CMS[CMS-concurrent-mark: 8.811/9.001 secs] [Times: user=10.95 sys=0.02, real=9.00 secs]  (concurrent mode failure): 2008891K->2014802K(2015232K), 24.2053380 secs] 2038395K->2014802K(2044736K), [CMS Perm : 50779K->50779K(86244K)] icms_dc=100 , 24.2054320 secs] [Times: user=24.16 sys=0.03, real=24.20 secs] [GC [1 CMS-initial-mark: 2014802K(2015232K)] 2015335K(2044736K), 0.0023250 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

    The last line shows that the old gen has:-
     2015232 - 2014802 = 430 KB
    of free space. Perhaps you were trying to allocate an object bigger than that.
    I'd suggest running with a larger heap (possibly using a 64-bit JVM if
    you need more Java heap).

    However, the end of your message does not show the heap to be too full.
    Perhaps Eclipse catches the OOM, and drops all of the objects before it exits,
    so you see the heap as not full in the final display:-
    (Eclipse experts on the list might want to weigh in.)

        This is the end of the output:

        Heap
         par new generation   total 29504K, used 23591K [0x2e8b0000, 0x308b0000, 0x308b0000)
         eden space 26240K,  77% used [0x2e8b0000, 0x2fc89f20, 0x30250000)
         from space 3264K, 100% used [0x30580000, 0x308b0000, 0x308b0000)
         to   space 3264K,   0% used [0x30250000, 0x30250000, 0x30580000)
         concurrent mark-sweep generation total 2015232K, used 61766K [0x308b0000, 0xab8b0000, 0xab8b0000)
         concurrent-mark-sweep perm gen total 87828K, used 52696K [0xab8b0000, 0xb0e75000, 0xb38b0000)

    Asides:-
    Never, never use values for MaxTenuringThreshold exceeding 15, unless
    you are sure you want that kind of behaviour. I'd suggest
    just leave that option out unless you know how to tune for it (there's
    lots of experience on this alias with tuning that though, should
    you need to tune that for performance in the future).

    More asides (specific to CMS):-
    Depending on what your platform is, if it has anything more than 2 cores,
    i'd advise dropping the -XX:+CMSIncrementalMode option. (You'd then
    want to drop other options starting with "CMSIncremental".
    CMS does not unload classes by default. With Eclipse etc. you would
    want to unload classes concurrently so as not to get OOM's:
    use -XX:+CMSClassUnloadingEnabled (and if on older JVM's -XX:+CMSPermGenSweepingEnabled).

    Bottom line: looks like you need more Java heap.
    -- ramki

    On 04/13/11 10:25, Rafael Angarita wrote:

      Hello everybody,

      I'm building a code generation application as an Eclipse and one of my test projects contains around 15000 source files. My application started having memory problems, so after doing some optimizations especific to the framework I'm using to develope my DSL, I started learning about GC, but I think I'm still lost.

      I have tried with different JVM options for the GC with no success. Currently, I'm trying:

      -Xms2000m -Xmx2000m -verbosegc -XX:+PrintGCDetails  -XX:+HeapDumpOnOutOfMemoryError -XX:+UseConcMarkSweepGC -XX:+CMSIncrementalMode -XX:+CMSIncrementalPacing -XX:CMSInitiatingOccupancyFraction=5 -XX:MaxTenuringThreshold=300 -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSIncrementalDutyCycleMin=1

      but this is just one of the several things I have tried.

      At first everything seems to go fine, but after awhile I get "promotion failed" and everything gets really slow, and finally the application crash with java.lang.OutOfMemoryError: Java heap space.

      CMS-concurrent-abortable-preclean: 0.070/0.587 secs] [Times: user=0.66 sys=0.02, real=0.58 secs] [GC[YG occupancy: 28574 K (29504 K)][Rescan (parallel) , 0.0198420 secs][weak refs processing, 0.0015200 secs] [1 CMS-remark: 1961760K(2015232K)] 1990335K(2044736K), 0.0215890 secs] [Times: user=0.03 sys=0.00, real=0.03 secs] [GC [ParNew: 29096K->2087K(29504K), 0.0270900 secs] 1990735K->1965523K(2044736K) icms_dc=100 , 0.0271650 secs] [Times: user=0.05 sys=0.00, real=0.03 secs] [GC [ParNew: 28327K->3264K(29504K), 0.0430410 secs] 1990448K->1969326K(2044736K) icms_dc=100 , 0.0431180 secs] [Times: user=0.07 sys=0.01, real=0.04 secs] [GC [ParNew: 29504K->3264K(29504K), 0.0658260 secs] 1995091K->1975795K(2044736K) icms_dc=100 , 0.0659090 secs] [Times: user=0.11 sys=0.00, real=0.07 secs] [GC [ParNew: 29504K->3264K(29504K), 0.0630250 secs] 2001944K->1982760K(2044736K) icms_dc=100 , 0.0631060 secs] [Times: user=0.11 sys=0.00, real=0.06 secs] [GC [ParNew: 29504K->3263K(29504K), 0.0435130 secs] 2008711K->1985752K(2044736K) icms_dc=100 , 0.0436310 secs] [Times: user=0.07 sys=0.00, real=0.04 secs] [CMS-concurrent-sweep: 1.813/2.058 secs] [Times: user=3.76 sys=0.02, real=2.05 secs] [CMS-concurrent-reset: 0.035/0.035 secs] [Times: user=0.06 sys=0.00, real=0.04 secs] [GC [ParNew (promotion failed): 29503K->29504K(29504K), 0.5729750 secs][CMS[Unloading class sun.reflect.GeneratedConstructorAccessor6]
      [Unloading class sun.reflect.GeneratedConstructorAccessor26]
      [Unloading class sun.reflect.GeneratedMethodAccessor9]
      [Unloading class sun.reflect.GeneratedConstructorAccessor17]
      [Unloading class sun.reflect.GeneratedConstructorAccessor20]
      [Unloading class sun.reflect.GeneratedMethodAccessor4]
      [Unloading class sun.reflect.GeneratedMethodAccessor8]
      [Unloading class sun.reflect.GeneratedConstructorAccessor25]
      [Unloading class sun.reflect.GeneratedMethodAccessor18]
      [Unloading class sun.reflect.GeneratedMethodAccessor17]
      [Unloading class sun.reflect.GeneratedConstructorAccessor27]
      [Unloading class sun.reflect.GeneratedConstructorAccessor19]
      [Unloading class sun.reflect.GeneratedConstructorAccessor12]
      [Unloading class sun.reflect.GeneratedMethodAccessor2]
      [Unloading class sun.reflect.GeneratedConstructorAccessor14]
      [Unloading class sun.reflect.GeneratedConstructorAccessor28]
      [Unloading class sun.reflect.GeneratedConstructorAccessor5]
      [Unloading class sun.reflect.GeneratedMethodAccessor16]
      [Unloading class sun.reflect.GeneratedMethodAccessor19]
      [Unloading class sun.reflect.GeneratedConstructorAccessor9]
      [Unloading class sun.reflect.GeneratedConstructorAccessor11]
      [Unloading class sun.reflect.GeneratedConstructorAccessor8]
      [Unloading class sun.reflect.GeneratedConstructorAccessor29]
      [Unloading class sun.reflect.GeneratedMethodAccessor3]
      [Unloading class sun.reflect.GeneratedConstructorAccessor24]
      [Unloading class sun.reflect.GeneratedConstructorAccessor18]
      [Unloading class sun.reflect.GeneratedMethodAccessor15]
      [Unloading class sun.reflect.GeneratedConstructorAccessor10]
      [Unloading class sun.reflect.GeneratedConstructorAccessor16]
      [Unloading class sun.reflect.GeneratedConstructorAccessor15]

      [Full GC [CMS[CMS-concurrent-mark: 8.811/9.001 secs] [Times: user=10.95 sys=0.02, real=9.00 secs]  (concurrent mode failure): 2008891K->2014802K(2015232K), 24.2053380 secs] 2038395K->2014802K(2044736K), [CMS Perm : 50779K->50779K(86244K)] icms_dc=100 , 24.2054320 secs] [Times: user=24.16 sys=0.03, real=24.20 secs] [GC [1 CMS-initial-mark: 2014802K(2015232K)] 2015335K(2044736K), 0.0023250 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
      This is the end of the output:

      Heap
       par new generation   total 29504K, used 23591K [0x2e8b0000, 0x308b0000, 0x308b0000)
       eden space 26240K,  77% used [0x2e8b0000, 0x2fc89f20, 0x30250000)
       from space 3264K, 100% used [0x30580000, 0x308b0000, 0x308b0000)
       to   space 3264K,   0% used [0x30250000, 0x30250000, 0x30580000)
       concurrent mark-sweep generation total 2015232K, used 61766K [0x308b0000, 0xab8b0000, 0xab8b0000)
       concurrent-mark-sweep perm gen total 87828K, used 52696K [0xab8b0000, 0xb0e75000, 0xb38b0000)

      I would appreciate if anybody can give me an advise about this.

      Thank you very much for your help.

      ------------------------------------------------------------------------

      _______________________________________________
      hotspot-gc-use mailing list
      hotspot-gc-use at openjdk.java.net
      http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use

------------------------------------------------------------------------------

  _______________________________________________
  hotspot-gc-use mailing list
  hotspot-gc-use at openjdk.java.net
  http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20110416/15fb53b3/attachment.html 