你了解这种 JVM GC 日志吗？ 99%的人没遇到过这种情况吧

[willbetter]

几乎是一直不断的 GC 偶尔会出现一次 FullGC ，但是没有发生 OOM ，有没有 v 友可以解释一下为什么出现这样的现象呢。

主要的 jvm 参数和 GC 日志如下

-Xms10g -Xmx10g -Xmn5g -Xss512k -XX:NewRatio=1 -XX:SurvivorRatio=8 -XX:MaxDirectMemorySize=3g -XX:ReservedCodeCacheSize=512m -XX:MetaspaceSize=512m -XX:MaxMetaspaceSize=512m -XX:MaxTenuringThreshold=15 -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=75 -XX:+UseCMSInitiatingOccupancyOnly -XX:+UseCMSCompactAtFullCollection -XX:CMSFullGCsBeforeCompaction=3 -XX:ConcGCThreads=12 -XX:ParallelGCThreads=16 -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=oom.hprof -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:jvm.log

2024-05-21T18:47:28.916+0800: 371856.391: [GC (Allocation Failure) 2024-05-21T18:47:28.916+0800: 371856.391: [ParNew (promotion failed): 4194304K->4635269K(4718592K), 0.4373197 secs]2024-05-21T18:47:29.354+0800: 371856.828: [CMS: 2231901K->2231895K(5242880K), 5.3415522 secs] 6426200K->6425987K(9961472K), [Metaspace: 171474K->171474K(1210368K)], 5.7797668 secs] [Times: user=9.42 sys=0.19, real=5.78 secs]

2024-05-21T18:47:34.703+0800: 371862.178: [GC (Allocation Failure) 2024-05-21T18:47:34.703+0800: 371862.178: [ParNew (promotion failed): 4194304K->4635169K(4718592K), 0.4400798 secs]2024-05-21T18:47:35.144+0800: 371862.618: [CMS: 2231897K->2231895K(5242880K), 5.5087331 secs] 6426199K->6426038K(9961472K), [Metaspace: 171474K->171474K(1210368K)], 5.9496682 secs] [Times: user=9.15 sys=0.40, real=5.95 secs]

2024-05-21T18:47:40.661+0800: 371868.136: [GC (Allocation Failure) 2024-05-21T18:47:40.661+0800: 371868.136: [ParNew (promotion failed): 4194304K->4635154K(4718592K), 0.4595525 secs]2024-05-21T18:47:41.121+0800: 371868.595: [CMS: 2231897K->2231895K(5242880K), 5.4417850 secs] 6426199K->6426090K(9961472K), [Metaspace: 171474K->171474K(1210368K)], 5.9023661 secs] [Times: user=9.46 sys=0.26, real=5.90 secs]

2024-05-21T18:47:46.570+0800: 371874.045: [GC (Allocation Failure) 2024-05-21T18:47:46.571+0800: 371874.045: [ParNew (promotion failed): 4194304K->4618886K(4718592K), 0.4888368 secs]2024-05-21T18:47:47.060+0800: 371874.534: [CMS: 2231897K->2231895K(5242880K), 5.5780372 secs] 6426199K->6426111K(9961472K), [Metaspace: 171474K->171474K(1210368K)], 6.0678031 secs] [Times: user=9.55 sys=0.44, real=6.07 secs]

2024-05-21T18:47:52.647+0800: 371880.122: [GC (Allocation Failure) 2024-05-21T18:47:52.648+0800: 371880.122: [ParNew (promotion failed): 4194304K->4667904K(4718592K), 0.4698026 secs]2024-05-21T18:47:53.118+0800: 371880.592: [CMS: 2231897K->2231895K(5242880K), 5.4107001 secs] 6426199K->6426134K(9961472K), [Metaspace: 171474K->171474K(1210368K)], 5.8813882 secs] [Times: user=9.50 sys=0.21, real=5.88 secs]

2024-05-21T18:47:58.536+0800: 371886.010: [GC (Allocation Failure) 2024-05-21T18:47:58.536+0800: 371886.011: [ParNew (promotion failed): 4194304K->4574048K(4718592K), 0.4713705 secs]2024-05-21T18:47:59.008+0800: 371886.482: [CMS: 2231897K->2231895K(5242880K), 5.6466353 secs] 6426199K->6426161K(9961472K), [Metaspace: 171474K->171474K(1210368K)], 6.1190005 secs] [Times: user=9.62 sys=0.36, real=6.12 secs]

