0 Replies Latest reply: May 11, 2010 9:05 AM by 843798 RSS

    Java Memory Incresease Exponentially

    843798
      Hi All ,


      When my program runs for a long time, the memory was increasing by time and the program halts some time . The following gives a brief of my issues,
      * The JVM memory utilized was increasing by time
      * The performance was affected due to long GC pauses
      * More CPU utilization time to time

      I tried to do some trouble shooting with the JVM tools, the details are,

      GC snapshot time to time
      --------------------------------------------------------------

      0.000: [GC [PSYoungGen: 5510K->1206K(78848K)] 5510K->1206K(254976K), 0.0354727 secs]
      0.036: [Full GC [PSYoungGen: 1206K->0K(78848K)] [PSOldGen: 0K->864K(176128K)] 1206K->864K(254976K) [PSPermGen: 4019K->4019K(16384K)]
      60.136: [GC [PSYoungGen: 39806K->2726K(78848K)] 40671K->3590K(254976K), 0.0476875 secs]
      60.184: [Full GC [PSYoungGen: 2726K->0K(78848K)] [PSOldGen: 864K->3219K(176128K)] 3590K->3219K(254976K) [PSPermGen: 9816K->9816K(16]
      ...
      202741.476: [GC [PSYoungGen: 8679K->511K(78848K)] 150325K->142157K(254976K), 0.0068342 secs]
      202741.483: [Full GC [PSYoungGen: 511K->0K(78848K)] [PSOldGen: 141645K->141494K(176128K)] 14
      ....

      340190.306: [Full GC [PSYoungGen: 61381K->54854K(78848K)] [PSOldGen: 180224K->180224K(180224K)] 241605K->235078K(259072K) [PSPermGe]
      340255.216: [Full GC [PSYoungGen: 65681K->55436K(78848K)] [PSOldGen: 180224K->180224K(180224K)] 245905K->235660K(259072K) [PSPermGe]
      340320.186: [Full GC [PSYoungGen: 66380K->52100K(78848K)] [PSOldGen: 180224K->180224K(180224K)] 246604K->232324K(259072K) [PSPermGe]
      340385.186: [Full GC [PSYoungGen: 60744K->55407K(78848K)] [PSOldGen: 180224K->180224K(180224K)] 240968K->235631K(259072K) [PSPermGe]
      340450.576: [Full GC [PSYoungGen: 61949K->55514K(78848K)] [PSOldGen: 180224K->180224K(180224K)] 242173K->235738K(259072K) [PSPermGe]
      340515.756: [Full GC [PSYoungGen: 66607K->55615K(78848K)] [PSOldGen: 180224K->180224K(180224K)] 246831K->235839K(259072K) [PSPermGe]

      ....
      421720.996: [GC [PSYoungGen: 12053K->535K(78848K)] 296887K->285368K(615424K), 0.0072620 secs]
      421721.003: [Full GC [PSYoungGen: 535K->0K(78848K)] [PSOldGen: 284833K->284938K(536576K)] 285368K->284938K(615424K) [PSPermGen: 10020K->10020K(16384K)], 5.8750348 secs]
      421786.886: [GC [PSYoungGen: 8392K->511K(78848K)] 293330K->285449K(615424K), 0.0080966 secs]
      421786.894: [Full GC [PSYoungGen: 511K->0K(78848K)] [PSOldGen: 284938K->285014K(536576K)] 285449K->285014K(615424K) [PSPermGen: 10025K->10025K(16384K)], 5.9864552 secs]
      421852.886: [GC [PSYoungGen: 5909K->487K(78848K)] 290923K->285501K(615424K), 0.0074509 secs]
      421852.893: [Full GC [PSYoungGen: 487K->0K(78848K)] [PSOldGen: 285014K->284900K(536576K)] 285501K->284900K(615424K) [PSPermGen: 10030K->10010K(16384K)], 6.1571002 secs]
      421919.056: [GC [PSYoungGen: 4533K->559K(78848K)] 289434K->285459K(615424K), 0.0074119 secs]
      421919.063: [Full GC [PSYoungGen: 559K->0K(78848K)] [PSOldGen: 284900K->284976K(536576K)] 285459K->284976K(615424K) [PSPermGen: 10015K->10015K(16384K)], 6.1046790 secs]
      421985.176: [GC [PSYoungGen: 7510K->527K(78848K)] 292487K->285503K(615424K), 0.0068276 secs]

      Hardware:
      -------------------------------
      Solaris Sparc

      Jmap -heap details:
      -------------------------------
      JVM version is 1.5.0_06-b05

      using thread-local object allocation.
      Parallel GC with 32 thread(s)

      Heap Configuration:
      MinHeapFreeRatio = 40
      MaxHeapFreeRatio = 70
      MaxHeapSize = 1073741824 (1024.0MB)
      NewSize = 2228224 (2.125MB)
      MaxNewSize = 4294901760 (4095.9375MB)
      OldSize = 1441792 (1.375MB)
      NewRatio = 2
      SurvivorRatio = 32
      PermSize = 16777216 (16.0MB)
      MaxPermSize = 67108864 (64.0MB)

      Jmap -histo details:
      -------------------------------
      Unknown oop at 0xe3448e30
      Oop's klass is null
      Unknown oop at 0xe34513e0
      Oop's klass is null
      Unknown oop at 0xe34a0698
      Oop's klass is null
      ...
      Debugger attached successfully.
      Server compiler detected.
      JVM version is 1.5.0_06-b05
      Iterating over heap. This may take a while...
      Object Histogram:

      Size Count Class description
      -------------------------------------------------------
      310075456 9689858 java.util.concurrent.locks.AbstractQueuedSynchronizer$Node
      2656968 22063 * ConstMethodKlass
      1592632 22063 * MethodKlass
      1498288 38145 * SymbolKlass
      1109992 2005 * ConstantPoolKlass


      The heap memory was taken by default, JVM heap properties was not modified.

      I have following questions based on the above,
      * Why there was lot of Full GC's and even it occurs once after a Minor GC cycle? I thought Full GC occurs when there is a need to reallocate/free memory when the heap is near close to heap size.
      * I found there was a memory leak bug related to java.util.concurrent.locks.AbstractQueuedSynchronizer$Node (http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6460501). Here they have told the problem was due to Semaphore timed tryAcquire(). In my case i'm using tryAcquire without time wait, is that valid in this case?
      * The program works in RMI environment, which results in RMI Thread timeouts , does this can create any memory leaks ?
      * Does anyone had similar issue and fixed it ??