Strange long ParNew collections
Kaj Nygren
kaj.nygren at mag.se
Wed May 6 05:06:13 PDT 2009
Hi,
We are having problems with occational long ParNew pauses in our
application running on a Jboss server. The server runs well for most of
the time but sometimes we get ParNew collections that can take up to 120
seconds. Most of the time we have several consecutive slow collections,
which are more or less killing the server under high load.
We are using JDK 1.5.0_16 on Windows Server 2003, and are using ParNew +
Concurrent CMS.
Our GC configuration is:
wrapper.java.additional.1=-Dprogram.name=run.bat
wrapper.java.additional.2=-server
wrapper.java.additional.3=-Xms19000m
wrapper.java.additional.4=-Xmx19000m
wrapper.java.additional.5="-XX:NewSize=1000m"
wrapper.java.additional.6="-XX:MaxNewSize=1000m"
wrapper.java.additional.7="-XX:MaxPermSize=256m"
wrapper.java.additional.8="-XX:PermSize=256m"
wrapper.java.additional.11="-Xloggc:c:\mygclog.gc"
wrapper.java.additional.12="-XX:+UseConcMarkSweepGC"
wrapper.java.additional.13="-XX:+PrintGCDetails"
wrapper.java.additional.14="-XX:-PrintTenuringDistribution"
wrapper.java.additional.15="-XX:+PrintHeapAtGC"
wrapper.java.additional.16="-XX:+DisableExplicitGC"
wrapper.java.additional.17="-XX:+PrintGCTimeStamps"
wrapper.java.additional.18="-XX:CMSInitiatingOccupancyFraction=50"
wrapper.java.additional.19="-XX:+CMSIncrementalMode"
wrapper.java.additional.20="-XX:+CMSIncrementalPacing"
wrapper.java.additional.21="-verbose:gc"
Usually ParNew is quick as can be seen here:
614276,653: [ParNew: 935058K->0K(1023040K), 0,0624699 secs]
12383872K->11459948K(19455040K) icms_dc=22 Heap after gc invocations=57822:
par new generation total 1023040K, used 0K [0x000000007fff0000,
0x00000000be7f0000, 0x00000000be7f0000)
eden space 1022080K, 0% used [0x000000007fff0000,
0x000000007fff0000, 0x00000000be610000)
from space 960K, 0% used [0x00000000be700000, 0x00000000be700000,
0x00000000be7f0000)
to space 960K, 0% used [0x00000000be610000, 0x00000000be610000,
0x00000000be700000)
concurrent mark-sweep generation total 18432000K, used 11459948K
[0x00000000be7f0000, 0x00000005237f0000, 0x00000005237f0000)
concurrent-mark-sweep perm gen total 262144K, used 112069K
[0x00000005237f0000, 0x00000005337f0000, 0x00000005337f0000)
}
, 0,0628860 secs]
But suddenly it becomes really slow:
620659,717: [ParNew: 1022080K->0K(1023040K), 1,3313817 secs]
12688913K->11692925K(19455040K) icms_dc=10 Heap after gc invocations=58587:
par new generation total 1023040K, used 0K [0x000000007fff0000,
0x00000000be7f0000, 0x00000000be7f0000)
eden space 1022080K, 0% used [0x000000007fff0000,
0x000000007fff0000, 0x00000000be610000)
from space 960K, 0% used [0x00000000be610000, 0x00000000be610000,
0x00000000be700000)
to space 960K, 0% used [0x00000000be700000, 0x00000000be700000,
0x00000000be7f0000)
concurrent mark-sweep generation total 18432000K, used 11692925K
[0x00000000be7f0000, 0x00000005237f0000, 0x00000005237f0000)
concurrent-mark-sweep perm gen total 262144K, used 112098K
[0x00000005237f0000, 0x00000005337f0000, 0x00000005337f0000)
}
, 1,3319554 secs]
620663,221: [GC {Heap before gc invocations=58587:
par new generation total 1023040K, used 1022080K [0x000000007fff0000,
0x00000000be7f0000, 0x00000000be7f0000)
eden space 1022080K, 100% used [0x000000007fff0000,
0x00000000be610000, 0x00000000be610000)
from space 960K, 0% used [0x00000000be610000, 0x00000000be610000,
0x00000000be700000)
to space 960K, 0% used [0x00000000be700000, 0x00000000be700000,
0x00000000be7f0000)
concurrent mark-sweep generation total 18432000K, used 11692925K
[0x00000000be7f0000, 0x00000005237f0000, 0x00000005237f0000)
concurrent-mark-sweep perm gen total 262144K, used 112106K
[0x00000005237f0000, 0x00000005337f0000, 0x00000005337f0000)
620663,222: [ParNew: 1022080K->0K(1023040K), 10,2909893 secs]
12715005K->11936864K(19455040K) icms_dc=10 Heap after gc invocations=58588:
par new generation total 1023040K, used 0K [0x000000007fff0000,
0x00000000be7f0000, 0x00000000be7f0000)
eden space 1022080K, 0% used [0x000000007fff0000,
0x000000007fff0000, 0x00000000be610000)
from space 960K, 0% used [0x00000000be700000, 0x00000000be700000,
0x00000000be7f0000)
to space 960K, 0% used [0x00000000be610000, 0x00000000be610000,
0x00000000be700000)
concurrent mark-sweep generation total 18432000K, used 11936864K
[0x00000000be7f0000, 0x00000005237f0000, 0x00000005237f0000)
concurrent-mark-sweep perm gen total 262144K, used 112106K
[0x00000005237f0000, 0x00000005337f0000, 0x00000005337f0000)
}
, 10,2915548 secs]
620676,392: [GC {Heap before gc invocations=58588:
par new generation total 1023040K, used 1022080K [0x000000007fff0000,
0x00000000be7f0000, 0x00000000be7f0000)
eden space 1022080K, 100% used [0x000000007fff0000,
0x00000000be610000, 0x00000000be610000)
from space 960K, 0% used [0x00000000be700000, 0x00000000be700000,
0x00000000be7f0000)
to space 960K, 0% used [0x00000000be610000, 0x00000000be610000,
0x00000000be700000)
concurrent mark-sweep generation total 18432000K, used 11936864K
[0x00000000be7f0000, 0x00000005237f0000, 0x00000005237f0000)
concurrent-mark-sweep perm gen total 262144K, used 112106K
[0x00000005237f0000, 0x00000005337f0000, 0x00000005337f0000)
620676,392: [ParNew: 1022080K->0K(1023040K), 3,8905950 secs]
12958944K->12020225K(19455040K) icms_dc=10 Heap after gc invocations=58589:
par new generation total 1023040K, used 0K [0x000000007fff0000,
0x00000000be7f0000, 0x00000000be7f0000)
eden space 1022080K, 0% used [0x000000007fff0000,
0x000000007fff0000, 0x00000000be610000)
from space 960K, 0% used [0x00000000be610000, 0x00000000be610000,
0x00000000be700000)
to space 960K, 0% used [0x00000000be700000, 0x00000000be700000,
0x00000000be7f0000)
concurrent mark-sweep generation total 18432000K, used 12020225K
[0x00000000be7f0000, 0x00000005237f0000, 0x00000005237f0000)
concurrent-mark-sweep perm gen total 262144K, used 112106K
[0x00000005237f0000, 0x00000005337f0000, 0x00000005337f0000)
}
, 3,8911113 secs]
620682,667: [GC {Heap before gc invocations=58589:
par new generation total 1023040K, used 1022080K [0x000000007fff0000,
0x00000000be7f0000, 0x00000000be7f0000)
eden space 1022080K, 100% used [0x000000007fff0000,
0x00000000be610000, 0x00000000be610000)
from space 960K, 0% used [0x00000000be610000, 0x00000000be610000,
0x00000000be700000)
to space 960K, 0% used [0x00000000be700000, 0x00000000be700000,
0x00000000be7f0000)
concurrent mark-sweep generation total 18432000K, used 12020225K
[0x00000000be7f0000, 0x00000005237f0000, 0x00000005237f0000)
concurrent-mark-sweep perm gen total 262144K, used 112112K
[0x00000005237f0000, 0x00000005337f0000, 0x00000005337f0000)
620682,668: [ParNew: 1022080K->0K(1023040K), 9,4186088 secs]
13042305K->12214571K(19455040K) icms_dc=10 Heap after gc invocations=58590:
par new generation total 1023040K, used 0K [0x000000007fff0000,
0x00000000be7f0000, 0x00000000be7f0000)
eden space 1022080K, 0% used [0x000000007fff0000,
0x000000007fff0000, 0x00000000be610000)
from space 960K, 0% used [0x00000000be700000, 0x00000000be700000,
0x00000000be7f0000)
to space 960K, 0% used [0x00000000be610000, 0x00000000be610000,
0x00000000be700000)
concurrent mark-sweep generation total 18432000K, used 12214571K
[0x00000000be7f0000, 0x00000005237f0000, 0x00000005237f0000)
concurrent-mark-sweep perm gen total 262144K, used 112112K
[0x00000005237f0000, 0x00000005337f0000, 0x00000005337f0000)
}
, 9,4191551 secs]
We also have problems with occational promotion failed, which I assume
is due to fragmentation.
I have attatched a longer log, which shows this behaviour and ends with
a promotion failed.
Does anybody have a glue as to what is going wrong, and how we can
change our gc configuration to reduce the problems?
Any help is greatly appreciated!
Regards
Kaj Nygren
kaj at mag.se
-------------- next part --------------
A non-text attachment was scrubbed...
Name: strangegclog.zip
Type: application/x-zip-compressed
Size: 268061 bytes
Desc: not available
Url : http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20090506/2c27e6e1/attachment.bin
More information about the hotspot-gc-use
mailing list