[GC调优案例+GC日志如何分析] 接口耗时下降60%，CPU负载降低30[GC调优案例+GC日志如何分析] 文章主要

线上问题描述

分析GC日志案例

1.1背景

我所负责的 A 服务每天的凌晨会定时执行一个批量任务，每天执行时都会触发 GC 频率告警，偶尔单机 CPU 负载超过 60%时，会触发 CPU 高负载告警。

曾经有考虑过通过单机限流器，限制任务执行速率，从而降低机器负载。然而因为业务上希望定时任务尽快执行完，所以优化方向就放在了如何降低 CPU 负载，如何降低 GC 频率。

1.2服务配置

版本：java8
GC 回收器：ParNew + CMS
硬件：8 核 16G 内存，Centos6.8
高峰期CPU 平均负载（分钟）超过 50%（每个公司计算口径可能不同。我司的历史经验超过 70%后，接口性能将会快速恶化）

1.3优化前GC情况

高峰期 Young GC频率 70次/min，单次 ygc 平均时间 125ms；
高峰期 Full GC频率每 3 分钟 1 次；单次 fgc 平均时间 610ms。

1.4优化前GC参数

参数配置说明

-Xmx6g
-Xms6g 堆内存大小为6G
-XX:NewRatio=4老年代的大小是新生代的 4 倍，即老年代占4.8G，新生代占1.2G
-XX:SurvivorRatio=8 Eden:From:To= 8:1:1，即Eden区占0.96G，两个Survivor区分别占0.12G
-XX:ParallelCMSThreads=4 设置 CMS 垃圾回收器使用的并行线程数为4
-XX:CMSInitiatingOccupancyFraction=72 设置老年代使用率达到 72% 时触发 CMS 垃圾回收。
-XX:+UseParNewGC启用 ParNew 作为年轻代垃圾回收器
-XX:+UseConcMarkSweepGC启用 CMS 垃圾回收器

问题分析定位

2.1增加日志并分析日志

由于打印GC信息不足，无法分析问题。因此添加了以下GC 打印参数

-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:+PrintCommandLineFlags
-XX:+PrintGCDateStamps
-XX:+PrintHeapAtGC
-XX:+PrintTenuringDistribution
-XX:+PrintGCApplicationStoppedTime
-XX:+PrintReferenceGC

2.2 提前晋升现象

配置如上参数后，每次发生 younggc后，都会打印详细的 younggc 日志。通过分析 gc 日志，我发现日志中经常出现类似内容。

Desired survivor size 61054720 bytes, new threshold 2 (max 15)

new threshold是新的晋升阈值，是指对象在新生代经过 new threshold 轮 younggc后，就能晋升到老年代，这个值通过 MaxTenuringThreshold配置，默认值是 15，在原有理解中阈值是固定值 15，实际上这个值会动态调整

为了能更好地适应不同程序的内存状况，虚拟机并不是永远地要求对象的年龄必须达到了 MaxTenuringThreshold 才能晋升老年代，如果在Survivor空间中相同年龄所有对象大小的总和大于Survivor空间的一半，年龄大于或等于该年龄的对象就可以直接进入老年代，无须等到MaxTenuringThreshold中要求的年龄

Desired survivor 一般是 Survivor 区的一半。假设年龄 1至N 的对象大小，超过了 Desired size，那么下一次 GC 的晋升阈值就会调整为 N。举个例子，假设 age=1的对象为 80M，超过了 61M，那么下一次GC 的晋升阈值就是 1，所有超过 1 的对象都会晋升到老年代，无需等到年龄到 15。

2.3 老年代增长速度过快

为了印证是否发生提前晋升，我通过监控查看到在事发时间，老年代内存的涨幅和 Survivor的内存基本一致，看来新生代的对象确实提前晋升到老年代了。grep 分析历次 GC 后的晋升阈值后，我发现绝大部分情况下，新生的对象无法在 15 次 GC后进入到老年代，基本上三次以后就会提前晋升到老年代…… 这解释了为什么会发生频繁的 FullGC。假设每次提前晋升 100M 到老年代，每分钟超过 15 次 ygc，则每分钟将会有 1.5G 对象进入老年代。因为频繁地提前晋升，老年代的增长速度极快。在高峰期时，往往 2 至 3 分钟左右，老年代内存就会触达 72% 的阈值，从而发生 FullGC。

