title: 95 consecutive Full GCs but no OOM. How could that happen?
body: <p>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 <code>java.lang.OutOfMemoryError: GC overhead limit exceeded</code> message.
  How could this be? </p>
  
  <p>Here are 6 Full GC entries:</p>
  
  <pre><code>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-&gt;7077887K(7077888K), 28.6425809 secs] 9043967K-&gt;9043787K(9043968K), [Metaspace: 75140K-&gt;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-&gt;7077888K(7077888K), 42.8881300 secs] 9043964K-&gt;9043856K(9043968K), [Metaspace: 75140K-&gt;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-&gt;7077888K(7077888K), 28.8305893 secs] 9043959K-&gt;9043845K(9043968K), [Metaspace: 75140K-&gt;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-&gt;7077887K(7077888K), 34.2235811 secs] 9043967K-&gt;9043802K(9043968K), [Metaspace: 75140K-&gt;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-&gt;7077887K(7077888K), 30.2722671 secs] 9043966K-&gt;9043854K(9043968K), [Metaspace: 75140K-&gt;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-&gt;7077887K(7077888K), 35.6276778 secs] 9043955K-&gt;9043843K(9043968K), [Metaspace: 75140K-&gt;75140K(1118208K)], 35.6278998 secs] [Times: user=35.61 sys=0.01, real=35.63 secs]
  </code></pre>
  
  <p>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.</p>
  
  <p>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.</p>
  
  <p>The <code>-XX:-UseGCOverheadLimit</code> flag has not been used.</p>
  
  <p>Here's a list of the GC params:</p>
  
  <pre><code>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 
  </code></pre>
  
  <p>JDK version is <code>openjdk-1.8.0_151</code></p>
  
  <p>Please let me know if you spot an error in my calculations or my understanding of the  <code>java.lang.OutOfMemoryError: GC overhead limit exceeded</code> 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.</p>
  
  <p>Any pointers are much appreciated. Thanks!</p>