2024-05-21T18:48:04.663+0800: 371892.138: [GC (Allocation Failure) 2024-05-21T18:48:04.663+0800: 371892.138: [ParNew (promotion failed): 4194304K->4626655K(4718592K), 0.4276313 secs]2024-05-21T18:48:05.091+0800: 371892.566: [CMS: 2231902K->2231894K(5242880K), 5.4168770 secs] 6426199K->6426166K(9961472K), [Metaspace: 171474K->171474K(1210368K)], 5.8454321 secs] [Times: user=9.23 sys=0.23, real=5.85 secs]

2024-05-21T18:48:10.516+0800: 371897.991: [GC (Allocation Failure) 2024-05-21T18:48:10.517+0800: 371897.991: [ParNew (promotion failed): 4194304K->4641746K(4718592K), 0.4627810 secs]2024-05-21T18:48:10.979+0800: 371898.454: [CMS: 2231902K->2231896K(5242880K), 5.5284212 secs] 6426198K->6426167K(9961472K), [Metaspace: 171474K->171474K(1210368K)], 5.9921634 secs] [Times: user=9.46 sys=0.30, real=6.00 secs]

2024-05-21T18:48:16.515+0800: 371903.990: [GC (Allocation Failure) 2024-05-21T18:48:16.516+0800: 371903.990: [ParNew (promotion failed): 4194304K->4649197K(4718592K), 0.4415676 secs]2024-05-21T18:48:16.957+0800: 371904.432: [CMS: 2231900K->2231896K(5242880K), 5.3513417 secs] 6426200K->6426167K(9961472K), [Metaspace: 171474K->171474K(1210368K)], 5.7940064 secs] [Times: user=9.28 sys=0.24, real=5.80 secs]

2024-05-21T18:48:22.322+0800: 371909.797: [GC (Allocation Failure) 2024-05-21T18:48:22.323+0800: 371909.797: [ParNew (promotion failed): 4194304K->4634752K(4718592K), 0.4521718 secs]2024-05-21T18:48:22.775+0800: 371910.250: [CMS: 2231898K->2231896K(5242880K), 5.4785770 secs] 6426200K->6426168K(9961472K), [Metaspace: 171474K->171474K(1210368K)], 5.9315963 secs] [Times: user=9.16 sys=0.43, real=5.93 secs]

2024-05-21T18:48:28.261+0800: 371915.736: [GC (Allocation Failure) 2024-05-21T18:48:28.261+0800: 371915.736: [ParNew (promotion failed): 4194304K->4651526K(4718592K), 0.4648037 secs]2024-05-21T18:48:28.726+0800: 371916.201: [CMS: 2231898K->2231896K(5242880K), 5.3247225 secs] 6426200K->6426168K(9961472K), [Metaspace: 171474K->171474K(1210368K)], 5.7905868 secs] [Times: user=9.57 sys=0.25, real=5.79 secs]

2024-05-21T18:48:34.062+0800: 371921.537: [GC (Allocation Failure) 2024-05-21T18:48:34.062+0800: 371921.537: [ParNew (promotion failed): 4194304K->4635314K(4718592K), 0.4950457 secs] 6426200K->6867214K(9961472K), 0.4959471 secs] [Times: user=4.49 sys=0.18, real=0.50 secs]

2024-05-21T18:48:34.559+0800: 371922.033: [Full GC (Allocation Failure) 2024-05-21T18:48:34.559+0800: 371922.034: [CMS: 2231900K->2231896K(5242880K), 5.8874914 secs] 6867214K->6426175K(9961472K), [Metaspace: 171474K->171474K(1210368K)], 5.8884068 secs] [Times: user=5.62 sys=0.26, real=5.89 secs]

2024-05-21T18:48:40.453+0800: 371927.927: [GC (Allocation Failure) 2024-05-21T18:48:40.453+0800: 371927.928: [ParNew (promotion failed): 4194304K->4651685K(4718592K), 0.4642263 secs]2024-05-21T18:48:40.917+0800: 371928.392: [CMS: 2231898K->2231896K(5242880K), 5.3888979 secs] 6426200K->6426176K(9961472K), [Metaspace: 171474K->171474K(1210368K)], 5.8540507 secs] [Times: user=9.35 sys=0.31, real=5.86 secs]

