Intermittent long ParNew times

[Y. S. Ramakrishna]

That long scavenge shows unusually high system time too.
Did you make sure there was no periodic (or aperiodic) other
activity on the system that may be causing part of the JVM
heap to get paged out? I'd check vmstat for starters.

(Also, FWIW, and just to rule it out as a factor, check the
promotion volume for these scavenges and see if it shows anything.)

And while I am throwing out conjectures, does this happen only
during the initial start-up phase when the old heap occupancy
is growing? If so, see if -XX:+AlwaysPreTouch makes any difference
(also mentioned recently by Brian Williams in a separate thread here).

-- ramki

On 11/17/10 14:44, Erwin wrote:
> Hello,
> 
> When we’re running our load test for about 1 hour, GC seems to be fine most of the times. However, there are times where the ParNew would go as high as 25 seconds. See below sample where it was 10 seconds.
> {Heap before GC invocations=11 (full 0):
>  par new generation   total 921600K, used 880508K [0xfffffffdd0000000, 0xfffffffe0e800000, 0xfffffffe0e800000)
>   eden space 819200K, 100% used [0xfffffffdd0000000, 0xfffffffe02000000, 0xfffffffe02000000)
>   from space 102400K,  59% used [0xfffffffe08400000, 0xfffffffe0bfdf1c8, 0xfffffffe0e800000)
>   to   space 102400K,   0% used [0xfffffffe02000000, 0xfffffffe02000000, 0xfffffffe08400000)
>  concurrent mark-sweep generation total 3170304K, used 685978K [0xfffffffe0e800000, 0xfffffffed0000000, 0xffffffff48000000)
>  concurrent-mark-sweep perm gen total 524288K, used 221175K [0xffffffff48000000, 0xffffffff68000000, 0xffffffff73800000)
> 37814.384: [GC 37814.384: [ParNew: 880508K->55794K(921600K), 0.1246958 secs] 1566486K->741772K(4091904K), 0.1249910 secs] [Times: user=0.37 sys=0.07, real=0.13 secs] 
> Heap after GC invocations=12 (full 0):
>  par new generation   total 921600K, used 55794K [0xfffffffdd0000000, 0xfffffffe0e800000, 0xfffffffe0e800000)
>   eden space 819200K,   0% used [0xfffffffdd0000000, 0xfffffffdd0000000, 0xfffffffe02000000)
>   from space 102400K,  54% used [0xfffffffe02000000, 0xfffffffe0567c880, 0xfffffffe08400000)
>   to   space 102400K,   0% used [0xfffffffe08400000, 0xfffffffe08400000, 0xfffffffe0e800000)
>  concurrent mark-sweep generation total 3170304K, used 685978K [0xfffffffe0e800000, 0xfffffffed0000000, 0xffffffff48000000)
>  concurrent-mark-sweep perm gen total 524288K, used 221175K [0xffffffff48000000, 0xffffffff68000000, 0xffffffff73800000)
> 
> {Heap before GC invocations=12 (full 0):
>  par new generation   total 921600K, used 874994K [0xfffffffdd0000000, 0xfffffffe0e800000, 0xfffffffe0e800000)
>   eden space 819200K, 100% used [0xfffffffdd0000000, 0xfffffffe02000000, 0xfffffffe02000000)
>   from space 102400K,  54% used [0xfffffffe02000000, 0xfffffffe0567c880, 0xfffffffe08400000)
>   to   space 102400K,   0% used [0xfffffffe08400000, 0xfffffffe08400000, 0xfffffffe0e800000)
>  concurrent mark-sweep generation total 3170304K, used 685978K [0xfffffffe0e800000, 0xfffffffed0000000, 0xffffffff48000000)
>  concurrent-mark-sweep perm gen total 524288K, used 221531K [0xffffffff48000000, 0xffffffff68000000, 0xffffffff73800000)
> 39088.225: [GC 39088.225: [ParNew: 874994K->102400K(921600K), 10.0339890 secs] 1560972K->821401K(4091904K), 10.0346984 secs] [Times: user=5.40 sys=31.71, real=10.04 secs] 
> Heap after GC invocations=13 (full 0):
>  par new generation   total 921600K, used 102400K [0xfffffffdd0000000, 0xfffffffe0e800000, 0xfffffffe0e800000)
>   eden space 819200K,   0% used [0xfffffffdd0000000, 0xfffffffdd0000000, 0xfffffffe02000000)
>   from space 102400K, 100% used [0xfffffffe08400000, 0xfffffffe0e800000, 0xfffffffe0e800000)
>   to   space 102400K,   0% used [0xfffffffe02000000, 0xfffffffe02000000, 0xfffffffe08400000)
>  concurrent mark-sweep generation total 3170304K, used 719001K [0xfffffffe0e800000, 0xfffffffed0000000, 0xffffffff48000000)
>  concurrent-mark-sweep perm gen total 524288K, used 221531K [0xffffffff48000000, 0xffffffff68000000, 0xffffffff73800000)
> 
> We’re on 64bit platform of WAS NDE 7.0.0.9 on Solaris10 platform. Our JVM args are:
> -server -Xmn1000m -XX:PermSize=512m -XX:+UseConcMarkSweepGC -XX:+HeapDumpOnOutOfMemoryError -DUseSunHttpHandler=true -Djavax.xml.soap.MessageFactory=weblogic.xml.saaj.MessageFactoryImpl -Doracle.jdbc.V8Compatible=true -XX:CMSInitiatingOccupancyFraction=70 -XX:+CMSClassUnloadingEnabled -verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -XX:-TraceClassUnloading -XX:+PrintGCApplicationStoppedTime -XX:+PrintHeapAtGC  -XX:MaxPermSize=694m -XX:+DisableExplicitGC -XX:+CMSParallelRemarkEnabled
> 
> Any help would be appreciated.
> Erwin
> 
> 
> 
>       
> _______________________________________________
> hotspot-gc-use mailing list
> hotspot-gc-use at openjdk.java.net
> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use