2.4 新生代内存不足

即便老年代配置 4.8G 的大内存，但频繁地发生提前晋升，老年代也很快被打满。这背后的根本原因在于新生代的内存太小了。新生代，总共 1.2G 大小，Survivor才 120M，这远远不够。于是我们调整了内存分配

优化后效果

3.1优化后GC参数

虽然改动不大，但是优化效果十分显著。由于公司监控有水印，我无法截图取证，敬请谅解。

调整后如下

-Xmx10g -Xms10g -Xmn6g
-XX:SurvivorRatio=8

堆内存由 6G 增加到 10G
大部分堆内存（6G）分配给新生代。新生代内存从 1.2G 增加到 6G。
Eden:From:To 的比例依然是 8:1:14.
Eden大小从 0.96 G 增加到 4.8 G。
Survivor区由 120 M 增加到 600 M

3.2 GC频率明显下降

• 高峰期 ygc 70 次/min 降到了 12 次/min，下降幅度达83%（单机 500 QPS） • 高峰期 fgc 三分钟1 次，降到了每天 1 次 Full GC。 • younggc 和 fullgc 单次平均耗时保持不变。

3.3 CPU 负载降低 30%+

• 优化之前高峰期 cpu 平均负载超过 50%；优化后降到了不足 30%，高峰期负载下降了 40%。 • CPU负载每日平均值由 29%，降到了 20%。日平均负载下降了 32%。

3.4 核心接口性能显著提升核心接口耗时下降明显

• 接口 A 高峰期 TPS 100/秒， tp999 由 200毫秒降到了 150 毫秒， tp9999 由 400 毫秒降到了 300 毫秒，接口耗时下降超过 25%！
• 接口 B 高峰期QPS 250/秒， tp999 由 190 毫秒降到了 120 毫秒， tp9999 由 450 毫秒下降到了 150 毫秒，接口耗时下降分别下降 37%和 67%！
• 接口 B 低峰期降幅更加明显，tp999 由 80 毫秒降到了 10 毫秒，下降幅度接近 90%！

后来又适当微调了 JVM 内存分配比例，但是优化效果不明显。

总结

经过此次 GC 优化经历，我学到了如下经验

要通过 GC 日志分析 GC 问题。
调整JVM 内存，保证足够的新生代内存。
优化 GC 可以降低接口耗时，提高接口可用性。
优化 GC 可以有效降低机器 CPU 负载，提高硬件使用率。反过来当接口性能差、cpu负载高的时候，不妨分析一下 GC ，看看有没有优化空间。

如何分析gc日志

ParNew + CMS 垃圾回收器的 young gc 日志

1) 历史GC次数

49590 {Heap before GC invocations=1807 (full 5):

代表 JVM 启动后，共发生 1807 次 young gc，5 次 full gc。

2) 新生代大小

49591 par new generation total 5976896K, used 5864962K [0x0000000540800000, 0x00000006c0800000, 0x00000006c0800000)

par new generation 代表新生代大小 5976M，已使用 5864M。这是大约值，近似除以 1000 即可，无需精确到 1024。

3) Eden Space 新生代Eden大小

49592 eden space 5662336K, 100% used [0x0000000540800000, 0x000000069a1a0000, 0x000000069a1a0000)

eden space 5662336K, 100% used 代表新生代使用率100%，一般发生 ygc时，eden 区为 100%。

4) Survivor 区大小

49593 from space 314560K, 64% used [0x00000006ad4d0000, 0x00000006b9ab08c0, 0x00000006c0800000)
49594 to space 314560K, 0% used [0x000000069a1a0000, 0x000000069a1a0000, 0x00000006ad4d0000)

