★ FEATURED ARTICLE 这是一个系列, 标题叫做线上问题实战录, 这是第二篇, 本文里面所有的命令和输出的内容全部都是从真实的复现环境里拿来的, 可以按照这个步骤一步步来重现。1. 问题现象的部分内容是一点一, 也就是告警。在凌晨两点十七分的时候, 告警群里弹出了一个消息。[PRODUCTION] CPU 使用率 90% (当前: 100%)[PRODUCTION] 接口 /api/order/list p99 响应时间: 8234ms (阈值: 500ms)[PRODUCTION] 错误率: 12.3% (阈值: 1%)接口响应的速度慢了很多, 足足达到了二十倍的增幅, 一部分的请求直接导致了五百零四错误码的出现, 整个服务看起来好像快要彻底挂掉了。1.2 快速止血在第一时间确认进程的当前处于一种什么样的状态。$ ps aux | grep javaappuser 18799 156% 85.2 java -Xmx128m -Xms128m -jar app.jarCPU的使用率已经达到了156%, 内存的已用存储量占到了85%。系统接口基本上已经处于无法使用的状态了。1.3, 关于应急恢复这项工作。我们先将设备重启, 以此来让业务得到恢复。$ kill -9 18799$ java -Xmx128m -Xms128m -jar app.jar 系统重新启动之后, 相关的数据曲线又恢复正常了。可是所有人都心里清楚——如果不去把最根本的原因找出来, 那么几个小时后面板就会再次崩溃。2. 在排查的整个过程里面, 首先是把复现的步骤给完整地走了一遍。第2.1这个部分, 是要去确认一下JVM参数。结果发现什么, 结果是发现了并没有配置那个自动进行dump的操作。$ jinfo -flag HeapDumpOnOutOfMemoryError 18799-XX:-HeapDumpOnOutOfMemoryError该配置用于指明停止操作, 也就是在发生内存溢出错误之后, 程序进程会突然间直接消失无踪, 并不会保留任何有关现场的数据或信息。2.第二步, 尝试使用 jmap 这个工具来进行人工手动式的内存镜像文件数据提取工作, 但是最终结果是导致操作没有能够实现, 发生了失败的情况。$ jmap -dump:live,formatb,file/tmp/heap.hprof 18799等了5分钟时间, 过程中没有出现任何信息输出。再次检查进程当前状态情况为:$ ps aux | grep 18799进程已经没了——jmap 在 dump 过程中触发了 文件没写完进程先挂了。2.将应用程序重新启动, 并且增加用于测试系统泄漏情况的负载压力。我将Demo应用程序重新启动, 并触发内存泄漏现象, 来模拟生产环境下的真实情况。# 启动限制 128MB 堆开启 GC 日志$ java -Xmx128m -Xms128m -XX:PrintGCDetails -Xloggc:gc.log \-jar target/oom-gdb-heapdump-1.0.0.jar --server.port18080$ curl http://localhost:18080/startLeak started at 21:49:512.我们对于 GC 这个情况进行了观察, 发现它已经触发了。利用 jstat 这一工具来对垃圾回收的状况进行监控。$ jstat -gcutil 18799 3000输出内容已经展示。S0 S1 E O M CCS YGC YGCT FGC FGCT CGC CGCT GCT0.00 99.76 93.06 27.02 98.50 95.46 3 0.011 0 0.000 2 0.001 0.012↓ 几秒后 ↓0.00 0.00 0.00 99.56 97.70 93.97 54 0.109 5 0.050 52 0.030 0.189关键指标解读S0/S1 两个区的数值都显示为 0, Eden 区的数值也是 0 —— 这代表所有的对象全都堆积在老年代里面, 并且没有办法进行回收。这就是一种经典的「内存泄漏」信号。2.5, 查看一下此时此刻应用的状态。$ curl http://localhost:18080/status | python3 -m json.tool{usedMemory: 123MB,cacheSize: 113,totalMemory: 128MB,leaking: true,maxMemory: 128MB}的使用量已经达到了上限的128MB中的123MB, 这意味着已经出现了内存泄漏的情况, 具体来说, 泄漏了113个密钥。2.关键的操作就是, 要使用jinfo这个工具来将其打开。# 设置 flag 为 true$ jinfo -flag HeapDumpBeforeFullGC 18799# 验证设置成功$ jinfo -flag HeapDumpBeforeFullGC 18799-XX:HeapDumpBeforeFullGC 这个符号用来表示开启功能的状态, 这就是人们常说的那一种现象情况, 意思是在下次程序运行操作开始之前, 底层虚拟机会自动提前完成一份特定内容的生成工作过程动作行为表现。2.请保持等待数分钟, 然后系统就会显示生成的信息。在不到 30 秒的时间段里, 垃圾回收日志中产生了这样的记录:[156.727s][info][gc,start] GC(101) Heap Dump (before full gc)[156.819s][info][gc] GC(101) Heap Dump (before full gc) 92.033ms检查当前目录$ ls -lh *.hprof-rw------- 1 caoyangjie caoyangjie 78M java_pid18799.hprof2.8 分析使用jdk自带的jhat命令, 快速查看相关信息。$ jhat -J-Xmx256m java_pid18799.hprofReading from java_pid18799.hprof...Snapshot resolved.Started HTTP server on port 7000Server is ready.用浏览器去打开就是了。:7000/histo/看到byte这个类型占用了61MB的空间, 而总的堆内存是128MB, 这种情况就是导致内存泄漏的根源。2.将现场恢复到原本的状态。排查工作结束以后, 应当将那个标识为flag的东西重新更改成原来的状态。接着, 需要把发生泄漏状况的那个线程给停止运行。$ jinfo -flag -HeapDumpBeforeFullGC 18799 # 关闭自动 dump$ curl http://localhost:18080/stop # 停泄漏Leak stopped at 21:52:283. 进行根因分析, 具体章节是三十一, 也就是关于源码的具体定位。public class OomDemoApplication {// 问题static HashMap 只增不删private static final Map LEAK_CACHE new HashMap();public void start() {new Thread(() - {while (true) {String value new String(new char[512 * 1024]); // 1MBLEAK_CACHE.put(UUID.randomUUID().toString(), value);Thread.sleep(50); // 每秒约 20MB 新增}}).start();}}在每一次循环执行写入操作的过程之中, 其数据量大约为一兆字节, 由此可以推算出每秒的写入速度大约在两十兆字节左右。针对这一个有一亿两千八百万兆字节的堆内存空间来讲, 它只需要经过六秒钟的时间就能够被完全填满。3.2 GC 日志印证[156.828s][info][gc] GC(101) Pause Full 123M-122M(128M) 8.603ms后来内存消耗从一百二十三兆字节降到了了一百二十二兆字节, 回收的量不足一兆字节。因为所有的对象都被强引用关联着且处于可达状态, 所以垃圾收集器也显得毫无办法, 无计可施。3.关于第三点, 需要说明一下为什么会发生 jmap 这样的操作失败的情况。jmap在进行dump操作的时候, 是需要暂停所有线程的, 也就是所谓的STW。然后它还必须要遍历整个堆内存。如果是面对128MB这么小的一个堆来说, 这个过程本身就会需要用到额外的内存空间。要是堆内存已经被完全占满了, 这时候再去执行jmap命令, 那情况就有点危险了。这就好比, 你已经有船快要沉水了, 你还得往船上再搬一箱重物给塞进去。这样做的话, 肯定就是直接把船弄彻底压垮掉的。3.之所以能够获得成功, 其核心原因究竟是在于哪些方面。触发这个 flag 的过程, 处于开始的阶段。在这个时候, 堆内存还没有来到 OOM 的边缘位置。当 GC 检测出老年代已经满了并且决定执行操作时, 它会先进行 dump, 接着才去执行回收操作。由于在 dump 的过程中对象不会被清理, 因为 GC 还没有真正开始, 所以能够拍摄到最完整的一份犯罪现场的证据。4. 关于修复方案部分, 其中第四点一内容主要是针对代码方面的问题进行修复工作。public class OomDemoApplication {// 修复使用 Caffeine Cache有上限有private static final Cache LEAK_CACHE Caffeine.newBuilder().maximumSize(10000) // 最大 10000 条.expireAfterWrite(1, TimeUnit.MINUTES) // 1 分钟.build();}4.在修复完成之后, 需要对结果进行验证工作。$ curl http://localhost:18080/status | python3 -m json.tool{usedMemory: 28MB, # 从 123MB 降到 28MBcacheSize: 42,...}后端的内存在正常情况之下能够回落到百分之三十以下的水平, 老年代部分的曲线不再呈现一种锯齿状的形状。5. 在避坑指南的第 5.1 小节里面, 我们提出了一个建议, 就是说要特别注意那些在生产环境当中必须去配置好的三个 JVM 参数。-XX:HeapDumpOnOutOfMemoryError # OOM 时自动 dump-XX:HeapDumpPath/var/log/heapdump/ # dump 文件位置-XX:ExitOnOutOfMemoryError # OOM 后自动退出容器场景下让 K8s 重启5.针对情况二, 存在两个作为最终保障的手段。场景方案命令Java 虚拟机还在运行, 但马上就要发生内存溢出错误了。使用jinfo工具, 将动态开启这一dump操作进行执行。jinfo -flag JVM 都已经挂了, 虽然有 core文件。gdb 或 分析 coregdb -c容器场景注意# 容器中的应用需要到宿主机操作$ ps auxff | grep 容器id -A10 # 找到 JVM 在宿主机上的 PID$ jinfo -flag HeapDumpBeforeFullGC 宿主PID # 对宿主 PID 操作5.在团队规范里面, 第三条规定, 在进行代码审查的时候, 凡是用到 Map 的地方和的地方, 都必须把清理策略给审查清楚, 并且还要去监控告警老年代的使用率, 如果超过百分之八十就得发出告警, 千万不要等到百分之九十五才去告警。在故障复盘环节, 每次出现 OOM 的情况, 都要形成文档并归档保存。接下来是第五百四十四条, 判断内存泄漏具有三个特征。第六部分是一份完整的操作清单, 对照这个表格就可以复现问题。本文涉及参考的文章都在附那里有说明, 最后是完整的命令清单以及进程诊断的内容。ps aux | grep java # 确认进程状态及 PIDkill -9 # 强制终止进程应急恢复JVM 参数查看与修改jinfo -flag HeapDumpOnOutOfMemoryError # 查看 OOM 自动 dump 是否开启jinfo -flag HeapDumpBeforeFullGC # 开启 FullGC 前自动 HeapDumpjinfo -flag HeapDumpBeforeFullGC # 验证设置是否生效jinfo -flag -HeapDumpBeforeFullGC # 排查完成后关闭应用启动与接口java -Xmx128m -Xms128m -XX:PrintGCDetails -Xloggc:gc.log -jar app.jar # 带 GC 日志启动curl http://localhost:18080/start # 触发内存泄漏curl http://localhost:18080/status | python3 -m json.tool # 查看内存与缓存状态curl http://localhost:18080/stop # 停止泄漏GC 监控jstat -gcutil 3000 # 每 3 秒输出 GC 统计生成jmap -dump:live,formatb,file/tmp/heap.hprof # 手工 dump堆满时可能失败堆转储分析jhat -J-Xmx256m java_pid18799.hprof # 启动堆分析 HTTP 服务端口 7000GC 日志分析grep -n Heap Dump gc.log # 查找 HeapDump 事件时间戳grep Pause Full gc.log | tail -3 # 查看最近 FullGC 回收效果容器场景ps auxff | grep 容器id -A10 # 在宿主机找到 JVM 真实 PID
阅读完成 · 觉得有帮助？
