记一次OOM查询过程
阅读量
现象
监控系统发现服务挂掉
登上机器 ps -ef|grep **
发现进程还在,因为监控系统是通过心跳检测来监控服务的存活状态的,服务假死了。
排查过程
1、df、free、top
三连
磁盘空间正常、内存使用率正常、某个进程的CPU占用率达300%多
2、top -H-p pid
查看占用CPU最高的进程对应线程,得到线程ID tid
3、printf ‘%x’ tid
线程ID转为16进制
4、jstack pid | grep -C 5 tid
查看进程中占用CPU最高的线程,发现是GC线程
"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007f181001d800 nid=0x31a7 runnable
"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007f181001f800 nid=0x31a8 runnable
"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x00007f1810021800 nid=0x31a9 runnable
"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x00007f1810023000 nid=0x31aa runnable
5、jstat -gc pid 500
查下GC情况,发现几乎每秒发生一次FULL GC
6、jmap -dump:format=b,file=/tmp/**.dump pid
dump出jvm堆内存数据
7、通过mat(Eclipse Memory Analysis Tools)分析dump文件
导入dump文件分析后,发现有两大块数据异常,占用了整个堆内存的80%左右
第一块是下面109.8MB的这个,继续分析是com.mysql.jdbc.JDBC4ResultSet这个对象占用的,通过代码最终定位到问题,是一个定时任务批量处理数据时没有分页处理,一次查出了80W+的数据,然后遍历处理,导致GC时内存不能得到释放,这里改为分页处理后,问题解决。
第二块是com.alibaba.druid.stat.JdbcDataSourceStat这个对象占用了210.3MB。
从名字可以看出这个类是druid用做统计的,他会记录最近n(默认1000)条的SQL执行情况,sqlStatMap这个Map是记录了最近1000条的SQL的执行情况,看看代码。
sqlStatMap = new LinkedHashMap<String, JdbcSqlStat>(16, 0.75f, false) {
protected boolean removeEldestEntry(Map.Entry<String, JdbcSqlStat> eldest) {
boolean remove = (size() > maxSqlSize);
if (remove) {
JdbcSqlStat sqlStat = eldest.getValue();
if (sqlStat.getRunningCount() > 0 || sqlStat.getExecuteCount() > 0) {
skipSqlCount.incrementAndGet();
}
}
return remove;
}
};
但是从图里可以看出这里其实只记录了203条SQL的执行情况,却占用了200多MB,理应没有这么大的,sqlStatMap的key其实就是我们执行的SQL,继续看sqlStatMap里面的值,发现了几个特别大的key,SQL内容是这样的update t_table set a=b where id in (id1,id2,id3....)
,这条SQL的查询条件in里面包含了几十万个id,占用空间10多MB,所以导致了sqlStatMap占用空间大。
所以这里的解决办法是:
1、先关闭druid的统计功能(我们并没有用到这个功能),释放JdbcDataSourceStat的内存占用;
<!-- 配置 p:filters="stat" 即开启druid的统计功能 -->
<bean id="dataSource" class="com.alibaba.druid.pool.DruidDataSource"
p:filters="stat"
p:connectionProperties="config.decrypt=true"/>
2、优化业务处理,采用分页的方式处理 。
总结
- 大量数据一定要用分页的方式处理
- 如非必要可以关闭druid的数据统计功能,可以节省大量的内存空间