Periodic long minor GC pauses

[Y. S. Ramakrishna]

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