三十万次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了)
  • 计算机真没有什么莫名其妙,只是我们还没找到那一个点

本文参与腾讯云自媒体分享计划,欢迎正在阅读的你也加入,一起分享。

发表于

我来说两句

0 条评论
登录 后参与评论

扫码关注云+社区

领取腾讯云代金券