kernel-4.14/Documentation/RCU/stallwarn.txt
本文首先论述RCU的CPU stall探测器可以定位哪些类型的问题,然后论述如何用内核参数和Kconfig的选项微调探测器的功能。最后,本文介绍了stall 探测器的 “splat” 格式
那么你的内核kernel打印了一个 RCU CPU stall 警告。下来就是想问“怎么导致的?”。
下面原因都可以导致 RCU CPU stall
警告:
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.
rcuupdate.rcu_cpu_stall_suppress 模块参数可以禁用RCU的CPU stall探测器,它可以探测RCU宽限期的过度延迟的情况。这个模块参数默认是使能CPU stall 探测器的,但是可能被启动参数改写或被运行过程中的sysfs改写。stall探测器的“过度延迟(unduly delayed)”的功能可以通过内核配置参数和CPP的宏控制。
这个内核配置参数定义了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使能和禁用。
尽管 lockdep工具非常有用,它会增加一些开销。因此用 CONFIG_PROVE_RCU 和 RCU_STALL_DELAY_DELTA 允许在打印RCU STALL 警告信息之前有额外 5s (这个CPP 宏不是内核配置参数)
CPU stall 探测器尝试让有问题的CPU打印自己的警告信息,这样会显示更多质量的栈信息。但是,如果有问题的CPU在 RCU_STALL_RAT_DELAY 指定的滴答时间内没有检测到自己到 stall,那就由其他CPU来解释。这个时间经常定义为2s(这个一个CPP宏,不是内核配置参数)
这个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宽限期失速的任务
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的实现。
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和进程任务在列表都会被调用。
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)检测到失速,它将在dmesg打印一个如下信息:
INFO: rcu_sched detected expedited stalls on CPUs: { 1 2 6 } 26009 jiffies s: 1043
它代表CPU1,2,6对一个处理器间中断调度(IPI)不响应,加急宽限期已经持续了26,009滴答,加急宽限期的时序计数器为1043。事实上最后一个值如果为奇数则代表一个加急宽限期即将到来。
完全可以在加急宽限期的同一次同时看到失速一般警告信息。