# 案例一:老年代内存泄漏

某晚八点收到报警邮件,一看是OOM:

报警对象:xxx
报警时间:xxx
报警信息:k8s docker events oom occured!
图标链接:xxx
1
2
3
4

打开 hickwall查看指标:JVM各项指标中 老年代在持续增长(从上次发布10月30号到11月10号的 12天 一直在增长,存在内存泄露迹象)

OOM

再查看RSS发现是系统驻留内存使用过高导致容器docker内存溢出(总内存4G,Java进程已占用3.92G,留给系统的可用内存不足80M,操作系统运行也需要内存)

OOM

(RSS统计的是 reserved预留内存或 commited提交申请的内存,并不是实际使用的内存)

邮件报的错是 docker oom :

OOM

java总内存=堆内+堆外: java堆内内存刚才已经分析过,尚有1G 可用内存,到这里基本可以定位是jvm堆外内存占用过高导致的。但是从hickwall上现在列出的几个堆外内存看不出问题点:

1.栈占用内存: 42M (168个线程 * -Xss256k)

OOM

2.metaspace元空间: 121M

OOM

3.codeCache: 95M

OOM

整个JVM当时占用的内存大概是 3.219G(堆内commit内存) + 258M ≈ 3.5G

但是当时 oom前 hickwall显示的已使用内存为3.92G, 所以不知道剩下的 420M(3.92G – 3.5G)堆外内存 被什么占用了?

当时的临时解决方案是调小堆内内存Xmx,按照上面计算的堆外内存多出的420M,当时把堆内内存设置为2.8G,留出更多的空间给堆外内存使用, 堆外内存占用可以使用 JVM的NMT(NativeMemoryTracking)命令排查,在启动文件src/main/webapp/WEB-INF/tars/prod/extraenv.sh 添加jvm参数: -XX:NativeMemoryTracking=summary/detail 但是NMT命令无法检测JNI的堆外内存泄露,而且NMT对性能会有所损耗,线上环境慎用。

堆外内存占用最大的一块应该是我们框架SOA的 httpclient或Cdubbo的 netty(底层通过操作DirectBuffer.allocate分配堆外内存),但公司框架一般不会出现内存泄露的问题,所以比较简单的方式是排查下项目中是否有自己打开的流或连接未关闭, 比如:
 ● 一些压缩解压工具deflater,Inflater,GZipStream流用完未关闭
 ● directByteBuffer,netty,httpclient等 IO框架
 ● inputStream,outputstream读写流

检查发现项目中确实有未关闭的http connection:

conn = (HttpURLConnection) url2.openConnection(); // 最后未执行conn.disconnect();
1

所以当时针对堆外内存泄露问题的解决方案是:
 ● 调小堆内内存Xmx
 ● 限制堆外内存大小(-XX:MaxDirectMemorySize)
 ● 关闭连接

当然主要问题还是在堆上,继续排查堆内内存泄露的问题,如下图所示:

OOM

从图中可以看出,从10月30号发布到11月10号oom期间11天老年代一直在缓慢上涨,虽然有下降,但整体趋势是上升的,平均每天泄露约50M内存,说明每次都无法完全释放干净。

# Dump 堆转储

因为是docker oom 不是jvm oom,所以没有生成 dump文件,需要自己去生产抓取:在 captain生产环境对应的机器下点击 dump按钮, 如下:

OOM

抓取完成后会发一封邮件给我们,直接点击下载链接就可以把dump文件下载到本地进行分析,也可以使用 jmap或 jcmd等 jvm命令进行 dump。

# 分析内存泄漏

内存泄漏和内存溢出还有些区别:内存泄露从老年代的增长情况可以看是缓慢上升的,最终达到老年代上限才会导致溢出,但有些内存溢出可能在很短的时间里就发生了,所以说内存泄露更隐蔽,不像内存溢出那样容易暴露,而且内存长时间得不到释放会导致性能越来越差,gc时间变长,响应变慢。

OOM

这里使用 Eclipse的 memory analysis tool(MAT)工具进行分析:把下载到本地的 dump文件用Eclipse的内存分析工具mat 依次打开("File → Open Heap Dump"),如下图:

OOM

# 1. 使用 compare basket 功能分析内存泄露

1> 菜单栏 window → compare basket,打开比较窗口。(如果最下面一栏已经有compare basket这一步不需要)

