Linux内核 失速（STALL） 警告说明文档翻译

kernel-4.14/Documentation/RCU/stallwarn.txt

如何使用RCU的处理器失速（CPU STALL）探测器

本文首先论述RCU的CPU stall探测器可以定位哪些类型的问题，然后论述如何用内核参数和Kconfig的选项微调探测器的功能。最后，本文介绍了stall 探测器的 “splat” 格式

什么情况下会导致 RCU CPU Stall 警告?

那么你的内核kernel打印了一个 RCU CPU stall 警告。下来就是想问“怎么导致的？”。
下面原因都可以导致 RCU CPU stall
警告：

• CPU 在RCU 读操作的临界区循环运行
• CPU 在中断禁用的情况下循环运行
• CPU 在禁止抢占的情况下循环运行。这个情况可发生在 RCU-sched stall里，如果使用软中断ksoftirqd，会发生在 RCU-bh stalls里
• CPU 在下半部禁用的情况下循环运行。这个情况可发生在 RCU-sched 和 RCU-bh stall里
• 在使用 !CONFIG_PREEMPT的配置下，CPU会在没有调用schedule（）的内核的任何地方循环运行。请注意 cond_resched() 不一定能阻止 RCU CPU stall 警告。因此，如果就是期望在在内核中循环是一个正常预设行为，你需要将一些 cond_resched() 替换为 cond_resched_rcu_qs()调用
• 用一个控制台消息速度很慢的控制连接来启动 Linux。例如，一个115K波特率的串口控制台来打印开机信息来说太慢了，可能很容易导致RCU CPU stall 警告打印。特别是添加了 调测相关的 printk()
• 任何阻止在RCU的宽限期的内核线程去运行的操作。这个可以导致打印 “All QSes seen” 控制台日志信息。这个信息讲包含什么时候 kthread 上一次运行过和它应该运行的频次是什么样的。
• 在打开CONFIG_PREEMPT的内核中绑定了实时任务的CPU中，当抢占了在读侧临界区中间的低优先级任务，特别糟糕的是如果低优先级任务也不被允许运行在其他CPU上的情况，而下一个RCU宽限期可能永远不能结束。这可能导致系统内存泄露和进程自身内存不足导致系统挂死，你可能看到 stall-warning 的错误信息
  
• 在打开CONFIG_PREEMPT_RT的内核中绑定了实时任务的CPU中，运行了比 RCU 软中断的内核进程高优先级的任务。这个会阻止调用 RCU 的回调函数，在拥有 CONFIG_PREEMPT_RCU的内核会更进一步阻止RCU宽限期的结束。无论如何，系统运行起来都会内存不足。在CONFIG_PREEMPT_RCU的情况下，你可能看到 stall-warning 的错误信息
• 没有在动态空闲模式下的CPU由于硬件或软件问题关闭了系统调度时钟中断的情况。这个问题经常真实产生，大部分看起来在在CONFIG_NO_HZ_COMMON内核中会导致RCU CPU stall 警告
• RCU 自身实现的一个bug问题
• 硬件错误。一般很少遇到，但是至少发生过一次。CPU在运行的系统过程中失败，变成了不响应，但不会立即崩溃。这个会导致一系列的 RCU CPU stall 警告，甚至导致CPU的执行失败

RCU,RCU-sched,RCH-bh和RCU-tasks 的实现会有CPU stall警告。注意 SRCU 是没有CPU stall 警告的。请注意 RCU 仅在进程的宽限期（grace period）检测CPU stall。非宽限期（grace period）是没有CPU stall警告的。
为了分析stall的原因，需要检查堆栈。有问题的函数往往在堆栈的最上面。如果你需要在stall里区分单个外部stall，比较堆栈过程可以帮我们定位stall发生的地方，这个地方通常是栈的顶部调用过程。如果你可以稳定的复现stall，用ftrace非常有用。

RCU 问题通常用 CONFIG_RCU_TRACE 和 RCU的事件跟踪来定位。获取RCU事件追踪的信息可以查看 include/trace/events/rcu.h.

