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

[willbetter]

题目说没有 OOM 是我不严谨表达，大家都知道只有内存不够才会 OOM 。
但是各位看日志，年轻代 GC 后并没有释放内存空间，并且内存大小也没有一直不停的增加。但是 GC 一直不断，这样的 GC 一直持续了一天，这样的 GC 开始后不久整个进程就相当于假死了。没有任何响应。

内存日志 dump 分析了引起这次不断 GC 的原因主要是有几个线程突然创建了大量的对象，我的疑问是为什么会一直在不断 GC 。

[bai4246464]

很正常的 gc 日志，资源够可以给新生代加资源

[fkname]

"内存日志 dump 分析了引起这次不断 GC 的原因主要是有几个线程突然创建了大量的对象，我的疑问是为什么会一直在不断 GC 。"
这句话看着怎么有点矛盾

[willbetter]

@dlmy #13 我猜大概也是这样的情况，导致大量对象对那几个业务线程几乎没法处理或处理得很慢

[willbetter]

@LiaoMatt #14 设置这些参数的人感觉就是乱用，这个业务把年轻代和老年代内存 55 分就是不合理的

[LiaoMatt]

进程假死了, 没有任何响应, 这就就是 OOM 的表现, 把服务器配置贴出来

[LiaoMatt]

如果是直接内存分配失败的 OOM, 你可以关注下 dmsg, 在业务日志上是没有体现的, 如果用 systemd 托管服务可能还可以看到有用的信息

[willbetter]

@LiaoMatt OOM 不会导致整个进程都假死了，会产生 OOM 文件。但这个进程是没有产生 OOM 文件的，我是怀疑这里触发了 GC 条件后，业务线程又没来得及处理完这些对象，只处理了一点点，又进行了下一次 GC 。

[fingerxie]

一、GPT4o
根据你提供的 JVM 参数和 GC 日志，几乎一直不断的 GC 和偶尔出现的 Full GC 可以归结于以下几个原因：

