Repeated ParNews when Young Gen is Empty?

[Jon Masamitsu]

What is the ParNew behavior like after the "concurrent mode failure"?

Jon

On 7/1/2013 1:44 PM, Andrew Colombi wrote:
> Hi,
>
> I've been investigating some big, slow stop the world GCs, and came upon this curious pattern of rapid, repeated ParNews on an almost empty Young Gen.  We're using - XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+CMSParallelRemarkEnabled.  Here is the log:
>
> 49355.202: [GC 49355.202: [ParNew: 12499734K->276251K(13824000K), 0.1382160 secs] 45603872K->33380389K(75010048K), 0.1392380 secs] [Times: user=1.89 sys=0.02, real=0.14 secs]
> 49370.274: [GC [1 CMS-initial-mark: 48126459K(61186048K)] 56007160K(75010048K), 8.2281560 secs] [Times: user=8.22 sys=0.00, real=8.23 secs]
> 49378.503: [CMS-concurrent-mark-start]
> 49378.517: [GC 49378.517: [ParNew: 7894655K->332202K(13824000K), 0.1304950 secs] 56021115K->48458661K(75010048K), 0.1314370 secs] [Times: user=2.00 sys=0.01, real=0.13 secs]
> 49378.735: [GC 49378.736: [ParNew: 669513K->342976K(13824000K), 0.0849560 secs] 48795972K->48469435K(75010048K), 0.0859460 secs] [Times: user=1.84 sys=0.03, real=0.09 secs]
> 49378.850: [GC 49378.851: [ParNew: 514163K->312532K(13824000K), 0.1114820 secs] 48640622K->48471080K(75010048K), 0.1122890 secs] [Times: user=2.21 sys=0.02, real=0.12 secs]
> 49379.000: [GC 49379.000: [ParNew: 529899K->247436K(13824000K), 0.1099240 secs]49379.110: [CMS2013-06-26T17:14:08.834-0400: 49395.671: [CMS-concurrent-mark: 16.629/17.168 secs] [Times: user=104.18 sys=1.86, real=17.16 secs]
>   (concurrent mode failure): 48227750K->31607742K(61186048K), 129.9298170 secs] 48688447K->31607742K(75010048K), [CMS Perm : 150231K->147875K(250384K)], 130.0405700 secs] [Times: user=209.80 sys=1.83, real=130.02 secs]
>
> By my read, it starts with a typical ParNew that cleans about 12GB (of a 13GB young gen).  Then CMS begins, and then the next three ParNews start feeling strange.  First it does a ParNew at 49378.517 that hits at only 7.8GB occupied of 13GB available. Then at  49378.736 and 49378.851 it does two ParNews when young gen only has 660MB and 514MB occupied, respectively.  Then really bad stuff happens: we hit a concurrent mode failure.  This stops the world for 2 minutes and clears about 17GB of data, almost all of which was in the CMS tenured gen.  Notice there are still 12GB free in CMS!
>
> My question is, Why would it do three ParNews, only 300ms apart from each other, when the young gen is essentially empty?  Here are three hypotheses that I have:
> * Is the application trying to allocate something giant, e.g. a 1 billion element double[]? Is there a way I can test for this, i.e. some JVM level logging that would indicate very large objects being allocated.
> * Is there an explicit System.gc() in 3rd party code? (Our code is clean.) We're going to disable explicit GC in our next maintenance period.  But this theory doesn't explain concurrent mode failure.
> * Maybe a third explanation is fragmentation? Is ParNew compacted on every collection?  I've read that CMS tenured gen can suffer from fragmentation.
>
> Some details of the installation.  Here is the Java version.
>
> java version "1.7.0_21"
> Java(TM) SE Runtime Environment (build 1.7.0_21-b11)
> Java HotSpot(TM) 64-Bit Server VM (build 23.21-b01, mixed mode)
>
> Here are all the GC relevant parameters we are setting:
>
> -Dsun.rmi.dgc.client.gcInterval=3600000
> -Dsun.rmi.dgc.server.gcInterval=3600000
> -Xms74752m
> -Xmx74752m
> -Xmn15000m
> -XX:PermSize=192m
> -XX:MaxPermSize=1500m
> -XX:CMSInitiatingOccupancyFraction=60
> -XX:+UseConcMarkSweepGC
> -XX:+UseParNewGC
> -XX:+CMSParallelRemarkEnabled
> -XX:+ExplicitGCInvokesConcurrent
> -verbose:gc
> -XX:+PrintGCDetails
> -XX:+PrintGCTimeStamps
> -XX:+PrintGCDateStamps // I removed this from the output above to make it slightly more concise
> -Xloggc:gc.log
>
> Any thoughts or recommendations would be welcome,
> -Andrew
>
>
>
> _______________________________________________
> 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: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20130719/a51471ce/attachment.html