Full GC 频率优化实战

作者：vivo 互联网服务器团队- Li Gang

本文介绍了游戏业务使用MAT和GC日志等工具对 Full GC频率进行优化的过程。

一、背景

游戏业务面对用户端的某个工程，每天Full GC频率达到120次，业务高峰期每7分钟就会有一次Full GC。为了避免情况持续变差，最大程度减少对系统响应时间的负面影响，需要对该工程的Full GC频率进行优化。

该项目JDK版本为1.8，老年代使用CMS作为垃圾回收器，优化前的部分启动参数如下：

-Xms4608M -Xmx4608M -Xmn2048M -XX:MetaspaceSize=320M -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=92 -XX:+UseCMSInitiatingOccupancyOnly

二、工具介绍

在本次优化过程中，我们主要使用了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，这里就简单列一些笔者排查过程中用过的语句，不再赘述：

// 字符串模糊匹配
SELECT * FROM char[] b where toString(b) LIKE ".*traceId.*"
// 查找地址>0x700000000的对象
SELECT * FROM java.lang.Object t WHERE  toHex(t.@objectAddress) >= "0x700000000"
// 查找长度等于73并且retained heap size>1000B 的对象
SELECT * FROM java.lang.Object[] a where a.@length=73 and a.@retainedHeapSize>1000
// 查找长度等于65536并且上层有引用的对象
SELECT * FROM char[] a where a.@length=65536 and (inbounds(a).size()>0)

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调用可以改为查询本地缓存，直接解决了问题。除此之外还有其他解决方案，需要结合自身业务选择合适的方案。

1. 直接使用dubbo的异步调用，而不是在上层再创建一个线程池来进行调用。
2. 合理设置线程池的大小，提高线程的利用率。
3. 写一个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）解决方案

1. 关闭Jackson的USE\_THREAD\_LOCAL_

   FOR\_BUFFER\_RECYCLING，关闭该开关会在每次反序列化时创建一个BufferRecycler，而不是复用ThreadLocal里的BufferRecycler，这样可能导致young gc频率提高。

2. 升级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情况：

1. 先用jamp生成dump文件，再使用MAT进行分析，找到可能引发问题的对象。
2. 使用内存分配火焰图找到哪些代码在频繁的分配内存。
3. 使用GC日志分析GC情况，了解GC频率/触发GC的原因等信息。

使用这些工具找到问题后，可以修改对应的业务代码或者调整JVM相关参数，以优化Full GC频率。