频繁的 Minor GC （ ParNew GC ）：
日志中显示，ParNew GC 频繁发生，并且每次都出现 promotion failed ，这意味着在 Minor GC 过程中，无法将新生代中的对象提升到老年代。
新生代的大小为 5 GB (-Xmn5g)，每次 GC 都在接近这个大小时触发，这说明对象在新生代中存活时间较长，无法被及时回收。
老年代的不足：
你使用的是 CMS GC （ Concurrent Mark-Sweep ），老年代大小为 5 GB (-Xmx10g 和 -Xmn5g ，所以老年代也是 5 GB ）。
CMS GC 的一个特点是，当老年代空间不足时，会触发 promotion failed ，这会导致 Minor GC 失败，并最终触发 Full GC 。
Full GC 触发：
在日志中可以看到 Full GC 发生的时间点，例如 2024-05-21T18:48:34.559+0800: 371922.033 ，这是因为在频繁的 Minor GC 过程中，老年代的空间不足以容纳新生代中提升的对象，因此触发了 Full GC 。
Full GC 的时间较长（例如 5.887 秒），这会导致应用暂停较长时间。
CMS GC 的配置：
-XX:CMSInitiatingOccupancyFraction=75 表示当老年代使用达到 75% 时，CMS GC 开始标记和清理。
但是，日志显示老年代几乎一直在 2231900K 附近（约 2.1 GB ），这意味着老年代没有足够的空间进行对象提升，导致频繁的 promotion failed 和 Full GC 。
解决方案建议
增加堆内存：
尝试增加堆的最大大小（-Xmx ）和新生代大小（-Xmn ），例如 -Xmx12g -Xmn6g ，以增加老年代和新生代的空间。
调整 CMS GC 参数：
增大 -XX:CMSInitiatingOccupancyFraction 的值，例如 85 或 90 ，让 CMS GC 更早地开始清理，以确保老年代有足够的空间。
考虑使用 -XX:+CMSScavengeBeforeRemark 选项，在 remark 之前进行一次 Minor GC ，减少老年代的压力。
优化应用的内存使用：
检查应用代码，优化内存分配和对象生命周期，减少长时间驻留在新生代和老年代的对象。
使用内存分析工具（如 VisualVM 或 YourKit ）进行分析，找出内存泄漏或不合理的对象持有。
调整 Survivor 区的大小：
通过调整 -XX:SurvivorRatio 来优化 Survivor 区的大小，确保对象在新生代能够有足够的空间进行复制和提升。
通过以上调整，可以减少频繁的 Minor GC 和 Full GC ，提升应用的性能和响应时间。
二、Claude3-Opus
根据您提供的 JVM 参数和 GC 日志，我可以看到以下几点：

1. 您使用的是 CMS (Concurrent Mark Sweep) 垃圾收集器，新生代和老年代的比例为 1:1 ，新生代中 Eden 和 Survivor 的比例为 8:1:1 。

2. 应用程序的堆内存设置为 10GB ，其中新生代为 5GB ，老年代为 5GB 。

3. GC 日志显示，应用程序频繁发生 Minor GC (ParNew)，几乎每次 Minor GC 都会发生 promotion failed ，即 Survivor 区域不足以容纳所有的存活对象，需要将对象提前晋升到老年代。

4. 在 Minor GC 后，紧接着会触发 Full GC (CMS)，CMS 会对老年代进行垃圾回收。但 CMS 回收后，老年代的使用量几乎没有减少，说明老年代中的大部分对象都是存活的，无法被回收。

5. 虽然没有发生 OOM ，但频繁的 Full GC 会导致应用的响应时间变长，吞吐量下降。

产生这种现象的原因可能有以下几点：

1. 应用程序中存在大量的长期存活对象，这些对象在 Minor GC 时会被频繁地复制和提升到老年代，导致老年代的使用量快速增长。

2. 新生代的空间设置得不够大，导致 Minor GC 的频率非常高。可以适当增加新生代的大小 (-Xmn) 来减少 Minor GC 的频率。

3. 老年代的空间利用率已经非常高，可能接近 CMS 的启动阈值 (-XX:CMSInitiatingOccupancyFraction)。您可以适当调高这个阈值，以延迟 CMS 的触发时机。

4. 如果可能的话，您可以尝试使用 G1 垃圾收集器来替代 CMS ，G1 在应对大堆、长时间运行的应用程序方面表现更好。

总之，您需要进一步分析应用程序的对象生命周期和内存使用情况，找出导致老年代快速填满的原因，并相应地调整 JVM 参数和优化应用程序。同时，密切关注 GC 日志，确保不会发生 OOM 或过长的 GC 暂停时间。

[magicZ]

我有个项目，就是不断建立 websocket, 接收音频流，处理后进行 asr 识别，这是初始堆内存 -Xms2048m -Xmx10240m
项目开始运行，新生代的空间几分钟就满了，然后 fullGC 清空，但是服务不会假死，正常运行

[admol]

内存日志 dump 分析了引起这次不断 GC 的原因主要是有几个线程突然创建了大量的对象，我的疑问是为什么会一直在不断 GC 。

=======

你的疑问不自己都回答了么，一直在不断 GC 就是因为有几个线程突然创建了大量的对象啊，对象对了空间不足不就是要 GC 吗，不 GC 不就 OOM 了吗

所以你现在不应该去找为什么会有几个线程突然创建大量对象？还是说你想让线程不停地创建大量对象，还不允许 GC ？

[jungledg]

promotion failed 晋升失败了，一般来说是老年代可用大小不够，放不下需要新声代中需要晋升的对象，所以 JVM 会触发一次 FGC ，来清理老年代，释放出更多的空间，这个过程会 STW ，这也是你服务无法响应的原因。

可以尝试增加堆内存 / 调大老年代比例 解决。

[cheng6563]

你这多半就是 OOM 了，但因为负载过高产不出 OOM 文件。加个 -XX:+ExitOnOutOfMemoryError 完事

[liuhailiang]

从 jvm 日志上看是 有内存泄露，不用盯着 jvm 日志看了，查查代码有没有什么地方无限创建对象（一直被引用，无法被 gc 回收的），或者项目日志改成 debug 级别，捞一些频繁打出的日志的地方看看代码
如果稳定复现很好排查的。

[me1onsoda]

就是因为没释放空间出来才要一直 gc 啊。。你这答案不就在题面上吗
假死又没有 oom ，我猜是内存不够被操作系统杀了吧

[Ashe007]

可以将 GC 理解为打扫 jvm 房间，触发 GC 时会发生 stw （ jvm 的所有进程阻塞——即你所提及进程假死）。GC 的触发分为两种情况：1 、周期性的打扫。2 、突然产生了大量垃圾急需临时大扫除（否则内存将很快超出 OS 分配给 jvm 的总内存）。
jvm 的频繁 GC 通常是第二种情况，而 Full GC 的场景往往是 young generation 和 old generation 区域都需要 clean （也就是整个堆内存区域快使用完了）。

看看 gpt 对你第一行 GC 日志的解释
↓↓↓↓
这段日志是一次垃圾收集（ GC ）事件的记录。让我们逐步分析它：

2024-05-21T18:47:28.916+0800: 371856.391: 表示此日志记录的时间戳，格式为 ISO 8601 ，即 YYYY-MM-DDTHH:mm:ss.sss±hhmm 。

[GC (Allocation Failure): 表示触发 GC 的原因为内存分配失败（ Allocation Failure ）。

ParNew (promotion failed): 4194304K->4635269K(4718592K), 0.4373197 secs: 表示 ParNew （新生代）的 GC 信息，其中：

ParNew: 表示使用的垃圾收集器为 ParNew 。
(promotion failed): 表示新生代中的对象晋升到老年代时出现了晋升失败。
4194304K->4635269K(4718592K): 表示 GC 前新生代的已使用空间和 GC 后的已使用空间，以及新生代总大小。
0.4373197 secs: 表示 GC 所花费的时间。
CMS: 2231901K->2231895K(5242880K), 5.3415522 secs: 表示 CMS （老年代）的 GC 信息，其中：

CMS: 表示使用的垃圾收集器为 CMS 。
2231901K->2231895K(5242880K): 表示 GC 前老年代的已使用空间和 GC 后的已使用空间，以及老年代总大小。
5.3415522 secs: 表示 GC 所花费的时间。
6426200K->6425987K(9961472K): 表示整个堆内存的 GC 信息，其中：

6426200K->6425987K(9961472K): 表示 GC 前堆内存的已使用空间和 GC 后的已使用空间，以及堆内存的总大小。
[Metaspace: 171474K->171474K(1210368K)]: 表示元空间（ Metaspace ）的 GC 信息，其中：

171474K->171474K(1210368K): 表示 GC 前元空间的已使用空间和 GC 后的已使用空间，以及元空间的总大小。
5.7797668 secs: 表示整个 GC 过程所花费的时间。

[Times: user=9.42 sys=0.19, real=5.78 secs]: 表示 GC 的 CPU 时间和实际时间，其中：

user=9.42: 表示用户 CPU 时间。
sys=0.19: 表示系统 CPU 时间。
real=5.78 secs: 表示实际时间。
根据日志内容可以看出，发生了一次新生代和老年代的 GC ，其中 ParNew 阶段由于晋升失败导致了 promotion failed ，而 CMS 阶段则正常完成。整个 GC 过程耗时 5.78 秒，期间堆内存从 6426200KB 降至 6425987KB 。
↑↑↑↑

可以看出每次 GC 所清理的内存空间非常少，6426200-6425987=213KB ，也就是说你的程序中有大量长期一直在使用的对象。

1 、那么是否可以考虑给 jvm 多分配一些内存空间？
2 、这些大量长期使用的对象是如何产生的？是否存在很多内存没有及时释放的代码——比如某些高并发接口内部存在很多内存未及时释放的情况

[chenfang]

你这也没指定垃圾回收器... 不过看着应该是老年代 CMS+年轻代 ParNew,这个组合我们公司在 18 年的时候就不用了.....
jdk8 应该就可以使用 G1,虽然不知道你上述是啥原因导致的,但是还是强烈推荐用用 G1,看看效果

[willbetter]

@admol #31 创建大量对象这几个线程我们清楚是为什么，关键这几个线程要创建的对象数量其实是固定的。

奇怪的现象是它一直在不停的 GC ，这个现象超过了 24 小时，期间其它的线程几乎都没有运行了，猜测是 GC 导致经常 STW 。
主要是想知道是什么原因原因导致它一直 GC 就是不抛出 OOM 错误，抛出 OOM 错误好歹影响的范围小一些，不至于整个进程像现在“假死”了一样

[willbetter]

@jungledg #32 但它一直在 GC 超过 24 小时了就是不会抛出 OOM ，导致一直处于 STW 状态，其它服务都调不通它了。

[admol]

@willbetter

感觉 JVM 的参数是有些不合理的，尤其是新生代和老年代的大小一样了，都可以考虑尝试优化下。

网上有很 Java 虚拟机参数分析、生成、优化的工具，可以参考下。