This discussion is archived
1 Reply Latest reply: Feb 15, 2012 1:35 AM by EJP RSS

GC freeze when collecting old generation

915571 Newbie
Currently Being Moderated
h1. GC is freezing from time to time

h2. The application
JBoss 4.x with (approx 2000 threads) with ORACLE 10g(/RAC). The load is varying during the day,
but typically there is a high load for several hours (8h-12h), after that the system
is basically idle. The entire application is just plain java (no additional native dll's).
h2. The Problem -> GC Freeze
The application server is rebooted once every week. Collecting the old generation takes typically less than 2 secs. However,
sometimes (after days) we experience extensive GC times when collecting the old generation:
Typically the major portion of the delay is found in the following phases:
*[summary phase, 8.9943085 secs]*
*[post compact, 29.4723376 secs]*
Total time for which application threads were stopped:  43.3590538 seconds

h2. JVM (java –version)
java version "1.6.0_24"
Java(TM) SE Runtime Environment (build 1.6.0_24-b07)
Java HotSpot(TM) Client VM (build 19.1-b02, mixed mode)
h2. The hardware/OS
OS: Microsoft Windows XP Service Pack 2 (build 3790) (64bit)
CPU: Intel(R) Xeon(R) CPU 8X E5530 @ 2.40GHz (Hyper Threading Enabled), RAM: 4078 Mb total
h2. GC Settings
-Dsun.rmi.dgc.client.gcInterval=3600000 -Dsun.rmi.dgc.server.gcInterval=3600000
-server -Xmx1580m -Xms1580m -Xmn800m
-Xss128k-XX:ThreadStackSize=128
-XX:+UseParallelGC
-XX:ParallelGCThreads=7
-XX:+UseParallelOldGC
-XX:-UseAdaptiveSizePolicy -XX:+ExplicitGCInvokesConcurrent
-XX:MaxGCPauseMillis=50 -XX:SurvivorRatio=6 -XX:MaxTenuringThreshold=30
-XX:PermSize=96m -XX:MaxPermSize=96m
-XX:+PrintParallelOldGCPhaseTimes -XX:+PrintHeapAtGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCApplicationStoppedTim

h4. 1. Can someone shed some light on the summary and post compact phase? Which steps are taken by the JVM here?
What might take so long?
h4. 2. I observed, that the JVM memory footprint (perfmon/private bytes of the JVM) is temporally increasing and the total memory usage
goes from 2.2 up to 3.0 GB. This additional memory is allocated on the C++ heap! For what? Why does a JVM temporally allocate
so much memory on the C++ heap (the application is just plain java).
h4. 3. Can the root cause for the intensive “post compacting” times be fragmentation of the java heap.
The documenation indicates that fragmentation of the old generation is possible:
"Each garbage collection thread reserves a part of the tenured generation for promotions and
the division of the available space into these "promotion buffers" can cause a
fragmentation effect."
Is there a simple way monitor/log the fragementation of the java heap?
h4. 4. Is there a known Bug bug in java version "1.6.0_24" that can cause this freeze?



Thanks for any help!*



---- GC snippet
2012-01-31T07:39:32.350-0500: 329853.039: [GC [PSYoungGen: 716798K->102393K(716800K)] 1475117K->879812K(1515520K), 0.0614928 secs] [Times: user=0.44 sys=0.00, real=0.06 secs]
Heap after GC invocations=28726 (full 187):
PSYoungGen total 716800K, used 102393K [0xb6bf0000, 0xe8bf0000, 0xe8bf0000)
eden space 614400K, 0% used [0xb6bf0000,0xb6bf0000,0xdc3f0000)
from space 102400K, 99% used [0xe27f0000,0xe8bee458,0xe8bf0000)
to space 102400K, 0% used [0xdc3f0000,0xdc3f0000,0xe27f0000)
ParOldGen total 798720K, used 777419K [0x85ff0000, 0xb6bf0000, 0xb6bf0000)
object space 798720K, 97% used [0x85ff0000,0xb5722cc8,0xb6bf0000)
PSPermGen total 98304K, used 77426K [0x7fff0000, 0x85ff0000, 0x85ff0000)
object space 98304K, 78% used [0x7fff0000,0x84b8cbc8,0x85ff0000)
}
Total time for which application threads were stopped: 0.0668004 seconds
{Heap before GC invocations=28727 (full 187):
PSYoungGen      total 716800K, used 716793K [0xb6bf0000, 0xe8bf0000, 0xe8bf0000)
  eden space 614400K, 100% used [0xb6bf0000,0xdc3f0000,0xdc3f0000)
  from space 102400K, 99% used [0xe27f0000,0xe8bee458,0xe8bf0000)
  to   space 102400K, 0% used [0xdc3f0000,0xdc3f0000,0xe27f0000)
ParOldGen       total 798720K, used 777419K [0x85ff0000, 0xb6bf0000, 0xb6bf0000)
  object space 798720K, 97% used [0x85ff0000,0xb5722cc8,0xb6bf0000)
PSPermGen       total 98304K, used 77426K [0x7fff0000, 0x85ff0000, 0x85ff0000)
  object space 98304K, 78% used [0x7fff0000,0x84b8cbc8,0x85ff0000)

h2. *2012-01-31T07:39:37.740-0500: 329858.432: [GC-- [PSYoungGen: 716793K->716793K(716800K)] 1494212K->1515510K(1515520K), 3.9532929 secs] [Times: user=0.72 sys=0.03, real=3.95 secs]*
Heap after GC invocations=28727 (full 187):
PSYoungGen total 716800K, used 716793K [0xb6bf0000, 0xe8bf0000, 0xe8bf0000)
eden space 614400K, 100% used [0xb6bf0000,0xdc3f0000,0xdc3f0000)
from space 102400K, 99% used [0xe27f0000,0xe8bee458,0xe8bf0000)
to space 102400K, 99% used [0xdc3f0000,0xe27efee0,0xe27f0000)
ParOldGen total 798720K, used 798717K [0x85ff0000, 0xb6bf0000, 0xb6bf0000)
object space 798720K, 99% used [0x85ff0000,0xb6bef670,0xb6bf0000)
PSPermGen total 98304K, used 77426K [0x7fff0000, 0x85ff0000, 0x85ff0000)
object space 98304K, 78% used [0x7fff0000,0x84b8cbc8,0x85ff0000)
}
329862.386: [pre compact{Heap before GC invocations=28728 (full 188):
PSYoungGen      total 716800K, used 716793K [0xb6bf0000, 0xe8bf0000, 0xe8bf0000)
  eden space 614400K, 100% used [0xb6bf0000,0xdc3f0000,0xdc3f0000)
  from space 102400K, 99% used [0xe27f0000,0xe8bee458,0xe8bf0000)
  to   space 102400K, 99% used [0xdc3f0000,0xe27efee0,0xe27f0000)
ParOldGen       total 798720K, used 798717K [0x85ff0000, 0xb6bf0000, 0xb6bf0000)
  object space 798720K, 99% used [0x85ff0000,0xb6bef670,0xb6bf0000)
PSPermGen       total 98304K, used 77426K [0x7fff0000, 0x85ff0000, 0x85ff0000)
  object space 98304K, 78% used [0x7fff0000,0x84b8cbc8,0x85ff0000)
, 0.0003397 secs]
h2. *2012-01-31T07:39:41.694-0500: 329862.386: [Full GC329862.388: [marking phase329862.388: [par mark, 0.5320380 secs]*
329862.921: [reference processing, 0.0051108 secs]
329862.926: [class unloading, 0.0369949 secs]
, 0.5742662 secs]
*329862.963: [summary phase, 8.9943085 secs]*
329871.957: [adjust roots, 0.0357495 secs]
329871.993: [compact perm gen, 0.0782944 secs]
329872.071: [compaction phase329872.071: [drain task setup, 0.0006238 secs]
329872.072: [dense prefix task setup, 0.0000046 secs]
329872.072: [steal task setup, 0.0000005 secs]
329872.072: [par compact, 0.2223263 secs]
329872.295: [deferred updates, 0.0189229 secs]
, 0.2421987 secs]
*329872.313: [post compact, 29.4723376 secs]*
h2. [PSYoungGen: 716793K->0K(716800K)] [ParOldGen: 798717K->335346K(798720K)] 1515510K->335346K(1515520K) [PSPermGen: 77426K->77422K(98304K)], 39.3998183 secs] [Times: user=3.53 sys=0.16, real=39.39 secs]
Heap after GC invocations=28728 (full 188):
PSYoungGen total 716800K, used 0K [0xb6bf0000, 0xe8bf0000, 0xe8bf0000)
eden space 614400K, 0% used [0xb6bf0000,0xb6bf0000,0xdc3f0000)
from space 102400K, 0% used [0xe27f0000,0xe27f0000,0xe8bf0000)
to space 102400K, 0% used [0xdc3f0000,0xdc3f0000,0xe27f0000)
ParOldGen total 798720K, used 335346K [0x85ff0000, 0xb6bf0000, 0xb6bf0000)
object space 798720K, 41% used [0x85ff0000,0x9a76c838,0xb6bf0000)
PSPermGen total 98304K, used 77422K [0x7fff0000, 0x85ff0000, 0x85ff0000)
object space 98304K, 78% used [0x7fff0000,0x84b8ba08,0x85ff0000)
}
h2. Total time for which application threads were stopped: 43.3590538 seconds
Total time for which application threads were stopped: 0.0180008 seconds

Legend

  • Correct Answers - 10 points
  • Helpful Answers - 5 points