Below is an example from a Remark. Of the total 1.3 seconds of elapsed time, 1.2 seconds is found between the first two timestamps. However, I'm not savvy enough to know whether this is the same problem or simply the result of a long scavenge that occurs as part of the Remark. Is there any way to tell?<br>
<br>2011-04-25T14:38:40.215-0400: 9466.139: [GC[YG occupancy: 712500 K (943744 K)]9467.353: [Rescan (parallel) , 0.0106370 secs]9467.374: [weak refs processing, 0.0159250 secs]9467.390: [class unloading, 0.0180420 secs]9467.408: [scrub symbol & string tables, 0.0458500 secs] [1 CMS-remark: 12520949K(24117248K)] 13233450K(25060992K), 0.1052950 secs] [Times: user=0.13 sys=0.01, real=1.32 secs]<br>
<br><br><div class="gmail_quote">On Tue, Apr 26, 2011 at 2:17 PM, Y. S. Ramakrishna <span dir="ltr"><<a href="mailto:y.s.ramakrishna@oracle.com">y.s.ramakrishna@oracle.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex;">
I had a quick look and all i could find was the GC prologue<br>
code (although i didn't look all that carefully).<br>
Bascially, GC is invoked, it prints this timestamp,<br>
does a bit of global book-keeping and some initialization,<br>
and then goes over each generation in the heap and<br>
says "i am going to do a collection, do whatever you need<br>
to do before i do the collection", and the generations each do a bit of<br>
book-keeping and any relevant initialization.<br>
<br>
The only thing i can see in the gc prologues other than a bit<br>
of lightweight book-keeping is some reporting code that could<br>
potentially be heavyweight. But you do not have any of those<br>
enabled in your option set, so there should not be anything<br>
obviously heavyweight going on.<br>
<br>
I'd suggest filing a bug under the category of jvm/hotspot/garbage_collector<br>
so someone in support can work with you to get this diagnosed...<br>
<br>
Three questions when you file the bug:<br>
(1) have you seen this start happening recently? (version?)<br>
(2) can you check if the longer pauses are "random" or do<br>
they always happen "during" CMS concurrent cycles or<br>
always outside of such cycles?<br>
(3) test set-up.<br>
<br>
-- ramki<div><div></div><div class="h5"><br>
<br>
On 04/26/11 10:45, Y. S. Ramakrishna wrote:<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
The pause is definitely in the beginning, before GC collection code<br>
itself runs; witness the timestamps:-<br>
<br>
2011-04-26T12:50:45.251-0400: 2120.686: [GC 2123.075: [ParNew: 943744K->79296K(943744K), 0.0559560 secs] 4989811K->4187520K(25060992K), 0.0563970 secs] [Times: user=0.31 sys=0.09, real=2.45 secs]<br>
<br>
The first timestamp is 2120.686 and the next one is 2123.075, so we have<br>
about 2.389 s between those two. If you add to that the GC time of 0.056 s,<br>
you get 2.445 which is close enough to the 2.45 s reported.<br>
<br>
So we need to figure out what happens in the JVM between those two<br>
time-stamps and we can at least bound the culprit.<br>
<br>
-- ramki<br>
<br>
On 04/26/11 10:36, Shane Cox wrote:<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
Periodically, our Java app on Linux experiences a long Minor GC pause that cannot be accounted for by the GC time in the log file. Instead, the pause is captured as "real" (wall clock) time and is observable in our application logs. An example is below. The GC completed in 56ms, but the application was paused for 2.45 seconds.<br>
<br>
2011-04-26T12:50:41.722-0400: 2117.157: [GC 2117.157: [ParNew: 943439K->104832K(943744K), 0.0481790 secs] 4909998K->4086751K(25060992K), 0.0485110 secs] [Times: user=0.34 sys=0.03, real=0.04 secs]<br>
2011-04-26T12:50:43.882-0400: 2119.317: [GC 2119.317: [ParNew: 942852K->104832K(943744K), 0.0738000 secs] 4924772K->4150899K(25060992K), 0.0740980 secs] [Times: user=0.45 sys=0.12, real=0.07 secs]<br>
2011-04-26T12:50:45.251-0400: 2120.686: [GC 2123.075: [ParNew: 943744K->79296K(943744K), 0.0559560 secs] 4989811K->4187520K(25060992K), 0.0563970 secs] [Times: user=0.31 sys=0.09, *real=2.45 secs]*<br>
2011-04-26T12:50:48.493-0400: 2123.928: [GC 2123.928: [ParNew: 918208K->81040K(943744K), 0.0396620 secs] 5026432K->4189265K(25060992K), 0.0400030 secs] [Times: user=0.32 sys=0.00, real=0.04 secs]<br>
2011-04-26T12:50:51.010-0400: 2126.445: [GC 2126.445: [ParNew: 919952K->104832K(943744K), 0.0845070 secs] 5028177K->4268050K(25060992K), 0.0848300 secs] [Times: user=0.52 sys=0.11, real=0.09 secs]<br>
<br>
<br>
Initially I suspected swapping, but according to the free command, 0 bytes of swap are in use.<br>
>free -m<br>
total used free shared buffers cached<br>
Mem: 32168 28118 4050 0 824 12652<br>
-/+ buffers/cache: 14641 17527<br>
Swap: 8191 0 8191<br>
<br>
<br>
Next, I read about a problem relating to mprotect() on Linux that can be worked around with -XX:+UseMember. I tried that, but I still see the same unexplainable pauses.<br>
<br>
<br>
Any suggestions/ideas? We've upgraded to the latest JDK, but no luck.<br>
<br>
Thanks,<br>
Shane<br>
<br>
<br>
java version "1.6.0_25"<br>
Java(TM) SE Runtime Environment (build 1.6.0_25-b06)<br>
Java HotSpot(TM) 64-Bit Server VM (build 20.0-b11, mixed mode)<br>
<br>
<br>
Linux 2.6.18-128.el5 #1 SMP Wed Jan 21 08:45:05 EST 2009 x86_64 x86_64 x86_64 GNU/Linux<br>
<br>
<br>
-verbose:gc -Xms24g -Xmx24g -Xmn1g -Xss256k -XX:PermSize=256m -XX:MaxPermSize=256m -XX:+PrintTenuringDistribution -XX:+UseConcMarkSweepGC -XX:+CMSParallelRemarkEnabled -XX:CMSInitiatingOccupancyFraction=70 -XX:+CMSClassUnloadingEnabled -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -XX:+HeapDumpOnOutOfMemoryError -XX:+UseCompressedStrings -XX:+UseMembar<br>
<br>
<br>
------------------------------------------------------------------------<br>
<br>
_______________________________________________<br>
hotspot-gc-use mailing list<br>
<a href="mailto:hotspot-gc-use@openjdk.java.net" target="_blank">hotspot-gc-use@openjdk.java.net</a><br>
<a href="http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use" target="_blank">http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use</a><br>
</blockquote>
_______________________________________________<br>
hotspot-gc-use mailing list<br>
<a href="mailto:hotspot-gc-use@openjdk.java.net" target="_blank">hotspot-gc-use@openjdk.java.net</a><br>
<a href="http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use" target="_blank">http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use</a><br>
</blockquote>
</div></div></blockquote></div><br>