使用 RCU 的 CPU 停顿检测器

本文档首先讨论 RCU 的 CPU 停顿检测器可以定位哪些类型的问题,然后讨论可用于微调检测器操作的内核参数和 Kconfig 选项。最后,本文档解释停顿检测器的“splat”格式。

什么原因导致 RCU CPU 停顿警告?

您的内核输出了 RCU CPU 停顿警告。下一个问题是“是什么原因造成的?” 以下问题可能导致 RCU CPU 停顿警告

  • CPU 在 RCU 读取侧临界区中循环。

  • CPU 在禁用中断的情况下循环。

  • CPU 在禁用抢占的情况下循环。

  • CPU 在禁用底部半部的情况下循环。

  • 对于 !CONFIG_PREEMPTION 内核,CPU 在内核中的任何位置循环,而没有可能调用 schedule()。如果内核中的循环确实是预期和理想的行为,您可能需要添加一些对 cond_resched() 的调用。

  • 使用控制台连接启动 Linux,该连接速度太慢,无法跟上启动时的控制台消息速率。例如,115Kbaud 的串行控制台速度可能慢,无法跟上启动时的消息速率,并且经常会导致 RCU CPU 停顿警告消息。特别是如果您添加了调试printk()

  • 任何阻止 RCU 的宽限期 kthread 运行的东西。这可能会导致“All QSes seen”控制台日志消息。此消息将包含有关 kthread 上次运行时间和预期运行频率的信息。它也可能导致rcu_.*kthread starved for控制台日志消息,其中将包含其他调试信息。

  • CONFIG_PREEMPTION 内核中 CPU 绑定的实时任务,它可能恰好在 RCU 读取侧临界区中间抢占低优先级任务。如果该低优先级任务不被允许在任何其他 CPU 上运行,这将尤其具有破坏性,在这种情况下,下一个 RCU 宽限期可能永远无法完成,这将最终导致系统耗尽内存并挂起。当系统正在耗尽内存时,您可能会看到停顿警告消息。

  • CONFIG_PREEMPT_RT 内核中 CPU 绑定的实时任务,它以高于 RCU softirq 线程的优先级运行。这将阻止 RCU 回调被调用,并且在 CONFIG_PREEMPT_RCU 内核中将进一步阻止 RCU 宽限期完成。无论哪种方式,系统最终都会耗尽内存并挂起。在 CONFIG_PREEMPT_RCU 情况下,您可能会看到停顿警告消息。

    您可以使用 rcutree.kthread_prio 内核引导参数来提高 RCU kthread 的调度优先级,这可以帮助避免此问题。但是,请注意,这样做可能会增加系统的上下文切换率,从而降低性能。

  • 周期性中断,其处理程序花费的时间超过连续中断对之间的时间间隔。这可能会阻止 RCU 的 kthread 和 softirq 处理程序运行。请注意,某些高开销调试选项,例如 function_graph 跟踪器,可能会导致中断处理程序花费的时间比正常情况长得多,这反过来可能会导致 RCU CPU 停顿警告。

  • 在快速系统上测试工作负载,将停顿警告超时调低到刚好避免 RCU CPU 停顿警告,然后在慢速系统上以相同的停顿警告超时运行相同的工作负载。请注意,热节流和按需调速器可能会导致单个系统有时快速,有时缓慢!

  • 硬件或软件问题关闭了不在 dyntick-idle 模式下的 CPU 上的调度程序时钟中断。这个问题确实发生过,并且似乎最有可能导致 CONFIG_NO_HZ_COMMON=n 内核的 RCU CPU 停顿警告。

  • 硬件或软件问题,阻止基于时间的唤醒发生。这些问题可能包括配置错误或有缺陷的定时器硬件、中断或异常路径中的错误(无论是硬件、固件还是软件)、Linux 定时器子系统中的错误、调度程序中的错误,甚至包括 RCU 本身的错误。它也可能导致rcu_.*timer wakeup didn't happen for控制台日志消息,其中将包含其他调试信息。

  • 定时器问题导致时间看起来向前跳跃,因此 RCU 认为 RCU CPU 停顿警告超时已超过,而实际上经过的时间要少得多。这可能是由于定时器硬件错误、定时器驱动程序错误,甚至可能是“jiffies”全局变量的损坏。在测试新硬件时,这些类型的定时器硬件和驱动程序错误并不少见。

  • 底层内核问题,要么未能调用 rcu_eqs_enter(true)、rcu_eqs_exit(true)、ct_idle_enter()、ct_idle_exit()、ct_irq_enter() 或 ct_irq_exit() 的变体之一,要么在另一方面,调用其中之一的次数过多。从历史上看,最常见的问题是遗漏了 irq_enter() 或 irq_exit(),这反过来分别调用 ct_irq_enter() 或 ct_irq_exit()。使用 CONFIG_RCU_EQS_DEBUG=y 构建内核可以帮助追踪这些类型的问题,这些问题有时会出现在特定于架构的代码中。

  • RCU 实现中的错误。

  • 硬件故障。这是非常不可能的,但在大型数据中心中根本不常见。在几十年前一个令人难忘的案例中,CPU 在运行的系统中出现故障,变得无响应,但没有导致立即崩溃。这导致了一系列 RCU CPU 停顿警告,最终导致人们意识到 CPU 已经发生故障。

