事故背景2023年3月10日14时19分C公司开发人员向A公司开发人员反映某开放接口从2023年3月10日14时许开始无法访问和使用。该系统为某基础数据接口服务基于 HTTP 协议进行通信。按照惯例首先排查网络是否异常经运维人员检查证明网络连通性没有问题。A公司开发组于2023年3月10日14时30分通知运维人员重启应用服务期间短暂恢复正常。但是很快十分钟后电话再次响起告知服务又出现异常无法访问。为了避免影响进一步扩大A公司决定将程序紧急回滚至上一稳定版本。回滚后系统业务功能恢复正常。短暂松一口气后开始排查问题。0x02 事故分析让运维拷贝和固定了更新前后的系统日志和应用包。根据前面的故障现象初步猜测是内存问题好在应用启停脚本中增加了参数-XX:HeapDumpOnOutOfMemoryError -XX:HeapDumpPath/app/logs/app.dump对于无法在生产环境上使用jstack、jmap等命令直接查错的——事实上大多数时候都不能dump文件显得尤为重要果不其然日志目录下出现了app.dump文件在日志中搜索找到了若干处内存溢出错误java.lang.OutOfMemoryError: Java heap space但是令人费解的是每次出现OOM错误的位置居然都不一样事情逐渐变得复杂起来。用MAT(Memory Analyzer Tool)工具打开转储文件原以为会发现某个类型对象占用大量的内存结果出乎意料Histogram直方图中显示活跃对象居然只有100多M尝试 Calculate Precise Retained Size计算精确大小计算结果与前面相差不大。检查 Outgoing References 追踪引用对象和 Incoming References追踪被引用对象也未见明显异常令人头大。擦擦汗日志已经明确提示我们java.lang.OutOfMemoryError: Java heap space首先肯定这是一个堆内存空间引起的问题可能的原因有内存加载数据量过大例如不受行数限制的数据库查询语句或者不限制字节数的文件读取等事故系统显然没有这些情况内存泄漏资源未关闭/无法回收当系统存在大量未关闭的 IO 资源或者错误使用ThreadLocal等场景时也会发生OOM经排查也不存在这种情况系统内存不足系统内存不足以支撑当前业务场景所需要的内存过小的机器内存或者不合理的JVM内存参数。如果排除所有合理选项最不合理那个会不会就是答案呢遂开始检查机器的内存根据运维的说法机器内存为16GBtop命令查看java进程占用内存约为7.8GB看起来似乎没毛病。但是随后另一个同事注意到了一个事情最后一次系统升级的时候改动过应用启停脚本对比旧版本的脚本发现差异部分就是内存参数旧版本原为-Xms8g -Xmx8g -Xmn3g新版本改为-Xms8g -Xmx8g -Xmn8g看到这里屏幕前的一众同事都无语啊……0x03 事故原因为什么-Xmn参数设置成与-Xmx参数一样的大小会导致OOM呢该项目使用的JDK版本为1.8看看JDK 8的内存模型不难发现Heap Space Size Young Space Size Old Space Size而-Xmn参数控制的正是 Young 区的大小当堆区被 Young Gen 完全挤占又有对象想要升代到 Old Gen 时发现 Old 区空间不足于是触发 Full GC触发 Full GC 以后呢通常又会面临两种情况Young 区又刚好腾出来一点空间对象又不用放到 Old 区里面了皆大欢喜Young 区空间还是不够对象还是得放到 Old 区Old 区空间不够卒喜提OOM诶就是奔着 Old 区去的管你 Young 不 YoungOld 区空间不够卒喜提OOM这个就解释了为什么系统刚刚启动时会有一个短时间正常工作的现象随后当某段程序触发 Old Gen 升代时就会发生随机的OOM错误。那么什么时候对象会进入老年代呢这里也很有意思不妨结合日志里面出现OOM的地方对号入座经历足够多次数 GC 依然存活的对象申请一个大对象比如超过 Eden 区一半大小GC 后 Eden 区对象大小超过 S 区之和Eden 区 S0 区 GC 后S1 区放不下换言之正常情况下-Xmn参数总是应当小于-Xmx参数否则就会触发OOM错误。我们可以构造一个简单的例子来验证这个场景。首先是一个简单的SpringBoot程序package com.example.oom; import org.springframework.boot.SpringApplication; import org.springframework.boot.autoconfigure.SpringBootApplication; import org.springframework.web.bind.annotation.GetMapping; import org.springframework.web.bind.annotation.RestController; import java.util.Random; SpringBootApplication public class OomApplication { static final byte[] ARRAY new byte[128 * 1024 * 1024]; public static void main(String[] args) { SpringApplication.run(OomApplication.class, args); } RestController public static class OomExampleController { GetMapping(/oom) public int oom() { byte[] temp new byte[128 * 1024 * 1024]; temp[0] (byte) 0xff; temp[temp.length - 1] (byte) 0xef; int noise new Random().nextInt(); ARRAY[0] (byte) (temp[0] temp[temp.length - 1] noise); return ARRAY[0]; } } }使用mvn clean package命令打包后我们用下面的命令启动它java -Xms512m -Xmx512m -Xmn512m -XX:HeapDumpOnOutOfMemoryError -XX:PrintGCDetails -XX:PrintGCDateStamps -XX:PrintHeapAtGC -Xloggc:gc.log -jar oom-1.0.0-RELEASE.jar然后借助Apache的ab.exe完成我们的验证测试。先是以1个并发访问100次上面的SpringBoot接口ab -c 1 -n 100 http://localhost:8080/oom你会发现它居然是可以正常运行的然后我们模拟用户负载上来之后的情况使用2个并发访问100次ab -c 2 -n 100 http://localhost:8080/oom如果前面的步骤都没错此时应该在SpringBoot应用控制台看到大量的OOM错误如下图所示然后在 GC 日志里面会看到触发 GC 的前后Old 区几乎都没有空间仅有的一点点还是JDK强行分配的在启动JVM时强制覆写了我们的-Xmn参数{Heap before GC invocations279 (full 139): PSYoungGen total 458752K, used 273877K [0x00000000e0080000, 0x0000000100000000, 0x0000000100000000) eden space 393728K, 69% used [0x00000000e0080000,0x00000000f0bf5798,0x00000000f8100000) from space 65024K, 0% used [0x00000000fc080000,0x00000000fc080000,0x0000000100000000) to space 65024K, 0% used [0x00000000f8100000,0x00000000f8100000,0x00000000fc080000) ParOldGen total 512K, used 506K [0x00000000e0000000, 0x00000000e0080000, 0x00000000e0080000) object space 512K, 98% used [0x00000000e0000000,0x00000000e007e910,0x00000000e0080000) Metaspace used 35959K, capacity 38240K, committed 38872K, reserved 1083392K class space used 4533K, capacity 4953K, committed 5080K, reserved 1048576K 2023-04-07T01:44:25.3480800: 57.446: [GC (Allocation Failure) --[PSYoungGen: 273877K-273877K(458752K)] 274384K-274384K(459264K), 0.0441401 secs] [Times: user0.06 sys0.30, real0.04 secs] Heap after GC invocations279 (full 139): PSYoungGen total 458752K, used 273877K [0x00000000e0080000, 0x0000000100000000, 0x0000000100000000) eden space 393728K, 69% used [0x00000000e0080000,0x00000000f0bf5798,0x00000000f8100000) from space 65024K, 0% used [0x00000000fc080000,0x00000000fc080000,0x0000000100000000) to space 65024K, 9% used [0x00000000f8100000,0x00000000f86e2070,0x00000000fc080000) ParOldGen total 512K, used 506K [0x00000000e0000000, 0x00000000e0080000, 0x00000000e0080000) object space 512K, 98% used [0x00000000e0000000,0x00000000e007e910,0x00000000e0080000) Metaspace used 35959K, capacity 38240K, committed 38872K, reserved 1083392K class space used 4533K, capacity 4953K, committed 5080K, reserved 1048576K } {Heap before GC invocations280 (full 140): PSYoungGen total 458752K, used 273877K [0x00000000e0080000, 0x0000000100000000, 0x0000000100000000) eden space 393728K, 69% used [0x00000000e0080000,0x00000000f0bf5798,0x00000000f8100000) from space 65024K, 0% used [0x00000000fc080000,0x00000000fc080000,0x0000000100000000) to space 65024K, 9% used [0x00000000f8100000,0x00000000f86e2070,0x00000000fc080000) ParOldGen total 512K, used 506K [0x00000000e0000000, 0x00000000e0080000, 0x00000000e0080000) object space 512K, 98% used [0x00000000e0000000,0x00000000e007e910,0x00000000e0080000) Metaspace used 35959K, capacity 38240K, committed 38872K, reserved 1083392K class space used 4533K, capacity 4953K, committed 5080K, reserved 1048576K 2023-04-07T01:44:25.3920800: 57.490: [Full GC (Ergonomics) [PSYoungGen: 273877K-142631K(458752K)] [ParOldGen: 506K-506K(512K)] 274384K-143137K(459264K), [Metaspace: 35959K-35959K(1083392K)], 0.0248171 secs] [Times: user0.14 sys0.00, real0.03 secs]接着无需改动任何代码我们调整下启动参数像这样
