Full GC 频率优化实战
作者：vivo 互联网服务器团队- Li Gang
本文介绍了游戏业务使用 MAT 和 GC 日志等工具对 Full GC 频率进行优化的过程。
一、背景
游戏业务面对用户端的某个工程，每天 Full GC 频率达到 120 次，业务高峰期每 7 分钟就会有一次 Full GC。为了避免情况持续变差，最大程度减少对系统响应时间的负面影响，需要对该工程的 Full GC 频率进行优化。
该项目 JDK 版本为 1.8，老年代使用 CMS 作为垃圾回收器，优化前的部分启动参数如下：
二、工具介绍
在本次优化过程中，我们主要使用了 MAT 和 GC 日志作为排查工具。MAT 是一个功能强大的内存分析工具，而 GC 日志则用于记录 Java 虚拟机中的垃圾回收行为和内存情况。这两者结合起来，能够帮助开发人员深入分析程序的内存使用情况，并进行相应的优化。下文将详细的介绍这两种工具的使用方法，以及对应的优化案例。
2.1 MAT（Memory Analyzer Tool）
Eclipse Memory Analyzer Tool（MAT）是一个开源的 Java 堆转储分析工具。它旨在帮助开发人员识别和消除 Java 堆中的内存泄漏和优化内存使用。MAT 允许用户分析 Java 堆转储文件，识别对象的内存占用情况，查找潜在的内存泄漏和冗余对象，以便执行一些内存优化。
使用 MAT 打开 dump 文件后，首先进入的是上图页面，此页面会显示 dump 包的缩略概览信息，包括堆大小，类数量，对象数量等信息。其中的 Biggest Objects By Retained Size 和 Leak Suspects 在问题明显时会比较有用，但对相对复杂的问题来说帮助不大。笔者比较常用的是下面这几个功能，下文将依次介绍：
2.1.1 Dominator Tree
（1）功能
展示对象的支配关系。对象 A 支配对象 B 代表从 GC Root（也不一定是 GC ROOT，也可以是 unreachable 的起点）达到对象 B 的所有路径都必须经过对象 A，这也意味着对象 A 被垃圾回收后，对象 B 也会被回收。
这个功能相较于下面的 Histogram 更强调对象的引用关系，此外还可以通过 Group By Class/Group By Package/Group By ClassLoader 来进一步的聚合对象。
MAT 的各种图标中会频繁的出现 Shallow Heap Size 和 Retained Heap Size 这两个名词，其含义如下：
Shallow Heap Size：这个对象自身在堆中的大小
Retained Heap Size：这个对象被垃圾回收后会释放的堆内存大小
上图中，情况 1 里对象 A 的 Retained Heap Size = A 的 Shallow Heap Size + B 的 Shallow Heap Size +C 的 Shallow Heap Size，情况 2 里对象 A 的 Retained Heap Size = A 的 Shallow Heap Size + B 的 Shallow Heap Size。
（2）使用方法
①上图为 Group By Class 的 dominator tree。刚打开 dominator tree 时默认是不进行 group 的，此时可以排查单个大对象，排查完单个大对象后，需要将对象 Group 一下才能进行下一步的排查。
② 从上图可以看出，这个堆内的对象内存占用比较分散，说明导致问题的原因可能不止一个，这种情况下只能结合自身业务逐个排查内存占用排在前面的对象。
③ 对这些可疑的对象，右键类，选择 List objects → with outgoing references 展开对象列表，查看这类对象具体存了什么，判断这些对象的值是否可以再分类。
④ 根据对象的值，判断对象的业务含义，确定是哪段代码创建的对象。
⑤ 结合代码，思考这类对象是在新生代还是老年代，如果能确定都在新生代，那这些对象一般不会导致老年代快速增长。
⑥如果在老年代，需要确定其是怎么从新生代晋升的，内存占用是否有上限，上限是多少，一般多长时间能达到上限，再确定有没有问题。
2.1.2 Histogram
功能
histogram 可以显示出各类对象的 Shallow Heap Size 和 Retained Heap Size，Retained Heap Size 默认不展示，需要点击菜单栏的 Calculate Retained Size 进行计算，堆较大时计算耗时较长。
这张表一般和 Dominator Tree 结合使用，我们能看到 char[]占用了较大的内存，但由于 Dominator Tree 里聚合好的 char[]都是顶层支配者，上层不会再有引用，有时无法直接确定这些对象曾经被谁持有过，这时可以通过 Histogram 查看同类对象，找到相似的并且 reachable 的对象来确定这类对象是谁创建的。但是这一步其实可以通过 oql 解决，所以这张表在排查过程中的使用率其实没有 Histogram 高。
2.1.3 OQL
功能
MAT 提供的一种类似 SQL 的查询语句，可以对对象进行过滤。这篇官方文章里给了很多查询语句样例：https://wiki.eclipse.org/MemoryAnalyzer/OQL，这里就简单列一些笔者排查过程中用过的语句，不再赘述：
2.2 GC 日志
GC 日志是记录 Java 虚拟机中垃圾回收活动的日志文件。在 GC 日志中，可以看到包括垃圾回收的时间、类型（如新生代 GC、老年代 GC 等）、回收周期、回收停顿时间、回收前后堆的使用情况等信息。GC 日志打印的信息可以通过以下启动项控制：
三、 案例介绍
在这篇文章中，我们将聚焦于一些具体的案例，涉及到大量被 Dubbo 的 FutureAdapter 引用的对象、Jackson 的 BufferRecycler 导致的大量 char[65536]以及对象晋升年龄阈值过小等问题。通过这些案例，我们将探讨这些具体问题的引起原因以及解决方案。
3.1 大量被 Dubbo 的 FutureAdapter 引用的对象
（1）分析过程
从上图中，我们可以看到 dubbo FutureAdapter 占用了 230M 左右的内存，前面的 PSWMS 对象虽然也占用了 230M 左右的内存，但这是业务使用的本地缓存相关对象，其内存占用是在预期范围内的，因此优先分析 FutureAdapter。先右键 List objects→with outgoing references 展开对象列表。
发现其中有大量大小几乎一致的 FutureAdapter，一个占用内存 328KB 左右，大小和内容几乎一致的对象约有 550 多个，总共占用内存 200M 左右。
FutureAdapter 被用来执行 Dubbo 的异步调用，项目使用的 dubbo 版本为 2.7.18。dubbo 的同步调用本质上是一个异步转同步的过程，发起异步调用将 CompletableFuture 对象放到 ThreadLocal 的 FutureContext 里，然后立刻调用 CompletableFuture.get 方法阻塞获取返回值，获取到返回值后，dubbo 不会主动清理 FutureContext，因此该线程的 ThreadLocal 里会有一条 FutureContext→ FutureAdapter→Result 的引用，如下图：
然而，那 550 多个 FutureAdapter 均为不可达对象，意味着其不被 ThreadLocal 引用，在下次 GC 时会被回收，不过我们无法直接确定这些对象是在老年代还是新生代，有可能这些对象都在新生代，下次 young gc 时就会被回收，不会晋升到老年代，更不会导致老年代增长。
但由于这个列表里的数据有明确的业务含义，可以找到对应的业务接口，此接口单机峰值 qps 约为 2，响应时间约 100ms，每被调用一次，就会创建一个该对象列表，此时该机器的 young gc 频率约为 10s 一次。假设这些对象都在新生代没有晋升老年代，那么这些对象在新生代最大的存活数量约为((接口响应时间 + 两次 young gc 间隔) * 对象创建速度) = (0.1s + 10s) * 2 ≈ 20，而堆里有 550 多个，如果这些对象没有晋升到老年代的话数量上对不上，所以可以推测出这些对象在老年代里，需要等下次 Full GC 时才会被回收。
那么这些不可达的 FutureAdapter 为什么会在老年代？每次执行 dubbo 调用，dubbo 都会用这次调用的 FutureAdapter 替换掉上次调用时存在 FutureContext 里的 FutureAdapter，上次调用的 FutureAdapter 不再被 GC Root 引用，在下次 GC 时被回收。当一个线程相对频繁的执行 dubbo 调用时，FutureAdapter 会被 young gc 回收，不会晋升到老年代。但在本例中，该 dubbo 调用被放到了 corePoolSize=150，maxPoolSize=500 的业务通用线程池中执行，该线程池会执行其他不需要调用 dubbo 服务的任务，并且该线程池的使用率并不高，这就意味着一个线程调用完 dubbo 服务后可能要过一段时间才能执行下一次 dubbo 调用。
由于这个原因导致 FutureAdapter 被放入 ThreadLocal 后，在新生代停留过长时间，最终晋升到老年代，这个"过长时间"对于此项目来说是 6 次 young gc 的间隔时长，这个时长的获取方法会在后续说明。
（2）解决方案
对于此业务来说，这个 dubbo 调用可以改为查询本地缓存，直接解决了问题。除此之外还有其他解决方案，需要结合自身业务选择合适的方案。
直接使用 dubbo 的异步调用，而不是在上层再创建一个线程池来进行调用。
合理设置线程池的大小，提高线程的利用率。
写一个 Dubbo Filter，每次同步调用完后清理 FutureContext（影响面可能较大，需自行评估风险）。
3.2. Jackson 的 BufferRecycler 导致的大量 char[65536]
（1）分析过程
从 dominator tree 中我们能看到 char[]也占用了相当大的一部分内存，展开 char[]，发现其中包含大量的 char[65536]，使用 oql 统计得知不被 gc root 引用的有 1600 个，占用内存 200M 左右，被 gc root 引用的有 500 个，这种 char[65536]里存储的数据均为 http 接口返回值反序列化后的字符。其被 gc root 引用时的链路如下，均被 ThreadLocal 里的 BufferRecycler 引用：
在 Jackson 库中，BufferRecycler 的主要作用是管理缓冲区的重用，可以减少频繁的内存分配和释放，从而降低垃圾回收的负担，提高性能。但从堆上看，这些 char 数组里不可达的数量远大于可达的数量（1600:500），说明其复用率并不高，与其设计的目标不符，需要查看源码才能搞清原因。
项目使用 jackson 的 ObjectMapper.
writeValueAsString()方法对 http 接口返回值进行了反序列化，使用的 Jackson 版本为 2.10，该方法完整的执行流程如下图：
简单来说，jackson 在反序列化时，会将反序列化的结果存储在多段 char[]里，每当最后一个 char[]空间不够存放结果时，就新建一个 char[]，大小为最后使用的 char[]的 1.5 倍，但不超过 65536，反序列化结束后将 char[]列表拼接起来就得到了结果，然后线程会将最后使用的那个 char[]存放到 ThreadLocal。此线程下次反序列化时，会从 ThreadLocal 取出这个 char[]进行复用。这样的一个复用逻辑会有一个问题，参考下图：
图中，_segements 是当前反序列化使用过的 char[]列表，currentSegement 是当前正在使用的 char[]。一个 char[]的大小最大为 65536。在第二次反序列化大对象时至少会创建一个新的大小为 65536 的 char[]（上一次的 char[]是 65536，再创建一个新 char[]其大小仍不能超过 65536）。可以看到在第一次反序列化结束后和第二次反序列化结束后，虽然 ThreadLocal 里存放的 char[]大小都是 65536，但其实它们已经不是同一个对象了。这样的一个替换是没有必要的，完全可以一直复用同一个 char[]。
当业务所有 http 接口的返回值都大且流量也大时，每次保存在 ThreadLocal 里的 char[65536]虽然会在下次反序列化结束时被替换导致其失去引用，但由于其在新生代只存活了一次接口请求的时间，所以不会晋升到老年代，可以被 young gc 回收。但是我们项目用来处理 http 请求的线程池都是同一个，这些接口的返回值只有一部分超过了 65536，在小于的时候 ThreadLocal 里的 char[]不会被替换，当这个 char[]在 ThreadLocal 里停留一段时间后，就会晋升到老年代，从而导致老年代内存增长。
（2）解决方案
关闭 Jackson 的 USE_THREAD_LOCAL_
FOR_BUFFER_RECYCLING，关闭该开关会在每次反序列化时创建一个 BufferRecycler，而不是复用 ThreadLocal 里的 BufferRecycler，这样可能导致 young gc 频率提高。
升级 Jackson 版本，请参考此issue，2.17 版本的 jackson 在调用 releaseByteBuffer 时会避免较小或者相同大小的 char 数组替换原有数组。
由于项目使用的 jackson 版本是 2.10，直接升级到 2.17 的版本跨度较大，可能带来不必要的风险，因此采用了方案 1，上线后，young gc 频率没有明显增加。方案 2 的 issue 里有提到使用 2.16 版本引入的 RecyclerPool 代替基于 ThreadLocal 的实现，这也是解决方案之一。
3.3 对象晋升年龄阈值过小
（1）背景知识
java 对象从新生代晋升到老年代有多种原因，在本项目中，对象的主要晋升原因是在新生代长期存活，这个长期具体是多久有以下两个判断条件：
对象晋升年龄阈值：
可通过-XX:MaxTenuringThreshold 启动项进行配置，对于 CMS，默认值是 6。此参数定义了对象在年轻代存活的最大年龄，如果一个对象在年轻代经过 N 次 GC 后依然存活，它将会被晋升到老年代。
动态年龄判定：
在 survivor 区中小于或等于某年龄的的所有对象大小的总和大于 survivor 空间的一定比例时，大于或等于该年龄的对象就直接进入老年代，这个比例可以通过-XX:TargetSurvivorRatio 启动项控制，默认值为 50，代表 50%。
一个对象的年龄满足上述两个条件之一时，就会晋升到老年代，具体的晋升年龄可以通过在启动项里添加-XX:+PrintTenuringDistribution 获取，添加该参数后的 gc 日志如下图：
其中区域 2 的(max 6)代表-XX:MaxTenuringThreshold 启动项配置的值，也就是说对象到达这个年龄一定会晋升，而 new threshold 6 代表对象实际晋升的年龄，上图代表这次 young gc 因对象到达年龄阈值会导致 9946864 bytes 的对象晋升。
区域 1 代表动态年龄判定所需的空间大小，也就是(survivor 空间大小 x targetSurvivotRatio)。此项目堆的单个 survivor 空间为 200M，所以只要在 survivor 区中小于或等于某年龄的所有对象大小的总和大于 200Mx50%，大于或等于该年龄的对象就会晋升，。
而下图的对象是因为动态年龄判定才晋升的，这次 young gc 因动态年龄判定会导致 38660424 bytes 的对象晋升：
（2）分析过程
优化前+调参前：
在进行 dubbo 和 jackson 以及其他业务代码上的优化前，我们保存了当时的 gc 日志，可以看到大部分对象都是因为年龄到达 6 晋升的，每次 young gc 约有 10M~16M 左右的对象晋升，显然对象的晋升年龄阈值太小，需要调大。
优化后+调参前：
在调整 JVM 参数之前，我们决定先着手进行业务上的优化。因为直接进行参数调整可能会治标不治本，无法消除潜在的隐患。在完成业务代码上的优化后，可以看到此时由于年龄达到 6 这一阈值晋升的对象大小从最开始的 10M~16M 降为了 4M 以下，意味着在新生代长期存活的对象数量明显减少了，但仍然有优化空间。
（3）解决方案
在完成业务代码上的优化后，我们对 JVM 参数进行了调整。将-XX:MaxTenuringThreshold 参数改为 15，-XX:TargetSurvivorRatio 改为 75%（实际上，通过调参后的 gc 日志我们能确定对于这个项目来说，50%也已经够用，因为年龄 1 到 15 的对象占用的总内存只有 38M 左右，远远小于单个 survivor 空间的 50%），以延长对象在新生代的存活时间。我们可以观察到，尽管会有一些对象存活到年龄 15 的阈值才晋升，但是这部分对象的总大小变小了，大部分情况下都是小于 2M。这部分对象通过添加监控的方式判断大概率是被移除（大小不足被淘汰，过期等原因）的 caffeine 本地缓存。
在经过上述一系列优化措施以及一些其他问题的修复后，该工程的 Full GC 频率从最初的每天 120 次，总耗时 1 分钟到 1.5 分钟，成功降低到每天约 30 次左右，总耗时控制在 15 秒到 25 秒之间。
① GC 次数优化曲线
② GC 总耗时优化曲线
总的来说，进行 GC 优化时，可以使用以下工具分析当前内存/GC 情况：
先用 jamp 生成 dump 文件，再使用 MAT 进行分析，找到可能引发问题的对象。
使用内存分配火焰图找到哪些代码在频繁的分配内存。
使用 GC 日志分析 GC 情况，了解 GC 频率/触发 GC 的原因等信息。
使用这些工具找到问题后，可以修改对应的业务代码或者调整 JVM 相关参数，以优化 Full GC 频率。
版权声明: 本文为 InfoQ 作者【vivo互联网技术】的原创文章。
原文链接:【http://xie.infoq.cn/article/8f9dff0ffeb4b4d6f56c536f0】。文章转载请联系作者。
官方公众号：vivo互联网技术，ID：vivoVMIC 2020-07-10 加入
分享 vivo 互联网技术干货与沙龙活动，推荐最新行业动态与热门会议。
评论