微调RCU的CPU STALL探测器

rcuupdate.rcu_cpu_stall_suppress 模块参数可以禁用RCU的CPU stall探测器，它可以探测RCU宽限期的过度延迟的情况。这个模块参数默认是使能CPU stall 探测器的，但是可能被启动参数改写或被运行过程中的sysfs改写。stall探测器的“过度延迟（unduly delayed)”的功能可以通过内核配置参数和CPP的宏控制。

• CONFIG_RCU_CPU_STALL_TIMEOUT

这个内核配置参数定义了RCU从等待宽限期到触发 RCU CPU stall警告的时间周期。这个时间一般21s。
这个参数可以在运行过程中通过 /sys/module/rcupdate/parameters/rcu_cpu_stall_timeout 节点来修改。但是这个参数在初始化的时候生效。或者说如果在进入40s的stall之前你只有10s机会，设置这个sysfs参数为5可以缩短下一次stall的超时时间，或当前stall的警告间隔时间。这个不会影响当前stall的下一次警告时序。
stall的警告信息也可以通过/sys/module/rcupdate/parameters/rcu_cpu_stall_suppress使能和禁用。

• RCU_STALL_DELAY_DELTA

尽管 lockdep工具非常有用，它会增加一些开销。因此用 CONFIG_PROVE_RCU 和 RCU_STALL_DELAY_DELTA 允许在打印RCU STALL 警告信息之前有额外 5s （这个CPP 宏不是内核配置参数）

• RCU_STALL_RAT_DELAY

CPU stall 探测器尝试让有问题的CPU打印自己的警告信息，这样会显示更多质量的栈信息。但是，如果有问题的CPU在 RCU_STALL_RAT_DELAY 指定的滴答时间内没有检测到自己到 stall，那就由其他CPU来解释。这个时间经常定义为2s（这个一个CPP宏，不是内核配置参数）

• rcuupdate.rcu_task_stall_timeout

这个boot/sysfs 参数控制了RCU-task stall的警告间隔。这个值要是0或小于0代表禁用 RCU-tasks stall警告。正数值代表stall警告的间隔滴答。RCU-stall 警告以下面语句为开头：

INFO: rcu_tasks detected stalls on tasks:

然后后门接着分别打印 output of sched_show_task() 每个在当前RCU-task宽限期失速的任务

解读RCU的CPU STALL探测器的打印信息

• 对于非RCU任务原因的RCU，当一个CPU检测到正在失速，它会打印下面类似的信息：

INFO: rcu_sched_state detected stall on CPU 5 (t=2500 jiffies)

这个信息代表CPU 5检测到它正在导致一个失速，这个失速影响了RCU-sched。打印信息一般跟着有问题CPU的栈打印。在 TREE_RCU 内核构建里，RCU和RCH-sched 用同样隐含的机制实现，在 PREEMPT_RCU 内核构建里，RCU实现替换为了rcu_preempt_state的实现。

• 另一方面，如果有问题CPU不能及时快速的打印stall警告信息，一些其他CPU将会打印以下同样的信息：

INFO: rcu_bh_state detected stalls on CPUs/tasks: { 3 5 } (detected by 2, 2502 jiffies)

这个信息代表CPU 2 检测到CPU 3 和 5 都在发生失速，他们失速导致了RCH-bh。这个信息后面跟着每个CPU的栈转储信息。请注意PREEMPT_RCU 构建也会由进程任务出现类似CPU一样的失速。进程任务由PID标识，例如，“P3421”。对rcu_preemp_state 失速很有可能同时发生在CPU和进程任务里。这种情况出问题的CPU和进程任务在列表都会被调用。

• 最后，如果宽限期结束的时候stall恰好正在打印，这会有一个欺骗性的警告信息：

INFO: rcu_bh_state detected stalls on CPUs/tasks: { } (detected by 4, 2502 jiffies)