RCU、RCU-sched、RCU-tasks 和 RCU-tasks-trace 实现具有 CPU 停顿警告。请注意,SRCU *没有* CPU 停顿警告。请注意,RCU 仅在宽限期进行时检测到 CPU 停顿。没有宽限期,就没有 CPU 停顿警告。

要诊断停顿的原因,请检查堆栈跟踪。有问题的函数通常位于堆栈顶部附近。如果您有一系列来自单个扩展停顿的停顿警告,比较堆栈跟踪通常可以帮助确定停顿发生的位置,这通常是在堆栈的顶部附近的函数中,该部分从一个跟踪到另一个跟踪保持不变。如果您可以可靠地触发停顿,ftrace 会非常有用。

RCU 错误通常可以在 CONFIG_RCU_TRACE 和 RCU 的事件跟踪的帮助下进行调试。有关 RCU 事件跟踪的信息,请参阅 include/trace/events/rcu.h。

微调 RCU CPU 停顿检测器

rcuupdate.rcu_cpu_stall_suppress 模块参数禁用 RCU 的 CPU 停顿检测器,该检测器检测不适当地延迟 RCU 宽限期的条件。此模块参数默认启用 CPU 停顿检测,但可以通过启动时参数或在运行时通过 sysfs 覆盖。停顿检测器对构成“不适当延迟”的理解由一组内核配置变量和 cpp 宏控制

CONFIG_RCU_CPU_STALL_TIMEOUT

此内核配置参数定义 RCU 从宽限期开始到发出 RCU CPU 停顿警告的时间段。此时间段通常为 21 秒。

此配置参数可以在运行时通过 /sys/module/rcupdate/parameters/rcu_cpu_stall_timeout 更改,但是此参数仅在周期开始时检查。因此,如果您在 40 秒的停顿中已经过了 10 秒,将此 sysfs 参数设置为(例如)5 将缩短*下一个*停顿的超时时间,或者当前停顿的以下警告(假设停顿持续足够长)。它不会影响当前停顿的下一个警告的计时。

可以通过 /sys/module/rcupdate/parameters/rcu_cpu_stall_suppress 完全启用和禁用停顿警告消息。

CONFIG_RCU_EXP_CPU_STALL_TIMEOUT

与 CONFIG_RCU_CPU_STALL_TIMEOUT 参数相同,但仅适用于加速宽限期。此参数定义 RCU 从加速宽限期开始到发出 RCU CPU 停顿警告的时间段。此时间段在 Android 设备上通常为 20 毫秒。值为零会导致使用 CONFIG_RCU_CPU_STALL_TIMEOUT 值,在转换为毫秒后。

此配置参数可以在运行时通过 /sys/module/rcupdate/parameters/rcu_exp_cpu_stall_timeout 更改,但是此参数仅在周期开始时检查。如果您处于当前停顿周期中,将其设置为新值将更改-下一个-停顿的超时时间。

可以通过 /sys/module/rcupdate/parameters/rcu_cpu_stall_suppress 完全启用和禁用停顿警告消息。

RCU_STALL_DELAY_DELTA

