I had a quick look and all i could find was the GC prologue
code (although i didn't look all that carefully).
Bascially, GC is invoked, it prints this timestamp,
does a bit of global book-keeping and some initialization,
and then goes over each generation in the heap and
says "i am going to do a collection, do whatever you need
to do before i do the collection", and the generations each do a bit of
book-keeping and any relevant initialization.
The only thing i can see in the gc prologues other than a bit
of lightweight book-keeping is some reporting code that could
potentially be heavyweight. But you do not have any of those
enabled in your option set, so there should not be anything
obviously heavyweight going on.
I'd suggest filing a bug under the category of jvm/hotspot/garbage_collector
so someone in support can work with you to get this diagnosed...
Three questions when you file the bug:
(1) have you seen this start happening recently? (version?)
(2) can you check if the longer pauses are "random" or do
they always happen "during" CMS concurrent cycles or
always outside of such cycles?
(3) test set-up.
-- ramki
On 04/26/11 10:45, Y. S. Ramakrishna wrote:
> The pause is definitely in the beginning, before GC collection code
> itself runs; witness the timestamps:-
>
> 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]
>
> The first timestamp is 2120.686 and the next one is 2123.075, so we have
> about 2.389 s between those two. If you add to that the GC time of 0.056 s,
> you get 2.445 which is close enough to the 2.45 s reported.
>
> So we need to figure out what happens in the JVM between those two
> time-stamps and we can at least bound the culprit.
>
> -- ramki
>
> On 04/26/11 10:36, Shane Cox wrote:
>> 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.
>>
>> 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]
>> 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]
>> 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]*
>> 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]
>> 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]
>>
>>
>> Initially I suspected swapping, but according to the free command, 0
>> bytes of swap are in use.
>> >free -m
>> total used free shared buffers cached
>> Mem: 32168 28118 4050 0 824 12652
>> -/+ buffers/cache: 14641 17527
>> Swap: 8191 0 8191
>>
>>
>> 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.
>>
>>
>> Any suggestions/ideas? We've upgraded to the latest JDK, but no luck.
>>
>> Thanks,
>> Shane
>>
>>
>> java version "1.6.0_25"
>> Java(TM) SE Runtime Environment (build 1.6.0_25-b06)
>> Java HotSpot(TM) 64-Bit Server VM (build 20.0-b11, mixed mode)
>>
>>
>> Linux 2.6.18-128.el5 #1 SMP Wed Jan 21 08:45:05 EST 2009 x86_64 x86_64
>> x86_64 GNU/Linux
>>
>>
>> -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
>>
>>
>> ------------------------------------------------------------------------
>>
>> _______________________________________________
>> 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