不知道是不是2020年太安逸了,都没加过班,最后12.30的时候警示一下我们。。。平时运行的好好的项目,突然发生了OOM,当时慌的一批,因为作为小菜鸡的我根本就没有遇到过这种问题啊,更没解决过这种问题,还好前段时间有在网上看过有关JVM的知识,对于简单的命令还是知道的,知道要下dump,然后分析dump。但是实际的问题往往没有那么的一帆风顺,其中的坎坷只有经历过才知道。下面让我细细道来~
首先讲一讲正常的OOM问题的解决思路吧。首先,OOM是OutOfMemoryError的简称,一般发生OOM的时候内存飙升,有类似nested exception is java.lang.OutOfMemoryError: Java heap space的错误日志,当然了,系统肯定是无法正常运行的了。
介绍几个实用的JDK自带命令,(命令依赖JDK,像我们之前项目是跑在docker中的,使用的是JRE,是无法使用下面的命令的,后来改成了JDK,才可以)
jps:查看Java进程(找到进程id:pid,后面的命令都需要使用到)
jstack pid:查看进程线程信息
jstat -gcutil pid:统计gc信息
jstat -gcutil pid 3000:统计gc信息,三秒刷新一次
jstat -gcmetacapacity pid:元空间使用情况
jmap -dump:format=b,file=/tmp/order.dump pid:保存pid对应进程当前dump
需要更多命令详细介绍的可以看一下这篇:https://blog.csdn.net/weixin_40910372/article/details/112244943
我使用了VisualVM和MAT来分析dump,高版本的JDK不带VisualVM,需要自行下载安装,IDE如果用的是eclipse的话可以装个MAT插件,如果是idea或者其他的工具可以单独下一个MAT。
以为实际的OOM复杂一点,所以接下来我们先自己制造一个OOM的问题,解决了,再来说生产上的问题。
首先,给测试的项目设置一下JVM参数:
-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/Users/ZHONGHUI/Desktop/dump -Xmx150M -Xms150M -Xmn10M -XX:MaxMetaspaceSize=130M -XX:MetaspaceSize=130M
解释一下分别是什么意思:
-XX:+HeapDumpOnOutOfMemoryError:发生HeapDumpOnOutOfMemoryError自动成dump文件
-XX:HeapDumpPath=/Users/ZHONGHUI/Desktop/dump:dump文件路径
-Xmx150M:最大堆内存
-Xms150M:堆初始内存
-Xmn10M:新生代最大内存
-XX:MaxMetaspaceSize=130M:元空间最大内存
-XX:MetaspaceSize=130M:元空间初始内存
接下来是代码,我只贴出重要的代码:
List<ShipOrderLogs> shipOrderLogsList = shipOrderLogsRepository.findAll(specification, Sort.by(sorts));
我在postman请求的时候,不传参数,它就会查整个表的数据,数据量很大,内存装不下,就会OOM。
好了,开始测试。
等几秒就会卡到日志:
发生了OOM,并且在制定的文件夹下生成了dump文件,用jconsole可以观察到内存使用情况和GC次数、时间。(我这里是本地,线上就不能使用jconsole了,可以使用上面说到的命令)。
使用VisualVM打开dump文件:
看到一个红色的线程,这个就是报OOM的线程,点击view all,
使用HTML格式查看,并找到我们刚刚看到的线程,
仔细查看线程调用栈
定位到报错代码
去我们代码里找到对应的类、行数,发现刚好是我们上面的那段代码,问题找到了,那么解决起来就很简单了。
但是这都是理想的情况,下面来说一说我们在生产上遇到的各种坑。
故事它开始了,这是一个悠闲地下午,我正在45度仰望天空,嘴角微扬,充满期待地幻想着愉快地元旦小长假,想拿起手机计划一下去玩点什么好玩的,吃点啥好吃的,正好有一条微信群消息,@了我,点开一看,说是用户没法操作了,系统崩了,???于是赶紧去看看服务的状态,我们是微服务的架构,服务比较多,先看了前端直接调用的web模块,发现有报错,调用order模块的断路器开了(我们用到了Hystrix),再去看order 发现内存飙升到3个g了,平时只有一个g的,去看了下日志,发现OOM了,啥情况???最近新做的功能由于供应商那边的问题没有上线,已经一个月没有发布了,我们双十一、双十二都过来了,怎么这会不行了?于是想着用前段时间学到的一些JVM命令去看看,因为我们是用的docker跑的,所以得先进入容器(docker exec)再执行JVM命令,进入容器之后发现,jps都打不出来,跟别说其他的了。。。这就很尴尬了。网上找了下,说直接使用JRE的项目会出现这个问题,因为jps是JVM带的命令,而JRE是没有的,刚好我们的docker里使用的是JRE而不是JDK,自然无法使用。于是赶紧将order模块重启,先让他跑起来,然后将JRE替换成JDK,然后加上两个JVM参数:
-XX:+HeapDumpOnOutOfMemoryError (发生OOM的时候自动生成dump文件)
-XX:HeapDumpPath=/tmp(dump文件存放位置,必须真实存在)
pp测试没毛病发到了生产。
过大大概一个小时,系统再次OOM,这时候我们在服务器上,使用
docker cp containerId:/tmp/java_pid11105.hprof .
将dump复制到VM上,使用sz命令下载到本地以便分析。
高版本的JDK是没有visualvm的,需要自己去下载的:https://visualvm.github.io/index.html,安装好设置完Javahome就可以使用了。
使用visualvm打开dump文件,按照上面的流程找到报OOM的线程,感觉离真相已经很近了,一看线程调用栈,懵了:
跟上面的情况不一样啊,并没有将有问题的代码显示出来,而且都是unknowString,连项目里的类名、包名都没有显示出来!只知道是在分配内存的时候出现了OOM。平复下心情,继续看,既然没法一步到位那么我们就来看看,内存里都存了些啥吧,发现byte数组占了75%的内存,明显是不正常的
那么我们来看看byte数组里是啥,发现是ArrayList中的数组,但是数据是ASCII,找了个ASCII转string的网站:https://onlinestringtools.com/convert-ascii-to-string。
转译过来,知道它是我们的一个对象,然后去到对象对应的数据库,找到慢查询的日志,发现了全表扫描的SQL。。。根据对象大概定位到类,还好查询方法不多,很快发现一个可疑的地方,有一个根据id查找所有子记录的findall方法,如果不传id会有可能造成全表扫描,然后找到所有调用这个方法的地方,发现有个特殊情况确实会传null的id字段(一种特别特殊的情况),但是问题是这种订单是不会在用户界面显示的没用户根本就没法操作这个订单,但是没有找到其他可疑的地方,死马当活马医吧,还是先修了,再加上日志,看看是否是这个地方的漏洞。
改完测试环境测一下,发现这种特殊情况下不会OOM了,发到生产上,观察了几天,确实是没有再发生OOM了,至于为什么用户会这么操作,还是有人恶意攻击,答案还待寻找。
总结一下这次的成长:
- 想使用JVM的命令,必须保证使用JDK来运行程序。
- 要分析OOM的问题,最好是在OOM的时候将dump文件保存下来,使用上面的JVM参数就OK了。
- 虽然有时候工具可以直接定位到问题,但是大多数时候,并不是报oom的线程就是造成OOM的线程,因为也有可能是其他线程用完了内存,当报错线程想分配内存的时候,发现没有内存可以分配,于是就报错了,所以这时候就需要做一些其他的分析了。比如查看堆中占用最多的对象是什么,一般就是可疑对象了。有时候还可以根据数据库的慢查询来看倒推。