虽然 lockdep 工具非常有用,但它确实增加了一些开销。因此,在 CONFIG_PROVE_RCU 下,RCU_STALL_DELAY_DELTA 宏允许在给出 RCU CPU 停顿警告消息之前额外等待 5 秒。(这是一个 cpp 宏,而不是内核配置参数。)

RCU_STALL_RAT_DELAY

CPU 停顿检测器尝试使有问题的 CPU 打印自己的警告,因为这通常会提供更高质量的堆栈跟踪。但是,如果有问题的 CPU 未能在 RCU_STALL_RAT_DELAY 指定的节拍数中检测到自己的停顿,则其他 CPU 将会抱怨。此延迟通常设置为两个节拍。(这是一个 cpp 宏,而不是内核配置参数。)

rcuupdate.rcu_task_stall_timeout

此引导/sysfs 参数控制 RCU-tasks 和 RCU-tasks-trace 停顿警告间隔。值为零或更小会抑制 RCU-tasks 停顿警告。正值以秒为单位设置停顿警告间隔。RCU-tasks 停顿警告以行开始

INFO: rcu_tasks detected stalls on tasks

并继续输出 sched_show_task() 以获取每个停顿当前 RCU-tasks 宽限期的任务。

RCU-tasks-trace 停顿警告以类似的方式开始(并继续)

INFO: rcu_tasks_trace detected stalls on tasks

解释 RCU 的 CPU 停顿检测器“Splats”

对于 RCU 的非 RCU-tasks 风格,当 CPU 检测到某些其他 CPU 正在停顿时,它将打印类似于以下内容的消息

INFO: rcu_sched detected stalls on CPUs/tasks:
2-...: (3 GPs behind) idle=06c/0/0 softirq=1453/1455 fqs=0
16-...: (0 ticks this GP) idle=81c/0/0 softirq=764/764 fqs=0
(detected by 32, t=2603 jiffies, g=7075, q=625)

此消息指示 CPU 32 检测到 CPU 2 和 CPU 16 都在导致停顿,并且该停顿正在影响 RCU-sched。此消息通常后跟每个 CPU 的堆栈转储。请注意,PREEMPT_RCU 构建可能会因任务以及 CPU 而停顿,并且任务将由 PID 指示,例如,“P3421”。甚至可能出现 rcu_state 停顿是由 CPU *和* 任务引起的,在这种情况下,有问题的 CPU 和任务都将在列表中被调用。在某些情况下,CPU 将检测到自身停顿,这将导致自身检测到的停顿。

CPU 2 的“(3 GPs behind)”指示此 CPU 在过去的三个宽限期内没有与 RCU 核心交互。相反,CPU 16 的“(0 ticks this GP)”指示此 CPU 在当前停顿的宽限期内没有采取任何调度程序时钟中断。

消息的“idle=”部分打印 dyntick-idle 状态。第一个“/”之前的十六进制数字是 dynticks 计数器的低 16 位,如果 CPU 处于 dyntick-idle 模式,则该值将为偶数,否则将为奇数。两个“/”之间的十六进制数字是嵌套的值,如果在空闲循环中(如上所示)则该值将是一个小的非负数,否则将是一个非常大的正数。最后一个“/”之后的数字是 NMI 嵌套,它将是一个小的非负数。

消息的“softirq=”部分跟踪停顿的 CPU 已执行的 RCU softirq 处理程序的数量。 “/”之前的数字是在引导后执行的次数,在该 CPU 上次注意到宽限期开始时,这可能是当前的(停顿的)宽限期,或者可能是较早的宽限期(例如,如果 CPU 可能在 dyntick-idle 模式下停留了很长时间)。 “/”之后的数字是自引导以来直到当前时间执行的次数。如果后一个数字在重复的停顿警告消息中保持不变,则 RCU 的 softirq 处理程序可能无法在此 CPU 上执行。如果停顿的 CPU 在禁用中断的情况下旋转,或者在 -rt 内核中,如果高优先级进程正在使 RCU 的 softirq 处理程序饥饿,则可能会发生这种情况。

“fqs=”显示自上次此 CPU 注意到宽限期开始以来,宽限期 kthread 在此 CPU 上进行的强制静止状态空闲/离线检测传递的次数。

