遇到Java内存溢出(OOM)时，这样排查

Posted 2021-08-24 记得别熬夜

一次Java内存溢出排查过程

背景

上周，我们项目中UAT环境突然无法访问了，查看了日志发现项目在报错 java.lang.OutOfMemoryError: ......java heap space..... ,虽然是UAT环境，但是所有在未发布之前所出现的问题，我们都应该重视。防止在生产上出现同样的问题。

修复措施

由于UAT环境，产品需要立马使用，所以我们需要先保证UAT环境可用，所以我们做了以下操作（本项目是集群搭建）

1. 先查看所有节点是否都是因为内存溢出的问题 使用 docker stats发现所有节点的内存占用以及cpu占用都已经超负荷了
2. 使用 docker inspect CONTAINER_ID，可以直接看到当前实例运行的是什么项目程序
3. 我们打算先重启部分当前项目的节点，先保证UAT环境暂时可用
4. 重启后，再次使用 docker stats 发现重启后的节点 内存还是在 60% 左右浮动，此时访问当前项目发现是可以访问了。

因为UAT暂时可用使用了，所以接下来就是我们自己的排查时间了。但是因为重启后的节点 内存还是居高不下，所以我们也需要迅速排查出来问题。否则已经重启的节点还是随时可能内存溢出

排查原因

哪些节点出现了问题

上述 修复措施 时我们已经找到了 项目中的 CONTAINER_ID，所以我们直接进入 实例内部具体看看是因为什么 导致的内存和CPU超负荷的问题。

docker inspect CONTAINER_ID //查看当前docker实例的详细信息，可以直接看出当前实例是什么项目
docker exec -it CONTAINER_ID /bin/bash  //进入docker实例
top //查看当前实例内进程情况
top -Hp PID // 找到内存和CPU占用率最高的PID 查看当前进程的所有线程占用情况
printf "%x\\n" Thead_PID // 把线程PID 转换成 16进制 ，因为我们在做堆栈排查时需要使用到 16进制的线程PID

到这里我们基本上前期的准备都做好了，接下来我们就应该去排查程序内到底时因为什么线程，或者那些对象占用了这么高的内存和CPU

小插曲

因为我们需要排查Java程序堆栈信息，所以我们必须要用到当前Java程序所运行的JDK自带的排查命令。但是这里很可惜，由于我们项目使用的基础镜像是阉割版的 JDK 我在 jdk/bin 下面没有找到相关命令。由于重新使用完整版基础镜像启动实例，实例本身就会被重启，如果重启了那可能还需要等到下一次发生该问题的时候我们才能排查，所以我们做了另一个决定，找一个当前相同版本的JDK 将 当前的 Java环境更改为这个完整版的JDK的环境，但是我们并没有操作成功，在执行相关排查命令的时候一直提示我 当前环境和本身Java程序环境不匹配。可能是因为中间出现了什么问题，这个就没有去深究下去了。所以我们还是选择了，更换镜像后重启当前实例节点。

使用JDK命令查看Java程序当前的线程状态

一天后,我们发现UAT再次无法访问，我们通过上述的操作定位到有问题的docker实例,排查过程如下

jstack -l PID > jastck_PID.log // 使用jstack可以看到当前程序中所有线程信息

我们使用上述中 将线程ID转换成16进制后的 标识，作为搜索条件

grep 16进制的线程ID -A20 -B20 jastck_PID.log 

这样我们就能看到到底是哪个线程出现了 占用CPU或者内存超载的问题，从而找到对应的业务代码。但是很可惜，我们发现我们这个线程是程序在执行GC操作时所产生的线程。所以很明显这是一个由于内存溢出，而导致Java程序一直执行GC操作，引发的CPU超负荷的问题。于是我们继续排查当前项目所占用的内存情况

使用JDK命令查看当前Java项目GC执行次数

由于我们在上述排查时发现CPU超负荷的问题是在于GC线程，我们首先先使用查看当前项目GC执行次数的命令，确定当前GC执行情况

jstat -gcutil PID 2000 10 //每两秒取样一次当前进程的内存情况

我们执行当前命令会看到当前进程中的内存占用情况，下面是每一列的官方解释:

S0:	Survivor space 0 utilization as a percentage of the space's current capacity.
S1:	Survivor space 1 utilization as a percentage of the space's current capacity.
E:	Eden space utilization as a percentage of the space's current capacity.
O:	Old space utilization as a percentage of the space's current capacity.
P:	Permanent space utilization as a percentage of the space's current capacity.
YGC:	Number of young generation GC events.
YGCT:	Young generation garbage collection time.
FGC:	Number of full GC events.
FGCT:	Full garbage collection time.
GCT:	Total garbage collection time.

我们发现我们的年轻代,老年代,永久代的内存占用情况基本上都是百分百了,同时在取样的过程中发现GC的执行时间一直在增加,但是GC次数没有增加,说明我们进程在执行GC时,有无法回收的对象,导致进程在一直GC

使用JDK命令查看当前Java项目的内存详情

jmap，为了获取的数据准确，可能会挂起线程，会导致应用暂停

jmap -heap PID //当前命令可以查看进程中内存的占用情况,进程的内存配置情况

我们要将内存的使用详情输出到文件中，并且通过 Memory Analyzer软件 详细查看内存对象

jmap -dump:format=b,file=heapdump.dump PID //在当前目录生成一个 heapdump.dump 文件,文件中包含项目中的内存对象占用情况
//由于我们目前在docker容器内 无法将文件传输到本机中，所以我们需要退出docker容器后,并且将文件拷贝到主机内
docker cp CONTAINER_ID:/tmp/heapdump.dump /tmp/heapdump.dump  //将容器内的 /tmp/heapdump.dump 文件拷贝到主机 /tmp/heapdump.dump 上

我们再将文件传输到本机中，使用 Memory Analyzer 软件进行内存对象排查，这里就不在阐述 Memory Analyzer 软件的使用了

查明真相

通过上述一番操作后,我们发现 每次重启项目，工作流都会重新部署一次流程定义。而工作流中的流程定义会作为缓存直接放在程序内存中。由于每次启动项目工作流定义重新生成，老的工作流定义没有标记未弃用状态。所以当缓存工作流定义的时候会将所有的工作流定义都缓存到内存中。所以我们在启动项目后内存就占用到 60% 左右。同时我们还发现，我们在使用redis lettuce连接时，使用了 netty的池化操作，并且没有释放当前池化缓冲区，导致redis lettuce 会直接占用剩余部分内存。

解决问题

我们既然已经查明真相，接下来我们就应该基于真相，进行相应的措施，保证环境不在发生当前问题

1. 由于我们UAT环境，程序内存限制最大只有1G ,我们首先增大UAT的内存限制
2. 由于工作流的问题，经过排查发现在编写工作流部署时有一个BUG，在比较当前流程定义文件和上一次流程定义文件时是否有变更，如果有变更才会重新部署流程定义。比较方法有些问题我们进行了改进
3. 针对于redis lettuce连接的问题，我们觉得既然 lettuce 使用了 netty 的池化操作 那我们就暂时不去变更他的操作，仅仅是减少了 池化内存大小的配置