一、OOM场景分析
场景:A系统从B系统全量同步一个表的内容。通过定时任务30s同步一次,数据分页返回,每页100条。B系统同步表有数据40W+,且表内容有个字段“content”是text类型。
问题:测试发现同步一段时间后导致系统出现OOM使系统宕机(测试机器分配512M内存)。后台错误日志如下:
分析步骤如下:
1、猜想是error日志过多导致OOM
原因:
a、快速定位“NewsSyncClient.java:63”发现报错代码处于循环内,且每次打印所有错误信息
b、“GC overhead limit exceeded”Sun 官方对此的定义是:“并行/并发回收器在GC回收时间过长时会抛出OutOfMemroyError。过长的定义是,超过98%的时间用来做GC并且回收了不到2%的堆内存。用来避免内存过小造成应用不能正常工作。
参考:
java.lang.OutOfMemoryError:GC overhead limit exceeded填坑心得
http://www.cnblogs.com/hucn/p/3572384.html综上猜测,此时系统还未出现OOM,而是打印error日志才导致的OOM,日志改为只记录e.getMessage。但是事情没那么简单,还未找到点上。关键点是为什么会抛出异常... ...
2、猜想是循环更新数据库效率低下导致OOM
原因:循环更新总是先查询,再来新增或更新,每次会多一次查询。
处理:把单个saveOrUpdate改为replace into,之所以不用批量是因为开头说过的表内容字段“content”是text类型,而且一页数据有100条,而我们线上设置的sql查询允许最大内存40M左右。防止使用批量语句后查询占用内存超过限制导致失败。
结果:修改后数据库更新效率提升不明显,问题仍然存在。还是没找到关键点... ...
3、猜想是定时任务没有做到单线程处理
原因:通过dump报表可以看到有多个线程(4个),而定时任务只允许同时只有一个线程的
处理:通过排查代码,发现如下红色框部分忘加导致一个线程在处理,由于数据量大未处理完,而定时任务又启动了另一个线程
结果:红色部分是人为疏忽导致漏加,这个bug还是被找了出来。但是问题还是没有解决... ...
4、猜想接口返回结果解析过慢且数据量大导致OOM
原因:
a、通过dump文件分析接口返回结果对象一直占有大量内存
b、接口返回结果SyncResp要经过数据解密,GSON转换等一些列操作
处理:把数据解密和GSON转换部分去掉,返回空对象,数据库保留更新操作。
结果:问题还是存在,在数据解密,GSON转换前后加上时间,发现这段处理耗时很少(用的Google的Gson),那么问题的关键点还是没找到... ...
5、猜想递归导致OOM
原因:分页查询使用了递归,每次查询会获得一个resp变量保存查到的数据(表有字段是text),且同步页数较多(4000页),最终resp积累过多导致了OOM,
重写SyncResp的finalize方法,结果也发现未被调用。
处理:用循环替代递归,观察重写SyncResp的finalize方法调用正常,自此问题得到解决,终于可以长舒一口气了。
教训:尽量不要使用递归
二、总结
1、递归坏处
由于递归需要系统堆栈,所以空间消耗要比非递归代码要大很多。而且,如果递归深度太大,可能系统撑不住。
耗空间:系统在每次递归前都要保护现场, 资源占用比其他调用高很多;
耗时间:栈帧上下文切换,切换到最新的方法栈帧。
2、设置HeapDumpOnOutOfMemoryError生成dump文件
2.1 、tomcat 生成dump文件:
linux中 :
1.打开/tomcat_home/bin/catalina.sh文件 ,
2.加上:JAVA_OPTS="$JAVA_OPTS -server -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home1/goct/logs/goct"
Windows中:
1.打开/tomcat_home/bin/catalina.bat文件;
2.加上:set JAVA_OPTS=%JAVA_OPTS% -server -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=D:\heapdump
2.2 、JWS:打开项目的 /goct-dev3/eclipse/goct.launch设置,不指定dump文件位置默认位于项目根目录
3、mat分析outofmemory问题