OOM

直方图:

OOM

支配树:

OOM

3> 我们以支配树做比对,在最下面一栏的"Navigation History (window → navigation history)"里(直方图的比较方式类似)找到上一步打开的支配树 dominator tree图标,右键添加到 compare basket,如下图:

OOM

4> 按照上面的2, 3步骤依次把其他的dump文件添加到"compare basket"栏,然后点击右上角的红色感叹号,生成比较结果(要先生成支配树再添加)

OOM

这里要注意三个支配树的顺序,就是你的dump文件的时间,按照升序排列,这样生成的比对结果也是按照时间顺序从左到右排列。(可以通过右上角的上箭头↑和下箭头↓调整顺序)。生成的比对结果如下:

OOM

Retained Heap #0,Retained Heap #1,Retained Heap #2 这3列分别对应:第一个dump文件占用的retained size,第二个dump文件占用的retained size,第三个dump文件占用的retained size。

红框圈出的是内存连续增长的对象,可以通过右边红框的 retained heap看出内存变大的趋势。
绿框圈出的是没有变化的对象(至少在这3次比较中没有变化)。
蓝框圈出的是内存占用下降的对象。

一般我们主要关注红框标出的对象,因为这部分发生内存泄露的嫌疑最大。

这里先区分两个概念:
Shallow Size
 ● 对象自身占用的内存大小,不包括它引用的对象。
 ● 针对非数组类型的对象,它的大小就是对象与它所有的成员变量大小的总和。当然这里面还会包括一些java语言特性的数据存储单元。
 ● 针对数组类型的对象,它的大小是数组元素对象的大小总和。

Retained Size
 ● Retained Size=当前对象大小+当前对象可直接或间接引用到的对象的大小总和。(间接引用的含义:A->B->C,C就是间接引用)
 ● Retained Size就是当前对象被GC后,从Heap上总共能释放掉的内存。

因为这里我们比较的是支配树,所以按照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-*" 有内存泄露的嫌疑,那就看下这个对象引用的其他对象到底存了什么? 看下它的引用关系:

{
    "ResponseStatus": {
        "Timestamp": "/Date(1605583909438+0800)/",
        "Ack": "Success",
        "Errors": [],
        "Build": null,
        "Version": null,
        "Extension": []
    },
    "downloadUrl": "https://tripcom.onelink.me/3361031008pid=internal&c=flight&af_sub1=platform%253Dapp%2526locale%253Den_XX%2526ext%253Demail&af_dp=
    ctripglobal%3A%2F%2FFlightOrderDetail%2F%3Forderid%3D12279212556%26from%3Demail%26template%3DRefundVoucherArrive%26gotorefund%3Dy&af_web_dp=
    https%3A%2F%2Fwww.trip.com%2Fm%2Fdownapp%3Flocale%3Den_XX%26utm_medium%3Dinternal%26utm_source%3Dflight%26utm_campaign%3D0%26utm_content%3Dplatform%253Dapp%2526locale%253Den_XX%2526ext%253Demail"
}
1
2
3
4
5
6
7
8
9
10
11
12
13

从上面那张 concurrentHashMap截图(key : SOA_METHOD_NAME) 可知这个接口名是: getDownloadLink,也就是说list里10675个对象存的都是"getDownloadLink"这个接口的报文。

而且这只是其中一个TaskThead内部情况,加上全部20个对象,20 * 10675 大概是213500个接口报文,这20个http线程里占用的总内存大概220M都是这个getDownloadLink接口报文导致的:

OOM

# 3. 代码分析

查看代码发现调用这个底层接口时新接入了我们部门封装的 soa组件公共类:AbstractSimpleHandler.java。(这个公共类主要是通过模板方法在调用接口时记录报文日志埋点,提供超时时间设置,mock等功能)

之前的邮件项目调用 soa接口是自己实现的一套流程(早于框架之前实现),也就是说只有这一个接口使用了新的公共类AbstractSimpleHandler,其他的接口调用还是原来的方式。

新的工具类AbstractSimpleHandler记录接口报文的代码是通过调用 ELKLogUtils.write() 实现的,这个方法的内部逻辑如下:

Object value = HttpContext.get(BEHAVIOR_LOG);
if (value == null) {
    value = new ConcurrentHashMap<>();
    HttpContext.add(BEHAVIOR_LOG, value);
}
1
2
3
4
5

