使用 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()s。

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

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

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

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

  • 一个周期性中断,其处理程序花费的时间比连续两对中断之间的时间间隔长。 这可能会阻止 RCU 的 kthread 和软中断处理程序运行。 请注意,某些高开销调试选项(例如 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_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 停滞警告消息。(这是一个 cpp 宏,而不是内核配置参数。)

RCU_STALL_RAT_DELAY

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

rcupdate.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 停顿检测器“喷溅”

对于 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 和 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 软中断处理程序的数量。 “/”之前的数字是从启动到此 CPU 最后记录宽限期开始时已执行的数量,这可能是当前的(停顿的)宽限期,也可能是较早的宽限期(例如,如果 CPU 可能在 dyntick-idle 模式下停留了很长时间)。“/”之后的数字是从启动到当前时间已执行的数量。如果后一个数字在重复的停顿警告消息中保持不变,则可能是 RCU 的软中断处理程序无法在此 CPU 上执行。如果停顿的 CPU 在禁用中断的情况下旋转,或者在 -rt 内核中,如果高优先级进程使 RCU 的软中断处理程序处于饥饿状态,则会发生这种情况。

“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 和任务都已通过静止状态,但宽限期仍未能结束,则停顿警告喷溅将包括类似以下内容:

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

“23807” 表示自宽限期 kthread 运行以来已超过 23000 个节拍。“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.

当然,即使所有 CPU 和任务都已通过所需的静止状态,使宽限期 kthread 无法获得 CPU 时间也可能会导致 RCU CPU 停顿警告。 “g” 数字显示当前宽限期序列号,“f” 在宽限期 kthread 的 ->gp_flags 命令之前,“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 的计时器在 23000 多个节拍之前过期。该行的其余部分含义与 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())来缩小范围。