一次频繁full gc引发的问题排查
一、背景
刚发布的应用,间隔8小时不到,就开始告警,告警的位置还很特殊,属于调用外组接口的位置,让人费解。
最后查明原因,是大对象造成频繁full gc,这里,记录下排查问题的过程。
如果大家正在寻找一个java的学习环境,或者在开发中遇到困难,可以加入我们的java学习圈,点击即可加入,共同学习,节约学习时间,减少很多在学习中遇到的难题。
二、初排查
2.1 看链路
报错的位置很奇葩,锅彷佛在外组身上,由于公司接入了skywalking,于是去看下skywalking的链路跟踪日志:
全都是几十毫秒,看不出啥,公司的skywalking也忒垃圾。没办法,去diss下外组人员,你家的接口怎么这么稀烂,看把我们应用搞成啥样了。
然而,仔细一看,另外一个外组的接口也这么慢,不正常啊。
再看下其他机器是正常的,只有两台机器是不正常的,那就不太可能是外组的接口问题了,要从自身找原因。
2.2 看性能
看下机器的监控信息
- 机器的信息看起来很正常,内存CPU都没打满,会不会是设置的最大内存小了?
ps -ef | grep java
看下jvm的参数,一看也是正常的。 - skywalking的监控信息也看下,发现两台机器在搞事情,gc很频繁。
所以可能是机器有问题?换个机器试试。因为是docker实例,随手可换。
三、找具体原因
docker实例重建无果,剩下的几台实例陆陆续续也告警了,这多半是代码问题了。
先看下内存使用情况:jstat -gcutil 8
full gc这么高,肯定是有内存泄漏。要么是大对象,要么是流没关。
然后坑继续:
- 生成java 堆信息报告:jmap -dump:format=b,file=heap.dump 导出了文件,但实在太大了,5个G,下载三分之一就会断掉,不得不重下。
- 使用jmap -histo:live 查看,最大的[I,int数组,看不出来是什么。
没办法,先猜测一波,是不是流没关呢?用了Okhttp的异步操作,一看异步操作果然没显式去关闭,如获至宝,close调起。发布等待中。
结果,八个小时不到,又开始了。原来,OkHttp的string()方法,finally里调用了Util.closeQuietly(source),是可以自动关闭流的。
四、问题解决
没办法,肯定是大对象了,只不过大对象在哪儿?只能去看dump文件。
4.1 下载dump文件
先想办法下载dump文件,5个G虽然大,分成10个文件下载还是能接受的。
split -b 700M -a 1 heap.dump heap.dump.
分割之后,出现8个文件,下载之。
4.2 合并文件
下载完成之后,合并文件。在windows上,可以打开git bash窗口(Linux环境即可)。输入命令:
cat heap.dump.* > heap.dump
还原heap.dump文件。
4.3 打开dump文件
分析dump文件,文章好多,当然先找个最简单的,用jdk自带的jvisualvm。
可是它有点不争气,一直在分析,卡在界面不动,不知所谓。
换个eclipse mat试试。先考虑用插件,在eclipse的marketplase里面下载,然而就是下载不了,弃之,直接下载mat:http://www.eclipse.org/mat/ 下载之,解压,双击,提示jdk至少要11,想换个低版本,但是谁知道哪个版本可以兼容jdk1.8的,不如下载jdk11来的快,下载之。
修改MemoryAnalyzer.ini指定jdk11:
代码语言:javascript复制-vm
C:/Program Files/Java/jdk-11/bin/javaw.exe
启动成功。但是会出现以下错误:
- 内存不够,内存分配要大于文件大小,-vmargs 调整
-Xmx10240m
,足够大 - 磁盘要够,index文件也要好几个G。
打开:
4.4 指标分析
全英文,太难了。下面是一些常用的指标的解释:
- Histogram可以列出内存中每个对象的名字、数量以及大小。
- Dominator Tree会将所有内存中的对象按大小进行排序,并且我们可以分析对象之间的引用结构。
- Leak Suspects Report:内存泄露报告,Leak Suspects 是MAT帮我们分析的可能有内存泄露嫌疑的地方,可以体现出哪些对象被保持在内存中,以及为什么它们没有被垃圾回收
- List objects --> with outgoing references 查看当前对象持有的外部对象引用(在对象关系图中为从当前对象指向外的箭头)
- List objects --> with incoming references 查看当前对象被哪些外部对象所引用(在对象关系图中为指向当前对象的箭头)
- Shallow Heap:当前对象自己所占内存的大小,不包含引用关系的
- Retained Heap:对象以及它所持有的其它引用(包括直接和间接)所占的总内存
- 首先打开了Leak Suspects Report。
高端大气看不懂!看这个报告还以为是logback有问题,其实并不是。
- 换个Histogram视图:
高端大气还是看不懂!就认识一个AES。这让我到哪儿说理去。
- 换个Dominator Tree视图:
一下子就看到了可以定位的的AESStack方法。找到它。
4.5 结果分析
代码语言:javascript复制class AESStack {
private ConcurrentLinkedQueue<AES> queue = new ConcurrentLinkedQueue<>();
public static final AESStack INSTANCE = new AESStack();
public void init(int num) {
int count = Math.min(Math.max(0, num), 500);
for (int i = 0; i < count; i ) {
queue.offer(new AES(AES.genAesKey()));
}
}
在这里,每次init的时候会生成num个AES对象,存入queue中,而调用方是另外一个类的构造函数。是创建thrift客户端的代码。
这段代码逻辑上是没有问题的,但是创建的客户端只能作为全局变量被创建一次,如果作为局部变量被创建多次,就会产生内容泄漏。而我们的代码就是将用写在方法中,因此产生了内存泄漏。
五、结论
没有结论是不完整的,但是这种full gc,其实就是查找内存泄漏的位置,需要借助于工具。而本次内存泄漏的原因,主要在于公司的基础组件太烂,在一个很普通的实体中写了一个不普通的连接池,而文档不健全,导致调用方难以及时发现其实隐藏的风险。