Periodic long minor GC pauses

Tue Apr 26 18:29:42 UTC 2011

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?

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]

On Tue, Apr 26, 2011 at 2:17 PM, Y. S. Ramakrishna <
y.s.ramakrishna at oracle.com> wrote:

> 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
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20110426/4acfabde/attachment.htm>
-------------- next part --------------
_______________________________________________
hotspot-gc-use mailing list
hotspot-gc-use at openjdk.java.net
http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use