实战排查：服务器日志里惊现‘rcu_sched stall on CPU’警告，我是这样一步步定位到内核模块bug的

从日志告警到代码修复：一次完整的RCU停滞问题排查实录

凌晨三点，服务器监控系统突然发出刺耳的警报声。睡眼惺忪地打开日志，一行鲜红的警告赫然在目：rcu_sched self-detected stall on CPU。作为运维工程师，这种内核级别的警告往往意味着需要立即介入的严重问题。但不同于常见的系统崩溃，这次的情况更加微妙——系统仍在运行，只是某个CPU核心的利用率持续保持在100%，像被某种无形的力量牢牢锁死。

1. 理解RCU停滞警告的本质

RCU（Read-Copy Update）是Linux内核中一种重要的同步机制，广泛应用于需要高性能读操作的场景。当系统出现rcu_sched stall警告时，本质上是在告诉我们：某个CPU核心已经太久没有参与RCU的协调工作，导致整个RCU机制无法正常推进。

1.1 RCU工作机制简析

想象一个繁忙的十字路口，RCU就像一位交通警察，协调着读写操作这"车流"的通行。正常情况下：

• 读操作：像绿灯方向的车流，可以快速通过（无需锁）
• 写操作：像红灯方向的车流，需要等待合适的间隙才能行动
• 宽限期（Grace Period）：所有读操作完成的一个安全时间窗口

当某个CPU核心"罢工"（停滞）时，就相当于一个方向的信号灯完全失灵，最终会导致整个路口陷入僵局。

1.2 停滞警告的关键信息解析

典型的RCU停滞警告日志包含以下关键信息：

[115.958161] rcu: INFO: rcu_sched self-detected stall on CPU [115.989538] rcu: 3-....: (14997 ticks this GP) idle=a2e/1/0x4000000000000002 softirq=6190/6192 fqs=7448 [115.990426] (t=15000 jiffies g=9409 q=23634) [115.990427] Task dump for CPU 3: [115.990429] process-name R running task 0 1814 1757 0x00000002

各字段含义如下表：

2. 初步诊断与信息收集

2.1 确认系统当前状态

首先通过基本命令确认系统整体状况：

# 查看CPU使用情况 top -1 -b -n 1 | grep -A10 '%Cpu' # 检查内核日志中相关条目 dmesg | grep -i 'rcu.*stall' -A20 -B5 # 确认受影响CPU上的进程 ps -eo pid,psr,comm,cmd | awk '$2==3 {print}' # 假设CPU3受影响

2.2 停滞类型的初步判断

根据经验，RCU停滞通常由以下几种情况引起：

1. CPU在禁用中断状态下循环
2. 内核模块中的死循环
3. 硬件故障（罕见但需排除）
4. RCU实现本身的bug

在我们的案例中，process-name进程显示为R（运行状态）且持续占用CPU，首先排除了硬件故障的可能性。

3. 深入追踪工具的使用

3.1 使用ftrace进行动态追踪

Ftrace是内核自带的强大追踪工具，非常适合诊断这类问题：

# 设置ftrace echo function_graph > /sys/kernel/debug/tracing/current_tracer echo rcu_sched_clock_irq > /sys/kernel/debug/tracing/set_ftrace_filter echo 1 > /sys/kernel/debug/tracing/tracing_on # 等待问题重现后停止追踪 echo 0 > /sys/kernel/debug/tracing/tracing_on cat /sys/kernel/debug/tracing/trace > /tmp/rcu_trace.log

分析追踪日志时，特别关注以下关键点：

• rcu_sched_clock_irq的调用频率
• 调用栈中长时间停留的函数
• 相邻函数调用的时间间隔异常点

3.2 perf工具的运用

perf可以提供更精细的性能分析：

# 记录受影响CPU的性能数据 perf record -C 3 -g -a sleep 30 # 生成火焰图 perf script | stackcollapse-perf.pl | flamegraph.pl > rcu_flame.svg

火焰图能直观展示CPU时间消耗的热点，帮助我们快速定位问题函数。

