线上服务Java进程假死快速排查、分析

服务器上的Java进程总是在运行个两三天后就无法响应请求了，具体现象如下：

• 请求业务返回状态码502，查看进程还在，意味着Java进程假死，无法响应请求了；
• 该Java进程占比CPU较高，高达132.8%。

使用top命令查看服务器整体运行情况：

可以看到PID为14760的Java进程CPU占比132.8%，内存占用37.6%，内存倒是在合理范围内，但是这个CPU就太高了。

查看进程14760的线程堆栈信息

执行命令：

top -Hp 14760

打印出当前进程的所有线程的运行情况：

发现PID为14767和14768的两个线程的CPU占比分别为47.8%和47.5%，而且TIME+占比较大，说明这两个线程一直在运行。

继续使用jstack命令来查看这两个线程的堆栈信息，jstack的基本命令格式如下：

jstack <pid> | grep '16进制的线程Id'

可以通过如下命令获取14767这个线程的16进制数值：

printf '%x\n' 14767

输出：0x39af，执行jstack相关命令：

jstack 14760 | grep -a 0x39af -C20 --color

其中这个-C20是显示当前行的上下20行 ，如果没有这个命令就只有孤零零的当前行，看不出更多有效的信息，输出内容如下：

通过上图就可以看到线程为什么吃CPU了，如果显示的是大家自己开发的业务代码，相信大家直接就可以review代码找出问题所在了。

但是有时候我们并不能根据线程Id就能查出有问题的代码在哪里，比如上图这种情况，红框里的两个线程是GC task Thread，说明线程一直在进行GC，而上面的其他线程则是出于WAITING等待状> > 态，也就是说造成Java服务进程假死的原因是因为JVM的长时间GC导致的Stop The World！

所以我们要找出来到底是什么原因导致的进程一直在GC，而无法响应业务请求。

jstat命令排查GC信息

既然是GC有问题，那么我们继续使用jstat命令来查看JVM heap的信息。

先来快速了解一下jstat命令的介绍和用法。

jstat命令格式如下：

jstat -<option> [-t] [-h<lines>] <vmid> [<interval> [<count>]]

相关参数：

• -class：显示加载class的数量以及所占空间信息
• -compiled：显示VM实时编译的数量信息
• -gc：显示gc的信息，查看gc的次数、时间
• -gccapacity:显示VM内存中三代（young、old、perm）对象的使用和占用大小
• -gcutil：统计gc信息
• -gcnew：统计VM年轻代信息
• -gcnewcapacity：VM年轻代对象的信息及占用量
• -gcold：VM年老代信息
• -gcoldcapacity：VM年老代对象的信息及占用量
• -gcpermcapacity：VM中永久代的信息及占用量
• -printcompilation：当前VM执行的信息。

执行命令：

jstat -gcutil  14760 1000

得出的GC Heap数据如图所示：

其中：

• S0：幸存1区当前使用比例
• S1：幸存2区当前使用比例
• E：伊甸园区使用比例
• O：老年代使用比例
• M：元数据区使用比例
• CCS：压缩使用比例
• YGC：年轻代垃圾回收次数
• FGC：老年代垃圾回收次数
• FGCT：老年代垃圾回收消耗时间
• GCT：垃圾回收消耗总时间

从图中的数据可以发现E(Eden区)和O(Old区)的内存已经被耗尽了，占比高达100%，FGC（Full GC）的次数高达23133次，FGCT（Full GC Time）总时间高达36221.931秒，每次FGC耗时36221.931/23133≈1.6秒，很显然Java进程都把时间花在FGC上了。

jmap命令拿到dump日志文件

通过以上数据分析，可以初步定为问题发生在程序的内存泄漏上。这时候就需要使用到jmap的命令了，我们可以通过jmap命令输出指定Java进程的dump二进制文件：

jmap -dump:format=b,file=dump.phrof <pid>

接下来开始用MAT工具分析拿到的dump文件

Eclipse Memory Analyzer是一个快速的并且功能丰富的Java堆分析工具，旨在帮助你发现内存泄漏问题和减少内存消耗。
使用MAT来分析生产数以亿计的对象堆转储文件，快速计算存活对象的大小，发现谁在阻碍GC回收对象，形成一个报告来自动提取内存泄漏嫌疑对象。

安装独立版本的MAT：https://www.eclipse.org/mat/downloads.php

MAT分析Java Heap Dump文件

MAT打开本地dump文件，选择Leak Suspects Report:

可以看到
org.hibernate.internal.SessionFactoryImpl这个实例占用了853,310,632 (92.24%) 字节，共813.3MB！目前可以知道的是在Hibernate数据查询这块有问题，具体点击Details继续跟进去找问题代码:

图中可以看到有问题的对象好几个，占用的内存也比较大。再来看下面一张图：

Accumulated Objects by Class in Dominator Tree是支配树中按类累积对象，可以看到BoundedConcurrentHashMap只有32个对象示例，其对象树却占据了853241512字节的堆大小。我们点击进去看看这个HashMap里面都存储了什么数据：

把这个value拷贝出来，是我们业务的sql，看到这个sql我就惊讶了，这个sql传了91976个参数！

至此，我们便找出了造成Java进程假死的代码在这个SQL上。

毋庸置疑，这个SQL存在两个大问题：

• SQL本身是慢SQL，不能迅速查出来；
• SQL本身查出来的数据需要分配更多的内存。

内存不足，需要回收对象，但是查询SQL有需要更多的对象空间来存储。因此这边一直在GC，但是有回收不出来有效的空间，那就需要继续GC。所以进程一直在FULL GC，导致一直stop the world。

---

原文章地址：
https://zhuanlan.zhihu.com/p/529350757