Strange long pauses between 2 Young GCs

[David Tavoularis]

Hi,

In my application, I noticed very strange pauses (15s+19s+25s+30s+59s+28s = 2min56) between 2 Young GCs (on Java6u13 64-bits / Solaris 10) with ParallelGC+ParallelOldGC collectors.
Has anyone encountered this kind of pauses and has an explanation (see extract of GC logs at the end of the mail) ?

My issue is that some JMS messages have been sent to DeadMessageQueue because the process was not "responding".

I do not think that my server was swapping (30GB free RAM) and usually, a Full GC takes between 2s and 10s (WallTime="real"), between 3s and 60s (CpuTime="user")

Thanks in advance

-- 
David

JVM options :
    -server
    -Xms13000m
    -Xmx13000m
    -XX:+UseParallelGC
    -XX:+AggressiveHeap
    -XX:GCHeapFreeLimit=5
    -XX:+PrintGCDetails
    -XX:+PrintGCTimeStamps
    -XX:+PrintHeapAtGC
    -XX:+PrintTenuringDistribution
    -XX:+PrintGCApplicationStoppedTime
    -XX:+PrintGCApplicationConcurrentTime
    -XX:+PrintGCDateStamps
    -Xloggc:/path/to/gc/logs
    -XX:+HeapDumpOnOutOfMemoryError
    -XX:HeapDumpPath=/path/to/heap/dumps
    -XX:NewSize=2048m
    -XX:MaxNewSize=2048m
    -XX:+UseParallelOldGC
    -XX:MaxPermSize=256m

2010-03-24T05:54:23.467+0100: 47058.915: [GC
Desired survivor size 181665792 bytes, new threshold 1 (max 15)
[PSYoungGen: 1792448K->16384K(1763776K)] 2472857K->702761K(12978624K), 0.1969989 secs] [Times: user=0.29 sys=0.07, real=0.20 secs]
Heap after GC invocations=3606 (full 0):
PSYoungGen total 1763776K, used 16384K [0xfffffffeec800000, 0xffffffff6c800000, 0xffffffff6c800000)
eden space 1747392K, 0% used [0xfffffffeec800000,0xfffffffeec800000,0xffffffff57270000)
 from space 16384K, 100% used [0xffffffff57270000,0xffffffff58270000,0xffffffff58270000)
