三十万次Full GC

症状

今天测试同学反馈API耗时很长，超过3秒的比例很高。 查看日志发现，小部分请求耗时比较大，约2秒左右，但是比例不高，与反馈比例有点不一致。后来发现是有一台服务器停止工作了（进程假死），对请求没有响应，也没有拒绝，重启后问题缓解。 因为第一次出现，没有引起重视。但是过了几个小时候，相同的问题又出现在另外一台服务器上，狗日的墨菲定律。

思路

查日志

• 先检查日志，找出耗时很长的请求，看看耗时都耗费在哪些地方：但是没有很好的结果，反而发现一些很奇怪的事情，有的相邻的两条日志之间的时间差有1秒多，但是这1秒没看出来服务器做了任何事情（没有思路，而且是第一次遇到，先放一边去了）

查进程状态

• 后来发现有服务器假死，不响应任何请求，就先top查看CPU，内存等服务器信息，发现都还算正常，甚至还在慢慢输出一些日志信息（也是相当莫名其妙啊）
• 为了不影响用户，先在负载均衡设备上去掉假死的服务器，保留现场
• jstack PID: 程序不响应，提醒使用-F参数，但是还是报错（错误不记得了，不过记得是JVM内部的异常）
• jmap导出内存映射： 程序也不响应，使用-F参数，还是报错
• 这个时候，真的有点不知所措了，各种工具都用不上啊。不过top命令还是看出，进程确实是正常的，CPU的占用率也有变化。

意外发现

本来应该早就该发现的

• 再去看日志，发现业务日志基本停止了，但是gc日志一直在刷新，而且都是Full GC，频率很快，差不多2秒一次（一次时间约1.5秒）。仔细分析日志可以看出，Full GC后回收的内存特别少
• jstat -gcutil PID: 发现Full GC高达三十多万次
• 这个时候我们基本确定是因为系统内存占用量太大，导致一直Full GC，又因为回收的内存很少，所以马上又需要再次Full GC，JVM根本没有时间去响应业务请求
• 而且我们也在其他几台服务器上也发现了同样的问题，只是那些服务器的内存还没有这么满，JVM还有部分时间可以用来响应用户请求

内存泄漏？

接下来就要定位占用内存的元凶了

• 在其他服务器上使用jmap导出内存映像，使用jdk自带的jvmvisual分析，通过类的排序看到一些类的实例数特别多。但是跟算法同学计算了一下，基本还算正常。然后通过占用内存数排序，发现double[]占用了63%的内存，我们怀疑可能是算法用到了double[]，但是没有及时释放，存在内存泄漏（感觉很明显了）。

谁偷走了内存？

• 元凶找到了，但是要找到使用者。因为jvmvisual看不出来对象之间的引用关系，我们也很难判断是哪些对象引用了double[]。我们就在代码中搜索double[]，但是分析了好久，也没有看出内存泄漏的影子。
• （不开心）再次不知所措，虽然我们肯定是内存泄露，但却没有好的办法定位源头
• 这个时候，我们想到了jhat和大名鼎鼎的mat(Eclipse Memory Analyzer )，最后使用mat来执行内存分析（因为直到mat分析完毕，jhat都还没打开内存文件）
• mat之前使用不太熟悉，这次就摸索着打开各种图表查看，最后找到了对象引用关系。发现存在34个特别大的double[]，再跟算法同学求证，就是存在一个特别大的模型，而且每个应用都有独立的模型。每个模型占用内存大约100M。
• 至此，问题已经完全定位，元凶也已经找到

原因

• 内存占用太大，导致内存不足，Full GC过于频繁，JVM无法影响请求

办法

• 减小模型大小，不同算法实例共享模型

结果

• 内存占用降下来了，Full GC也恢复到正常的个位数

总结

• （先收集信息，再定位问题）事后看来，问题其实还是有很多表现，只是没有第一时间发现，而是着急去快速定位问题了。如果一开始就使用了jstat -gcutil PID查看的话，就可以很快的地发现Full GC的问题
• 知道是Full GC导致响应时长很慢，就明白了为什么相邻的两行日志的时间会差那么多了（因为JVM Stop the World了）
• 计算机真没有什么莫名其妙，只是我们还没找到那一个点