你了解这种 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]

[HiShan]

@willbetter #38 这个情况我遇到过，因为你的线程创建的对象被占用了，不能 GC 掉，导致 JVM 内存不够，达到了 GC 阀值就会不停的处罚 GC 出现进程卡死的情况。不会 OOM 是因为 JVM 进程没有超过操作系统的内存上限。 你可以试一下把线程中创建的对象，用完之后直接 赋值 null 并且避免被其他地方持有，这样一次 GC 就会回收掉了。或者你把 JVM 的内存调大

[willbetter]

@fingerxie
@cheng6563
@liuhailiang
@me1onsoda
@Ashe007
感谢各位大佬的分析，其实我主要的疑问就是我在 38 楼所说的。

[willbetter]

@cheng6563 #33 不排除会存在你说的这种情况，但我们另一台服务器另一个服务也有类似的配置和负载的情况下是会产生 OOM 文件的

[willbetter]

@HiShan 跟你说的情况差不多，那些对象是还有很多没有用完所以没有释放。但我们服务设置了最大堆内存，按理说因为年轻代不够分配内存空间导致 GC ，那最终肯定会把符合条件的对象移动到老年代，一直这样运行最终内存会使用完发生 OOM 啊

[zhangjiashu2023]

从你提供的 JVM 参数和 GC 日志来看，这种频繁的 GC 活动（特别是 Promotion Failed 和多次 Full GC ）很可能是由于老年代（ CMS ）空间不足以容纳从新生代晋升的对象所引起的。

堆空间配置: 你的 JVM 堆空间配置为-Xms10g -Xmx10g ，新生代（ Young Generation ）为 5G ，老年代也大约为 5G 。新生代的这个配置相对较大，使得老年代的可用空间减少，可能不足以容纳足够多晋升的对象。

晋升失败（ Promotion Failed ）: GC 日志中多次出现了“Promotion Failed”的记录。这表示有大量对象尝试从新生代晋升到老年代时失败，这通常是因为老年代空间不足。这会导致接下来的 Full GC 尝试释放老年代的空间。

Full GC 频繁发生: 虽然老年代的 CMS GC 试图清理空间，但如果晋升的对象过多，清理出的空间可能仍然不足以满足需求，导致不得不频繁进行 Full GC 。每次 Full GC 后，老年代的利用率几乎未变，表明在老年代几乎没有空间被成功释放。

线程创建大量对象: 如果有线程突然创建大量对象，这会迅速填满新生代，导致频繁的 GC 。由于老年代空间有限，晋升的对象可能无法有效迁移，从而触发连续的 Full GC 。

建议
调整堆配置：考虑减少新生代的大小，为老年代腾出更多空间，以便可以容纳更多晋升的对象。比如将-Xmn 设置为 3G 或更低。
优化 GC 策略：考虑切换到 G1 GC ，这对于大堆内存管理通常更为高效，尤其是在需要更细粒度控制堆内存分布时。
代码优化：审查引起大量对象创建的代码部分，看是否可以优化以减少内存压力，或者使用对象池等技术来管理对象生命周期。
增加更多的日志记录：使用-XX:+PrintTenuringDistribution 来观察对象在新生代的存活情况，从而更好地调整-XX:MaxTenuringThreshold 等参数。
这些调整可以帮助你更好地管理内存，减少 GC 的频率和影响，提升应用性能。

[HiShan]

@willbetter #44 会有种情况是，比如：第一次创建了 10G 的对象 第二次创建对象也要 10G, 由于 JVM 内存不够所以触发一次 GC 清理了第一次创建的对象. 像这种大对象的创建不会放到年轻代的，会直接放到老年代。而且不用过多关注年轻代老年代没有太多价值。

[tairan2006]

改成 G1 或者 ZGC ，别调优了，啥年代了……

[0xD800]

我遇到过几次进程假死的情况，JSTACK 排查不到问题，有几次是卡在日志框架上 logback,JUL 都有。那时候没看 GC 日志。。