一次线上JVM调优实践，FullGC40次/天到10天一次的优化过程

客官°小女子只卖身不卖艺 2023-01-13 10:08 109阅读 0赞

## 你知道的越多，不知道的就越多，业余的像一棵小草！ ##

你来，我们一起精进！你不来，我和你的竞争对手一起精进！

## 编辑：业余草 ##

blog.csdn.net/cml\_blog/article/details/81057966

## 推荐：https://www.xttblog.com/?p=5180 ##

通过这一个多月的努力，将FullGC从40次/天优化到近10天才触发一次，而且YoungGC的时间也减少了一半以上，这么大的优化，有必要记录一下中间的调优过程。

对于JVM垃圾回收，之前一直都是处于理论阶段，就知道新生代，老年代的晋升关系，这些知识仅够应付面试使用的。前一段时间，线上服务器的FullGC非常频繁，平均一天40多次，而且隔几天就有服务器自动重启了，这表明的服务器的状态已经非常不正常了，得到这么好的机会，当然要主动请求进行调优了。未调优前的服务器GC数据，FullGC非常频繁。

![7fa509344acf6dd1dfa47300cbf2fb8e.png][]

首先服务器的配置非常一般（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就完全不行了。

![4833be55f1a4936c238662c1af87f208.png][]

就这样第一次优化宣告失败。

## 第二次优化 ##

在优化的过程中，我们的主管发现了有个对象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内存，终于抓到了一个大对象。

![cff7b35ae36d83feaefe93c1c1b0622a.png][]

dump内存

![6e3aa922671a4a37d83d3c57e30ccd98.png][]

ByteArrowRow对象

这个对象竟然有4W多个，而且都是清一色的ByteArrowRow对象，可以确认这些数据是数据库查询或者插入时产生的了。于是又进行一轮代码分析，在代码分析的过程中，通过运维的同事发现了在一天的某个时候入口流量翻了好几倍，竟然高达83MB/s，经过一番确认，目前完全没有这么大的业务量，而且也不存在文件上传的功能。咨询了阿里云客服也说明完全是正常的流量，可以排除攻击的可能。

![9482f7867a8c6c3cbddb47f8c57fbaa4.png][]

入口流量翻倍

就在我还在调查入口流量的问题时，另外一个同事找到了根本的原因，原来是在某个条件下，会查询表中所有未处理的指定数据，但是由于查询的时候 where 条件中少加了模块这个条件，导致查询出的数量达40多万条，而且通过log查看当时的请求和数据，可以判断这个逻辑确实是已经执行了的，dump 出的内存中只有4W多个对象，这个是因为dump时候刚好查询出了这么多个，剩下的还在传输中导致的。而且这也能非常好的解释了为什么服务器会自动重启的原因。

解决了这个问题后，线上服务器运行完全正常了，使用未调优前的参数，运行了3天左右FullGC只有5次。

![311ce1c815161de1bf359f093d536845.png][]

FullGC统计

## 第二次调优 ##

内存泄漏的问题已经解决了，剩下的就可以继续调优了，经过查看 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：

![50830aeb8624704ae9453679f89235c0.png][]

FullGC 统计

![877a0f6d12fc3d99e2972409c385b889.png][]

FullGC 统计

![77f3ba9a3a78a14f2bae085b2733faa7.png][]

FullGC 统计

prod4：

![e398ca4c5299500cd18782bae951430c.png][]

FullGC 统计

对比来说，1，2两台服务器 FullGC 远远低于 3，4 两台，而且 1，2 两台服务器的 YounGC 对比 3，4 也减少了一半左右，而且第一台服务器效率更为明显，除了YoungGC 次数减少，而且吞吐量比多运行了一天的3，4两台的都要多（通过线程启动数量），说明 prod1 的吞吐量提升尤为明显。**「通过 GC 的次数和 GC 的时间，本次优化宣告成功，且 prod1 的配置更优，极大提升了服务器的吞吐量和降低了 GC 一半以上的时间。」**

prod1 中的唯一一次FullGC：

![e262ba88bfce647f8ef2ac789b1f395e.png][]

FullGC

![51c2e41b0121404cbf8dd1e1f0a60ce9.png][]

FullGC

通过 GC log 上也没看出原因，老年代在 cms remark 的时候只占据了 660M 左右，这个应该还不到触发 FullGC 的条件，而且通过前几次的 YoungGC 调查，也排除了晋升了大内存对象的可能，通过 metaspace 的大小，也没有达到 GC 的条件。这个还需要继续调查，有知道的欢迎指出下，这里先行谢过了。

## 总结 ##

通过这一个多月的调优总结出以下几点：

*  FullGC一天超过一次肯定就不正常了
 *  发现FullGC频繁的时候优先调查内存泄漏问题
 *  内存泄漏解决后，jvm可以调优的空间就比较少了，作为学习还可以，否则不要投入太多的时间
 *  如果发现CPU持续偏高，排除代码问题后可以找运维咨询下阿里云客服，这次调查过程中就发现CPU 100%是由于服务器问题导致的，进行服务器迁移后就正常了。
 *  数据查询的时候也是算作服务器的入口流量的，如果访问业务没有这么大量，而且没有攻击的问题的话可以往数据库方面调查
 *  有必要时常关注服务器的GC，可以及早发现问题

以上是最近一个多月 JVM 调优的过程与总结，如有错误之处欢迎指正。

![70e7c6a4f945098e3c5180e23c123435.png][]

[7fa509344acf6dd1dfa47300cbf2fb8e.png]: /images/20221022/0378ef4dc4a64f4aaf1424f8bc726708.png
[4833be55f1a4936c238662c1af87f208.png]: /images/20221022/afce51bfdfbb4b46a9b4c21fcc416d59.png
[cff7b35ae36d83feaefe93c1c1b0622a.png]: /images/20221022/82dd027c176a4946b105b36824d4368c.png
[6e3aa922671a4a37d83d3c57e30ccd98.png]: /images/20221022/71daf10532934d78b7e5af266a518491.png
[9482f7867a8c6c3cbddb47f8c57fbaa4.png]: /images/20221022/5cb56b1bbeef4a70bf6c5237d1620c26.png
[311ce1c815161de1bf359f093d536845.png]: /images/20221022/be23bfc869ef4f59891f413ea8015cea.png
[50830aeb8624704ae9453679f89235c0.png]: /images/20221022/a09066a4d4024c97bd50c8c97336dbc5.png
[877a0f6d12fc3d99e2972409c385b889.png]: /images/20221022/10c04d7bfacf476ca215eddbc39323eb.png
[77f3ba9a3a78a14f2bae085b2733faa7.png]: /images/20221022/b5360fe18d5543538aa2f385fa086a21.png
[e398ca4c5299500cd18782bae951430c.png]: /images/20221022/fadfeb30cb6e4e058ce50bfce524e65a.png
[e262ba88bfce647f8ef2ac789b1f395e.png]: /images/20221022/4db9b58509a04d65ad343537fa7e462a.png
[51c2e41b0121404cbf8dd1e1f0a60ce9.png]: /images/20221022/ab6261a698724dd090dd8b990b0d8543.png
[70e7c6a4f945098e3c5180e23c123435.png]: /images/20221022/59a2401a0dc24fa0915d368cb348ff17.png