java - 连续 95 次 Full GC，但没有 OOM。怎么会这样？

Question

我正在对 Java Web 应用程序进行故障排除，该应用程序在一段时间内运行良好，之后堆突然飙升至 100%，这导致连续的 Full GC 几乎没有旧的 gen 被清除。但是，这不会导致带有通常java.lang.OutOfMemoryError: GC overhead limit exceeded消息的 OOM。这怎么可能？

这里有 6 个 Full GC 条目：

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]

根据我的计算，基于这 6 个条目的日志的总持续时间为 164.872 秒，其中 GC 占用 164.8583663 秒，相当于 99.99% 的 GC 时间。给定总堆 9043968K 将 2% 提高到 180879.36K。

在这 5 次执行中从日志中清除的总堆为 679K（跨调用），远低于 2%，但没有引发 OOM。

该-XX:-UseGCOverheadLimit标志尚未使用。

以下是 GC 参数列表：

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版本是openjdk-1.8.0_151

java.lang.OutOfMemoryError: GC overhead limit exceeded如果您在我的计算中发现错误，或者我对当总时间的 98% 以上用于垃圾回收且堆恢复不到 2% 时抛出错误的规则的理解，请告诉我 。

任何指针都非常感谢。谢谢！

标签： javagarbage-collectionout-of-memory