OOM异常追踪

2,932 阅读6分钟

  • 产品:叮(一份execl传送过来),这是今天要清洗的数据。
  • 我:嗯????什么情况???
  • 产品:之前新增一个字段,需要将历史数据补充完毕
  • 我:我在开发需求
  • 产品:好的,今天洗完
  • 我:........我洗!

于是今日写好数据清洗程序之后,就让运维小哥跑一下,在清洗过程中出现了OOM的异常情况。然后让运维小哥哥将对应的线程栈信息以及内存信息dump下来。

先说明发生OOM的可能原因:

  • outOfMemoryError 年老代内存不足。
  • outOfMemoryError:PermGen Space 永久代内存不足。
  • outOfMemoryError:GC overhead limit exceed 垃圾回收时间占用系统运行时间的98%或以上。

在这里我们就要结合代码,观察是否大量应该被回收的对象在一直被引用或者是否有占用内存特别大的对象无法被回收。

问题展示

日志文件:

时间戳 [http-nio-端口号-exec-1] ERROR ResponseExceptionHandle:26 - Handler dispatch failed; nested exception is java.lang.OutOfMemoryError: GC overhead limit exceeded
org.springframework.web.util.NestedServletException: Handler dispatch failed; nested exception is java.lang.OutOfMemoryError: GC overhead limit exceeded
	****中间一大段****
Caused by: java.lang.OutOfMemoryError: GC overhead limit exceeded

这个时候要是有可视化界面就好了(或者拥有运维的电脑,自己用Arthas上去😂),没办法,只能让运维线程栈信息以及内存信息下载下来。

Linux上生成文件命令

# 生成堆转储快照dump文件命令
jmap -dump:format=b,file=heapdump.hprof pid
# 生成线程堆栈信息文件命令
jstack -l pid >> stack.txt

堆栈信息查看

"http-nio-端口号-exec-1" #37 daemon prio=5 os_prio=0 tid=0x00007f789d236800 nid=0x650e waiting on condition [0x00007f7851409000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000000faa51ba0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
	at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
	at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:103)
	at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:31)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:745)

   Locked ownable synchronizers:
	- None
****等等容器内其他线程

上面只是我截取整个线程堆栈信息的一个容器线程状态查看,整个文件下来是没有发现死锁的发生,那线程方面是没有问题的,不会有线程相互竞争资源造成服务内部请求阻塞而造成OOM的情况发生。

堆转储快照查看

我们通过上面那条指令,以hprof二进制格式转储Java堆到指定filename的文件中。按照普通的文件方式打开肯定是行不通的(你在想啥呢?醒醒)。我这边是有两种方式去处理分析这种文件的。

1.利用jhat

利用JDK里面的指令去分析文件(有时dump出来的堆很大,在启动时会报堆空间不足的错误,可加参数:jhat -J-Xmx512m <heap dump file>。这个内存大小可根据自己电脑进行设置。):

接着你就可以在浏览器里面输入 http://localhost:7000/进行访问:

当前页面是展示了当前容器内包含的类以及id。页面的最下面是导航栏了:

  • All classes including platform 显示堆中所包含的所有的类
  • Show all members of the Rootset 从根集能引用到的对象
  • Show instance counts for all classes(including platform)显示平台包括的所有类的实例数量
  • Show instance counts for all classes(excluding platform)显示除去平台包括的所有类的实例数量
  • Show heap histogram 堆实例分布表
  • Show finalizer summary 显示终结器概述
  • Execute Object Query Language(OQL)query 执行对象查询语句

一般查看堆异常情况主要看这个两个部分:

  • Show instance counts for all classes (excluding platform),平台外的所有对象信息。如下图:
  • Show heap histogram,以树状图形式展示堆情况。如下图:

要注意的是,一般不会直接在服务器上进行分析,因为jhat是一个耗时并且耗费硬件资源的过程,一般把服务器生成的dump文件复制到本地或其他机器上进行分析。

2.利用Memory Analyzer

打开matMAC端安装MAT)然后导入文件:

这里面参数说明很多(我到现在都没有看完全过😂):

Shallow Heap 表示一个对象消费的内存的总量。对象 X 的 Retained Set 指的是一旦 X 被垃圾回收后也会随之被 GC 回收掉的对象的集合。对象 X 的 Retained heap 指的是 X 的 retained set 中所有对象的 shallow heap 之和,或者说是因为对象 X而保持 alive 的内存的大小。

我们查看下面的选项:

  1. Histogram可以列出内存中的对象,对象的个数以及大小。
  2. Dominator Tree可以列出那个线程,以及线程下面的那些对象占用的空间。
  3. Top consumers通过图形列出最大的object。
  4. Leak Suspects通过MA自动分析泄漏的原因。

我们看到最大的那个区域就好(占用了41MB的):我们可以看到左下角是显示对象的名称:org.hibernate.internal.SessionFactoryImpl。我们的技术栈持久层框架使用的是hibernate(但是不怎么对底层了解😂)。

我们点击Leak Suspects,然后出现:

经过MAT出现了两个怀疑内存泄露相关的问题:

我们通过查看下面的问题描述知道:

Question1:被LaunchedURLClassLoader类加载器加载的一个SessionFactoryImpl实例中的BoundedConcurrentHashMap堆积着内存空间,占据了42,984,656字节。

Question2:该内存中存在被SystemClassLoader加载的7,941个Class对象,占据了10,075,768字节。

从Q1入手进行查看:

  1. Description 描述信息
  2. Shortest Paths To the Accumulation Point 到堆积点的最短路径
  3. Accumulated Objects by Class in Dominator Tree 支配树中按类累积对象
  4. All Accumulated Objects by Class 所有按类累积的对象

我们这里就选择从下面三个都可以进行查看当前容器内部的内存堆积问题。上面的第二个是从堆积点一直追踪到线程,可以看到每一个线程对应的Shallow Heap以及Retained heap

庖丁解牛中

我们这里就查看第三个:

我们查看到是SessionFactoryImpl中的QueryPlanCache中存在一个Map集合,该集合占据了大量的内存空间。这个类实际运用中还没有使用到过,不过看这个提示以及名称,个人觉得跟ConcurrentHashMap相似😂(有大佬对BoundedConcurrentHashMap了解的嘛,可以评论下让我涨涨知识)。通过QueryPlanCache的名字,就可以知道它是用来缓存查询计划的,也就是缓存sql语句,以便于后边的相同的sql重复编译。

我本次清洗的数据大约在40w的数据量,而且每个参数都是不相同的,那么有可能会导致的hibernate在进行查询的时候,缓存大量的sql导致heap内存溢出(还是不怎么了解我们的技术栈。。。惭愧惭愧),知道问题了,就要想办法解决去也~~~

最后再给自己拉个票😂一位后端小白的2019年 | 掘金年度征文