生产System.GC导致业务不可用；故障分析

文章编写与2016年10月；日记迁移至简书！

问题背景

xx日项目上线新功能，当时还比较顺利，第二天早上发现当用户量上来，系统整体做交易比较慢，严重一点直接访问超时，必须要重启系统 才能暂时恢复正常，由于这次上线跟多个系统有对接关系，回退相当困难，只能在线上分析问题了，唉 不说多了，下面来一起分析问题吧。

系统背景

整体使用 ESB架构 实现分布式部署，以及实现前后端分离（此文分析前端系统），前端系统 使用 WEB 服务器 对应一台 AP服务器 , 采用直连方式访问。在异地也配置两台备机AP。再通过网络层实现负载均衡以轮训的访问访问3台AP 。

• 基础软件方面
  采用 WEB服务器、AP服务器、DB服务器的操作系统环境均采用RedHad5.8 ,数据库采用Oracle10.2.0.4 ,中间件采用Weblogic 10.3.5,WEB服务器采用Apache 2.0
• 系统配置
  WEB配置：2核CPU ，4G物理内存，300G硬盘内存
  AP配置：4核CPU ， 16G物理内存，600G硬盘内存
  DB配置：4核CPU，32G物理内存，600G硬盘内存

当时分析点

• 查看日志是否有死锁，异常交易。
• 代码有死循环代码块，导致整个系统运行缓慢。
• 数据库连接不够，导致有连接竞争，阻塞(Blocked)。
• 数据库 有锁表的的问题。
• 调用其他系统接口，可能有定时任务。导致响应缓慢，占用连接资源拖慢系统。
• 服务器运行内存，CPU不够。

我们围绕着这5个点，逐步排查

• 系统大部分交易日志都运行正常，非正常的就是访问超时。
• 我们对新上线的功能进行Code Review，并没发现有死循环，非正常消耗资源的代码。
• 有时候连接数不够用，我们把连接池数也加大。
• 改完后我们运行，体现不出效果。当系统运行缓慢的时候，有很多连接都是空闲状态的。所以这点
  可以排除点了。
• 数据库锁表问题，如果一旦锁表会导致修改删除，不能操作。但是我们系统流程可以正常运行，
  这点也可以排除掉。
• 我们有跟其他系统的接口人，一起测试过，他们响应都是毫秒级（不过一旦系统缓慢，我们这边监控到响应速度也是10几秒的）。
• 后来我们通过top命令，查看服务器使用资源有时候CPU会彪到300~400（我们系统4核），怀疑点指向了硬件配置。

最终决定解决方案：

• 调大CPU，把现有4核调整到8核，调优之后确实好转很多。系统运行时间 是之前的倍数，才会导致系统慢下来，这也算是治标不治本，权宜之计罢了。

搭建测试环境

我们在本地通过Jmeter压测，同时通过Java Viratul 、Jconsole远程监控线程，发现有日志阻塞（Blocked），
还有极少的Weblogic阻塞现象，但并没有有死锁（Deadlock） 。

image.png

CPU跑的极度不稳定时高时低，Weblogic没有异常现象。

image.png image.png image.png

这个时候疑问来了，因为跑的并发数也只有少数个，为什么会导致CPU这么不稳定呢？会不会是跑通信（netty）服务端（提供接口方）跑的流程太多，导致低并发高耗时的问题，
为了验证这个问题我们把挡板（屏蔽服务端通信，本地通信）搭建来。测试结果也是一如既往。

我们再从一个最简单的交易压测试试 ，CPU平均70%，CPU幅度还是比较大，压测（Jmeter）20几分钟左右停止 压测工具后，问题又出现了Weblogic又异常的卡。我们再通过jstat 看看GC回收情况。

image.png

压测工具（Jmeter）聚合结果，少数个并发，平均响应10秒以上(测试登陆交易聚合报告)

image.png

少个并发，压测了26多分钟导致发生Full GC发生数5678次，耗时5017.323秒，相当吓人啊。

目测应该是程序某个地方触发了GC。全局搜索了下代码 程序中真有地方频繁调用System.gc() 。

我们再把代码中调用系统垃圾回收(Full GC)去掉，同样的并发数，同样的测试时间，测试结果如下所示：
CPU使用率相对稳定

image.png

Java 虚拟机回收也比较稳定

image.png

Full GC(Mark-Sweep、标记-清除)触发0次 ，Minor GC触发68次。

image.png image.png

少数个并发，压测了26多分钟导致发生Full GC发生数0次，耗时0秒，CPU使用相对稳定，日志打印正常。

压测中之所以CPU使用率幅度大，是因为Java虚拟机垃圾回收器机制所导致，我们使用的是Parallel GC 并行回收；那么一直会有对应核数*2的线程，一直在消耗CPU的资源，这种情况下可能会导致 【业务线程】获取不到CPU资源。导致系统业务懈怠，用户视角系统是一直卡死的。

最奇葩的是业务并不是完全执行不了偶发会执行部分正常业务；也没有内存溢出问题，在高峰用户访问时；部分日志正常；造成排查问题困难。

实用排查方法以及命令

查看消耗CPU 最高的线程

• 使用命令top -p <pid> ，显示你的java进程的内存情况，pid是你的java进程号，比如123
• 按H，获取每个线程的内存情况
• 找到内存和cpu占用最高的线程pid，比如15248
• 执行 printf 0x%x 15248 得到 0x3b90 ,此为线程id的十六进制
• 执行 jstack 123|grep -A 10 3b90，得到线程堆栈信息中3b90这个线程所在行的后面10行
• 查看对应的堆栈信息找出可能存在问题的代码

Linux JVM 常用命令

• jstat gcutil pid 可实时查看JVM 内存运行情况
• jmap pid 查看JVM内存配置
• jstack pid 查看堆栈信息

JVM 常用自带工具

1、jinfo
2、jconsole
3、jvisualvm
4、jstat
5、jmap
6、jps
7、jhat
8、jstat

统计线程运行状态

• 通过jstack pid 重定向到dump，再通过grep 统计线程状态
  linux命令：
  jstack 29957 > /home/mw/weblogic/dump
  grep java.lang.Thread.State dump | awk '{print 24$5}' | sort | uniq -c