Consecutive Full GCs but no OOM

[Thomas Schatzl]

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