JVM异常FGC问题查找过程总结

  • 问题现象及分析
  • 可能原因分析
  • 手动重现异常
    • 大对象问题
    • 流量暴涨
    • 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问题排查总结

  1. JVM参数必须设置齐全,GC日志详细必须打印
  2. 善用工具，使用脚本，当发生问题时，可以将系统的各个日志记录下来，有了日志排查问题事半功倍
  3. 善用工具类，工具类是大神和前辈的经验结晶，大家踩过非常多坑了，写代码一定要注意，不管代码习惯还是其他小细节问题，都可能导致非常大的问题。比如我校验字符串空时采用StringUtils.isNotBlank()，在这个情况下就不会出问题
  4. 调优的问题在另一篇文章 《JVM调优总结》

其他遗留的问题

参数校验太复杂麻烦，不过我已经写了工具解决这个问题，还有一个隐含大问题，就是我们的Dao工具太落后，工作量大，麻烦也隐含难以发现的错误，而且字符串拼接不方便重构和问题排查。

时间： 2024-08-09 22:03:11

JVM异常FGC问题查找过程总结的相关文章

JVM加载类的过程,双亲委派机制中的方法

JVM加载类的过程: 1)JVM中类的整个生命周期: 加载＝>验证＝>准备＝>解析＝>初始化＝>使用＝>卸载  1.1.加载 类的加载阶段,主要是获取定义此类的二进制字节流,并将这个字节流所代表的静态存储结构转化为方法区的运行时数据结构,最后在Java堆中生成一个代表这个类的java.lang.Class对象作为方法区这些数据的访问入口.相对于类加载过程的其他阶段,加载阶段是开发期可控性最强的阶段.我们可以通过定制不通的类加载器,也就是ClassLoader来控制二进制

HiPAC高性能规则匹配算法之查找过程

收到一封邮件,有位朋友觉得我误解了nf-HiPAC,如此的一个高性能算法怎能被什么传统的hash,tree之类的胁迫.是啊,HiPAC是一个很猛的算法,文档也比较少,这就更加增加了其神秘感,但是这决不意味着它是不可理解的,相反,它的思想很简单.       HiPAC算法本质上是一种基于优先级的区间匹配算法,怎么理解呢?我们把匹配域定义成一个连续的区间,那么每一条Rule则定义了该区间的一段子区间,如果多条规则覆盖了相同的子区间,那么就涉及到了优先级的问题,这个在防火墙的访问控制列表中很有用,在

jvm学习一：类加载过程详解

(自学笔记,持续更新,欢迎指正) 我们都知道一个java程序运行要经过编译和执行,但是这太概括了,中间还有很多步骤,今天来说说类加载 学完类加载之后,java运行过程就可以分为  编译  > 类加载  >  执行 类加载主要是由jvm虚拟机负责的,过程非常复杂,类加载分三步  加载   >  连接  >初始化,下面详细说说每一步的过程 1.加载:这个很简单,程序运行之前jvm会把编译完成的.class二进制文件加载到内存,供程序使用,用到的就是类加载器classLoader ,这里

C#发送邮件异常：根据验证过程,远程证书无效

今天在做发送邮件功能时,开始用qq邮箱和163邮箱都可以正常发送,后再改用我公司的邮箱和smtp时竟然报错了. 异常提示-----"根据验证过程,远程证书无效",后来通过查询资料解决该问题,上代码: using log4net; using System; using System.Collections.Generic; using System.Linq; using System.Net; using System.Net.Mail; using System.Net.Secur

命题作文：在一棵IPv4地址树中彻底理解IP路由表的各种查找过程

这是一篇命题作文.近期一直想写点东西,但一直找不到题目.正好收到一封邮件,有人问我Linux路由表的布局问题以及路由缓存的问题,加之前些日子又帮人做了一个片上路由表,所以认为这是个好题目,索性花了多半个周末的时间,奋笔疾书. 前面的套话 不写命题作文已经11年了.最后一次是在高考的考场上. 收到邮件时,被人要求写这样的命题作文,其实我是拒绝的,由于你不能叫我写我就立即去写,首先我自己得懂这个.我又不能说到了写完了的时候贴了非常多baidu出来的图片,说了非常多套话,人家一看就知道我这是转载或者翻

JVM中对象的创建过程

JVM中对象的创建过程如以下流程图中所示: 对其主要步骤进行详细阐述: 为新生对象分配内存: 内存的分配方式: 指针碰撞:假设Java堆中内存是绝对规整的,所有用过的内存放在一边,空闲的内存在另一边,中间防着一个指针作为分界的指示器,那么当分配内存时仅需移动指针即可. 空闲列表:维护一个列表,记录那些内存可用,分配时找出一块足够大的空间进行划分,并更新列表记录. 选择:内配方式的选择依赖于内存大小是否规整,内存大小的规整,依赖于垃圾收集器是否带有压缩整理功能. 并发情况下保证线程安全: 方法一:

［jvm解析系列］［十三］字节码指令小节，从字节码看JVM的栈解释器执行过程。

众所周知,JVM以前一直采用的是解释执行,但是后来在历代的版本更迭中也加入了编译执行.所以总的来说JVM是包含了解释执行和编译执行.这一部分不属于JVM的范畴了,已经属于编译了,大多数都是进行词法分析之类的,以后有时间会补充. 同时大家都知道现在大体上分为两种指令集架构,第一种就是基于栈的第二种是基于寄存器的,简单点说,基于寄存器的架构速度更快,但是可移植性不强,但是基于栈的指令集架构虽然慢,但是可移植性很强,大家都知道java本身就是依靠可移植性出名的,所以无可争议的使用了栈的指令集架构.(也

jvm加载类的过程

前言: 说下这篇文章的来龙去脉:昨天接到了阿里小哥哥的面试电话,小哥哥问我jvm加载类的过程.然后我巴拉巴拉说了一堆classLoader装载类的过程.然后小哥哥说我不是要问这些...好吧装载加载傻傻分不清楚. jvm加载类过程(本人不会,以下内容由小哥哥解释给我听的): classLoader装载类 连接(包括验证,准备,解析:小哥哥详述了这三个步骤..因为我比较疑问哈哈哈) 初始化 (小哥哥开始问我这个具体初始化过程) ( 本人其实脑子一片浆糊,很多概念傻傻分不清除)比如:类的初始化和对象的

小心sae的jvm异常导致的Error 404 – Not Found.No context on this server matched or handled this request.

本来用着sae好好的,结果第二天部署的应用突然不好使了,各种Error 404 – Not Found.No context on this server matched or handled this request. 折腾了一下午也一直是这个错,没招只好重写一个程序放上去,结果还是这个错误..删应用删jar包各种无解... 后来有点受不了,直接点击jvm管理,停止,重启,停止重启,n次后sae又恢复正常了...证明一个问题,jvm出现了异常,所以适当时候需要考虑反复重启jvm...我真是无奈