这种情况很少发生，但在实际过程中随时有可能发生。这种打印也有可能是瞬间（zero-jiffy）失速 ，取决于失速警告的和宽限期初始化发生的时序关系。请注意是不可能在完整的评估出这种不调用stop_machine()操作的假阳性问题的，调用stop_machine对这类问题来说太过严苛了。
内核最后打印一个长格式的失速警告信息：

	INFO: rcu_preempt detected stall on CPU
	0: (63959 ticks this GP) idle=241/3fffffffffffffff/0 softirq=82/543
	   (t=65000 jiffies)

配置了CONFIG_RCU_FAST_NO_HZ 的内核，会打印更多的信息：

In kernels with CONFIG_RCU_FAST_NO_HZ, more information is printed:

	INFO: rcu_preempt detected stall on CPU
	0: (64628 ticks this GP) idle=dd5/3fffffffffffffff/0 softirq=82/543 last_accelerate: a345/d342 nonlazy_posted: 25 .D
	   (t=65000 jiffies)

“(64628 ticks this GP)” 代表在当前失速宽限期内这个CPU发生了65,000的中断调度。如果CPU还没有感知到当前的宽限期（例如CPU处于离线状态），然后这个信息片段代表CPU失速了多少个宽限期。
打印信息的“idel=”字段打印了 dyntick-idle 的状态。第一个“/”前面的16进制数字是dynticks计数器的低12位，如果CPU处于dyntick-idle模式，它就是一个偶数值反之为奇数。在两个“/”之间的16进制数字是嵌套的数，如果在空闲态循环，它是一个很小的整数反之是一个很大的正数。
打印信息为“softirq=” 的字段追踪了使CPU运行处于失速的RCU 软中断处理程序的数量。“/” 前面的数字代表从CPU启动以来检测到的第一个宽限期的开始的个数。它有可能是当前宽限期，也可能是一些早前的宽限期（例如，如果CPU处在dyntick-idle 模式下扩展期）“/”后面的数字代表从启动以来软中断的个数。如果后面这个数字一直不停的打印失速警告信息，就有可能RCU的软中断服务程序不能在这个CPU上执行了。这种情况发生在如果失速的CPU在中断被禁用的情况下自旋，或者高优先级进程RCU的软件中断程序处于饥饿态，CPU在实时内核里自旋。

对于CONFIG_RCU_FAST_NO_HZ 内核，“last_accelerate:” 打印滴答计数器的低16位（16进制）代表这个CPU从 rcu_needs_cpu()到最后一次调用rcu_try_advance_all_cbs()或从rcu_prepare_for_idle()到最后一次调用rcu_accelerate_cbs()的时间。“nonlazy_posted:”打印从最后调用rcu_needs_cpu()的non-lazy回调执行次数。最后，“L” 代表当前没有非non-lazy回调（反之则打印“.”，如上所示）“D”dyntick-idel 处理已经被使能（反之则打印“.”，例如通过“nohz=”的内核启动参数来禁用）
如果相关宽限期的内核线程不能运行stall警告，下面额外信息会打印：

	rcu_preempt kthread starved for 2023 jiffies!

宽限期内核线程的CPU饥饿时间当然可以导致 RCU CPU stall 的警告。这时所有的CPU和任务进程都进入了对应的静止态

一个失速多个警告

如果失速持续足够长，多个失速警告信息将会打印出来。下一个和后续打印信息间隔很长时间打印出来，第一个和第二打印信息的时间间隔是失速开始到第一条打印语句时间的三倍。

加急宽限期（Expedited Grace Periods）的失速警告

如果一个加急宽限期（Expedited Grace Periods）检测到失速，它将在dmesg打印一个如下信息：

	INFO: rcu_sched detected expedited stalls on CPUs: { 1 2 6 } 26009 jiffies s: 1043

它代表CPU1，2，6对一个处理器间中断调度（IPI）不响应，加急宽限期已经持续了26，009滴答，加急宽限期的时序计数器为1043。事实上最后一个值如果为奇数则代表一个加急宽限期即将到来。

完全可以在加急宽限期的同一次同时看到失速一般警告信息。