2024-05-21T18:48:46.316+0800: 371933.791: [GC (Allocation Failure) 2024-05-21T18:48:46.317+0800: 371933.792: [ParNew (promotion failed): 4194304K->4635361K(4718592K), 0.4578858 secs]2024-05-21T18:48:46.775+0800: 371934.249: [CMS: 2231900K->2231896K(5242880K), 5.7059036 secs] 6426200K->6426186K(9961472K), [Metaspace: 171474K->171474K(1210368K)], 6.1648408 secs] [Times: user=9.57 sys=0.40, real=6.17 secs]

2024-05-21T18:48:52.489+0800: 371939.964: [GC (Allocation Failure) 2024-05-21T18:48:52.489+0800: 371939.964: [ParNew (promotion failed): 4194304K->4635374K(4718592K), 0.4588958 secs]2024-05-21T18:48:52.948+0800: 371940.423: [CMS: 2231898K->2231896K(5242880K), 5.5571464 secs] 6426200K->6426197K(9961472K), [Metaspace: 171474K->171474K(1210368K)], 6.0169221 secs] [Times: user=9.62 sys=0.21, real=6.02 secs]

[c3de3f21]

虽然看不懂，但是隐约觉得可能是 jvm 参数配置不合理 或者代码有问题？导致资源不足导致 GC 分配一些东西失败？

[liprais]

https://gceasy.io/ 解君愁

[gy123]

搜索引擎:

Allocation Failure：
表明本次引起 GC 的原因是因为在年轻代中没有足够的空间能够存储新的数据了。

[willbetter]

@c3de3f21 参数可能有不合理的，引起这次一直不断 GC 都原因是一下子创建了很多对象。关键是一直在 GC 没有 OOM 就很奇怪

[willbetter]

@liprais 把整个 GC 日志都给它分析过，没有得到非常有用的信息

[me1onsoda]

@gy123 新生代满了怎么可能 full gc...

[me1onsoda]

哦，只有偶尔 full gc ，这有什么不对吗

[sagaxu]

分代 GC 不都这样吗？年轻代满了就在年轻代内部回收一下，年轻代回收释放不了足够内存时，那就顺带把老年代也回收一下。如果老年代回收完了依然释放不了足够内存，那就 OOM 一下。

[me1onsoda]

是 full gc 之后还是没能释放出内存直到没空间可用才会 oom 。

[chendy]

不了解，但是既然 gc 时间看着这么长，直接进行一个 dump 分析找泄漏点吧

[humingk]

为什么 FullGC 就要 OOM 呢

[dlmy]

大内存服务器用 ParNew+CMS 的垃圾收集器组合，GC 时间肯定会很长，好不容易等 GC 结束，程序又产生了大量垃圾，这不又继续 GC 了。

[LiaoMatt]

1. NewRatio 和 Xmn 同时设置只会生效一个, 优先 Xmn;
2. Suvivor 占用比例是不是可以更小一些, 比如 20:1:1, 目前一个 suvivor 有 500M, 两个就有 1GB, 对象实例很容易就能晋级到老年代(个人觉得), 然后每次 FullGC 又把这些提升到老年代的实例释放,能腾出 430MB 让程序勉强走下去; 应对方法, 降低 suvivor 区的比例, 增加晋升到老年代需要的存活次数

[LiaoMatt]

花里胡哨的 JVM 参数配置太多了, 管理的内存这么大, 如果是 JDK8 直接用 G1GC, 然后其他参数不用配置, 应该情况也会好很多

[roundgis]

CMS 我記得會產生內存碎片

條件允許換 G1 試試

[skyemin]

@LiaoMatt survivor 区太小,每次新生代回收装不下不就直接去老年代了

[tianshuang]

送分题

[cheng6563]

年轻代就是频繁 GC 的啊，有啥问题...
偶尔出现一次 FullGC ，说明堆内存不宽松，也没啥奇怪的吧...
然后，为什么 FullGC 就要 OOM ？

[LiaoMatt]

@skyemin 只有大对象才会有这个情况, 而且从参数来看没有设置 PretenureSizeThreshold 阈值

[choice4]

几乎稳定 6 秒一次 的 GC ，可以检查有没有周期性任务。