背景
事情是这个样子的,本部门维护了一个在线报表查询服务(简称为 report),近一段时间,经常有用户向运营小伙伴反馈,report 经常发生页面打不开,一段时间后自己恢复的问题。虽然不是交易系统,但给用户造成的困扰也很严重,浪费了大量资源,所以最近打算抽出时间精力,集中解决下。
过程
在这个现象再一次发生时,登陆到服务器发现 JVM 一直在进行 fullGC, 但始终回收不到内存,同时日志中报出了 java.lang.OutOfMemoryError: Java heap space
无奈之下只能先重启服务保障正常访问。
随后,通过修改 Tomcat 启动脚本,在 JVM 启动参数中添加 OOM dump:
vi catalina.sh
#java jvm config
#JAVA_OPTS="-Xms1024m -Xmx4096m -Xss1024K -XX:PermSize=512m -XX:MaxPermSize=2048m"
JAVA_OPTS="-Xms1024m -Xmx4096m -Xss1024K -XX:PermSize=512m -XX:MaxPermSize=2048m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/opt/tomcat8999/temp"
一段时间后,再一次出现问题时登陆服务器发现 OOM 日志已经被 dump 出来了,24428 就是当前 JVM 的进程号
接下来把日志拷贝到本机,启动 Eclipse Memory Analyzer,加载 java_pid24428.hprof,如图:
打开 Histogram 查看各个类的对象情况
除去 char[]
,String
等 java 基础对象外,没发现占用大量空间的自定义类,再看下DominatorTree
, 这个视图列出了内存中最大的对象
这里我们发现了一个异常现象,
@0x6c3391470 pool-1-thread-3
这个线程占用了整个内存的 97.5%, 展开后问题定位到 ReportQueryController
这个类,这就好办了。
其实从 Leak Suspects Report
也可以印证这一点:
然后我们看 stack 详情:
OK! 到这里问题已经准备定位到了,ReportQueryController.writeDownFile
方法是提供报表数据下载的方法,问题就出在下载环节,接下来就是查找代码漏洞了。
// 输出报表内容
@Override
public void processRow(List<String> row) throws Exception {String value = "\n" + format.format(row.toArray());
write(out, value, charset);
atomicTotal.incrementAndGet();}
...
if (atomicTotal.get() > DOWNLOAD_MAX) {throw new RuntimeException(DOWNLOAD_MAX_ERROR);
}
问题就出在这段代码里,程序本来想限制最大下载行数 DOWNLOAD_MAX=100000
行,所以定义了一个自增 Integer
,每读取一行数据则+1
,最后判断这个AtomicInteger
的值是否达到 DOWNLOAD_MAX
,进而决定是否抛出异常。
可问题是,如果读出的数据量远远超过 DOWNLOAD_MAX
,就有可能在判断atomicTotal.get() > DOWNLOAD_MAX
前把内存占满。
而且我们看此时 AtomicInteger
的值已经是 11066861
Class Name | Shallow Heap | Retained Heap | Percentage
java.util.concurrent.atomic.AtomicInteger @ 0x6df9c11e8 11066861 | 16 | 16 | 0.00%
一千多万条记录最终把内存占满。
接下来就是改造代码:
// 输出报表内容
@Override
public void processRow(List<String> row) throws Exception {String value = "\n" + format.format(row.toArray());
write(out, value, charset);
// 每隔 1000 行 flush
flushPerOneThousand(flushSignal, out);
// 超过 100000 行检查
if (checkOverFlow(atomicTotal)) {breakOut(out);
}
}
改造后会在每 1000 行 flush
数据到文件,且检查达到 DOWNLOAD_MAX
后第一时间退出方法,并关闭流,抛出异常。
经测试,改造完成的版本,在下载之前会发生问题的记录集时不会造成OOM
.
[ypdata@sjsa-hadooptest tomcat8999]$ jstat -gc 14754 1000 20000
S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT
44544.0 45568.0 0.0 14588.5 1300992.0 66862.7 848896.0 367583.8 78552.0 76517.4 8152.0 7735.1 349 231.509 5 57.185 288.694
44544.0 45568.0 0.0 14588.5 1300992.0 66862.7 848896.0 367583.8 78552.0 76517.4 8152.0 7735.1 349 231.509 5 57.185 288.694
44544.0 45568.0 0.0 14588.5 1300992.0 66955.7 848896.0 367583.8 78552.0 76517.4 8152.0 7735.1 349 231.509 5 57.185 288.694
44544.0 45568.0 0.0 14588.5 1300992.0 66955.7 848896.0 367583.8 78552.0 76517.4 8152.0 7735.1 349 231.509 5 57.185 288.694
44544.0 45568.0 0.0 14588.5 1300992.0 66957.8 848896.0 367583.8 78552.0 76517.4 8152.0 7735.1 349 231.509 5 57.185 288.694
44544.0 45568.0 0.0 14588.5 1300992.0 66959.8 848896.0 367583.8 78552.0 76517.4 8152.0 7735.1 349 231.509 5 57.185 288.694
44544.0 45568.0 0.0 14588.5 1300992.0 66966.4 848896.0 367583.8 78552.0 76517.4 8152.0 7735.1 349 231.509 5 57.185 288.694
44544.0 45568.0 0.0 14588.5 1300992.0 67059.4 848896.0 367583.8 78552.0 76517.4 8152.0 7735.1 349 231.509 5 57.185 288.694
44544.0 45568.0 0.0 14588.5 1300992.0 67105.6 848896.0 367583.8 78552.0 76517.4 8152.0 7735.1 349 231.509 5 57.185 288.694
44544.0 45568.0 0.0 14588.5 1300992.0 67105.6 848896.0 367583.8 78552.0 76517.4 8152.0 7735.1 349 231.509 5 57.185 288.694
44544.0 45568.0 0.0 14588.5 1300992.0 67105.6 848896.0 367583.8 78552.0 76517.4 8152.0 7735.1 349 231.509 5 57.185 288.694
至此,本次 report 稳定性问题得到解决。
总结
- 线上系统应添加 dump on oom 选项,以便第一时间得到 heap 镜像
- 出现 OOM 后,应及时利用内存分析工具排查泄露原因,定位到具体代码段
- 平时写代码要时刻绷紧一根弦,不止关注业务逻辑的实现,更需要考虑程序对资源的调用(计算、内存、网络、磁盘)
enjoy yourself