V2EX = way to explore
V2EX 是一个关于分享和探索的地方
现在注册
已注册用户请  登录
• 请不要在回答技术问题时复制粘贴 AI 生成的内容
willbetter
V2EX  ›  程序员

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

  •  
  •   willbetter · 2024-05-23 11:18:47 +08:00 · 3777 次点击
    这是一个创建于 388 天前的主题,其中的信息可能已经有所发展或是发生改变。
    几乎是一直不断的 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]
    第 1 条附言  ·  2024-05-23 14:32:52 +08:00
    题目说没有 OOM 是我不严谨表达,大家都知道只有内存不够才会 OOM 。
    但是各位看日志,年轻代 GC 后并没有释放内存空间,并且内存大小也没有一直不停的增加。但是 GC 一直不断,这样的 GC 一直持续了一天,这样的 GC 开始后不久整个进程就相当于假死了。没有任何响应。

    内存日志 dump 分析了引起这次不断 GC 的原因主要是有几个线程突然创建了大量的对象,我的疑问是为什么会一直在不断 GC 。
    48 条回复    2024-05-24 08:52:25 +08:00
    c3de3f21
        1
    c3de3f21  
       2024-05-23 11:35:47 +08:00
    虽然看不懂,但是隐约觉得可能是 jvm 参数配置不合理 或者代码有问题?导致资源不足导致 GC 分配一些东西失败?
    liprais
        2
    liprais  
       2024-05-23 11:37:08 +08:00   ❤️ 2
    gy123
        3
    gy123  
       2024-05-23 11:42:58 +08:00
    搜索引擎:

    Allocation Failure:
    表明本次引起 GC 的原因是因为在年轻代中没有足够的空间能够存储新的数据了。
    willbetter
        4
    willbetter  
    OP
       2024-05-23 11:56:57 +08:00
    @c3de3f21 参数可能有不合理的,引起这次一直不断 GC 都原因是一下子创建了很多对象。关键是一直在 GC 没有 OOM 就很奇怪
    willbetter
        5
    willbetter  
    OP
       2024-05-23 11:58:33 +08:00
    @liprais 把整个 GC 日志都给它分析过,没有得到非常有用的信息
    me1onsoda
        6
    me1onsoda  
       2024-05-23 12:04:55 +08:00
    @gy123 新生代满了怎么可能 full gc...
    me1onsoda
        7
    me1onsoda  
       2024-05-23 12:06:57 +08:00
    哦,只有偶尔 full gc ,这有什么不对吗
    sagaxu
        8
    sagaxu  
       2024-05-23 12:19:01 +08:00
    分代 GC 不都这样吗?年轻代满了就在年轻代内部回收一下,年轻代回收释放不了足够内存时,那就顺带把老年代也回收一下。如果老年代回收完了依然释放不了足够内存,那就 OOM 一下。
    me1onsoda
        9
    me1onsoda  
       2024-05-23 12:20:31 +08:00
    是 full gc 之后还是没能释放出内存直到没空间可用才会 oom 。
    chendy
        10
    chendy  
       2024-05-23 12:21:20 +08:00   ❤️ 1
    不了解,但是既然 gc 时间看着这么长,直接进行一个 dump 分析找泄漏点吧
    humingk
        11
    humingk  
       2024-05-23 12:35:09 +08:00 via iPhone
    为什么 FullGC 就要 OOM 呢
    dlmy
        12
    dlmy  
       2024-05-23 12:46:51 +08:00   ❤️ 2
    大内存服务器用 ParNew+CMS 的垃圾收集器组合,GC 时间肯定会很长,好不容易等 GC 结束,程序又产生了大量垃圾,这不又继续 GC 了。
    LiaoMatt
        13
    LiaoMatt  
       2024-05-23 13:01:03 +08:00   ❤️ 2
    1. NewRatio 和 Xmn 同时设置只会生效一个, 优先 Xmn;
    2. Suvivor 占用比例是不是可以更小一些, 比如 20:1:1, 目前一个 suvivor 有 500M, 两个就有 1GB, 对象实例很容易就能晋级到老年代(个人觉得), 然后每次 FullGC 又把这些提升到老年代的实例释放,能腾出 430MB 让程序勉强走下去; 应对方法, 降低 suvivor 区的比例, 增加晋升到老年代需要的存活次数
    LiaoMatt
        14
    LiaoMatt  
       2024-05-23 13:10:33 +08:00
    花里胡哨的 JVM 参数配置太多了, 管理的内存这么大, 如果是 JDK8 直接用 G1GC, 然后其他参数不用配置, 应该情况也会好很多
    roundgis
        15
    roundgis  
       2024-05-23 13:42:53 +08:00 via Android
    CMS 我記得會產生內存碎片

    條件允許換 G1 試試
    skyemin
        16
    skyemin  
       2024-05-23 13:49:12 +08:00
    @LiaoMatt survivor 区太小,每次新生代回收装不下不就直接去老年代了
    tianshuang
        17
    tianshuang  
       2024-05-23 13:54:48 +08:00
    送分题
    cheng6563
        18
    cheng6563  
       2024-05-23 14:01:28 +08:00
    年轻代就是频繁 GC 的啊,有啥问题...
    偶尔出现一次 FullGC ,说明堆内存不宽松,也没啥奇怪的吧...
    然后,为什么 FullGC 就要 OOM ?
    LiaoMatt
        19
    LiaoMatt  
       2024-05-23 14:11:32 +08:00
    @skyemin 只有大对象才会有这个情况, 而且从参数来看没有设置 PretenureSizeThreshold 阈值
    choice4
        20
    choice4  
       2024-05-23 14:18:18 +08:00
    几乎稳定 6 秒一次 的 GC ,可以检查有没有周期性任务。
    willbetter
        21
    willbetter  
    OP
       2024-05-23 14:26:57 +08:00
    题目说没有 OOM 是我不严谨表达,大家都知道只有内存不够才会 OOM 。
    但是各位看日志,年轻代 GC 后并没有释放内存空间,并且内存大小也没有一直不停的增加。但是 GC 一直不断,这样的 GC 一直持续了一天,这样的 GC 开始后不久整个进程就相当于假死了。没有任何响应。

    内存日志 dump 分析了引起这次不断 GC 的原因主要是有几个线程突然创建了大量的对象,我的疑问是为什么会一直在不断 GC 。
    bai4246464
        22
    bai4246464  
       2024-05-23 14:29:56 +08:00
    很正常的 gc 日志,资源够可以给新生代加资源
    fkname
        23
    fkname  
       2024-05-23 14:36:10 +08:00
    "内存日志 dump 分析了引起这次不断 GC 的原因主要是有几个线程突然创建了大量的对象,我的疑问是为什么会一直在不断 GC 。"
    这句话看着怎么有点矛盾
    willbetter
        24
    willbetter  
    OP
       2024-05-23 14:46:10 +08:00
    @dlmy #13 我猜大概也是这样的情况,导致大量对象对那几个业务线程几乎没法处理或处理得很慢
    willbetter
        25
    willbetter  
    OP
       2024-05-23 14:50:01 +08:00
    @LiaoMatt #14 设置这些参数的人感觉就是乱用,这个业务把年轻代和老年代内存 55 分就是不合理的
    LiaoMatt
        26
    LiaoMatt  
       2024-05-23 14:52:40 +08:00
    进程假死了, 没有任何响应, 这就就是 OOM 的表现, 把服务器配置贴出来
    LiaoMatt
        27
    LiaoMatt  
       2024-05-23 14:56:19 +08:00
    如果是直接内存分配失败的 OOM, 你可以关注下 dmsg, 在业务日志上是没有体现的, 如果用 systemd 托管服务可能还可以看到有用的信息
    willbetter
        28
    willbetter  
    OP
       2024-05-23 15:02:44 +08:00
    @LiaoMatt OOM 不会导致整个进程都假死了,会产生 OOM 文件。但这个进程是没有产生 OOM 文件的,我是怀疑这里触发了 GC 条件后,业务线程又没来得及处理完这些对象,只处理了一点点,又进行了下一次 GC 。
    fingerxie
        29
    fingerxie  
       2024-05-23 15:43:56 +08:00   ❤️ 1
    一、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
        30
    magicZ  
       2024-05-23 16:29:41 +08:00
    我有个项目,就是不断建立 websocket, 接收音频流,处理后进行 asr 识别,这是初始堆内存 -Xms2048m -Xmx10240m
    项目开始运行,新生代的空间几分钟就满了,然后 fullGC 清空,但是服务不会假死,正常运行
    admol
        31
    admol  
       2024-05-23 16:37:00 +08:00
    内存日志 dump 分析了引起这次不断 GC 的原因主要是有几个线程突然创建了大量的对象,我的疑问是为什么会一直在不断 GC 。

    =======

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

    所以你现在不应该去找为什么会有几个线程突然创建大量对象?还是说你想让线程不停地创建大量对象,还不允许 GC ?
    jungledg
        32
    jungledg  
       2024-05-23 16:39:47 +08:00
    promotion failed 晋升失败了,一般来说是老年代可用大小不够,放不下需要新声代中需要晋升的对象,所以 JVM 会触发一次 FGC ,来清理老年代,释放出更多的空间,这个过程会 STW ,这也是你服务无法响应的原因。

    可以尝试增加堆内存 / 调大老年代比例 解决。
    cheng6563
        33
    cheng6563  
       2024-05-23 16:45:05 +08:00   ❤️ 1
    你这多半就是 OOM 了,但因为负载过高产不出 OOM 文件。加个 -XX:+ExitOnOutOfMemoryError 完事
    liuhailiang
        34
    liuhailiang  
       2024-05-23 17:03:30 +08:00
    从 jvm 日志上看是 有内存泄露,不用盯着 jvm 日志看了,查查代码有没有什么地方无限创建对象(一直被引用,无法被 gc 回收的),或者项目日志改成 debug 级别,捞一些频繁打出的日志的地方看看代码
    如果稳定复现很好排查的。
    me1onsoda
        35
    me1onsoda  
       2024-05-23 17:06:15 +08:00
    就是因为没释放空间出来才要一直 gc 啊。。你这答案不就在题面上吗
    假死又没有 oom ,我猜是内存不够被操作系统杀了吧
    Ashe007
        36
    Ashe007  
       2024-05-23 17:06:20 +08:00
    可以将 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
        37
    chenfang  
       2024-05-23 17:16:20 +08:00
    你这也没指定垃圾回收器... 不过看着应该是老年代 CMS+年轻代 ParNew,这个组合我们公司在 18 年的时候就不用了.....
    jdk8 应该就可以使用 G1,虽然不知道你上述是啥原因导致的,但是还是强烈推荐用用 G1,看看效果
    willbetter
        38
    willbetter  
    OP
       2024-05-23 17:39:44 +08:00
    @admol #31 创建大量对象这几个线程我们清楚是为什么,关键这几个线程要创建的对象数量其实是固定的。

    奇怪的现象是它一直在不停的 GC ,这个现象超过了 24 小时,期间其它的线程几乎都没有运行了,猜测是 GC 导致经常 STW 。
    主要是想知道是什么原因原因导致它一直 GC 就是不抛出 OOM 错误,抛出 OOM 错误好歹影响的范围小一些,不至于整个进程像现在“假死”了一样
    willbetter
        39
    willbetter  
    OP
       2024-05-23 17:46:17 +08:00
    @jungledg #32 但它一直在 GC 超过 24 小时了就是不会抛出 OOM ,导致一直处于 STW 状态,其它服务都调不通它了。
    admol
        40
    admol  
       2024-05-23 18:24:29 +08:00
    @willbetter

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

    网上有很 Java 虚拟机参数分析、生成、优化的工具,可以参考下。
    HiShan
        41
    HiShan  
       2024-05-23 18:29:07 +08:00
    @willbetter #38 这个情况我遇到过,因为你的线程创建的对象被占用了,不能 GC 掉,导致 JVM 内存不够,达到了 GC 阀值就会不停的处罚 GC 出现进程卡死的情况。不会 OOM 是因为 JVM 进程没有超过操作系统的内存上限。 你可以试一下把线程中创建的对象,用完之后直接 赋值 null 并且避免被其他地方持有,这样一次 GC 就会回收掉了。或者你把 JVM 的内存调大
    willbetter
        42
    willbetter  
    OP
       2024-05-23 19:10:50 +08:00
    @fingerxie
    @cheng6563
    @liuhailiang
    @me1onsoda
    @Ashe007
    感谢各位大佬的分析,其实我主要的疑问就是我在 38 楼所说的。
    willbetter
        43
    willbetter  
    OP
       2024-05-23 19:15:01 +08:00
    @cheng6563 #33 不排除会存在你说的这种情况,但我们另一台服务器另一个服务也有类似的配置和负载的情况下是会产生 OOM 文件的
    willbetter
        44
    willbetter  
    OP
       2024-05-23 19:28:50 +08:00
    @HiShan 跟你说的情况差不多,那些对象是还有很多没有用完所以没有释放。但我们服务设置了最大堆内存,按理说因为年轻代不够分配内存空间导致 GC ,那最终肯定会把符合条件的对象移动到老年代,一直这样运行最终内存会使用完发生 OOM 啊
    zhangjiashu2023
        45
    zhangjiashu2023  
       2024-05-23 21:31:45 +08:00
    从你提供的 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
        46
    HiShan  
       2024-05-23 22:44:17 +08:00
    @willbetter #44 会有种情况是,比如:第一次创建了 10G 的对象 第二次创建对象也要 10G, 由于 JVM 内存不够所以触发一次 GC 清理了第一次创建的对象. 像这种大对象的创建不会放到年轻代的,会直接放到老年代。而且不用过多关注年轻代老年代没有太多价值。
    tairan2006
        47
    tairan2006  
       2024-05-24 08:33:28 +08:00
    改成 G1 或者 ZGC ,别调优了,啥年代了……
    0xD800
        48
    0xD800  
       2024-05-24 08:52:25 +08:00
    我遇到过几次进程假死的情况,JSTACK 排查不到问题,有几次是卡在日志框架上 logback,JUL 都有。那时候没看 GC 日志。。
    关于   ·   帮助文档   ·   博客   ·   API   ·   FAQ   ·   实用小工具   ·   2532 人在线   最高记录 6679   ·     Select Language
    创意工作者们的社区
    World is powered by solitude
    VERSION: 3.9.8.5 · 27ms · UTC 05:31 · PVG 13:31 · LAX 22:31 · JFK 01:31
    Developed with CodeLauncher
    ♥ Do have faith in what you're doing.