记一次，线上服务频繁FGC排查过程

Hodu
4,050 阅读4分钟

1、问题

最近接到运营部门的反馈网站时常会出现小批量的502且在网站出现502之前反应特别慢,刷新几次以后又可以正常访问了。

2、排查过程

项目部署了两台机器，其中一台出现重启的情况，部分用户在访问当前服务器时正好机器重启了，导致访问异常。

2.1、查看日志文件

查看生产环境日志发现其中一台机器重启了多次，从warpper log中可以发现warpper在多次ping不通时自动重启了多次，从运维那边确认这台服务器多次出现无响应的情况。此时第一时间想到OOM进一步查看日志并没有发现OutOfMemoryException抛出，也没有StackOverflowException。

2.2、生产环境资源、GC情况

通过top命令查看生产环境CPU占用一直非常高，load也一直高居不下，GC长时间占用CPU资源。

image

进一步查看GC情况，发现在重启后很短的时间内FGC 次数达7W+；Old Generation 持续占用100%,而每次FGC的时间又非常的短.

jstat -gcUtil [pid] 1000

image

在通过jmap -histo [pid]查看内存实例情况也没有发现异常。

image
是什么导致如此频繁的FGC?。

2.3、查看堆栈信息

由于没有触发OOM手动添加以下启动参数，打印FGC 前后堆内存情况

-XX:+HeapDumpBeforeFullGC
-XX:+HeapDumpAfterFullGC
-XX:HeapDumpPath=/tmp

果然，重启后短时间内开始输出 dump

接下来使用jvisualvm (JDK 自带的内存分析工具) 查看堆dump文件。 以下列出FGC前后的堆dump类视图

  • FGC前
    image
  • FGC后
  • image

对比FGC前后发现在FGC之前存在大量的int[]和char[]数组,且数组的length都非常大,而这些大数组在FGC之后又被有效的回收了。对jvm垃圾回收有了解的同学应该知道，jvm为了避免频繁的移动大对象会将大对象直接创建在Old Generation。此时开始怀疑是不是Old Generation的空间不够了，逐一排查线上环境的jvm启动参数。

-Xms 2048
-Xmx 2048
...

-Xmn 2000
-

image

......

最后发现，由于这台机器内存只有2G而新生代分配的内存却达到了2000M剩下的内存只有48M。而大数组又会直接分配到Old Generation当Old Generation没有足够的空间来存放大数组对象时，就可能触发FGC修改 -Xmn 683默认新生代和老年代的比值为1:2。重新发布问题解决，top、jstat -gc查看服务器状态各项数据都非常可爱。

3、复盘

由于项目已经跑了好几年，一开始的思路都在查找项目代码层面的问题，丝毫没有意Jvm启动参数的问题，其实对一些有经验的同学来说发现问题搜集到的一些信息就可以定位问题。如：

  1. GC那张图就可以明显的看出问题。FGC 异常频繁（7W+），但FGCT却不高（1.9W），这说明每次 FGC的效率非常高。而每次FGC的时候New Generation的占用却非常少，可以排除是因为程序问题短时间内产生大量新对象触发的 FGC，这些都提供了直接的排查方向应该从:导致FGC 触发的条件入手，而不是找程序的问题。
  2. dump中存在大量无引用的对象，也从侧面反应出在FGC之前没有有效的触发YGC。

还有一点值得注意，jvm启动参数的默认值在绝大多数情况下都可以完美的运行，不到系统优化的最后一步尽量使用默认配置，最后还有一点疑问大量的int[]、char[]数组是从那里来得？通过分析项目中的代码，以及FGC前存在大量的pattern(正则表达式)相关对象分析，初步怀疑是因为项目中大量不规范的使用Pattern导致的。

4、总结排查过程

  1. 查看日志是否有OutOfMemoryException、StackOverflowException抛出。
  2. 查看线上服务器状态、GC情况。
  3. 分析GC前后的dump文件。
  4. 定位问题。
avatar
文章
阅读
粉丝