我的新课
《C2C 电商系统微服务架构120天实战训练营》
在公众号
儒猿技术窝
上线了,感兴趣的同学,可以长按扫描下方二维码了解课程详情:
课程大纲请参见文末
本文以我司生产环境Java应用内存泄露为案例进行分析,讲解如何使用Eclipse的MAT分析定位问题
一. 背景
11月10号晚上8点收到报警邮件,一看是
OOM
打开公司监控系统查看应用各项指标发现JVM中
老年代在持续增长
(从上次发布10月30号到11月10号的12天内一直在增长, 存在
内存泄露
迹象)
从图中可以看出, 从10月30号发布到11月10号oom期间11天老年代一直在缓慢上涨, 虽然有下降, 但整体趋势是上升的,平均每天泄露约50M内存, 说明每次都无法完全释放干净
因为生产环
境的JVM添加了
-XX:+HeapDumpOnOutOfMemoryError
参数,该配置会把dump文件的快照保存下来供后续分析排查问题,也可以使用jmap或jcmd等jvm命令进行dump:
jmap -dump:format=b,file=文件名 [pid]
jcmd pid GC.heap_dump 文件路径
二. 分析内存泄露
内存泄露和内存溢出的区别:
内存泄露从老年代的增长情况看是缓慢上升的, 最终达到老年代上限才会导致溢出,有些内存泄露可能需要很长的时间发生, 所以说内存泄露更隐蔽, 不像内存溢出那样容易暴露(内存溢出直接抛出OOM), 而且内存长时间得不到释放会导致服务性能越来越差、gc时间变长、响应变慢:
从图中可以看出在12天里每天大概泄露(增长)
50M
左右, 这种情况下定位泄露原因需要多次dump采集样本, 然后和上次的比较分析, 即需要多个dump文件进行比较分析才能精确定位问题。
否则很难看出具体泄露的点, 加上dump文件中大部分是正常的内存使用, 会干扰问题的定位, 增加排查难度。
所以当时的做法是每天固定时间dump一次, 采集足够多的样本, 如下图:
另外测试环境不好重现的主要原因是不清楚是哪个接口调用引起的, 这个Java服务有多个暴露的api, 而且测试环境不方便压测,压测量大了, 底层接口熔断, 压测量小看不出泄露迹象, 所以得从dump分析入手, 找到问题所在再去测试环境验证。
这
里使用Eclipse的memory analysis tool(MAT)工具进行分析
把下载到本地的多个dump文件用mat依次打开("File → Open Heap Dump"), 如下图:
比如我们要分析这3个dump文件(当然你也可以分析更多个, 这样会更精准), 打开后, 使用
compare basket
功能找出内存泄露的差异点:
1. 使用 compare basket 功能分析内存泄露
1> 菜单栏 window → compare basket ,打开比较窗口(如果最下面一栏已经有compare basket则这步不需要),如下图:
2
> 依次打开3个dump的dashboard面板, 在下方的 Actions一栏点击"histogram"或"dominator tree"生成对应的直方图或支配树列表,如下图:
直方图或支配树都可以列出堆中存活的所有对象,但二者的维度不同, 直方图按照类型统计, 支配树是以对象维度统计。
如果你对项目代码比较熟悉, 通过直方图定位内存泄露会更快,因为它是按照类型全部平铺开的,如果这个项目不是你负责的, 建议使用支配树的方式, 因为支配树包含了对象之间的引用关系(支配树视图可以展开查看内部引用层级)
3> 我们以支配树做比对, 在最下面一栏的"Navigation History (window → navigation history)"里(直方图类似)找到在第2步打开的支配树dominator tree图标, 右键添加到compare basket, 如下图:
4> 重复上面的2, 3步骤依次把其他的dump文件添加到"compare basket"栏, 然后点击右上角的红色感叹号, 生成比较结果,如下图:
(
注意比较的dump文件的顺序,时间最早的在上面,可以通过右上角的上箭头↑和下箭头↓调整顺序)
生成的比对结果如下:
(可以放大查看)
Shallow Heap一列后面的序号 #0, #1, #2 分别对应:
第一个dump文件占用的shallow size, 第二个dump文件占用的shallow size , 第三个dump文件占用的shallow size
Retained Heap #0, Retained Heap #1, Retained Heap #2 这3列分别对应:
第一个dump文件占用的retained size, 第二个dump文件占用的retained size , 第三个dump文件占用的retained size
通过Retained Heap的变化趋势可以看出:
一般我们主要关注
红框
标出的对象, 因为这部分发生内存泄露的
嫌疑最大
这里先区分两个概念:
Shallow Size
Retained Size
因为这里我们比较的是支配树, 所以按照retained heap倒序排列, 从左到右依次为: retained heap #0 → retained heap #1 → retained heap #2(以最后一个retained heap #2 倒序, 因为这个是最后一次dump的内存快照, 这样可以看出内存泄露的增长趋势)
2. 定位内存泄露
基于上一步得出的比较结果, 可以看出"
org.apache.tomcat.util.threads.TaskThread http-nio-8080-exec-*
" 有内存泄露的嫌疑, 查看它的引用关系:
点击"with outgoing references"后逐层展开第一个对象内部的引用关系(以Retained Heap倒序,主要是看retained size排在前面的对象), 如下:
可以看到
TaskThead
内部有一个threadLocal, threadLocal内部有一个
concurrentHashMap
,这个map里存的是我们的日志相关对象"
com.*.framework.log.FieldAppendedValue
",从下面几个map里的key可以确定是我们记录到日志系统(ElasticSearch)的对象, 这些日志对象主要记录调用接口的请求报文、响应报文、SOA接口名称等信息,如下图:
但为什么日志对象会占用这么多内存?
而且这里看到的只是其中一个taskThread里,继续展开RESPONSE_CONTENT的val对象
FieldAppendedValue
内部引用, 如下:
发现
FieldAppendedValue
内部维护了一个
CopyOnWriteArrayList
对象, 这个list里竟然存放了
10674
个值,正常来讲不可能一次接口请求会有这么多的日志对象, 而且接口请求完记录到ES后, 这部分内存就应该释放了才对。
查看
CopyOnWriteArrayList
内部存储的内容,如下:
随便打开10675个中的几个
FieldAppendedValue
, 发现内部存放的都是
同一个接口
的请求响应报文,如下图:
可以右键copy→ value 把值复制出来查看, 接口报文如下:
(响应报文)
{
"ResponseStatus"
: {
"Timestamp": "/Date(1605583909438+0800)/",
"Ack": "Success",
"Errors": [],
"Build": null,
"Version": null,
"Extension": []
},
"downloadUrl": "https://ii066.cn/hFGBEW"
}
从上面那张
concurrentHashMap
截图(key : SOA_METHOD_NAME) 可知这个接口名是: getDownloadLink, 也就是说list里10675个日志对象存的都是"getDownloadLink"这个接口的报文。
而且这只是其中一个TaskThead内部情况, 加上全部20个对象, 20 * 10675 大概是213500个接口报文,如下图:
这个接口是什么鬼?
3. 代码分析
查看代码得知这个接口并没什么幺蛾子,只是当时的开发同学在调用这个底层接口时新接入了我们部门封装的SOA组件公共类:
AbstractSimpleHandler.java
(这个公共类主要是通过模板方法在调用接口时记录报文日志埋点、超时时间设置、mock等功能)
这次出现OOM的这个Java项目之前调用soa接口是自己实现了一套公共方法(早于框架之前实现), 也就是说只有这一个接口使用了新的公共类
AbstractSimpleHandler
,其他的接口调用方式还是原来的方式。
新的工具类
AbstractSimpleHandler
记录接口报文的代码是通过调用
ELKLogUtils.write()
实现的, 这个方法的内部大致逻辑如下:
Object value = HttpContext.get(BEHAVIOR_LOG);
if (value == null) {
value = new ConcurrentHashMap<>();
HttpContext.add(BEHAVIOR_LOG, value);
}
HttpContext内部维护的是一个
ThreadLocal
:
public class HttpContext {
private static final int CONTEXT_DEFAULT_SIZE = 1 <6;
private static final ThreadLocal
所有调用soa底层接口的报文日志都是通过
ThreadLocal
内的map存储的, 然后统一发送到ES日志系统。
我们都知道theadLocal是线程安全的, 但是一般我们的项目都是部署在Tomcat等web容器里, tomcat维护了一个http
线程池
, 就是前面截图的那个
TaskThead Http-nio*
线程对象,每次前端app发起请求都会从tomcat的线程池里取一个线程处理前端的请求, 如果复用的是上一个线程, 那他内部的
threadLocal
没有清空, 还是会保存上次的报文信息,这样的话这次请求又会继续存放接口报文, 就会越积越多。
。
。
新接入的组件把接口报文存到threadLoacl的代码是在
AbstractSimpleHandler.java
里的,而清除threadLoacl的代码是在另外一个公共类
BaseService.java
里做的,也就是说要接入新的公共类
除了
AbstractSimpleHandler.java
外,还要接入
BaseService.java
这个公共类!
这个也是有历史原因的, 这个Java项目本身比较早, 那时候还没有我们部门框架的SOA公共类, 所以自己实现了一套,后来使用新的框架组件调用接口的开发小伙伴没有调研全面, 少接了一个公共类(
BaseService
)导致了这一问题发生。
所以这个问题的根因是
threadllocal使用不当引起的内存泄露
弄清楚原因后就好办了, 解决办法是在请求完接口后主动调用下框架里的
HttpContext.clear()
, 清除下框架内部的
threadlocal.map
即可,当然后续还是要统一接口的调用方式, 不能两套工具类并存。
4. 使用 path to gc root 定位业务代码
还有另外一个内存泄露的嫌疑是"
com.*.common.utils.ITextRendererPoolManager
", 如上面比对结果的图:
单独在dominator tree支配树视图展开如图所示:
ITextRendererPoolManager
内部使用了apache的一个对象缓冲池, 目的可能是为了对象复用, 继续展开,如下图:
发现是pdf的一个工具类:
org.xhtmlrenderer.pdf.ITextRenderer
, 这个开源的pdf工具是我们项目的邮件功能在发送附件的时候生成pdf文档时引入的一个第三方jar包,开始怀疑是否是这个开源的pdf工具导致的内存泄露, 但是不清楚这个jar包是在哪里调用的?
这里可以通过"
path to gc root
"查看是谁在引用他, 即我们业务代码调用的地方,如下图:
这里先说下"path to gc root"选项的含义:
-
with all references : 所有引用, 包括强引用, 弱引用, 软引用, 虚引用
-
exclude weak reference : 排除弱引用
-
exclude soft reference : 排除软引用
-
。
。
。
。
我们知道软引用, 弱引用这些在发生full gc时可能会被回收掉(回收时机不同, 具体可自行百度), 目的是不造成内存溢出。
一般引起内存溢出的都是
强引用
,所以你可以选择"exclude all ptantom/weak/soft reference"只查看强引用。
但在这个案例中
pdf.ITextRenderer