Strange long ParNew collections
Jon Masamitsu
Jon.Masamitsu at Sun.COM
Wed May 6 15:06:52 PDT 2009
Kaj,
I don't see anything in the logs that points to
a specific problem.
Why are you using CMSIncrementalMode?
By default the CMS collector promotes all
objects that survive 1 minor collection
(into the tenured generation). You might
find it useful to use larger survivor
spaces and a larger tenuring threshold.
See
http://blogs.sun.com/jonthecollector/entry/the_fault_with_defaults
for some suggestions of values to try. You might also benefit
from a larger young. Have you tried larger values? 2g? Or maybe
even 4g
Jon
On 05/06/09 05:06, Kaj Nygren wrote:
> 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
>
>
> ------------------------------------------------------------------------
>
> _______________________________________________
> hotspot-gc-use mailing list
> hotspot-gc-use at openjdk.java.net
> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
More information about the hotspot-gc-use
mailing list