“detected by”行指示哪个 CPU 检测到停顿(在这种情况下,CPU 32),自宽限期开始以来经过了多少节拍(在这种情况下为 2603),宽限期序列号(7075),以及所有 CPU 上排队的 RCU 回调总数的估计值(在这种情况下为 625)。

如果宽限期恰好在停顿警告开始打印时结束,则会有一个虚假的停顿警告消息,其中将包括以下内容

INFO: Stall ended before state dump start

这种情况很少见,但在现实生活中确实会不时发生。在这种情况下,还可能标记零节拍停顿,具体取决于停顿警告和宽限期初始化的交互方式。请注意,如果不诉诸 stop_machine() 之类的东西,则不可能完全消除这种误报,对于这种问题来说,stop_machine() 是一种过度行为。

如果所有 CPU 和任务都已通过静止状态,但宽限期仍然未能结束,则停顿警告 splat 将包括以下内容

All QSes seen, last rcu_preempt kthread activity 23807 (4297905177-4297881370), jiffies_till_next_fqs=3, root ->qsmask 0x0

“23807”表示自宽限期 kthread 运行以来已经超过 23,000 个节拍。 “jiffies_till_next_fqs”指示该 kthread 应该运行的频率,给出强制静止状态扫描之间的节拍数,在这种情况下为 3,远小于 23807。最后,打印根 rcu_node 结构的 ->qsmask 字段,该字段通常为零。

如果在停顿警告之前相关的宽限期 kthread 无法运行,如上面的“All QSes seen”行所示,则会打印以下附加行

rcu_sched kthread starved for 23807 jiffies! g7075 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1 ->cpu=5
Unless rcu_sched kthread gets sufficient CPU time, OOM is now expected behavior.

使宽限期 kthread 缺乏 CPU 时间当然会导致 RCU CPU 停顿警告,即使所有 CPU 和任务都已通过所需的静止状态。 “g”数字显示当前宽限期序列号,“f”位于 ->gp_flags 命令之前发送到宽限期 kthread,“RCU_GP_WAIT_FQS”表示 kthread 正在等待短超时,“state”位于 task_struct ->state 字段的值之前,“cpu”表示宽限期 kthread 上次在 CPU 5 上运行。

如果相关的宽限期 kthread 未能在合理的时间内从 FQS 等待中唤醒,则会打印以下附加行

kthread timer wakeup didn't happen for 23804 jiffies! g7076 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402

“23804”表示 kthread 的定时器在 23,000 多个节拍之前已过期。该行的其余部分具有类似于 kthread 饥饿情况的含义。

此外,还会打印以下行

Possible timer handling issue on cpu=4 timer-softirq=11142

这里的“cpu”表示宽限期 kthread 上次在 CPU 4 上运行,它在其中排队了 fqs 定时器。 “timer-softirq”之后的数字是 cpu 4 上的当前 TIMER_SOFTIRQ 计数。如果此值在连续的 RCU CPU 停顿警告中没有变化,则更有理由怀疑是定时器问题。

这些消息通常后跟涉及停顿的 CPU 和任务的堆栈转储。这些堆栈跟踪可以帮助您找到停顿的原因,请记住,检测停顿的 CPU 将具有一个主要用于检测停顿的中断帧。

来自一个停顿的多个警告

如果停顿持续足够长的时间,将为该停顿打印多个停顿警告消息。第二个和后续消息以更长的时间间隔打印,因此第一个和第二个消息之间的时间间隔大约是停顿开始和第一个消息之间的时间间隔的三倍。比较同一停顿宽限期的不同消息的堆栈转储可能会有所帮助。

加速宽限期的停顿警告

如果加速宽限期检测到停顿,它将在 dmesg 中放置类似以下内容的消息

INFO: rcu_sched detected expedited stalls on CPUs/tasks: { 7-... } 21119 jiffies s: 73 root: 0x2/.

