JVM异常FGC问题查找过程总结
2016-07-09 12:04
253 查看
问题现象及分析
可能原因分析
手动重现异常
大对象问题
流量暴涨
CPU资源被其他进程占用
内存被其他进程占用的情况swap分区问题
数据库连接异常
堆文件分析
shell脚本
JVM问题排查总结
其他遗留的问题
前段时间线上的zzuser的服务模块出现大量的异常FGC情况,经过大量排查工作,最后锁定是因为一个sql的大查询导致的。这也给了我非常大的教训,同时我在这次问题的排查过程中也获益匪浅,所以把经过写下来或许能给其他处理JVM问题的同学一些启示或者借鉴,本文假设你对JVM有一定的了解,如果不了解,可以看另外一篇文章
异常GC日志如下:
线程堆栈信息:
因为FGC后又自动恢复正常,所以jstack并不能打印出当时的真实情况,后面我写了一个脚本在FGC后马上打印线程堆栈信息,基本可以保留线程信息
大家可以看到我们的
可能是流量暴涨,创建突然对象增多,YGC无法回收,只能分配在old,虽然上文分析过流量暴涨引发的情况和需要解决的现象不同,但是开始是不清楚的
CPU、内存等资源被其他进程占用,JVM没有足够的资源用以GC,我们的GC配置的是需要20个线程进行回收操作,还是比较耗费资源的。
在查找问题的过程中,有文章提到swap分区可能导致问题的产生
数据库连接异常,可能导致线程上的对象无法及时释放
分析了可能出现问题的原因,能重现问题,就是离解决问题不远了了,所以现在最重要的是能参考原因,重现异常
下图是流量突然增大时的GC情况
大家可以看到我们的
可以和异常日志红色部分对比,在异常FGC发生之前,会出现一次耗时非常长的YGC,对比之前正常YGC,这次YGC后old区发生了突然增长,然后触发了FGC。显然流量暴涨并不能导致异常FGC,这条路也走不通了。
CPU使用情况(原图没保存,随便截了个,现象一样)
当有其他进程将大量cpu占用以后,在1:1线上流量下基本GC情况不会有太大的差距。
经过各种分析,都无法重现异常,这时候有一台机器发生FGC时没有恢复,基本宕掉了。这是一个大好的机会,我们使用jmap dump了整个堆信息,本来是要jstack线程信息,结果卡住了,就没有保留线程信息。
存在3个异常线程,每个线程上的对象达200多万个,耗费内存800多M。加起来就是两个多G的内存,我们Eden区总共才3G,所以这个很有可能是问题的原因。这个现象的发现让我感觉到很有可能是由于数据库查询出太多对象导致的。感觉问题就要找到了,但是如何准确定位还不知道怎么办。
很简单,当发生FGC时,将各种信息记录下来方便查询。
运行一天以后,果然发生了数次FGC,查看到最重要的信息
GC发生之前系统资源使用情况
CPU使用高达644%,而当时消耗最高的线程居然只是一个小小的查询
找到这段代码
代码只判断了unionId == null ,但是确没有判断unionId == “”的情况,但是为什么以前没有问题呢?因为之前我们系统全是微信用户,所以unionId不存在空的情况。最近接入了其他系统,所以出现了”“的情况。(后来我基于hibernate-validation写了一个小框架方便参数校验)
问题终于找到了,就是这么一个小问题。走了非常多的弯路,总结一下。
善用工具,使用脚本,当发生问题时,可以将系统的各个日志记录下来,有了日志排查问题事半功倍
善用工具类,工具类是大神和前辈的经验结晶,大家踩过非常多坑了,写代码一定要注意,不管代码习惯还是其他小细节问题,都可能导致非常大的问题。比如我校验字符串空时采用
调优的问题在另一篇文章 《JVM调优总结》
可能原因分析
手动重现异常
大对象问题
流量暴涨
CPU资源被其他进程占用
内存被其他进程占用的情况swap分区问题
数据库连接异常
堆文件分析
shell脚本
JVM问题排查总结
其他遗留的问题
前段时间线上的zzuser的服务模块出现大量的异常FGC情况,经过大量排查工作,最后锁定是因为一个sql的大查询导致的。这也给了我非常大的教训,同时我在这次问题的排查过程中也获益匪浅,所以把经过写下来或许能给其他处理JVM问题的同学一些启示或者借鉴,本文假设你对JVM有一定的了解,如果不了解,可以看另外一篇文章
问题现象及分析
JVM核心参数配置如下:-Xms6g -Xmx6g -Xmn3g -Xss1024K -XX:PermSize=256m -XX:MaxPermSize=512m -XX:ParallelGCThreads=20 -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+UseCMSCompactAtFullCollection -XX:SurvivorRatio=65536 -XX:MaxTenuringThreshold=0 -verbose:gc -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -XX:CMSInitiatingOccupancyFraction=80
异常GC日志如下:
线程堆栈信息:
因为FGC后又自动恢复正常,所以jstack并不能打印出当时的真实情况,后面我写了一个脚本在FGC后马上打印线程堆栈信息,基本可以保留线程信息
大家可以看到我们的
S区大小基本为空,因为我们的应用服务器都是是无状态的,所以理论上,每次YGC都能将对象回收,所以不需要在
S区做任何停留,这在低并发时基本没有问题,但是高并发时就会出现YGC无法回收线程对象的情况,这时候S区为空,对象只能存储在Old区,导致高并发时old区突然暴涨的情况,从而产生大量FGC,但是这种配置即使发生了流量暴涨,也只是正常的YGC和FGC,不会突然在上位到达
CMSInitiatingOccupancyFraction=80及Old区到百分之80使用率才进行FGC
可能原因分析
对象突然出现在old区,可能是因为有数量可观的大对象被创建,这些对象直接进入old区,导致old区突然增加,这种对象一般是流数据可能是流量暴涨,创建突然对象增多,YGC无法回收,只能分配在old,虽然上文分析过流量暴涨引发的情况和需要解决的现象不同,但是开始是不清楚的
CPU、内存等资源被其他进程占用,JVM没有足够的资源用以GC,我们的GC配置的是需要20个线程进行回收操作,还是比较耗费资源的。
在查找问题的过程中,有文章提到swap分区可能导致问题的产生
数据库连接异常,可能导致线程上的对象无法及时释放
分析了可能出现问题的原因,能重现问题,就是离解决问题不远了了,所以现在最重要的是能参考原因,重现异常
手动重现异常
大对象问题
因为我对zzuser业务模块不熟悉,所以请教了其他同学,zzuser模块并不存在流数据等大对象,所以第一个先搁置,实在找不到问题了再说(结果证明确实没有)流量暴涨
要模拟流量暴涨还是比较容易的,前期我先使用TestNG调用几个方法进行压测,将压力突然调高,方法比较粗糙,后来让运维的同学给我们开了流量,使用tcpcopy将线上的流量引入到测试服务上,这种方式就非常准确科学了。
下图是流量突然增大时的GC情况
大家可以看到我们的
S区大小基本为空,因为我们的应用服务器都是是无状态的,所以理论上,每次YGC都能将对象回收,所以不需要在
S区做任何停留,这在低并发时基本没有问题,但是高并发时就会出现YGC无法回收线程对象的情况,这时候S区为空,对象只能存储在Old区,导致高并发时old区突然暴涨的情况,从而产生大量FGC,但是这种配置即使发生了流量暴涨,也只是正常的YGC和FGC,不会突然在上位到达
CMSInitiatingOccupancyFraction=80及Old区到百分之80使用率才进行FGC
可以和异常日志红色部分对比,在异常FGC发生之前,会出现一次耗时非常长的YGC,对比之前正常YGC,这次YGC后old区发生了突然增长,然后触发了FGC。显然流量暴涨并不能导致异常FGC,这条路也走不通了。
CPU资源被其他进程占用
这里用到一个脚本,用来将cpu资源消耗光#! /bin/bash # filename killcpu.sh endless_loop() { echo -ne "i=0; while true do i=i+100; i=100 done" | /bin/bash & } if [ $# != 1 ] ; then echo "USAGE: $0 <CPUs>" exit 1; fi for i in `seq $1` do endless_loop pid_array[$i]=$! ; done for i in "${pid_array[@]}"; do echo 'kill ' $i ';'; done
CPU使用情况(原图没保存,随便截了个,现象一样)
当有其他进程将大量cpu占用以后,在1:1线上流量下基本GC情况不会有太大的差距。
内存被其他进程占用的情况,swap分区问题
因为没有服务器root权限,所以脚本没有运行成功,但是事后分析,理论上JVM的内存在开始已经分配好了,并不会因为内存被其他进程占用过多而导致异常#!/bin/bash mkdir /tmp/memory mount -t tmpfs -o size=20480M tmpfs /tmp/memory dd if=/dev/zero of=/tmp/memory/block sleep 5 rm /tmp/memory/block umount /tmp/memory rmdir /tmp/memory
数据库连接异常
我用TestNG,将代码里面加上sleep(),希望模拟出数据库连接问题,测试后发生JVM依然正常,分析原因,当数据库连接异常时,线程都在等待数据库连接,这时候调用方即使有大量请求堆积到队列中,但是因为工作线程已经都在sleep,所以根本不会创建更多的对象,JVM自然不会有异常经过各种分析,都无法重现异常,这时候有一台机器发生FGC时没有恢复,基本宕掉了。这是一个大好的机会,我们使用jmap dump了整个堆信息,本来是要jstack线程信息,结果卡住了,就没有保留线程信息。
堆文件分析
因为堆文件是在太大,在线上机器使用jmap分析了好久,也出不来报告,我们将它下载到本地,找了一台16G的Mac进行分析,因为是别人的机器,而且文件太大,爆卡。所以这里就说一个基本现象。存在3个异常线程,每个线程上的对象达200多万个,耗费内存800多M。加起来就是两个多G的内存,我们Eden区总共才3G,所以这个很有可能是问题的原因。这个现象的发现让我感觉到很有可能是由于数据库查询出太多对象导致的。感觉问题就要找到了,但是如何准确定位还不知道怎么办。
shell脚本
上文讲到我最后利用一个脚本定位了问题,脚本内容#! /bin/bash pid=`scf list | grep zzuser | awk '{print $5}'` echo "pid=$pid" flag=1 fgc1=0 while((flag==1)) do sleep 1 fgc2=`scf jstat -gcutil zzuser | sed -n '2'p | awk '{print $8}'` echo "---------------start----------------">>gc.log echo "fgc2=$fgc2, fgc1=$fgc1" >> gc.log echo "fgc2=$fgc2, fgc1=$fgc1" echo "-------------top--------------">>gc.log top -b| head -12 >> gc.log div=`expr $fgc2 - $fgc1` if [ $div -gt 0 ] then fgc1=$fgc2 echo "------------------------------------出现了fgc---------------------------------" >> gc.log echo "------GC 情况-----" echo `scf jstat -gcutil zzuser` >> gc.log for i in {1..3} do #查找消耗最高线程id # 加上-b不会出现乱码 tid=`top -H -b -p $pid | head -10 | sed -n '8'p | awk '{print($1)}'` echo "tid=$tid" tid16=`printf "%x" $tid` echo "cpu 消耗最高线程 id 是${tid16}啊" >>gc.log echo "cpu 消耗最高线程 id 是${tid16}" date=`date` echo "-------------堆栈信息--${tid}--${tid16}---${date}------------" >> gc.log jstack $pid | grep -A 20 $tid16 >> gc.log jstack $pid > $pid$tid.jstack done fi done
很简单,当发生FGC时,将各种信息记录下来方便查询。
运行一天以后,果然发生了数次FGC,查看到最重要的信息
cpu 消耗最高线程 id 是7140啊 -------------堆栈信息--28992--7140---2016年 07月 06日 星期三 15:20:01 CST------------ "async task worker[24]" daemon prio=10 tid=0x00007ff53ce63800 nid=0x7140 runnable [0x00007ff4acb58000] java.lang.Thread.State: RUNNABLE at java.util.ArrayList.size(ArrayList.java:177) at java.util.AbstractList$Itr.hasNext(AbstractList.java:339) at com.bj58.zhuanzhuan.lib.util.DaoOptimize.populateData(DaoOptimize.java:44) at com.bj58.zhuanzhuan.zzuser.components.ZZUserService$1.exec(ZZUserService.java:58) at com.bj58.sfft.utility.dao.basedao.DAOHelper.execQuery(DAOHelper.java:94) at com.bj58.zhuanzhuan.zzuser.components.ZZUserService.getByUnionid(ZZUserService.java:54) at ZZUserServiceProxyStub1467616292464.getByUnionid(ZZUserServiceProxyStub1467616292464.java) at ZZUserServiceProxyStub1467616292464.invoke(ZZUserServiceProxyStub1467616292464.java) at com.bj58.spat.scf.server.core.proxy.InvokerBase.doInvoke(InvokerBase.java:114) at com.bj58.spat.scf.server.core.proxy.AsyncInvokerHandle$1.run(AsyncInvokerHandle.java:97) at com.bj58.spat.utility.expandasync.AsyncWorker.execTimeoutTask(AsyncWorker.java:155) at com.bj58.spat.utility.expandasync.AsyncWorker.run(AsyncWorker.java:132)
GC发生之前系统资源使用情况
top - 15:19:57 up 331 days, 15:33, 1 user, load average: 3.95, 3.32, 2.78 Tasks: 566 total, 3 running, 562 sleeping, 0 stopped, 1 zombie Cpu(s): 6.6%us, 2.5%sy, 0.0%ni, 90.3%id, 0.1%wa, 0.0%hi, 0.6%si, 0.0%st Mem: 131900336k total, 129866704k used, 2033632k free, 33196k buffers Swap: 32767996k total, 6714812k used, 26053184k free, 50267092k cached PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 28623 work 20 0 22.2g 5.8g 9m S 644.0 4.6 1641:48 java 28002 dia 20 0 19.6g 2.2g 3292 S 227.7 1.8 36196:58 java 11193 work 20 0 1860m 429m 1984 S 156.8 0.3 277:44.58 router 16782 work 20 0 23.3g 3.4g 9.9m S 112.0 2.7 748:04.01 java 31629 work 20 0 23.7g 3.7g 10m S 93.3 2.9 2980:07 java
CPU使用高达644%,而当时消耗最高的线程居然只是一个小小的查询
ZZUserService.getByUnionid(ZZUserService.java:54)
找到这段代码
public ZZUser getByUnionid(String unionId, final String strLog) throws Exception { if (unionId == null) { throw new Exception("参数错误"); } String sql = "SELECT * FROM user WHERE `unionid`=" + unionId;
代码只判断了unionId == null ,但是确没有判断unionId == “”的情况,但是为什么以前没有问题呢?因为之前我们系统全是微信用户,所以unionId不存在空的情况。最近接入了其他系统,所以出现了”“的情况。(后来我基于hibernate-validation写了一个小框架方便参数校验)
问题终于找到了,就是这么一个小问题。走了非常多的弯路,总结一下。
JVM问题排查总结
JVM参数必须设置齐全,GC日志详细必须打印善用工具,使用脚本,当发生问题时,可以将系统的各个日志记录下来,有了日志排查问题事半功倍
善用工具类,工具类是大神和前辈的经验结晶,大家踩过非常多坑了,写代码一定要注意,不管代码习惯还是其他小细节问题,都可能导致非常大的问题。比如我校验字符串空时采用
StringUtils.isNotBlank(),在这个情况下就不会出问题
调优的问题在另一篇文章 《JVM调优总结》
其他遗留的问题
参数校验太复杂麻烦,不过我已经写了工具解决这个问题,还有一个隐含大问题,就是我们的Dao工具太落后,工作量大,麻烦也隐含难以发现的错误,而且字符串拼接不方便重构和问题排查。相关文章推荐
- Java 6 JVM参数选项大全(中文版)
- 深入解析JVM对dll文件和对类的装载过程
- JVM Tomcat性能实战(推荐)
- Java虚拟机JVM性能优化(二):编译器
- Java程序员必须知道的5个JVM命令行标志
- Java虚拟机JVM性能优化(三):垃圾收集详解
- 简单谈谈JVM、JRE和JDK的区别与联系
- 解析Java虚拟机中类的初始化及加载器的父委托机制
- JAVA中JVM的重排序详细介绍
- 浅谈Java的虚拟机结构以及虚拟机内存的优化
- JVM角度调试优化MyEclipse
- Java虚拟机JVM性能优化(一):JVM知识总结
- Android Studio 报错failed to create jvm error code -4的解决方法
- 解析Linux系统中JVM内存2GB上限的详解
- 了解Java虚拟机JVM的基本结构及JVM的内存溢出方式
- Java堆空间占满的gc日志实例
- JVM调优之Tomcat启动参数配置及详解(一)
- java动态代理模式
- 一次FULL GC问题的排查
- Groovy Meta Object Protocol