Consecutive Full GCs but no OOM

[Binoy Dalal]

Thomas,
Thanks for your response.
How did you calculate 4% remaining?
Is there some error in my calculations because the total amount of heap
cleared is 679K which is less than 2%(180879.36K) of the total heap (9043968K)?
Or am I using incorrect parameters while calculating?

Thanks.



On Mon, May 14, 2018 at 11:11 PM Thomas Schatzl <thomas.schatzl at oracle.com>
wrote:

> Hi,
>
> On Thu, 2018-05-10 at 14:39 +0000, Binoy Dalal wrote:
> > Hi,
> > I'm troubleshooting a Java web application which runs fine for a
> > while after which the heap suddenly spikes up to 100% and this
> > results in consecutive Full GCs with almost no old gen being cleared
> > out. This however does not result in an OOM with the
> > usual java.lang.OutOfMemoryError: GC overhead limit exceeded message.
> > How could this be?
> > Here are 6 Full GC entries:
> >
> > gc_20180423_1443.log.11.current:37491:2018-05-01T09:10:52.156+0000:
> > 671212.664: [Full GC (Allocation Failure) 2018-05-
> > 01T09:10:52.156+0000: 671212.664: [CMS: 7077887K->7077887K(7077888K),
> > 28.6425809 secs] 9043967K->9043787K(9043968K), [Metaspace: 75140K-
> > >75140K(1118208K)], 28.6428227 secs] [Times: user=28.63 sys=0.00,
> > real=28.64 secs]
> > gc_20180423_1443.log.11.current:37510:2018-05-01T09:11:20.803+0000:
> > 671241.311: [Full GC (Allocation Failure) 2018-05-
> > 01T09:11:20.803+0000: 671241.311: [CMS: 7077887K->7077888K(7077888K),
> > 42.8881300 secs] 9043964K->9043856K(9043968K), [Metaspace: 75140K-
> > >75140K(1118208K)], 42.8883826 secs] [Times: user=42.85 sys=0.01,
> > real=42.89 secs]
> > gc_20180423_1443.log.11.current:37529:2018-05-01T09:12:03.694+0000:
> > 671284.201: [Full GC (Allocation Failure) 2018-05-
> > 01T09:12:03.694+0000: 671284.201: [CMS: 7077888K->7077888K(7077888K),
> > 28.8305893 secs] 9043959K->9043845K(9043968K), [Metaspace: 75140K-
> > >75140K(1118208K)], 28.8308264 secs] [Times: user=28.83 sys=0.01,
> > real=28.83 secs]
> > gc_20180423_1443.log.11.current:37548:2018-05-01T09:12:32.527+0000:
> > 671313.035: [Full GC (Allocation Failure) 2018-05-
> > 01T09:12:32.527+0000: 671313.035: [CMS: 7077888K->7077887K(7077888K),
> > 34.2235811 secs] 9043967K->9043802K(9043968K), [Metaspace: 75140K-
> > >75140K(1118208K)], 34.2238304 secs] [Times: user=34.22 sys=0.00,
> > real=34.23 secs]
> > gc_20180423_1443.log.11.current:37567:2018-05-01T09:13:06.754+0000:
> > 671347.261: [Full GC (Allocation Failure) 2018-05-
> > 01T09:13:06.754+0000: 671347.262: [CMS: 7077887K->7077887K(7077888K),
> > 30.2722671 secs] 9043966K->9043854K(9043968K), [Metaspace: 75140K-
> > >75140K(1118208K)], 30.2725042 secs] [Times: user=30.27 sys=0.00,
> > real=30.27 secs]
> > gc_20180423_1443.log.11.current:37586:2018-05-01T09:13:37.028+0000:
> > 671377.536: [Full GC (Allocation Failure) 2018-05-
> > 01T09:13:37.028+0000: 671377.536: [CMS: 7077887K->7077887K(7077888K),
> > 35.6276778 secs] 9043955K->9043843K(9043968K), [Metaspace: 75140K-
> > >75140K(1118208K)], 35.6278998 secs] [Times: user=35.61 sys=0.01,
> > real=35.63 secs]
> > As per my calculations total duration based on the logs for these 6
> > entries is 164.872s out of which GC takes up 164.8583663s which
> > equals 99.99% time in GC. Given total heap of 9043968K bring 2% to
> > 180879.36K.
> >
> > The total heap cleared from the logs in these 5 executions is 679K
> > (across the calls) which is way less than 2% yet there's no OOM
> > thrown.
> >
> > The -XX:-UseGCOverheadLimit flag has not been used.
> >
> > Here's a list of the GC params:
>
> There is unfortunately no way to get detailed information in a product
> build about what Hotspot thinks.
>
> However not only gc overhead is accounted for in the decision to give
> an OOME, but also how much memory the full gcs free.
>
> Probably the most important flag here would be GCHeapFreeLimit:
> simplified, if free space after full gc is below this percentage of
> total heap, that full gc does not count against GCOverHeadLimit.
>
> Looking at the log output, after Full GC there is ~4% of max heap
> available. The default value for GCOverHeadLimit is 2 (percent).
>
> This might be the reason why there is no OOME.
>
> Thanks,
>   Thomas
>
-- 
Regards,
Binoy Dalal
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20180525/63a6fc6e/attachment.html>