Full GCs with long pauses
Long delays are being encountered when Full GCs kick in. Here are the statistics relating
to the a sample Full GC, with heap readings from before and after.
[Wed Dec 06 12:06:49 MET 2006] stdout:{Heap before GC invocations=1923:
[Wed Dec 06 12:06:49 MET 2006] stdout: Heap
[Wed Dec 06 12:06:49 MET 2006] stdout:PSYoungGentotal 393344K, used 8322K [0x35400000, 0x50b00000, 0x50b00000)
[Wed Dec 06 12:06:49 MET 2006] stdout:eden space 337152K, 0% used [0x35400000,0x35400000,0x49d40000)
[Wed Dec 06 12:06:49 MET 2006] stdout:from space 56192K, 14% used [0x49d40000,0x4a560ad8,0x4d420000)
[Wed Dec 06 12:06:49 MET 2006] stdout:tospace 56192K, 0% used [0x4d420000,0x4d420000,0x50b00000)
[Wed Dec 06 12:06:49 MET 2006] stdout:PSOldGentotal 1214968K, used 1078564K [0x50b00000, 0x9ad7e000, 0xf54000
00)
[Wed Dec 06 12:06:49 MET 2006] stdout:object space 1214968K, 88% used [0x50b00000,0x92849260,0x9ad7e000)
[Wed Dec 06 12:06:49 MET 2006] stdout:PSPermGentotal 50688K, used 39889K [0xf5400000, 0xf8580000, 0xf9400000)
[Wed Dec 06 12:06:49 MET 2006] stdout:object space 50688K, 78% used [0xf5400000,0xf7af4640,0xf8580000)
[Wed Dec 06 12:12:11 MET 2006] stdout: 67063.273: [Full GC[Unloading class sun.reflect.GeneratedMethodAccessor378]
[Wed Dec 06 12:12:11 MET 2006] stdout: [Unloading class sun.reflect.GeneratedSerializationConstructorAccessor186]
[Wed Dec 06 12:12:11 MET 2006] stdout: [Unloading class sun.reflect.GeneratedConstructorAccessor120]
[Wed Dec 06 12:12:11 MET 2006] stdout: [Unloading class sun.reflect.GeneratedMethodAccessor352]
[Wed Dec 06 12:12:11 MET 2006] stdout: [Unloading class sun.reflect.GeneratedConstructorAccessor168]
[Wed Dec 06 12:12:11 MET 2006] stdout: [Unloading class sun.reflect.GeneratedMethodAccessor351]
[Wed Dec 06 12:12:11 MET 2006] stdout: [Unloading class sun.reflect.GeneratedMethodAccessor66]
[Wed Dec 06 12:12:11 MET 2006] stdout: [Unloading class sun.reflect.GeneratedConstructorAccessor177]
[Wed Dec 06 12:12:11 MET 2006] stdout: [Unloading class sun.reflect.GeneratedConstructorAccessor164]
[Wed Dec 06 12:12:11 MET 2006] stdout: [Unloading class sun.reflect.GeneratedMethodAccessor376]
[Wed Dec 06 12:12:11 MET 2006] stdout: [Unloading class sun.reflect.GeneratedSerializationConstructorAccessor185]
[Wed Dec 06 12:12:11 MET 2006] stdout: [Unloading class sun.reflect.GeneratedConstructorAccessor78]
[Wed Dec 06 12:12:11 MET 2006] stdout: [Unloading class sun.reflect.GeneratedMethodAccessor381]
[Wed Dec 06 12:12:11 MET 2006] stdout: [Unloading class sun.reflect.GeneratedConstructorAccessor180]
[Wed Dec 06 12:12:11 MET 2006] stdout: [Unloading class sun.reflect.GeneratedConstructorAccessor162]
[Wed Dec 06 12:12:11 MET 2006] stdout: [Unloading class sun.reflect.GeneratedMethodAccessor347]
[Wed Dec 06 12:12:11 MET 2006] stdout: [Unloading class sun.reflect.GeneratedSerializationConstructorAccessor183]
[Wed Dec 06 12:12:11 MET 2006] stdout: [Unloading class sun.reflect.GeneratedMethodAccessor382]
[Wed Dec 06 12:12:11 MET 2006] stdout: [Unloading class sun.reflect.GeneratedConstructorAccessor167]
[Wed Dec 06 12:12:11 MET 2006] stdout: [Unloading class sun.reflect.GeneratedMethodAccessor350]
[Wed Dec 06 12:12:11 MET 2006] stdout: [Unloading class sun.reflect.GeneratedConstructorAccessor179]
[Wed Dec 06 12:12:11 MET 2006] stdout: [Unloading class sun.reflect.GeneratedConstructorAccessor181]
[Wed Dec 06 12:12:11 MET 2006] stdout: [Unloading class sun.reflect.GeneratedMethodAccessor349]
[Wed Dec 06 12:12:11 MET 2006] stdout: [Unloading class sun.reflect.GeneratedSerializationConstructorAccessor184]
[Wed Dec 06 12:12:11 MET 2006] stdout: [Unloading class sun.reflect.GeneratedConstructorAccessor174]
[Wed Dec 06 12:12:11 MET 2006] stdout: [Unloading class sun.reflect.GeneratedSerializationConstructorAccessor69]
[Wed Dec 06 12:12:11 MET 2006] stdout: [Unloading class sun.reflect.GeneratedConstructorAccessor173]
[Wed Dec 06 12:12:11 MET 2006] stdout: [Unloading class sun.reflect.GeneratedSerializationConstructorAccessor1]
[Wed Dec 06 12:12:11 MET 2006] stdout: [Unloading class sun.reflect.GeneratedConstructorAccessor76]
[Wed Dec 06 12:12:11 MET 2006] stdout: [Unloading class sun.reflect.GeneratedSerializationConstructorAccessor182]
[Wed Dec 06 12:12:11 MET 2006] stdout: [Unloading class sun.reflect.GeneratedSerializationConstructorAccessor44]
[Wed Dec 06 12:12:11 MET 2006] stdout: [Unloading class sun.reflect.GeneratedConstructorAccessor169]
[Wed Dec 06 12:12:48 MET 2006] stdout:1086887K->1023366K(1608312K), 358.9035143 secs]
[Wed Dec 06 12:12:48 MET 2006] stdout:Heap after GC invocations=1923:
[Wed Dec 06 12:12:48 MET 2006] stdout: Heap
[Wed Dec 06 12:12:48 MET 2006] stdout:PSYoungGentotal 393344K, used 0K [0x35400000, 0x50b00000, 0x50b00000)
[Wed Dec 06 12:12:48 MET 2006] stdout:eden space 337152K, 0% used [0x35400000,0x35400000,0x49d40000)
[Wed Dec 06 12:12:48 MET 2006] stdout:from space 56192K, 0% used [0x49d40000,0x49d40000,0x4d420000)
[Wed Dec 06 12:12:48 MET 2006] stdout:tospace 56192K, 0% used [0x4d420000,0x4d420000,0x50b00000)
[Wed Dec 06 12:12:48 MET 2006] stdout:PSOldGentotal 1214968K, used 1023366K [0x50b00000, 0x9ad7e000, 0xf5400000)
[Wed Dec 06 12:12:48 MET 2006] stdout:object space 1214968K, 84% used [0x50b00000,0x8f261810,0x9ad7e000)
[Wed Dec 06 12:12:48 MET 2006] stdout:PSPermGentotal 49152K, used 39189K [0xf5400000, 0xf8400000, 0xf9400000)
[Wed Dec 06 12:12:48 MET 2006] stdout:object space 49152K, 79% used [0xf5400000,0xf7a456b8,0xf8400000)
[Wed Dec 06 12:12:48 MET 2006] stdout: } Total time for which application threads were stopped: 358.9442028 seconds
The original JVM paramaters were
vmparam -Xms512m# JVM Minimum Heap Size
vmparam -Xmx3072m # JVM Maximum Heap Size.
vmparam -Xmn439m# JVM New Objects Heap Size
vmparam -XX:MaxPermSize=64m# JVM Max Permanent Heap Size
vmparam -Xss256k# Stack size of threads
The system stopages due to Full GC with class unloading, ranged from 5 minutes to 25 minutes.
1)
This was occurring with the default collectors. The Throughput Collectors (Parallel Scavenge Collector)
was then trialled with the following settings
-XX:+UseParallelGC
-XX:-UseAdaptiveSizePolicy
UseAdaptiveSizePolicy was disabled due to Java Bug ID: 6314461
http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6314461
This did not stop the excessive Full GC pauses from occurring.
2)
We then increased the PermSize and MaxPermSize and still use the Parallel GC
for eden collections.
vmparam -XX:PermSize=128m# Added new parameter
vmparam -XX:MaxPermSize=128m # Increased from 64m
Since the longest pauses with Full GC seemed to directly correspond with the amount
of reflected classes being unloaded, the Permanent space was increased, but this had
no effect. Permanent generation only filled up but only to around 80% and did not reduce
following Full GC and unloading of classes.
3)
The Low Pause Collector for young space was then implemented using
-XX:+UseParNewGC
PermSize and MaxPermSize were kept at 128m but obviously the Throughput Collector
parameter was removed.
This did not have the desired effect.
[Thu Dec 14 03:28:11 MET 2006] stdout: : 1819171K->1021636K(1819264K), 691.9769140 secs] 2247043K->1021636K(2255616K) Heap after GC invocations=1226:
[Thu Dec 14 03:28:11 MET 2006] stdout: Total time for which application threads were stopped: 692.2252804 seconds
4)
The Low Pause Collector for Eden and Permanent are now being trialled
using
-XX:+UseParNewGC
-XX:+UseConcMarkSweepGC
To see does Full GC performance improve or can the application continue while
Full GC be in operation.
?
Should the Low Pause Collector for Young and Permanent exhibit the same system
delay as has been encountered with the other collectors, does it point specifically
at a potential code issue.
Or can this outage be linked with the Class unloading that is taking place
occasionally as part of Full GC.
System Info
--
The java version is java version "1.4.2_03"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.4.2_03-b02)
Java HotSpot(TM) Client VM (build 1.4.2_03-b02, mixed mode)
It is not an option to upgrade to a later full version of java.
OS is SunOS 5.8 Generic_108528-26 sun4u sparc SUNW,Sun-Fire-880
8 cpu machine.
Heap Size seems to be adequate and they appears to be no swapping to disk
while Full GC is occurring to indicate lack of memory on the box.
Message was edited by:
shaneorourke
