内存溢出真实案例分析

背景：

某业务系统中，同一天产生多次excel导出请求，excel数据需要通过查表获取，由于数据量过大，导致了OutOfMemoryError

事先在服务启动脚本中已设置OOM异常触发堆快照参数及GC详情打印参数：-XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:+HeapDumpOnOutOfMemoryError，已知为该服务环境分配的jvm内存为6G，所以在事故发生后，我们可以得到gc.log和heapDump.hprof文件来进行分析

堆快照分析：

通过MAT(eclipse memory analyser)分析堆快照

异常线程描述

线程http-bio-8443-exec-2的Retained Heap，即持有资源约为3.5g左右，加上jdbc结果集对象、数据库连接池对象等，占据6g左右空间，而JVM最大空间为6g，所以OOM也是情理之中

占用空间Top3对象

到这里我们得到的线索是：2号线程及数据查询相关对象均持有非常多的资源，那么这个资源具体对应什么内容，我们查看mat持有树便可发现

线程持有的大批量对象

线程中存在着海量的CmcCustomer对象，每个对象占用1到2K空间，mat还为我们提供了OOM时的一些日志信息，我们可以查找一下什么方法创建了这么多对象

导致OOM的方法：exportExcel方法

CmcCustomer对象为cmc下的一个pojo，那么我们可以初步推断：exportExcel方法需要返回一个excel，excel所需的数据需要在数据库中查询业务所需的CmcCustomer表数据，但负责此请求的2号线程持有的该对象量过大，导致在该方法执行过程中需要分配更多空间时，没有了足够空间可以分配，导致了OutOfMemoryError

至此，我们通过堆快照分析，得到了"exportExcel方法引起OOM"的初步结论，那么这个方法就是OOM的罪魁祸首吗？现场还有一条gc.log的线索，我们可以通过GC日志来分析OOM的形成原因。

GC日志分析：

在实时打印的gc日志中，我们先分析一段事故发生前的gc信息

{Heap before GC invocations=6425 (full 29):

par new generation total 699072K, used 358594K [0x0000000660000000, 0x00000006a0000000, 0x00000006a0000000)

eden space 349568K, 100% used [0x0000000660000000, 0x0000000675560000, 0x0000000675560000)

from space 349504K, 2% used [0x0000000675560000, 0x0000000675e30aa0, 0x000000068aab0000)

to space 349504K, 0% used [0x000000068aab0000, 0x000000068aab0000, 0x00000006a0000000)

137826.671: [GC137826.671: [ParNew: 358594K->9042K(699072K), 0.0174300 secs] 3006268K->2656717K(5941952K), 0.0176250 secs] [Times: user=0.05 sys=0.01, real=0.02 secs]

Heap after GC invocations=6426 (full 29):

par new generation total 699072K, used 9042K [0x0000000660000000, 0x00000006a0000000, 0x00000006a0000000)

eden space 349568K, 0% used [0x0000000660000000, 0x0000000660000000, 0x0000000675560000)

from space 349504K, 2% used [0x000000068aab0000, 0x000000068b384950, 0x00000006a0000000)

to space 349504K, 0% used [0x0000000675560000, 0x0000000675560000, 0x000000068aab0000)

concurrent mark-sweep generation total 5242880K, used 2647675K [0x00000006a0000000, 0x00000007e0000000, 0x00000007e0000000)

concurrent-mark-sweep perm gen total 524288K, used 75286K [0x00000007e0000000, 0x0000000800000000, 0x0000000800000000)

}

这是一次gc，下一次gc与其间隔500s，均是新生代并行回收，新生代分配了1G空间，eden区达到350M左右，survivor区空间均充足，回收后新生代仅剩余9M左右空间，效果明显，老年代分配了5G空间，使用空间保持在2.6G左右，永久代空间更加充裕，500M空间仅使用70M左右。

接下来我们定位到excel的导出方法

2017-08-02 18:22:40,141 INFO [jeesite.modules.cmc.web.CmcCustomerController] - 导出指定时间段内的数据到Excel

2017-08-02 18:22:40,142 DEBUG [modules.cmc.dao.CmcCustomerDao.getExcelCmcList] - ==> Preparing: SELECT 篇幅关系此处省略查询字段 WHERE a.del_flag = ? AND a.create_date > concat(?," ","00:00:00") AND a.create_date < concat(?," ","23:59:59") ORDER BY a.pid DESC

