一次线上JVM调优实践，FullGC40次/天到10天一次的优化过程
共 4410字，需浏览 9分钟
·
2021-05-29 09:35
作者 | cmlbeliever
通过这一个多月的努力，将FullGC从40次/天优化到近10天才触发一次，而且YoungGC的时间也减少了一半以上，这么大的优化，有必要记录一下中间的调优过程。
对于JVM垃圾回收，之前一直都是处于理论阶段，就知道新生代，老年代的晋升关系，这些知识仅够应付面试使用的。前一段时间，线上服务器的FullGC非常频繁，平均一天40多次，而且隔几天就有服务器自动重启了，这表明的服务器的状态已经非常不正常了，得到这么好的机会，当然要主动请求进行调优了。未调优前的服务器GC数据，FullGC非常频繁。
首先服务器的配置非常一般（2核4G），总共4台服务器集群。每台服务器的FullGC次数和时间基本差不多。其中JVM几个核心的启动参数为：
-Xms1000M
-Xmx1800M -Xmn350M -Xss300K
-XX:+DisableExplicitGC
-XX:SurvivorRatio=4 -XX:+UseParNewGC
-XX:+UseConcMarkSweepGC
-XX:CMSInitiatingOccupancyFraction=70
-XX:+CMSParallelRemarkEnabled
-XX:LargePageSizeInBytes=128M
-XX:+UseFastAccessorMethods
-XX:+UseCMSInitiatingOccupancyOnly
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:+PrintHeapAtGC
-Xmx1800M：设置JVM最大可用内存为1800M。
-Xms1000m：设置JVM初始化内存为1000m。此值可以设置与-Xmx相同，以避免每次垃圾回收完成后JVM重新分配内存。
-Xmn350M：设置年轻代大小为350M。整个JVM内存大小=年轻代大小 + 年老代大小 + 持久代大小。持久代一般固定大小为64m，所以增大年轻代后，将会减小年老代大小。此值对系统性能影响较大，Sun官方推荐配置为整个堆的3/8。
-Xss300K：设置每个线程的堆栈大小。JDK5.0以后每个线程堆栈大小为1M，以前每个线程堆栈大小为256K。更具应用的线程所需内存大小进行调整。在相同物理内存下，减小这个值能生成更多的线程。但是操作系统对一个进程内的线程数还是有限制的，不能无限生成，经验值在3000~5000左右。
第一次优化
一看参数，马上觉得新生代为什么这么小，这么小的话怎么提高吞吐量，而且会导致YoungGC的频繁触发，如上如的新生代收集就耗时830s。初始化堆内存没有和最大堆内存一致，查阅了各种资料都是推荐这两个值设置一样的，可以防止在每次GC后进行内存重新分配。基于前面的知识，于是进行了第一次的线上调优：提升新生代大小，将初始化堆内存设置为最大内存
-Xmn350M -> -Xmn800M -XX:SurvivorRatio=4 -> -XX:SurvivorRatio=8 -Xms1000m ->-Xms1800m
将SurvivorRatio修改为8的本意是想让垃圾在新生代时尽可能的多被回收掉。就这样将配置部署到线上两台服务器（prod，prod2另外两台不变方便对比）上后，运行了5天后，观察GC结果，YoungGC减少了一半以上的次数，时间减少了400s，但是FullGC的平均次数增加了41次。YoungGC基本符合预期设想，但是这个FullGC就完全不行了。
服务压测发现怪异现象，一顿排查，揪出“TIME_WAIT”这个内鬼
就这样第一次优化宣告失败。
第二次优化
在优化的过程中，我们的主管发现了有个对象T在内存中有一万多个实例，而且这些实例占据了将近20M的内存。于是根据这个bean对象的使用，在项目中找到了原因：匿名内部类引用导致的，伪代码如下：
public void doSmthing(T t){
redis.addListener(new Listener(){
public void onTimeout(){
if(t.success()){
//执行操作
}
}
});
}
由于listener在回调后不会进行释放，而且回调是个超时的操作，当某个事件超过了设定的时间（1分钟）后才会进行回调，这样就导致了T这个对象始终无法回收，所以内存中会存在这么多对象实例。
通过上述的例子发现了存在内存泄漏后，首先对程序中的error log文件进行排查，首先先解决掉所有的error事件。然后再次发布后，GC操作还是基本不变，虽然解决了一点内存泄漏问题，但是可以说明没有解决根本原因，服务器还是继续莫名的重启。
内存泄漏调查
经过了第一次的调优后发现内存泄漏的问题，于是大家都开始将进行内存泄漏的调查，首先排查代码，不过这种效率是蛮低的，基本没发现问题。于是在线上不是很繁忙的时候继续进行dump内存，终于抓到了一个大对象。
这个对象竟然有4W多个，而且都是清一色的ByteArrowRow对象，可以确认这些数据是数据库查询或者插入时产生的了。于是又进行一轮代码分析，在代码分析的过程中，通过运维的同事发现了在一天的某个时候入口流量翻了好几倍，竟然高达83MB/s，经过一番确认，目前完全没有这么大的业务量，而且也不存在文件上传的功能。咨询了阿里云客服也说明完全是正常的流量，可以排除攻击的可能。
就在我还在调查入口流量的问题时，另外一个同事找到了根本的原因，原来是在某个条件下，会查询表中所有未处理的指定数据，但是由于查询的时候 where 条件中少加了模块这个条件，导致查询出的数量达40多万条，而且通过log查看当时的请求和数据，可以判断这个逻辑确实是已经执行了的，dump 出的内存中只有4W多个对象，这个是因为dump时候刚好查询出了这么多个，剩下的还在传输中导致的。而且这也能非常好的解释了为什么服务器会自动重启的原因。
解决了这个问题后，线上服务器运行完全正常了，使用未调优前的参数，运行了3天左右FullGC只有5次。
第二次调优
内存泄漏的问题已经解决了，剩下的就可以继续调优了，经过查看 GC log，发现前三次 GullGC 时，老年代占据的内存还不足30%，却发生了FullGC。于是进行各种资料的调查，发现 metaspace 会导致 FullGC 的情况，服务器默认的 metaspace 是 21M，在 GC log 中看到了最大的时候 metaspace 占据了 200M左右，于是进行如下调优，以下分别为 prod1 和 prod2 的修改参数，prod3，prod4保持不变
-Xmn350M -> -Xmn800M -Xms1000M ->1800M -XX:MetaspaceSize=200M -XX:CMSInitiatingOccupancyFraction=75
和
-Xmn350M -> -Xmn600M -Xms1000M ->1800M -XX:MetaspaceSize=200M -XX:CMSInitiatingOccupancyFraction=75
prod1和2只是新生代大小不一样而已，其他的都一致。到线上运行了10天左右，进行对比：
prod1：
prod4：
对比来说，1，2两台服务器 FullGC 远远低于 3，4 两台，而且 1，2 两台服务器的 YounGC 对比 3，4 也减少了一半左右，而且第一台服务器效率更为明显，除了YoungGC 次数减少，而且吞吐量比多运行了一天的3，4两台的都要多（通过线程启动数量），说明 prod1 的吞吐量提升尤为明显。「通过 GC 的次数和 GC 的时间，本次优化宣告成功，且 prod1 的配置更优，极大提升了服务器的吞吐量和降低了 GC 一半以上的时间。」
prod1 中的唯一一次FullGC：
通过 GC log 上也没看出原因，老年代在 cms remark 的时候只占据了 660M 左右，这个应该还不到触发 FullGC 的条件，而且通过前几次的 YoungGC 调查，也排除了晋升了大内存对象的可能，通过 metaspace 的大小，也没有达到 GC 的条件。这个还需要继续调查，有知道的欢迎指出下，这里先行谢过了。
总结
通过这一个多月的调优总结出以下几点：
FullGC一天超过一次肯定就不正常了 发现FullGC频繁的时候优先调查内存泄漏问题 内存泄漏解决后，jvm可以调优的空间就比较少了，作为学习还可以，否则不要投入太多的时间 如果发现CPU持续偏高，排除代码问题后可以找运维咨询下阿里云客服，这次调查过程中就发现CPU 100%是由于服务器问题导致的，进行服务器迁移后就正常了。 数据查询的时候也是算作服务器的入口流量的，如果访问业务没有这么大量，而且没有攻击的问题的话可以往数据库方面调查 有必要时常关注服务器的GC，可以及早发现问题
以上是最近一个多月 JVM 调优的过程与总结，如有错误之处欢迎指正。
往期推荐
关注我回复「加群」，加入Spring技术交流群