症状
今天测试同学反馈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了）
- 计算机真没有什么莫名其妙，只是我们还没找到那一个点
网友评论