4. 问题定位与根因分析

4.1 调用栈分析

通过上述工具，我们获得了如下的关键调用栈：

rcu_sched_clock_irq └─ rcu_pending └─ check_cpu_stall └─ print_cpu_stall └─ rcu_dump_cpu_stacks └─ dump_cpu_task └─ sched_show_task └─ show_stack └─ dump_backtrace

结合日志中的任务转储信息，发现停滞时CPU3正在执行某个内核模块的data_processing_loop函数。

4.2 代码审查

找到相关内核模块的源代码，发现以下可疑片段：

static void data_processing_loop(struct device *dev) { while (!kthread_should_stop()) { // 禁用抢占 preempt_disable(); // 数据处理逻辑 process_data(dev); // 忘记重新启用抢占 // preempt_enable(); // 这行被错误注释掉了 } }

这段代码存在明显问题：

1. 循环中禁用了抢占但未重新启用
2. 在process_data函数中可能执行耗时操作
3. 没有调用cond_resched()让出CPU

4.3 根本原因确认

这正是RCU停滞的典型场景之一：CPU在抢占被禁用状态下执行长时间循环。根据RCU机制的要求：

• 正常操作需要定期调度
• 抢占禁用会阻止RCU的grace period推进
• 超过阈值（默认60秒）后触发stall警告

5. 问题修复与验证

5.1 修复方案实施

针对发现的问题，我们实施了以下修复：

static void data_processing_loop(struct device *dev) { while (!kthread_should_stop()) { // 使用preempt_disable/enable的配对调用 preempt_disable(); process_data(dev); preempt_enable(); // 在长时间循环中添加调度点 cond_resched(); } }

同时优化了process_data函数：

1. 将大块数据处理分片
2. 添加中断检查点
3. 限制单次处理的最大耗时

5.2 修复验证步骤

为确保修复有效，我们设计了以下验证方案：

1. 单元测试：验证模块在各种负载下的行为
2. 压力测试：模拟高负载场景持续运行24小时
3. 内核调试：通过ftrace监控RCU相关函数调用
4. 性能基准：对比修复前后的系统指标

验证命令示例：

# 监控RCU状态 watch -n 1 'cat /proc/rcu*/rcu*' # 检查抢占计数器 perf stat -e 'sched:sched_switch' -a sleep 10 # 追踪模块函数调用 echo 'data_processing_loop' > /sys/kernel/debug/tracing/set_ftrace_filter

6. 经验总结与最佳实践

6.1 RCU停滞排查流程总结

通过这次事件，我们提炼出以下排查流程：

1. 日志分析：解读RCU警告的详细信息
2. 系统快照：记录问题发生时的系统状态
3. 动态追踪：使用ftrace/perf定位问题点
4. 代码审查：结合调用栈分析可疑代码
5. 修复验证：确保问题彻底解决

6.2 内核开发的最佳实践

为避免类似问题，建议遵循以下准则：

• 抢占控制：

  • 保持preempt_disable/enable严格配对
  • 禁用抢占的时间尽可能短
  • 长时间操作中插入cond_resched()

• 中断处理：

  • 避免在中断禁用状态下执行耗时操作
  • 中断处理函数应尽量简短

• 模块开发：

  • 为循环添加退出条件检查
  • 实现模块的stop机制
  • 添加必要的日志和统计信息

6.3 监控与告警优化

我们改进了监控系统，新增了以下检测项：

# 定期检查RCU状态 rcu_check_monitor() { local timeout=$(sysctl -n kernel.rcu_cpu_stall_timeout) echo "RCU stall timeout: ${timeout}s" grep -q 'rcu.*stall' /var/log/kern.log && \ echo "WARNING: RCU stall detected in logs" } # 监控CPU的抢占计数 preempt_monitor() { for cpu in /sys/devices/system/cpu/cpu[0-9]*; do echo "CPU ${cpu##*/}: $(cat $cpu/preempt_count)" done }

将这些检查纳入日常监控，可以在问题早期发出预警。