HttpContext内部维护的是一个ThreadLocal

 public class HttpContext {
  
     private static final int CONTEXT_DEFAULT_SIZE = 1 << 6;
  
     private static final ThreadLocal<Map<String, Object>> CONTEXT = new ThreadLocal<Map<String, Object>>() {
         @Override
         protected Map<String, Object> initialValue() {
             return new ConcurrentHashMap<>(CONTEXT_DEFAULT_SIZE);
         }
     };
1
2
3
4
5
6
7
8
9
10

所有调用soa底层接口的报文日志都是通过ThreadLocal内的map存储的,然后统一发送到ES日志系统,我们都知道theadLocal是线程安全的,但是一般我们的项目都是部署在tomcat里,tomcat维护了一个http线程池,就是前面截图的那个TaskThead Http-nio* 对象,每次前端app发起请求都会从tomcat的线程池里取一个线程处理前端的请求,如果复用的是上一个线程,那他内部的threadLocal如果没有清空,还是会保存上次的报文,这样的话这次请求又会继续存储接口报文,会越积越多...

查看项目代码发现虽然代码里有清除HttpContext上下文,但是清除的是自己创建的HttpContext对象里的threadLocal,并不是soa框架里提供的HttpContext里的threadLocal!

邮件项目自己创建的 httpContext

OOM

新接入组件AbstractSimpleHandler的httpContext:

OOM

虽然两个HttpContext.clear()方法内部调用的都是 threadLocal的 map.clear()

两个名字一样的HttpContext各自维护了一个自己 ThreadLocal,每个 ThreadLocal里又创建了单独的ConcurrentHashMap:

OOM

新接入的组件把接口报文存到threadLoacl的代码是在AbstractSimpleHandler.java里的,而清除threadLoacl的代码是在另外一个公共类BaseService.java里做的,也就是说要接入组件的公共类除了AbstractSimpleHandler.java外,还要接入BaseService.java 这个公共类!

因为清除框架记录报文日志的threadlocal是在BaseService里执行的。

虽然邮件项目的代码也清除了threadlocal,但是清除的是自己的threadlocal,因为没有接入BaseService类,导致框架的threadlocal里报文越积越多。

这个也是有历史原因的,邮件项目本身比较早,那时候还没有我们部门框架的SOA公共类,所以自己实现了一套,后来使用新的框架组件调用接口的开发同学没有调研全面,少接了一个公共类导致了这一问题发生。

所以这个问题的根因是 threadllocal使用不当引起的内存泄露。

弄清楚原因后就好办了,解决办法是在请求完接口后主动调用下框架里的HttpContext.clear(),清除下框架内部的threadlocal.map即可,当然后续还是要统一调用接口的方式,不能两套工具并存。

# 4. 使用 path to gc root 定位业务代码

还有另外一个内存泄露的嫌疑是"com.xxx.internalws.common.utils.ITextRendererPoolManager",如上面比对结果的图。

OOM

单独在dominator tree支配树视图展开如图所示:

OOM

 ● with all references : 所有引用, 包括强引用,弱引用,软引用,虚引用
 ● exclude weak reference : 排除弱引用
 ● exclude soft reference : 排除软引用
 ● ....

我们知道软引用,弱引用这些在发生full gc时可能会被回收掉(他们的回收时机不同,具体可以自行百度),目的是不造成内存溢出。一般引起内存溢出的都是强引用,所以你可以选择下面那个 "exclude all ptantom/weak/soft reference", 只查看强引用。

但是在这个案例中pdf.ITextRenderer是被软引用引用的,虽然说软引用不会导致溢出,但可能会引起内存一点点上升,我理解这也算是一种泄露,这个跟本地缓存还不一样,因为shareContext信息没有达到复用的目的,每次都生成一份新的拷贝,而且最重要的是它没有失效机制,只要没有达到堆最大值或发生full gc就会一直存在,这样的话会拖累 JVM的性能,所以这里我选择"with all references"查看引用情况:

OOM
try (ByteArrayOutputStream outputStream = new ByteArrayOutputStream()) {
            iTextRenderer = iTextRendererPoolManager.borrowObject();
            ......
            iTextRenderer.layout();
        } catch (Exception e) {
            LOGGER.error(e);
            LoggerHelper.appendResponseContent(String.format("generating PDF byte stream with Html string exception" +
                    ".\n%s", ThrowableUtils.getExceptionDesc(e)));
        } finally {
            if (iTextRenderer != null) {
                iTextRendererPoolManager.returnObject(iTextRenderer);
            }
        }
1
2
3
4
5
6
7
8
9
10
11
12
13

但是在放回对象池前没有对ITextRenderer里面的sharedContext属性清空,这样的话下次从对象池里如果还是获取到这个对象,就会对ITextRenderer内部的属性"org.xhtmlrenderer.layout.SharedContext"继续叠加,如上面截图看到的"org.xhtmlrenderer.layout.SharedContext"对象。

一直占用着内存,这个问题和上面的threadlocal类似,都是没有清除上次使用过的内存。

查了下官网使用手册发现没有这样的用法,所以导致这个问题的原因应该是我们的使用姿势不对

解决方法,一种是继续使用对象池,但在放回对象池(调用iTextRendererPoolManager.returnObject(iTextRenderer);)之前先清除下SharedContext,或者就是每次new一个,因为是在方法内部创建的局部变量,不会逃逸出方法外,方法调用完就自动释放了,所以也不用担心会占用过多内存。

因为这个问题只有在特定条件下才会走到这段缓存对象池的代码,所以相比第一个threadlocal的问题,泄露的内存不明显,但肯定也是问题。

# 5. 验证结果

把这两个问题和http connection未关闭的问题一起改完发布到测试环境,然后使用 jmeter压测一天没有再出现内存泄露的问题,然后发布到生产环境去验证,从2020年12月10号发布上线一直到今天(25号),大概15天里内存再没有泄露迹象,堆外内存(RSS-JVM内存)也稳定下来。

OOM

# 总结

查看代码提交记录发现这个问题在线上存在有一段时间了, 10月30号之前就存在了

OOM

但测试环境又很难测试出来,很少有应用在测试环境压测10天以上的,压测频率高了,接口容易熔断...

而且有些泄露也不是真正的泄露,比如本地缓存的失效策略设置不合理,写多读少 内存占用持续上升,直到触发抛弃策略。

从这次堆转储dump分析中可以看出内存泄露其实包含三个不同区域:
 ● 仍然具有GC根引用但从未在应用程序代码中使用的对象。这也是传统意义上的内存泄漏
 ● 对象太多或太大。意味着没有足够的堆可用于执行应用程序,因为内存中保存了太大的对象树(例如缓存)
 ● 临时对象太多。意味着Java代码中的处理暂时需要太多内存

第一种区域是大家都熟悉的内存泄露,后两种多半属于写代码不规范,或业务流程上设计不合理或写代码时没充分考虑缓存的使用场景,所以:写代码时要加强这方面的意识,包括review的人。同时发布上线后要定时监控,及早发现这个问题。

# MAT工具使用相关事项

使用mat前最好把初始化内存设置大一点,因为一般生产环境的dump文件都比较大,mat内存大小至少要cover住dump文件的大小。配置文件如图:

OOM
-startup
plugins/org.eclipse.equinox.launcher_1.3.100.v20150511-1540.jar
--launcher.library
plugins/org.eclipse.equinox.launcher.win32.win32.x86_64_1.1.300.v20150602-1417
-vmargs
-Xms4g
-Xmx4g
1
2
3
4
5
6
7

另外最好设置下显示单位,以兆M/G 为单位更便于理解,如图:

OOM

2.Biggest Objects by Retained Size 显示的就是堆内存活的最大对象分布情况,但这里是Retained Size保留大小统计的,这个对象本身占用的内存可能不多,但他引用其他对象的内存大小加起来可能就很大了。

这里有两个概念要区分一下:

Shallow Size
 ● 对象自身占用的内存大小,不包括它引用的对象。
 ● 针对非数组类型的对象,它的大小就是对象与它所有的成员变量大小的总和。当然这里面还会包括一些java语言特性的数据存储单元。
 ● 针对数组类型的对象,它的大小是数组元素对象的大小总和。

Retained Size
 ● Retained Size=当前对象大小+当前对象可直接或间接引用到的对象的大小总和。(间接引用的含义:A->B->C, C就是间接引用)
 ● Retained Size就是当前对象被GC后,从Heap上总共能释放掉的内存。

3.Reports → Leak Suspects 泄露嫌疑报告,就是查看最有可能导致内存泄露的对象,一般如果你的项目报了OutOfMemoryError的情况,这个泄露报告对定位溢出代码很有价值,如下图:

OOM

但是我们的项目没有出现溢出,只是内存泄露,而且泄露的不明显,所以可能需要借助下面两种方式:histogram/dominator tree分析。

  1. Histogram/Dominator tree 直方图和支配树都是列表的方式列出所以的堆内对象占用内存情况,二者的维度不同,直方图按照类型统计,支配树是以对象形式统计,如果你对项目代码比较熟悉,通过直方图定位内存泄露会更快,因为它是按照类型全部平铺开的,如果这个项目不是你负责的, 建议使用支配树的方式,因为支配树是按照对象之间的依赖引用关系展示的(可以展开查看内部引用层级)

5.Duplicate Classes 检测由多个类加载器加载的类,这个可以查看类加载情况统计,对于分析元空间metaspace的内存占用有帮助。

# 案例二:Meta Space内存溢出问题排查与总结

线上项目因为 JVM报 OOM 异常而报警,导致整个服务不可用被拉出集群。现象如下:Error:Metaspace

OOM

当时的解决方案是增加 MetaSpace 的容量:-XX:MaxMetaspaceSize=500m, 从原来默认的256m改为500m,虽然没有再出现oom,但这个只是临时解决方案,通过hickwall观察metaspace的使用情况还是在上升,后面随着业务访问量越来越大还是有可能达到阈值。

OOM

Metaspace元空间主要是存储类的元数据信息,应用中加载的各种类描述信息(类名,属性,方法,访问限制等),按照一定的结构存储在 Metaspace里,Metaspace空间增长是由于反射类加载,动态代理生成的类加载等导致的,也就是说 Metaspace的大小和加载类的数据有关系,加载的类越多,Metaspace占用的内存也就越大。

了解当时的业务场景是因为有个邮件服务访问订单详情接口的访问量突然上升。以及查看 clog的error日志发现大部分都是订单详情接口先报出的这个问题:java.lang.OutOfMemoryError: Metaspace。

我在测试环境的 JVM里增加 -XX:+TraceClassLoading -XX:+TraceClassUnloading记录下类的加载和卸载情况,然后通过 jmeter多个线程调用订单详情接口模拟 Metaspace溢出的现象。发现在catalina.out文件里输出的除了业务上用到的类外还有大量的反射类,如下:

OOM

这些反射类被频繁的加载和卸载是不正常的, 通过 Arthas [阿尔萨斯] 工具观察发现每次调用接口都是通过反射的方式实现的。

OOM

目前我们的项目都是基于 soa框架对外提供访问的,从上图中的 sun.reflect 的调用者com.ctriposs.baiji.rpc 这些命名也能看出来。

OOM

同样对底层接口返回的 json数据反序列化时也会用到反射。

OOM

继续跟代码可以看到这些反射的实现都会用到 java.lang.Class里的 ReflectionData对象。比如上面的 getDeclaredConstructor

OOM

ReflectionData是个内部静态类被缓存起来,里面的属性就是我们做反射操作时需要用的属性Field,方法 Method和构造函数等。但是有个问题 reflectionData是被SoftReference软引用修饰的,如下图:

OOM

SoftRefLRUPolicyMSPerMB这个参数大概意思是每1M空闲空间可保持的 SoftReference对象的生存时长(单位是ms毫秒),LRU应该是Least Recently Used的缩写,最近最少使用的,这个值默认是1000ms,如果被设置为0,就会导致软引用对象马上被回收掉,进而会导致重新频繁的生成新的类,而无法达到复用的效果,第三张图里大量的sun.reflect.GeneratedSerializationConstructorAccessor,GeneratedMethodAccessor就是这样产生的。我把这个参数改为-XX:SoftRefLRUPolicyMSPerMB=1000 (1秒), 发布到生产环境验证了下, 发布后就降下来了,到今天为止基本上比较稳定:

OOM

所以我们在平时的业务代码开发中如果遇到两个对象赋值的操作尽量少用反射的方式实现,比如下面的代码里使用了:

OOM

如果字段少的话直接赋值算了,多的话可以使用Cglib的 BeanCopier类,BeanCopier类底层是采用asm字节码操作方式来进行对象拷贝操作,性能和内存开销都比较小。

(adsbygoogle = window.adsbygoogle || []).push({});