from space 314560K 代表Survivor区大小 314M，
Survivor区大小可通过 SurvivorRadio配置，默认为 8，
即 Eden和 Survivor 比例=8:2，
其中 Survivor区分为 From 和 TO，各占 1 半。实际比例Eden: From:TO=8:1:1

5) GC前老年代大小

49595 concurrent mark-sweep generation total 4194304K, used 1986511K [0x00000006c0800000, 0x00000007c0800000, 0x00000007c0800000)

这行代表发生 younggc 前，老年代总共 4194M，已使用 1986M。

6) 元空间大小

49596 Metaspace used 333223K, capacity 338440K, committed 338560K, reserved 1357824K

元空间大小，存储了类的二进制数据，注意非 Class 对象。其中 Meta 区分为 ClassSpace 和 NonClass Space，nonClass space包含常量池等。

used、capacity、committed、reserved 这 4 个值逐渐变大。

7) YoungGC 失败原因

49597 class space used 30014K, capacity 30770K, committed 30848K, reserved 1048576K

49598 2024-05-22T11:08:43.619+0800: 157559.408: [GC (Allocation Failure) 2024-05-22T11:08:43.620+0800: 157559.409: [ParNew2024-05-22T11:08:43.678+0800: 157559.467: [SoftReference, 0 refs, 0.0004327 secs]202 4-05-22T11:08:43.678+0800: 157559.467: [WeakReference, 5244 refs, 0.0004675 secs]2024-05-22T11:08:43.679+0800: 157559.468: [FinalReference, 1436 refs, 0.0006603 secs]2024-05-22T11:08:43.679+0800: 1575 59.468: [PhantomReference, 1 refs, 0 refs, 0.0030363 secs]2024-05-22T11:08:43.683+0800: 157559.471: [JNI Weak Reference, 0.0000337 secs]

Allocation Failure 说明 ygc 原因是空间不足，一般都是这个原因

8) 为什么会发生提前晋升

49599 Desired survivor size 161054720 bytes, new threshold 15 (max 15) Desired survivor 一般是 Survivor 区的一半。假设年龄 1至N 的对象大小，超过了 Desired size，那么下一次 GC 的晋升阈值就会调整为 N。举个例子，假设 age=1的对象为 300M，超过了 161M，那么下一次GC 的晋升阈值就是 1，所有超过 1 的对象都会晋升到老年代，无需等到年龄到 15。

注意：调整的是下一次 GC 的阈值，而非本次。

49600 - age 1: 154907320 bytes, 154907320 total
49601 - age 2: 3302040 bytes, 158209360 total 
49602 - age 3: 2765624 bytes, 160974984 total

以上是每一代对象的大小，其中 total 部分是 1-N 代的总和。

为了能更好地适应不同程序的内存状况，虚拟机并不是永远地要求对象的年龄必须达到了MaxTenuringThreshold才能晋升老年代，如果在Survivor空间中相同年龄所有对象大小的总和大于Survivor空间的一半，年龄大于或等于该年龄的对象就可以直接进入老年代，无须等到MaxTenuringThreshold中要求的年龄

《深入理解Java虚拟机》一书中提到，对象晋升年龄的阈值是动态判定的。

JVM按年龄给对象分组，取total（累加值，小于等与当前年龄的对象总大小）最大的年龄分组，如果该分组的total大于survivor的一半，就将晋升年龄阈值更新为该分组的年龄

注意：不是是超过survivor一半就晋升，超过survivor一半只会重新设置晋升阈值（threshold），在下一次GC才会使用该新阈值

9) 并行GC 及耗时

49603 : 5864962K->245458K(5976896K), 0.0632069 secs] 7851473K->2231969K(10171200K), 0.0638268 secs] [Times: user=0.46 sys=0.01, real=0.07 secs]

[Times: user=0.46 sys=0.01, real=0.07 secs] 说明了 GC 耗时，其中 user+sys是 CPU的耗时，real是实际耗时，即应用实际感受到的暂停时间。由于新生代使用 ParNew 是多线程 GC，所以 real 是多线程并行后处理的时间。

