Consecutive Full GCs but no OOM

[Binoy Dalal]

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:

CommandLine flags: -XX:CICompilerCount=4
-XX:CMSInitiatingOccupancyFraction=50
-XX:CMSMaxAbortablePrecleanTime=6000 -XX:+CMSParallelRemarkEnabled
-XX:+CMSScavengeBeforeRemark -XX:ConcGCThreads=4
-XX:+CrashOnOutOfMemoryError -XX:GCLogFileSize=10485760
-XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=/WORK/log/solr/solr.hprof
-XX:InitialHeapSize=9663676416 -XX:LogFile=/WORK/log/solr/vm.log
-XX:+LogVMOutput -XX:MaxHeapSize=9663676416 -XX:MaxNewSize=2415919104
-XX:MaxTenuringThreshold=8 -XX:MinHeapDeltaBytes=196608 -XX:NewRatio=3
-XX:NewSize=2415919104 -XX:NumberOfGCLogFiles=20 -XX:OldPLABSize=16
-XX:OldSize=7247757312 -XX:OnOutOfMemoryError=/WORK/bin/oom.sh solr
-XX:ParallelGCThreads=4 -XX:+ParallelRefProcEnabled
-XX:PretenureSizeThreshold=67108864 -XX:+PrintGC
-XX:+PrintGCApplicationStoppedTime -XX:+PrintGCDateStamps
-XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC
-XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1
-XX:+PrintTenuringDistribution -XX:+SafepointTimeout
-XX:SafepointTimeoutDelay=500 -XX:SurvivorRatio=4
-XX:TargetSurvivorRatio=90 -XX:ThreadStackSize=256
-XX:+UnlockDiagnosticVMOptions -XX:-UseBiasedLocking
-XX:+UseCMSInitiatingOccupancyOnly -XX:+UseCompressedClassPointers
-XX:+UseCompressedOops -XX:+UseConcMarkSweepGC
-XX:+UseGCLogFileRotation -XX:+UseParNewGC

JDK version is openjdk-1.8.0_151

Please let me know if you spot an error in my calculations or my
understanding of thejava.lang.OutOfMemoryError: GC overhead limit exceeded rule
that error is thrown when more than 98% of the total time is spent in
garbage collection and less than 2% of the heap is recovered.

Any pointers are much appreciated. Thanks!

I have posted this same question on stack overflow in case anyone wants to
respond there:
https://stackoverflow.com/questions/50181547/95-consecutive-full-gcs-but-no-oom-how-could-that-happen


-- 
Regards,
Binoy Dalal
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20180510/e8c28674/attachment-0001.html>