当前位置：首页 > article >正文

记一次线上程序宕机问题分析【写 GC 日志导致进程挂起】

article 2025/3/29 1:44:44

1. 背景

运维侧持续反馈了几次线上业务程序 A 出现宕机告警的信息，重启后一段时间后又出现宕机，这里针对最后一次告警进行深入排查和分析。

首先这一次故障出现在 2024-03-14 04:18:23，和以往的宕机故障略有不同，以往的现象是切换 GC 日志文件时卡住然后进程挂掉，这一次是写 GC 日志时进程卡住进入假死状态，但是这一次是过了两分钟后能够自动恢复；

部署方式：一台物理机虚拟化出来多台 VM，业务模块部署再 VM 上；

2. 问题排查过程

2.1 程序监控分析

在监控图中，程序问题发生前的各项指标没有明显的变化，当时处于凌晨业务低峰期，程序的压力也非常低，按照目前的各项指标来看，初步判断该问题和程序业务功能无关，如果问题根因是由程序业务功能导致，那么有可能是缺失了监控指标。
在这里插入图片描述

2.2 程序日志分析

在 grafana 上查看 loki 收集到的程序日志，发现该故障期间的两分钟没有任何输出；
在这里插入图片描述
通过日志进行聚合统计出来的流量图也显示在故障期间没有任何日志输出；

小结：确认故障期间程序处于挂起/假死状态，这个状态下所有业务功能都不工作，有可能导致这个问题的原因大概有：

出现了 Full GC、mixed GC 等让业务线程停顿的 GC 类型，且 GC 时间长达两分多钟；
出现了 swap 空间交换，swap 空间交换会让进程挂起；
其他操作系统、机器级别的异常。

2.3 GC 日志分析

通过查看 GC 日志，发现进程停顿了 156 秒，看上去是一次耗时非常长的 GC，且 GC 类型为 mixed GC， mixed GC 会对老年代进行回收，回收时会让业务线程停止工作；
在这里插入图片描述

通过对 GC 日志进行筛选，看到实际 GC 时间大于 100 毫秒的只有 4 次，最长的一次是 156 秒，其次是 760 毫秒，这两次 GC 时间比较高，存在一个共同点是 read > user + sys；
在这里插入图片描述

看到这里就让人很疑惑了，比较合理的应该是 real <= user + sys；

user 表示在用户态执行的 GC 操作耗时，例如垃圾标记等动作，如果回收的数据比较多，可能这个值比较大，在多核 CPU + 多线程 GC 的情况下甚至大于 real；
sys 表示在内核态执行的 GC 操作耗时，例如在操作系统内核中执行的代码耗时；
real 表示实际让业务线程停止工作的耗时。

由于这里发现了 real > user + sys，看上去这部分耗时从 GC 日志中没法找到是哪个步骤的耗时，出现这种现象可能是 GC 日志没有打印齐全，或者有一部分耗时无法被 JVM 统计到，于是再看看 JVM 启动参数。

以下是模块 A 的启动 JVM 参数（已省略不必要的），可以看到使用的是 G1 垃圾收集器，-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCApplicationStoppedTime 这几个参数其实已经可以打印比较详细的 GC 日志了，也能够记录到各个步骤的耗时，所以这里判断这个问题可能是和操作系统甚至是机器硬件有关系；

-server -Xms500M -Xmx8192M -XX:+HeapDumpOnOutOfMemoryError -XX:+UseG1GC -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCApplicationStoppedTime -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=30m -Xloggc:./logs/gc.%p.log

结合下图的 GC 过程，可以看到，线程停顿时间其实包括写 GC 日志的时间，再次断定和操作系统甚至是机器硬件有关系；
在这里插入图片描述

2.4 机器监控分析

通过监控可以看到，问题发生的时候，刚好机器的硬盘利用率达到了 100%，持续时间为 2 分钟左右，和告警恢复时间吻合，初步判断该故障和硬盘利用率有关。
在这里插入图片描述

通过监控程序的源码发现，该指标数据来源于 iostat -dxm 2 2 这个命令，如下图所示，这个命令可以查到硬盘的各项指标，例如读写速度、IO 请求占比等，而监控图上看到的则是下图中最后的一列；
在这里插入图片描述

查看 iostat 的文档，%util 列的含义表示的是 IO 请求占比监控硬盘时表示的是硬盘 IO 请求占比，监控网络时表示网络 IO 请求占比，这个占比越高，说明读写越繁忙，不过查阅资料后发现在现在硬盘有并行读写功能后这个占比即使到了 100% 也无法说明 IO 饱和了，还需要结合其他指标来看；
在这里插入图片描述

这里结合硬盘读写这个指标来看，当时的读写速度都为 0，说明这台机器有很多 IO 请求，但是硬盘处于无法读写状态，结合 CPU 使用情况这项指标，初步判断是这个时候是往硬盘发送了多次的 IO 请求，所以 CPU 升高，但是硬盘处于无法读写状态，所有的 IO 请求都被挂起，最终 %util 也占到 100% 了。
在这里插入图片描述

3. 问题确认

通过和运维侧的沟通，确认到物理机有数据备份的操作，备份时需要对硬盘进行进行读写，最终可能引发了该问题；

4. 参考

https://www.linkedin.com/blog/engineering/archive/eliminating-large-jvm-gc-pauses-caused-by-background-io-traffic
https://blog.gceasy.io/2016/12/08/real-time-greater-than-user-and-sys-time

查看全文

http://www.kler.cn/a/600578.html