记录一次 Tomcat 假死的经历

场景

某天上班午休起来之后某个客户反馈给他们开发的CRM系统现在访问不了，于是我赶紧尝试访问了一下，确实访问不了，我一开始以为是宕机了，于是赶紧去后台看了下进程，发现进程还是，只是当时的load average接近7，基本上都是被Tomcat所使用的，服务器是四核的，这明显不太正常。

过程

• 首先查询一下该进程的情况

// 8946是进程的PID
ps -ef | grep 8946

由于当时在跳板机没有截图，但是load average非常高，而且基本上是Tomcat独自占有的。

这么高的CPU消耗一般是由两个可能的原因:

1. GC消耗，也就是垃圾回收过于频繁导致的。
2. Tomcat内部消耗，也就是业务系统确确实实是用了这么多的CPU资源。

• 查看一下当时虚拟机的回收情况

// 8946是PID，5000是间隔多长时间打印一次GC的情况，单位是ms，也就是5s打印一次
jstat -gc 8946 5000

image-20210328112703521

表头的对照：

符号	释义	单位
S0C	Survivor0 区域总共大小	KB
S1C	Survivor1 区域总共大小	KB
S0U	Survivor0 区域所使用大小	KB
S1U	Survivor1 区域所使用大小	KB
EC	Eden区域总共大小	KB
EU	Eden区域所使用大小	KB
OC	Old 区总共大小	KB
OU	Old 区所使用大小	KB
PC	PermGen区域总共大小（限JDK7）	KB
PU	PermGen区域使用大小（限JDK7）	KB
YGC	YoungGC次数	次
YGCT	YongGC总共消耗的时间	秒
FGC	FullGC次数	次
FGCT	FullGC总共消耗的时间	秒
GCT	GC总共消耗的时间	秒

可以看到YGC次数非常频繁，但是并没有出现FGC，FGC的次数一直是0，在5s的时间内基本上最少都有5次YGC，5s的间隔太长了，我缩短到1s输出一次看下情况。

image-20210328113107071

可以看出基本上1s回收一到两次，这明显不正常，说明有线程在源源不断的创建对象，只要找到这个是在哪里创建的对象或者创建什么对象就基本上可以解决这个问题了

• 查看当时内存中的各种对象数量情况

// `jmap -histo pid`是用来查询内存中存活对象情况的，sort -k -3 -g -r是按照第3列逆序，less可以简单的认为分页。
jmap -histo 62327|sort -k 3 -g -r|less

该命令可以查看出当前内存中的存活对象按大小的排名，从第一列起 分别为：排名、个数、内存大小、对象种类，Java中的基础数据类型都使用了一个字母表示，后面有该对照表。

image-20210328114008136

马赛克的部分涉及公司的部分包名，不再显示。

上面显示除了Byte、Char、Integer之外，还有aspenswobfuscated.xxx值得关注

下面是一些对象类型的对照表：

Java类型	符号
Byte	B
Char	C
Integer	I
Boolean	Z
Short	S
Long	L
Float	F
Double	D
Void	V

​

• 强制进行一次垃圾回收然后查看对象存活情况

// 这个和上个命令只多了一个":live"，使用后虚拟机会强制进行一次垃圾回收，然后输出内存对象的情况
jmap -histo:live 8946|sort -k 3 -g -r|less

使用该命令就能得知哪些对象在垃圾回收之后消失了，也就是知道了那些对象是年轻代垃圾回收的主要成分，那么这部分对象可能就是问题的原因了。

image-20210328173340035

可以明显看出：

原本第3的Integer、第4和第5的aspenswobfuscated.xxx消失了，所以也就是重点关注aspenswobfuscated.xxx产生的问题。

该包来自于Apose服务，主要用于将CRM中的word合同文件转化成PDF供用户预览，本来想看看源代码是不是我们写的有问题，我打开之后直接放弃了，该包下所有类名都经过混淆了。

image-20210328174331510

可惜最后我也没能从网上找到很好的解决这个的方案，因为功能影响不大，后来直接换了实现方式。顺便看到一个老哥和我相同的经历。。。

image-20210328180150274