这表示 CPU 7 未能响应重新调度 IPI。 CPU 编号后的三个句点(“.”)表示 CPU 在线(否则,第一个句点将改为“O”),CPU 在加速宽限期开始时在线(否则,第二个句点将改为“o”),并且 CPU 自引导后至少在线一次(否则,第三个句点将改为“N”)。 “jiffies”之前的数字表示加速宽限期已经进行了 21,119 个节拍。 “s:”之后的数字表示加速宽限期序列计数器为 73。事实上,最后一个值为奇数表示加速宽限期正在进行中。“root:”之后的数字是一个位掩码,表示根 rcu_node 结构的哪些子项对应于阻止当前加速宽限期的 CPU 和/或任务。如果树有多个级别,则将为树中其他 rcu_node 结构的状态打印附加十六进制数字。

与正常宽限期一样,PREEMPT_RCU 构建可能会因任务以及 CPU 而停顿,并且任务将由 PID 指示,例如,“P3421”。

完全有可能在同一次运行期间几乎同时看到来自正常宽限期和加速宽限期的停顿警告。

RCU_CPU_STALL_CPUTIME

在以 CONFIG_RCU_CPU_STALL_CPUTIME=y 构建或以 rcupdate.rcu_cpu_stall_cputime=1 引导的内核中,每个 RCU CPU 停顿警告都会提供以下附加信息

rcu:          hardirqs   softirqs   csw/system
rcu:  number:      624         45            0
rcu: cputime:       69          1         2425   ==> 2500(ms)

这些统计信息是在采样期间收集的。 “number:”行中的值是有问题的 CPU 上的硬中断数、软中断数和上下文切换数。 “cputime:”行中的前三个值表示有问题的 CPU 上的硬中断、软中断和任务消耗的 CPU 时间(以毫秒为单位)。最后一个数字是测量间隔,也以毫秒为单位。因为用户模式任务通常不会导致 RCU CPU 停顿,所以这些任务通常是内核任务,这就是为什么只考虑系统 CPU 时间。

采样周期显示如下

|<------------first timeout---------->|<-----second timeout----->|
|<--half timeout-->|<--half timeout-->|                          |
|                  |<--first period-->|                          |
|                  |<-----------second sampling period---------->|
|                  |                  |                          |
           snapshot time point    1st-stall                  2nd-stall

以下描述了四种典型情况

  1. CPU 在禁用中断的情况下循环。

    rcu:          hardirqs   softirqs   csw/system
    rcu:  number:        0          0            0
    rcu: cputime:        0          0            0   ==> 2500(ms)
    

    因为在整个测量间隔内禁用了中断,所以没有中断,也没有上下文切换。此外,因为 CPU 时间消耗是使用中断处理程序测量的,所以系统 CPU 消耗被错误地测量为零。这种情况通常还会在该 CPU 的摘要行上打印“(0 ticks this GP)”。

  2. CPU 在禁用底部半部的情况下循环。

    这与前面的示例类似,但硬中断的非零数量和 CPU 时间消耗,以及内核执行消耗的非零 CPU 时间

    rcu:          hardirqs   softirqs   csw/system
    rcu:  number:      624          0            0
    rcu: cputime:       49          0         2446   ==> 2500(ms)
    

    没有软中断这一事实暗示这些已禁用,可能是通过 local_bh_disable()。当然,有可能没有软中断,可能是因为所有会导致软中断执行的事件都仅限于其他 CPU。在这种情况下,应继续诊断,如下一个示例所示。

  3. CPU 在禁用抢占的情况下循环。

    在这里,只有上下文切换数为零

    rcu:          hardirqs   softirqs   csw/system
    rcu:  number:      624         45            0
    rcu: cputime:       69          1         2425   ==> 2500(ms)
    

    这种情况暗示停顿的 CPU 在禁用抢占的情况下循环。

  4. 没有循环,但大量的硬中断和软中断。

    rcu:          hardirqs   softirqs   csw/system
    rcu:  number:       xx         xx            0
    rcu: cputime:       xx         xx            0   ==> 2500(ms)
    

    在这里,硬中断的数量和 CPU 时间都是非零的,但上下文切换数和消耗的内核 CPU 时间为零。软中断的数量和 cputime 通常为非零,但可能为零,例如,如果 CPU 在单个硬中断处理程序中旋转。

    如果可以重现这种类型的 RCU CPU 停顿警告,您可以通过查看 /proc/interrupts 或编写代码来跟踪每个中断(例如,通过参考 show_interrupts())来缩小范围。