Strange long pauses between 2 Young GCs

Thu Mar 25 00:54:53 PDT 2010

Hi Ramki,

Thanks for your answers. I misunderstood these messages and I thought that GC could have been responsible for the JMS messages sent to DeadMessageQueue.
But this is not the case as there was no important pauses (less than 0.2s) between the 2 Young GCs.

> Hmm, that seems strange. What does mpstat/prstat indicate during those times?
They were not running. This is a production server, so I cannot launch them.
This issue happened only yesterday, so I will try to investigate it with the JMS provider logs.

In conclusion, there was no hotspot/GC issue.

Thanks again.

--
David

On Wed, 24 Mar 2010 18:13:04 +0100, Y. Srinivas Ramakrishna <Y.S.Ramakrishna at sun.com> wrote:

> David Tavoularis wrote:
>> 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
>
> Those are not pauses of the application. Rather those are the durations for
> which the application runs (is not paused). The pauses are the short ones
> in between those. They are likely related to bias lock revocations or
> deoptimization or something. If you use -XX:+PrintSafepointStatistics (especially
> with a latest hs18 jvm) you would know what those very short stoppages
> in between are for.
>
>> 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".
>
> Hmm, that seems strange. What does mpstat/prstat indicate during those times?
> You might want to run this on Sun Studio Collector (perf anakyzer) and
> see if it shows up the issues? If this is on a production system, and
> this occurs at some time that lasts a while, you may be able to collect the
> performance data during that period of time.
>
> But first a simple mpstat/prstat data may be useful before a SS collector experiment.
>
> -- ramki
>
>>
>> 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-24T*05: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-24T*05: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
>>
>>
>>
>> ------------------------------------------------------------------------
>>
>> _______________________________________________
>> hotspot-gc-use mailing list
>> hotspot-gc-use at openjdk.java.net
>> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>