一次频繁full gc引发的问题排查

2023-10-22 15:13:56 浏览数 (2)

一次频繁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:对象以及它所持有的其它引用(包括直接和间接)所占的总内存
  1. 首先打开了Leak Suspects Report。

高端大气看不懂!看这个报告还以为是logback有问题,其实并不是。

  1. 换个Histogram视图:

高端大气还是看不懂!就认识一个AES。这让我到哪儿说理去。

  1. 换个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,其实就是查找内存泄漏的位置,需要借助于工具。而本次内存泄漏的原因,主要在于公司的基础组件太烂,在一个很普通的实体中写了一个不普通的连接池,而文档不健全,导致调用方难以及时发现其实隐藏的风险。

0 人点赞