X系统OOM问题分析报告

问题描述

10月9日、11月2日、11月3日,X系统发生了三次OOM情况,均表现为出现长时间未提交事务,随后引发OOM情况。

问题分析

从生产及测试环境堆Dump发现,发生OOM时内存中均有大量的DelegatingDatabaseMetadata类的对象未释放。从测试环境的复现结果看,该对象在发生OOM时占用内存达60%-70%左右。单一对象大小为20328B,堆Dump时共有49037个对象。

DelegatingDatabaseMetadata类为DBCP数据源的代理类。在每次与数据源进行交互时,均会创建该类的对象。理论上在完成与数据库交互后,相应对象即可以被标记为可释放。DelegatingDatabaseMetadata类继承AbandonedTrace类。AbandonedTrace类被用作DBCP数据源的追踪,DBCP要求所有代理类均需继承该类。根据AbandonedConfig配置情况决定该类的执行情况。

AbandonedConfig共有三个参数可配置,分别为removeAbandoned(移除作废链接),logAbandoned(记录作废链接日志),removeAbandonedTimeout(作废链接超时设置)。

AbandonedTrace的基本原理为,在代理类的对象被创建后,即通过构造方法调用该类的初始化方法。该类的构造法有两个重载,即为有父追踪对象和无父追踪对象情况。在AbandonedConfig配置为True时,调用如下初始化方法。对于DelegatingDatabaseMetadata对象而言,其父Trace对象为PoolableConnection,在初始化时会将该对象放到父对象的TraceList中,故在父对象未释放时,该对象无法被标记为可释放。

//初始化方法
private void init(AbandonedTrace parent) {
    if (parent != null) {
        parent.addTrace(this);
    }

    if (config == null) {
        return;
    }
    if (config.getLogAbandoned()) {
        createBy = new AbandonedObjectException();
    }
}

生产现状removeAbandoned设置为true,猜想removeAbandoned设置为false后不再进行作废连接追踪。故设置removeAbandoned为false,重新进行定时任务测试。抓取堆Dump后证明猜想正确,DelegatingDatabaseMetadata类的对象均在数据库执行完毕后被释放。但若removeAbandoned设置为false,则对于失效作废连接的释放没有兜底手段,会给生产带来新的隐患

继续分析removeAbandonedTimeout设置的相关代码,该项仅用于进行超时判定,未影响对象的释放操作。故将问题聚焦至logAbandoned设置的相关代码上。经分析注意到,在logAbandoned设置为true时,新建了AbandonedObjectException内部类的对象用于记录堆栈信息。猜想是否因为堆栈信息内容多,导致DelegatingDatabaseMetadata类占用内存较大。故设置logAbandoned为false,重新进行定时任务测试。抓取堆Dump,对比两者情况。

下图分别为关闭logAbandoned和打开logAbandoned时,PoolableConnection的TraceList情况。可以很明显的看出,关闭logAbandoned后,由于不再记录堆栈等信息,DelegatingDatabaseMetadata占用空间大幅度缩小,仅为104B。PoolableConnection占用空间有649M缩小至1.6M。

关闭logAbandoned 堆Dump情况
打开logAbandoned 堆Dump情况

进一步分析关闭和打开logAbandoned时的对象情况,可以看出打开logAbandoned时,DelegatingDatabaseMetadata下AbandonedObjectException内部类对象,共占据20224B空间。关闭后则无该内部类对象。

关闭logAbandoned 无AbandonedObjectException对象
打开logAbandoned 有AbandonedObjectException对象

分析该定时任务的执行情况,在拿到PE的返回结果后,将单一批次所有明细分别进行处理。每一笔处理与数据库发生15笔以上交互,即会创建10个DelegatingDatabaseMetadata类的对象。在全部明细执行完毕后提交事务,此时PoolableConnection关闭,所有内存空间才会被释放。在未关闭logAbandoned时,按照人行最多单一报文2000笔明细计算,共占用内存大小为2000x15x20328=581MB,现生产设置JVM内存大小为1G,已占用超过50%,此时若有其他类似定时任务同时执行,极易发生内存溢出情况。

深入研究

通过问题分析我们已经可以确认,是开启logAbandoned选项后产生的AbandonedObjectException内部类的对象最终导致了OOM的情况发生。然而我们仔细分析AbandonedObjectException发现,该内部类本身内容较为单一。既然如此,该内部类是如何占据了近20K的内存空间便值得我们进一步分析。

既然该内部类本身没有问题,我们便将关注的视野进一步确定在了其继承的Exception基类上。分析该基类的代码可以发现,Exception类自身组成也较为简单,只有自身的构造方法和一些其他的简单方法。进一步将关注焦点聚焦在Exception的基类Throwable上。

分析Throwable类的构造方法,可以发现该方法调用了native的fillInStackTrace()方法,异常栈的构造即是通过该方法进行。注意到该方是一个synchronized方法,Java在构造异常时,绝大部分的性能开销也正是来源于此方法。在JDK 1.7版本后,已经允许通过设置是否记录异常栈属性减少该方法的性能开销,在实际使用过程中,也可以通过重写fillInStackTrace()方法规避异常带来的性能问题。

对于其他数据源的分析

DBCP目前在我行除了少部分遗留系统和迁移系统外,使用范围较为有限。但是,类似于Druid等的数据源同样存在logAbandoned配置项。其他数据源是否也存在类似于DBCP一样的问题?此处我们以Druid为例进行了实验。

将X系统的数据源由DBCP切换为Druid,重复问题分析部分中的实验,发送381报文附带2000笔明细,通过定时任务进行处理。通过JVM监控内存占用情况并抓取堆Dump进行分析。可以看出,在开启和关闭logAbandoned配置项时,两者的内存占用均接近,同构对堆Dump的分析也可以看出,Druid数据源并没有如DBCP数据源一样,通过新建Exception对象的方式记录调用堆栈信息。

通过分析Druid数据源源码可以看出,在isLogAbandoned()选项开启时,并没有通过新建异常类对象的方式记录堆栈信息。所有的堆栈信息均被保存在PooledConnection对象的ConnectStackTrace成员变量中。其判定数据源泄漏的方式也未通过创建代理类记录最后访问时间的方式,而是将判定泄漏连接作为了独立的线程,通过设置检测时间间隔执行。在这样的场景下,不存在Delegating代理对象因为父对象未被释放而无法释放的情况,也就不存在潜在的内存溢出问题。

解决方案
  • 调整数据源设置,关闭logAbandoned,从根本上减少内存占用。
  • 调整JVM内存设置,均设置为机器节点的1/4大小即4GB,提高内存使用效率。
  • 调整节点分配,将定时任务处理节点与联机交易节点分开,避免因为定时任务处理异常造成联机交易处理异常。
  • 后续考虑调整优化定时任务处理逻辑,尽可能避免长事务发生。

发表回复

您的邮箱地址不会被公开。 必填项已用 * 标注