Strange long ParNew collections

Wed May 6 21:56:28 UTC 2009

This may or may not be a cause of the sudden spikes in
ParNew collection, but I'd suggest using the survivor
spaces to age objects for at least a few collections
before promoting to the old gen. This reduces pressure
on the old gen allocation (during scavenge) improving
scavenges and on CMS collection as well.

I'd suggest trying -XX:SurvivorRatio=8 -XX:MaxTenuringThreshold=4
to start off with and iterate based on data from -XX:+PrintTenuringDistribution.

It is possible that the promotion of very short-lived objects fragments
the old gen and causes old gen allocation (for promotion) to slow down.
It can also cause lots of mutation in the old gen and adversely affect
card-scanning times further slowing down scavenges.

-- ramki

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

_______________________________________________
hotspot-gc-use mailing list
hotspot-gc-use at openjdk.java.net
http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use