2017-08-02 18:22:40,142 DEBUG [modules.cmc.dao.CmcCustomerDao.getExcelCmcList] - ==> Parameters: 0(String), 2017-04-17(String), 2017-07-31(String)

=>18:22分，查询了2017-04-17至2017-07-31的CmcCustomer数据，开始后，gc日志如下

{Heap before GC invocations=1454 (full 192):

par new generation total 699072K, used 699071K [0x0000000660000000, 0x00000006a0000000, 0x00000006a0000000)

eden space 349568K, 100% used [0x0000000660000000, 0x0000000675560000, 0x0000000675560000)

from space 349504K, 99% used [0x0000000675560000, 0x000000068aaaffe8, 0x000000068aab0000)

to space 349504K, 0% used [0x000000068aab0000, 0x000000068aab0000, 0x00000006a0000000)

202585.700: [Full GC202585.700: [CMS202589.173: [CMS-concurrent-mark: 3.507/3.509 secs] [Times: user=3.56 sys=0.00, real=3.51 secs]

(concurrent mode failure): 5242879K->5242879K(5242880K), 14.3420460 secs] 5941951K->5936395K(5941952K), [CMS Perm : 74280K->74274K(524288K)], 14.3421470 secs] [Times: user=14.35 sys=0.00, real=14.34 secs]

Heap after GC invocations=1455 (full 193):

par new generation total 699072K, used 693515K [0x0000000660000000, 0x00000006a0000000, 0x00000006a0000000)

eden space 349568K, 99% used [0x0000000660000000, 0x000000067555ffb8, 0x0000000675560000)

from space 349504K, 98% used [0x0000000675560000, 0x000000068a542fe8, 0x000000068aab0000)

to space 349504K, 0% used [0x000000068aab0000, 0x000000068aab0000, 0x00000006a0000000)

concurrent mark-sweep generation total 5242880K, used 5242879K [0x00000006a0000000, 0x00000007e0000000, 0x00000007e0000000)

concurrent-mark-sweep perm gen total 524288K, used 74274K [0x00000007e0000000, 0x0000000800000000, 0x0000000800000000)

}

202600.077: [Full GC202600.077: [CMS: 5242879K->5242879K(5242880K), 8.9369500 secs] 5941951K->5936519K(5941952K), [CMS Perm : 74277K->74277K(524288K)], 8.9370540 secs] [Times: user=8.95 sys=0.00, real=8.93 secs]

我们可以发现：

1.两次gc间隔时间仅为5秒钟

2.gc发生时，eden区、survivor区均爆满，而且回收后仅回收了1%

3.老年代空间未见减少，停留在5242879K

4.cms收集器发生了concurrent mode failure-并发模式失败（发生的原因一般是CMS正在进行，但是由于老年代空间内存不足，需要尽快回收老年代里死的java对象，这个时候需要触发full gc，停止所有的java线程，同时终止CMS）。

篇幅原因在此不列出后续所有gc日志，本次gc是第192次，但是在OutOfMemory发生时，gc执行到了第597次，并且均为"cms回收->被阻断concurrent mode failure->full gc"的循环，而且老年代始终未见减少，直到最后一次请求分配空间，并且没有空间可分配，JVM也无法再回收，在这种情况下产生了内存溢出。

到这里，结论慢慢清晰，exportExcel方法产生太多的对象，占满了新生代、老年代空间，JVM也无法回收更多对象。但是有一点不知道有没有引起大家的好奇——老年代是什么时候变的这么大了？在之前正常回收的日志中，老年代使用空间只有2.6g左右，即使峰值也不到4g，就被JVM回收掉了，而现在使用空间已经到了阈值。下面这个图模拟了老年代已使用空间随gc次数的变动

两种回收情况下老年代已使用空间

导出excel动作在事故发生日发生多次，但时间范围为当天的查询请求中，数据量不小，但是JVM还是可以支撑，只是新生代gc频繁，效果如上图（左）所示；但发生OOM的那次请求中，时间起止范围在100天左右，数据量非常之大，新生代不断产生海量对象，survivor区瞬间达到最大值，eden区跳过survivor区进入老年代的对象非常多，即使JVM仍在gc，但是回收的效率低于对象增长的速度，那么就会产生上图（右）的现象，CMS收集器无法进行，full gc强制进行，系统停顿时间暴增，直至新生代、老年代占用空间均达到峰值，JVM再无可分配空间，游戏结束。