to space 177408K, 0% used [0xffffffff61ac0000,0xffffffff61ac0000,0xffffffff6c800000)
ParOldGen total 11214848K, used 686377K [0xfffffffc40000000, 0xfffffffeec800000, 0xfffffffeec800000)
object space 11214848K, 6% used [0xfffffffc40000000,0xfffffffc69e4a480,0xfffffffeec800000)
PSPermGen total 73728K, used 56019K [0xfffffffc30000000, 0xfffffffc34800000, 0xfffffffc40000000)
object space 73728K, 75% used [0xfffffffc30000000,0xfffffffc336b4c30,0xfffffffc34800000)
}
Total time for which application threads were stopped: 0.2054411 seconds
Application time: 2.1629642 seconds
Total time for which application threads were stopped: 0.0089378 seconds
Application time: 0.0000853 seconds
Total time for which application threads were stopped: 0.0012767 seconds
Application time: 0.0001092 seconds
Total time for which application threads were stopped: 0.0010313 seconds
Application time: 0.0000721 seconds
Total time for which application threads were stopped: 0.0010318 seconds
Application time: 0.3016250 seconds
Total time for which application threads were stopped: 0.0087502 seconds
Application time: 15.0009372 seconds
Total time for which application threads were stopped: 0.0074670 seconds
Application time: 18.9151668 seconds
Total time for which application threads were stopped: 0.0230399 seconds
Application time: 0.0001326 seconds
Total time for which application threads were stopped: 0.0012976 seconds
Application time: 0.0000646 seconds
Total time for which application threads were stopped: 0.0010412 seconds
Application time: 25.4543868 seconds
Total time for which application threads were stopped: 0.0087742 seconds
Application time: 0.0001073 seconds
Total time for which application threads were stopped: 0.0013600 seconds
Application time: 0.0001158 seconds
Total time for which application threads were stopped: 0.0049206 seconds
Application time: 0.0025729 seconds
Total time for which application threads were stopped: 0.0012530 seconds
Application time: 0.0001156 seconds
Total time for which application threads were stopped: 0.0009663 seconds
Application time: 0.0007467 seconds
Total time for which application threads were stopped: 0.0010364 seconds
Application time: 0.0001326 seconds
Total time for which application threads were stopped: 0.0009763 seconds
Application time: 29.9838922 seconds
Total time for which application threads were stopped: 0.0075727 seconds
Application time: 4.4557342 seconds
Total time for which application threads were stopped: 0.0187998 seconds
Application time: 0.0000837 seconds
Total time for which application threads were stopped: 0.0012345 seconds
Application time: 0.0000634 seconds
Total time for which application threads were stopped: 0.0010140 seconds
Application time: 59.1763410 seconds
Total time for which application threads were stopped: 0.0198018 seconds
Application time: 0.0001009 seconds
Total time for which application threads were stopped: 0.0011658 seconds
Application time: 0.0000614 seconds
Total time for which application threads were stopped: 0.0010269 seconds
Application time: 27.9028562 seconds
Total time for which application threads were stopped: 0.0080420 seconds
Application time: 0.0001698 seconds
Total time for which application threads were stopped: 0.0012317 seconds
Application time: 0.1080374 seconds
Total time for which application threads were stopped: 0.0073232 seconds
Application time: 0.1215694 seconds
Total time for which application threads were stopped: 0.0078813 seconds
Application time: 0.0000801 seconds
Total time for which application threads were stopped: 0.0014642 seconds
Application time: 0.0001074 seconds
Total time for which application threads were stopped: 0.0012944 seconds
Application time: 0.0000676 seconds
Total time for which application threads were stopped: 0.0012189 seconds
Application time: 0.0192653 seconds
Total time for which application threads were stopped: 0.0021554 seconds
Application time: 0.0001444 seconds
Total time for which application threads were stopped: 0.0013011 seconds
Application time: 0.2620606 seconds
Total time for which application threads were stopped: 0.0034052 seconds
Application time: 0.8994294 seconds
{Heap before GC invocations=3607 (full 0):
PSYoungGen total 1763776K, used 1763776K [0xfffffffeec800000, 0xffffffff6c800000, 0xffffffff6c800000)
eden space 1747392K, 100% used [0xfffffffeec800000,0xffffffff57270000,0xffffffff57270000)
 from space 16384K, 100% used [0xffffffff57270000,0xffffffff58270000,0xffffffff58270000)
to space 177408K, 0% used [0xffffffff61ac0000,0xffffffff61ac0000,0xffffffff6c800000)
ParOldGen total 11214848K, used 686377K [0xfffffffc40000000, 0xfffffffeec800000, 0xfffffffeec800000)
object space 11214848K, 6% used [0xfffffffc40000000,0xfffffffc69e4a480,0xfffffffeec800000)
PSPermGen total 73728K, used 56020K [0xfffffffc30000000, 0xfffffffc34800000, 0xfffffffc40000000)
object space 73728K, 75% used [0xfffffffc30000000,0xfffffffc336b5330,0xfffffffc34800000)
2010-03-24T05:57:29.620+0100: 47245.068: [GC


$/usr/jdk/instances/jdk1.6.0/jre/bin/sparcv9/java -version
java version "1.6.0_13"
Java(TM) SE Runtime Environment (build 1.6.0_13-b03)
Java HotSpot(TM) 64-Bit Server VM (build 11.3-b02, mixed mode)

$ uname -a
SunOS XXX 5.10 Generic_120011-14 sun4u sparc SUNW,Sun-Fire
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20100324/963b3303/attachment.html