1、问题
最近接到运营部门的反馈网站时常会出现小批量的502
且在网站出现502
之前反应特别慢,刷新几次以后又可以正常访问了。
2、排查过程
项目部署了两台机器,其中一台出现重启的情况,部分用户在访问当前服务器时正好机器重启了,导致访问异常。
2.1、查看日志文件
查看生产环境日志发现其中一台机器重启了多次,从warpper log
中可以发现warpper
在多次ping
不通时自动重启了多次,从运维那边确认这台服务器多次出现无响应的情况。此时第一时间想到OOM
进一步查看日志并没有发现OutOfMemoryException
抛出,也没有StackOverflowException
。
2.2、生产环境资源、GC情况
通过top
命令查看生产环境CPU
占用一直非常高,load
也一直高居不下,GC长时间占用CPU
资源。
进一步查看GC
情况,发现在重启后很短的时间内FGC
次数达7W+;Old Generation
持续占用100%,而每次FGC
的时间又非常的短.
jstat -gcUtil [pid] 1000
在通过jmap -histo [pid]
查看内存实例情况也没有发现异常。
FGC
?。
2.3、查看堆栈信息
由于没有触发OOM
手动添加以下启动参数,打印FGC
前后堆内存情况
-XX:+HeapDumpBeforeFullGC
-XX:+HeapDumpAfterFullGC
-XX:HeapDumpPath=/tmp
复制代码
果然,重启后短时间内开始输出 dump
接下来使用jvisualvm
(JDK 自带的内存分析工具) 查看堆dump
文件。 以下列出FGC
前后的堆dump
类视图
- FGC前
- FGC后
对比FGC
前后发现在FGC
之前存在大量的int[]
和char[]
数组,且数组的length
都非常大,而这些大数组在FGC
之后又被有效的回收了。对jvm
垃圾回收有了解的同学应该知道,jvm
为了避免频繁的移动大对象会将大对象直接创建在Old Generation
。此时开始怀疑是不是Old Generation
的空间不够了,逐一排查线上环境的jvm
启动参数。
-Xms 2048
-Xmx 2048
...
-Xmn 2000
-
复制代码
......
最后发现,由于这台机器内存只有2G
而新生代分配的内存却达到了2000M
剩下的内存只有48M
。而大数组又会直接分配到Old Generation
当Old Generation
没有足够的空间来存放大数组对象时,就可能触发FGC
修改 -Xmn 683
默认新生代和老年代的比值为1:2
。重新发布问题解决,top
、jstat -gc
查看服务器状态各项数据都非常可爱。
3、复盘
由于项目已经跑了好几年,一开始的思路都在查找项目代码层面的问题,丝毫没有意Jvm
启动参数的问题,其实对一些有经验的同学来说发现问题搜集到的一些信息就可以定位问题。如:
GC
那张图就可以明显的看出问题。FGC
异常频繁(7W+),但FGCT
却不高(1.9W),这说明每次FGC
的效率非常高。而每次FGC
的时候New Generation
的占用却非常少,可以排除是因为程序问题短时间内产生大量新对象触发的FGC
,这些都提供了直接的排查方向应该从:导致FGC
触发的条件入手,而不是找程序的问题。- dump中存在大量无引用的对象,也从侧面反应出在
FGC
之前没有有效的触发YGC
。
还有一点值得注意,jvm
启动参数的默认值在绝大多数情况下都可以完美的运行,不到系统优化的最后一步尽量使用默认配置,最后还有一点疑问大量的int[]
、char[]
数组是从那里来得?通过分析项目中的代码,以及FGC
前存在大量的pattern
(正则表达式)相关对象分析,初步怀疑是因为项目中大量不规范的使用Pattern
导致的。
4、总结排查过程
- 查看日志是否有
OutOfMemoryException
、StackOverflowException
抛出。 - 查看线上服务器状态、
GC
情况。 - 分析
GC
前后的dump
文件。 - 定位问题。