总结：

通过堆快照、GC日志的分析，我们得到了最终的结论：问题确实出在excel导出方法，这个方法在内存中一次性加载的数据量太过庞大，虽然不是立即发生GC，但是新对象的不断堆积最终还是压垮JVM发生了内存溢出，这是一种典型的内存溢出问题。

一、查询开始后，对象的创建过程，

解决：

1.分配更大的JVM内存空间，但不推荐，目前系统流量不大，扩大空间只是缓兵之计，假如后期推广开始，100个人同时导出excel，总不能扩大100倍的内存，这会造成资源的浪费

2.优化业务流程，每日凌晨定时生成当日excel数据，用户若有需求，可以异步推送到其用户空间，但这种方式等于修改了产品层面内容，代价比较大

3.将导出excel改为写入csv，这样就通过流输出解决了创建超大excel的问题，用户可以通过excel打开csv数据；而由于是流输出，我们也可以利用游标的思想，进行流式读取，如利用MyBatisCursorItemReader：

static void testCursor1() throws UnexpectedInputException, ParseException, Exception {

try {

Mapparam = new HashMap();

AccsDeviceInfoDAOExample accsDeviceInfoDAOExample = new

AccsDeviceInfoDAOExample();

accsDeviceInfoDAOExample.createCriteria().

andAppKeyEqualTo("12345").andAppVersionEqualTo("5.7.2.4.5").

andPackageNameEqualTo("com.test.zlx");

param.put("oredCriteria", accsDeviceInfoDAOExample.getOredCriteria()); // 设置参数

myMyBatisCursorItemReader.setParameterValues(param); // 创建游标

myMyBatisCursorItemReader.open(new ExecutionContext()); //使用游标迭代获取每个记录

Long count = 0L;

AccsDeviceInfoDAO accsDeviceInfoDAO;

while ((accsDeviceInfoDAO = myMyBatisCursorItemReader.read()) != null) {

System.out.println(JSON.toJSONString(accsDeviceInfoDAO));

++count;

System.out.println(count);

}

} catch (Exception e) {

System.out.println("error:" + e.getLocalizedMessage());

} finally { // do some

myMyBatisCursorItemReader.close();

}

}

MyBatisCursorItemReader注入：

<bean id="myMyBatisCursorItemReader" class="org.mybatis.spring.batch.MyBatisCursorItemReader">

<property name="sqlSessionFactory" ref="sqlSessionFactory" />

<property name="queryId" value="com.taobao.accs.mass.petadata.dal.sqlmap.AccsDeviceInfoDAOMapper.selectByExampleForPetaData" />

</bean>

mapper.xml中再手动为sql加入fetchSize=-2147483648来配置JDBC的流式抓取，对这个配置感兴趣的同学可以参考此文章，这种方式返回了操作ResultSet的游标让用户自己迭代获取数据，我们也可以使用Mybatis的ResultHandler，内部直接操作ResultSet逐条获取数据并调用回调handler的handleResult方法进行处理

static void testCursor2() {

SqlSession session = sqlSessionFactory.openSession(); Mapparam = new HashMap();

AccsDeviceInfoDAOExample accsDeviceInfoDAOExample = new AccsDeviceInfoDAOExample();

accsDeviceInfoDAOExample.createCriteria().andAppKeyEqualTo("12345").

andAppVersionEqualTo("1.2.3.4").andPackageNameEqualTo("com.hello.test");

param.put("oredCriteria", accsDeviceInfoDAOExample.getOredCriteria());

session.select("com.taobao.accs.mass.petadata.dal.sqlmap.

AccsDeviceInfoDAOMapper.selectByExampleForPetaData", param, new

ResultHandler() {

@Override

public void handleResult(ResultContext resultContext) {

AccsDeviceInfoDAO accsDeviceInfoDAO = (AccsDeviceInfoDAO) resultContext.getResultObject();

System.out.println(resultContext.getResultCount());

System.out.println(JSON.toJSONString(accsDeviceInfoDAO));

}

}

);

}

本次事故复盘结束，解决方案不尽完善，希望对遇到类似问题的同学有所帮助。