ParallelGCThreads 可以设置并行线程数，8 核及以下默认是 cpu 核数，8 核以上：3 +（（5*CPU）/ 8）。

所以越是强劲的硬件性能，GC 暂停时间越短！

10) 新生代 younggc耗时高的原因

49604 Heap after GC invocations=1808 (full 5):
49605 par new generation total 5976896K, used 245458K [0x0000000540800000, 0x00000006c0800000, 0x00000006c0800000)

par new generation total 5976896K, used 245458K 此刻代表新生代 GC 后大小，GC 后，由于 Eden 区一般为 0，已使用部分一般是 From 区大小。

49606 eden space 5662336K, 0% used [0x0000000540800000, 0x0000000540800000, 0x000000069a1a0000)
49607 from space 314560K, 78% used [0x000000069a1a0000, 0x00000006a91548b0, 0x00000006ad4d0000)
49608 to space 314560K, 0% used [0x00000006ad4d0000, 0x00000006ad4d0000, 0x00000006c0800000)

from space 314560K, 78% used：注意这代表本次 GC 幸存下对象的大小，这个值越大，代表本次 GC，Survivor From 和 To 拷贝的对象越大！GC 耗时也就越长！据我的经验~ 要想younggc耗时在 50ms 以下，Survivor 幸存下对象最好少于 200M。

注意：拷贝内存对象有耗时，拷贝越多耗时越长，所以Survivor幸存对象大小影响了younggc的耗时。

11) 老年代增长较快的原因！

49609 concurrent mark-sweep generation total 4194304K, used 1986511K [0x00000006c0800000, 0x00000007c0800000, 0x00000007c0800000)

concurrent mark-sweep generation total 这是老年代 GC 后的内存使用情况。使用这个值减去 GC 前的使用率，就是本次 younggc，老年代的增长情况

这个值要结合 new threshold N 即晋升阈值一起看，如果经常发生提前晋升，老年代增长速度一定会很快，就会导致更频繁的FullGC。

其根本原因大概率是：Survivor 空间不足，可以适当降低 SurvivorRadio，或者增加整个新生代大小，从而增加 Survivor 区大小，减少提前晋升现象的发现。

老年代增长较快的后果是：Full gc会更加频繁~ 系统耗时增加明显。

注意：提前晋升到老年代的对象越多，younggc 耗时越长，这是因为Cpu 大量拷贝对象时也是非常耗时的。我遇到的例子，有一次提前晋升了 230M，gc 耗时增加到了 200ms+，而平常只有 90ms，这多出来的时间就是因为需要拷贝的对象变多了，并且相比新生代From拷贝到TO，跨代拷贝耗时更长。

12) 应用暂停时间，cpu核数越多，younggc越快

49610 Metaspace used 333223K, capacity 338440K, committed 338560K, reserved 1357824K
49611 class space used 30014K, capacity 30770K, committed 30848K, reserved 1048576K
49612 }
49613 2024-05-22T11:08:43.684+0800: 157559.472: Total time for which application threads were stopped: 0.0663871 seconds, Stopping threads took: 0.0002652 seconds

Total time for which application threads were stopped: 0.0663871 seconds 这代表应用暂停时间，和上面的 real 时间基本一致。

注意：ParNew GC 是并行GC，cpu核数越多，younggc越快。

如何配置才能让以上内容打在GC 日志中？

以上 GC 日志并不是默认就有的，需要额外配置，才会打印。

-XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintCommandLineFlags -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:+PrintTenuringDistribution -XX:+PrintGCApplicationStoppedTime -XX:+PrintReferenceGC

GC日志解析总结

如果经常性的发生提前晋升情况，需要调整新生代大小和Survivor 区大小。
调整 SurvivorRadio 比例
调整整个新生代比例，例如 -xmn=2g调整到 -xmn=6g，gc情况会大大改善
提前晋升会增加 younggc 耗时，因为跨代拷贝是很耗时的。
注意 Survivor 区幸存对象大小是否过大，这也是影响 younggc 耗时的因素。

[GC调优案例+GC日志如何分析] 接口耗时下降60%，CPU负载降低30