Java 程序开发者,多多少少都遇到过 Java 堆内存溢出的错误,错误发生时可以在日志文件中看到 java.lang.OutOfMemoryError: Java heap space
字样。不像 NullPointerException
等其他异常,抛出 OutOfMemoryError
的代码往往并不是罪魁祸首,只是想申请内存时发现内存已经被其他人占光了而已。这个特点导致开发者较难找到导致 OutOfMemoryError
的根本原因。许多人喜欢靠前后版本代码比较,甚至根据一些蛛丝马迹来推测问题点,但这些手段都很低效,无法推广。
本文从一个项目的实际例子出发,讲述如何通过分析内存 dump 文件定位问题代码,甚至还原问题发生时的场景。
问题出现
最近某项目报告生产环境 服务器的 Java 堆内存大小不断攀升,怀疑存在内存泄漏。
接到报告后,我们就请项目运维人员做了一次内存 dump。在这里推荐使用类似下面的命令(把 Java 进程 11780
内存 dump 到 a.hprof
文件中):
jmap -dump:live,format=b,file=xxx.hprof 11780
|
分析工具
Java VisualVM (不推荐)
Java VisualVM 是 JDK 自带的 Java 内存分析工具,执行命令 jvisualvm
即可运行。
其实用 VisualVM 也是可以分析内存泄漏问题的,不过 VisualVM 的界面做得不是很人性化,用起来不如下文要重点推荐的 Eclipse Memory Analyzer,所以在这里暂不作详述了。
Eclipse Memory Analyzer (推荐)
Eclipse Memory Analyzer 是 Eclipse 组织开发的 Java 内存分析工具。
推荐到其官方主页去下载最新版本: http://www.eclipse.org/mat/
本文使用 Eclipse Memory Analyzer 1.10.0
版本,发布于 2020 年 3 月 18 日。
分析过程
加载 dump 文件
点击 Eclipse Memory Analyzer 菜单 File
→ Open Heap Dump…
选择 dump 出来的 heap_live520.hprof
文件,就开始加载。该项目生产环境内存比较大,dump 出来的文件有 6GB
多,需要耐心等待几分钟。
加载完成后,会询问用户是否要显示 Leak Suspects Report,也就是泄漏怀疑对象报告。这是 Memory Analyzer 对内存进行智能分析后得出的一份泄漏怀疑对象报告,一般可以选择显示该报告,但今天我们不使用该报告,完全手工来搞定。 |
Dominator Tree 找到“内存堆积点”
点击工具栏图标 (
Open Dominator Tree for entire heap.
),打开 Dominator Tree。dominator 直译为“主宰者”,在这里的意思就是占用内存最多的对象。
在上面的图里我们可以看到各个对象,格式是 类名 @ 对象地址 ,而且是按 Retained Heap 从大到小排序的。
Dominator Tree 各列含义
详细解释请查阅 Eclipse Memory Analyzer 自带的 Help Contents。 |
对我们来说,要观察的就是 Retained Heap。哪个对象的 Retained Heap 大,就说明由于它的存在,这么多内存都释放不掉,那么这个对象就可能是内存泄漏的点。
为了更好地说明,我们先不看排名第一的 org.apache.tomcat.util.threads.TaskThread @ 0x6ab74a1a0
,而来看排名第二的 com.mysql.cj.jdbc.result.ResultSetImpl @ 0x6a0fe1a40
。
双击该对象展开其子树,展开几层后,可以看到 Retained Heap 有一个断崖式的降低(从 914677440
一下子降到了 3600
):
这个突然降低的位置称为“内存堆积点” (memory accumulation point),也就是说 java.lang.Object[360145] @ 0x6b7166310
数组对象中含有 299134
个 com.mysql.cj.protocol.a.result.ByteArrayRow
元素。注意:展开时默认只显示 25 个子节点,要看更多的话就要再双击 Total: 25 of 299,134 entries; 299,109 more
这一行。
看到这里,我们大概可以推断出这是一句 SQL 返回了将近 30 万行数据,而且这些行数据全都堆积在内存中没有得到释放。接下去我们要找出是什么代码创建出了这样一个对象。
Path To GC Roots 找到线程
右键点击 com.mysql.cj.jdbc.result.ResultSetImpl @ 0x6a0fe1a40
,在弹出菜单中点击 Path To GC Roots
→ with all references
:
可以看到该对象到 GC Root 的各条路径:
GC Root 的含义请查阅 Eclipse Memory Analyzer 自带的 Help Contents,若看英文比较吃力的话,也可参考文末的参考文档。
一个对象可能有多条路径通往多个 GC Root。但一般来说,其中某一个 GC Root 必定是一个线程。从上图可以看到 com.mysql.cj.jdbc.result.ResultSetImpl @ 0x6a0fe1a40
对象通往 GC Root 的路径有很多条,但最终都殊途同归到了线程对象 org.apache.tomcat.util.threads.TaskThread @ 0x6ab74a1a0 http-nio-7001-exec-10
。这就是说,是 http-nio-7001-exec-10
线程在运行过程中创建出了 com.mysql.cj.jdbc.result.ResultSetImpl @ 0x6a0fe1a40
对象。那么我们接着看看 http-nio-7001-exec-10
线程到底在干什么?
Thread Overview
右键点击 http-nio-7001-exec-10
线程对象,在弹出菜单中点击 Java Basics
→ Thread Overview and Stacks
,打开该线程的 Thread Overview:
上图中可以看到第一行就是 http-nio-7001-exec-10
线程。双击展开该线程的堆栈,接下来就要重点观察那些我们自己写的类里的方法,这里需要凭借一些对自己代码的熟悉度和经验了。我们可以看到堆栈中有调用到 logwire.web.controller.ActionController.requerySelectRows
方法,这是在 选中全部 后再点击操作按钮后会调用到的方法:
猜测可能是根据条件查询到的数据量太大了,导致内存被用完。
然后我们再看看到底是在哪个界面功能里执行了该方法?继续往下找,可以看到 logwire.web.controller.ActionController.doAction
方法:
这个方法里有两个 String
类型的 local 变量。local 变量在内存中没有变量名称,但是我们可以根据其顺序来判断它是哪个变量。在一个方法下展开的 local 变量中,第一个一定是对象本身,接下去是各个方法参数,最后是方法体内定义的局部变量(按代码执行的顺序)。所以我们在这里看到的第一个字符串 payment_report_query
就是 doAction
方法的第一个参数(看源代码可知是 queryName
)的值,第二个字符串 payment_back_other
就是第二个参数 action
的值。
根据 payment_report_query
和 payment_back_other
这两条线索便可弄清用户是在哪个界面点击了哪个按钮,引发了内存溢出。
更进一步的探究:找到执行用户
现在我们已经知道了是哪段代码出了问题。不过如果想搞清楚用户为什么会执行操作,就得去问问操作者本人,那么就需要知道执行操作的用户是谁。
目前项目是把登录用户信息记在 Spring Security 框架的 SecurityContext
中,调用其 setAuthentication
方法,其本质是把登录用户对象记在了 Java 线程本地变量 (ThreadLocal) 中。阅读 Spring Security 代码可知,该线程本地变量是由 org.springframework.security.core.context.ThreadLocalSecurityContextHolderStrategy
对象的静态成员变量 contextHolder
持有的。
为了快速找到该对象,可以点击工具栏图标 (
Create a histogram from an arbitrary set of objects.
) ,打开 Histogram。Histogram 展示了每一种 Java 类有多少个实例,总共占了多少内存。
这里类实在太多了,我们要过滤一下,快速找到想要的类。在 Class Name
列的正则表达式过滤器中输入 ThreadLocalSecurityContextHolderStrategy
并回车(回车后会自动在前后加上 .*
,表示前后还可以有任意多个字符),这样就找到了那个类:
但这只是类,而不是实例对象。我们需要列出该类的所有实例对象。右键点击该类后,在弹出菜单中点击 List objects
→ with outgoing references
:
可以看到该类只有一个实例对象,展开以后看到了这个类的静态变量 contextHolder
,是一个 java.lang.ThreadLocal @ 0x6a6fcc3c8
。
找到这个线程本地变量 (ThreadLocal
) 后,我们就要看看在 http-nio-7001-exec-10
线程中对应该线程本地变量的值是什么,也就是执行用户是谁。
阅读 JDK 代码可知,在线程 Thread
对象中有一个 threadLocals
成员变量持有 ThreadLocal.ThreadLocalMap
对象。当调用 ThreadLocal
对象的 get
或 set
方法时,实际上是以 ThreadLocal
对象为 key,存入了线程的 threadLocals
中。
所以我们可以找出所有 threadLocals
的 key 中含有 java.lang.ThreadLocal @ 0x6a6fcc3c8
的线程,再找到 http-nio-7001-exec-10
线程的 threadLocals
中相应 key 的 value 即可。
右键点击 contextHolder
,也就是 java.lang.ThreadLocal @ 0x6a6fcc3c8
对象,在弹出菜单中点击 List objects
→ with incoming references
,找到所有引用了该对象的对象:
我们看到除了 contextHolder
以外,还有很多线程的 ThreadLocal.ThreadLocalMap
引用了该对象,这表示很多线程中都有该线程执行时的用户:
然后要干点体力活儿了,逐个展开后,我们最终找到了 http-nio-7001-exec-10
线程:
笔者觉得应该可以利用 OQL 功能(类似于 SQL 语法,在内存分析中做各种查询),更快速地找到 http-nio-7001-exec-10 线程对应的用户。但是暂时没花精力去详细研究,以后有时间再补充。 |
在上面的图中,我们看到左边 Attributes 列表中,value
属性的值是一个 org.springframework.security.core.context.SecurityContextImpl @ 0x6cd141978
对象。右键点击该对象,在弹出菜单中点击 List objects
→ with outgoing references
,再展开:
最终就看到了该线程的执行用户的 username
。(为保护客户隐私,具体的 username
值用马赛克遮蔽了)
其他
为什么不直接用 Leak Suspects Report?
其实 Leak Suspects Report 还是很好用的,但是不能过度依赖于它。
因为 Leak Suspects Report 只展示最可疑的两个对象,通常是当前 Retained Heap 最大的两个对象。但有时候 当前最大的 并非 真正泄漏的 ,如果太依赖 Leak Suspects Report,可能会找不到真正的泄漏原因。
为什么 当前最大的 并非 真正泄漏的 ?
假设这样一个场景:
-
Java 运行参数中设置了最大堆内存
200 MB
(-Xmx200m
) -
系统中有一段导致内存泄漏的代码,该代码是个死循环,每天会在一个
List
中添加一个元素,增加占用1 MB
内存。 -
系统对外提供了一个 API,该 API 每次调用时需要占用
50 MB
内存,调用完就全部释放
在这样的场景下,该系统刚启动后可以支持大约 3
个客户端同时调用 API,这样总共占用 150 MB
内存(其他 50 MB
是 Tomcat 等启动后固定占用的部分)。
但是过了一个月后,那段内存泄漏代码的 List
占用了 30 MB
内存,这时若仍然有 3
个客户端同时调用 API,则会抛出 OutOfMemoryError
。因为这时空闲内存只有 120 MB
了,最多支持 2
个客户端同时调用 API。
在这种情况下,内存 dump 分析会发现占用内存最大的仍然是那几个 API 线程,而不能立即发现真正的内存泄漏点。
如何精确定位内存泄漏点?
既然这样,那么该如何精确定位内存泄漏点呢?
从理论上来讲,不存在绝对有效的方法。但是通常生产环境的 -Xmx
参数不会设得太小,所以如果正常的代码已经无法获取合适大小的内存,那么往往内存泄漏对象已经占用了很大的内存 (Retained Heap)。
当然,有时候并不存在严格意义上的“内存泄漏”。就以本文的例子来说,只是因为某次查询到的数据行数太多,撑破了 -Xmx
上限。但如果拼命增加 -Xmx
,直到足够容纳查询到的行数,那么查询过后也照样会释放内存,并不会 OutOfMemoryError
。不过从代码工程上来讲,单次请求处理占用的内存超过 1 GB
,这种设计就是不合理的。一般来说,单次请求处理占用的内存应该控制在 50 MB
以内。
合理使用比较功能
有时候可以对同一个 Java 进程先后多次 dump,然后来比较这些 dump 文件的内容。
在第一个 dump 文件的 Navigation History
中右键点击某个视图,然后 Add to Compare Basket
:
在第二个 dump 文件也做同样的操作。于是在 Compare Basket
中可以看到有两个待比较对象。接着再点击 (
Compare the results
)
这样就可以看到比较结果:
有时候可以看到某个类型的实例数量以及内存一直在增长,那么就可能是内存泄漏点。
方法体内定义的局部变量,不一定能在 local 变量中找到
上文说到过在线程堆栈里可以看到每个方法里各个 local 变量的值。但这只是一个笼统的说法,并不是非常精确。
看这样一个例子:
- public void method1() {
- if (true) {
- String s = "abc";
- }
- while (true) {
- new ArrayList<>().add(new byte[1024]);
- }
- }
在上述 method1
方法中,内存泄漏发生在 while
循环中,列表不断变长,最终会内存溢出。但是在用 Eclipse Memory Analyzer 观察线程堆栈时,method1
方法下是看不到字符串 abc
这个 local 变量的。因为该变量的作用域只在 if
语句内,也许早在内存溢出之前,字符串 abc
就已经被 GC 回收了,这样在分析 dump 文件时自然就看不到了。
参考
Eclipse Memory Analyzer 自带的 Help Contents 解释得很详细了。但如果阅读英文比较慢的话,也可以看一些中文资料:
-
关于 Shallow Heap、Retained Heap、GC Root 的解释: https://blog.csdn.net/hhww0101/article/details/8133219