前言

[  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
[  115.990431] Call trace:
[  115.990435]  dump_backtrace+0x0/0x178
[  115.990436]  show_stack+0x14/0x20
[  115.990438]  sched_show_task.part.0+0xe0/0x108
[  115.990440]  sched_show_task+0x3c/0x40
[  115.990441]  dump_cpu_task+0x40/0x4c
[  115.990443]  rcu_dump_cpu_stacks+0xa0/0xe0
[  115.990444]  rcu_sched_clock_irq+0x530/0x790
[  115.990446]  update_process_times+0x2c/0x88
[  115.990448]  tick_sched_handle.isra.0+0x30/0x50
[  115.990450]  tick_sched_timer+0x48/0x98
[  115.990451]  __hrtimer_run_queues+0xec/0x1e8
[  115.990452]  hrtimer_interrupt+0x110/0x2c0
[  115.990456]  arch_timer_handler_virt+0x30/0x40
[  115.990457]  handle_percpu_devid_irq+0x80/0x140
[  115.990459]  generic_handle_irq+0x24/0x38
[  115.990460]  __handle_domain_irq+0x60/0xb8
[  115.990461]  gic_handle_irq+0x5c/0x148
[  115.990462]  el1_irq+0xb8/0x140
[  115.990464]  __memset+0xf0/0x188
				......

最近内核代码时出现一个偶现的BUG,进程 process-name 一直占用着某一个进程 ,比如CPU3,进程CPU占用率100%,进程 process-name无法停止,且其使用的内核模块也无法也没法正常卸载,处于使用中,导致提示警告:

rcu: INFO: rcu_sched self-detected stall on CPU

RCU(Read-Copy Update)的CPU停滞检测器能够定位和识别与CPU停滞相关的问题。当CPU由于各种原因无法取得进展时,例如长时间运行的任务或锁争用,就会发生停滞。

当存在CPU停滞时,RCU的性能可能会受到影响。CPU停滞指的是CPU由于各种原因而无法取得进展,例如繁重的计算、长时间运行的任务、中断争用或锁争用等。这种停滞可能导致RCU无法及时完成其任务,导致宽限期内该CPU没有发生调度,从而影响系统的响应性能和吞吐量。

为了解决这些问题,Linux内核引入了RCU的CPU停滞检测器。该检测器能够监视CPU的活动并检测停滞情况。当检测到CPU停滞时,检测器会采取一些措施,例如打印警告消息、记录调用堆栈信息或触发调试工具等,以帮助开发人员识别和解决问题。

通常是在驱动代码中的循环部分出现了问题,导致一直占着某个CPU。

一、RCU CPU Stall 警告的原因

RCU(Read-Copy-Update)CPU停滞警告可能由系统中的各种问题引起。以下是可能的原因:

(1)CPU在RCU读侧临界区域中循环:当CPU在持有RCU读侧临界区域时进入循环,阻止其他CPU取得进展,就会发生这种情况。

(2)CPU在中断被禁用时循环:如果CPU禁用了中断并进入循环,就会引起RCU CPU停滞警告,因为中断对于RCU的进展是必需的。

(3)CPU在抢占被禁用时循环:当CPU禁用抢占并进入循环时,会导致RCU停滞,因为抢占对于RCU调度任务是必需的。

(4)CPU在底半部被禁用时循环:底半部是内核用于延迟工作的机制。如果CPU禁用了底半部并进入循环,就会阻止RCU执行必要的任务。

(5)对于非可抢占内核,在内核中的任何位置循环而没有调用schedule():在非可抢占内核中,如果CPU在没有调用schedule()函数的情况下循环,会导致RCU CPU停滞警告。添加调用cond_resched()可以解决这个问题。

(6)引导过程中慢速控制台连接:如果用于Linux引导的控制台连接速度太慢无法跟上消息速率,就会导致RCU CPU停滞警告,尤其是如果添加了额外的调试printk()语句。

(7)任何阻止RCU优雅期k线程运行的因素:如果有任何因素阻止RCU的优雅期k线程运行,会导致RCU CPU停滞警告。这可能包括调度问题或影响RCU任务执行的其他因素。

(8)CPU密集型实时任务:在可抢占内核中,以较高优先级运行的CPU密集型实时任务可能会抢占RCU读侧临界区域中的低优先级任务。这会阻止RCU优雅期完成,导致RCU CPU停滞警告。

(9)执行时间较长的周期性中断处理程序:如果周期性中断的处理程序执行时间超过连续两个中断之间的时间间隔,会阻止RCU的k线程和软中断处理程序运行,导致RCU CPU停滞警告。

(10)在不同系统速度上测试工作负载:如果在速度较快的系统上使用调整过的停滞警告超时时间测试工作负载,然后在速度较慢的系统上使用相同的超时时间运行,由于系统速度的差异,可能会引发RCU CPU停滞警告。

(11)调度器时钟中断问题:在不处于dyntick-idle模式的CPU上关闭调度器时钟中断可能导致RCU CPU停滞警告,尤其适用于CONFIG_NO_HZ_COMMON=n配置的内核。

(12)RCU实现中的错误:在某些情况下,RCU CPU停滞警告可能表明RCU实现本身存在错误。

(13)硬件故障:尽管罕见,但硬件故障(例如,CPU故障)可能会导致RCU CPU停滞警告,如果CPU变得无响应但不会立即导致系统崩溃。

当涉及到调试RCU相关问题时,有几种技术和工具可以提供帮助:

RCU CPU停滞警告:RCU的实现(如RCU、RCU-sched和RCU-tasks)在宽限期(grace period)进行时,如果某个CPU出现延迟,就会生成CPU停滞警告。这些警告表明系统可能存在问题,可以作为进一步调查的起点。

堆栈跟踪:检查堆栈跟踪通常可以揭示导致停滞的有问题函数。通过查看堆栈顶部附近的函数,可以确定造成延迟的代码。

比较堆栈跟踪:如果在一次长时间停滞期间观察到一系列停滞警告,比较不同跟踪之间的堆栈跟踪可以帮助确定造成停滞的具体函数。在所有跟踪中,保持在堆栈顶部附近的函数很可能是问题所在。

Ftrace:Ftrace是Linux内核中强大的跟踪框架,可帮助诊断和调试RCU停滞。通过适当启用和配置Ftrace,可以跟踪执行流程并收集有关停滞期间RCU操作的详细信息。

CONFIG_RCU_TRACE:内核配置选项CONFIG_RCU_TRACE可以启用RCU的附加调试功能。通过启用此选项,可以使用RCU的事件跟踪功能,提供有关RCU活动的详细信息,有助于识别和解决与RCU相关的错误。

二、源码解析

/*
 * Called from the timer interrupt handler to charge one tick to the current
 * process.  user_tick is 1 if the tick is user time, 0 for system.
 */
void update_process_times(int user_tick)
{
	struct task_struct *p = current;

	/* Note: this timer irq context must be accounted for as well. */
	account_process_tick(p, user_tick);
	run_local_timers();
	rcu_sched_clock_irq(user_tick);
#ifdef CONFIG_IRQ_WORK
	if (in_irq())
		irq_work_tick();
#endif
	scheduler_tick();
	if (IS_ENABLED(CONFIG_POSIX_TIMERS))
		run_posix_cpu_timers();
}

这段代码是从定时器中断处理程序调用的函数,用于将一个时钟滴答计入当前进程的时间。user_tick参数表示该滴答是否属于用户时间(1表示是),0表示系统时间。

函数首先获取当前进程的task_struct结构体指针,并将其赋值给变量p。然后调用account_process_tick函数,将该滴答的时间计入当前进程的统计信息中,同时根据user_tick参数确定是用户时间还是系统时间。接着调用run_local_timers函数,运行本地定时器。然后调用rcu_sched_clock_irq函数,处理与RCU调度相关的时钟中断,同样根据user_tick参数确定是用户时间还是系统时间。

在定义了CONFIG_IRQ_WORK宏的情况下,如果当前处于中断上下文(in_irq函数返回真),则调用irq_work_tick函数,处理IRQ工作。紧接着调用scheduler_tick函数,执行调度器的时钟滴答处理。最后,如果启用了CONFIG_POSIX_TIMERS宏,在POSIX定时器支持的情况下,调用run_posix_cpu_timers函数,运行POSIX CPU定时器。

总体而言,该函数用于更新当前进程的时间统计信息,并处理与时钟相关的任务,如定时器、RCU调度、IRQ工作和调度器。

在这里我们主要关注 rcu_sched_clock_irq 函数:

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()

最后调用dump_backtrace打印函数调用栈。

其中print_cpu_stall函数表示RCU的CPU停滞检测器开始打印警告信息:

static void print_cpu_stall(void)
{
	int cpu;
	unsigned long flags;
	struct rcu_data *rdp = this_cpu_ptr(&rcu_data);
	struct rcu_node *rnp = rcu_get_root();
	long totqlen = 0;

	/* Kick and suppress, if so configured. */
	rcu_stall_kick_kthreads();
	if (rcu_cpu_stall_suppress)
		return;

	/*
	 * OK, time to rat on ourselves...
	 * See Documentation/RCU/stallwarn.txt for info on how to debug
	 * RCU CPU stall warnings.
	 */
	pr_err("INFO: %s self-detected stall on CPU\n", rcu_state.name);
	raw_spin_lock_irqsave_rcu_node(rdp->mynode, flags);
	print_cpu_stall_info(smp_processor_id());
	raw_spin_unlock_irqrestore_rcu_node(rdp->mynode, flags);
	for_each_possible_cpu(cpu)
		totqlen += rcu_get_n_cbs_cpu(cpu);
	pr_cont("\t(t=%lu jiffies g=%ld q=%lu)\n",
		jiffies - rcu_state.gp_start,
		(long)rcu_seq_current(&rcu_state.gp_seq), totqlen);

	rcu_check_gp_kthread_starvation();

	rcu_dump_cpu_stacks();

	raw_spin_lock_irqsave_rcu_node(rnp, flags);
	/* Rewrite if needed in case of slow consoles. */
	if (ULONG_CMP_GE(jiffies, READ_ONCE(rcu_state.jiffies_stall)))
		WRITE_ONCE(rcu_state.jiffies_stall,
			   jiffies + 3 * rcu_jiffies_till_stall_check() + 3);
	raw_spin_unlock_irqrestore_rcu_node(rnp, flags);

	panic_on_rcu_stall();

	/*
	 * Attempt to revive the RCU machinery by forcing a context switch.
	 *
	 * A context switch would normally allow the RCU state machine to make
	 * progress and it could be we're stuck in kernel space without context
	 * switches for an entirely unreasonable amount of time.
	 */
	set_tsk_need_resched(current);
	set_preempt_need_resched();
}

三、调整RCU CPU停滞检测器的参数

rcuupdate.rcu_cpu_stall_suppress模块参数用于禁用RCU的CPU停滞检测器,该检测器用于检测导致RCU优雅期延迟的条件。此模块参数默认启用CPU停滞检测,但可以通过引导时参数或运行时通过sysfs进行覆盖。停滞检测器对于何种情况被认为是"过度延迟"的判断是由一组内核配置变量和cpp宏控制的:

(1)CONFIG_RCU_CPU_STALL_TIMEOUT

这个内核配置参数定义了RCU从宽限期(grace period)开始等待的时间,直到发出RCU CPU停滞警告。

# cat /boot/config-4.19.90-24.4.v2101.ky10.aarch64 | grep CONFIG_RCU_CPU_STALL_TIMEOUT
CONFIG_RCU_CPU_STALL_TIMEOUT=60

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

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

(2)RCU_STALL_DELAY_DELTA

尽管lockdep工具非常有用,但它会增加一些开销。因此,在CONFIG_PROVE_RCU下,RCU_STALL_DELAY_DELTA宏允许额外延迟五秒钟才发出RCU CPU停滞警告消息。(这是一个cpp宏,而不是内核配置参数)

备注:"cpp macro"指的是C/C++语言中的预处理宏(preprocessor macro)。C预处理器(C preprocessor)是一种在编译前对源代码进行预处理的工具。它会根据预定义的宏和指令,对源代码进行文本替换和条件编译等操作。

在给出的描述中,“RCU_STALL_DELAY_DELTA"和"RCU_STALL_RAT_DELAY"被提到是"cpp macro”,意味着它们是在编译前由预处理器处理的宏定义,而不是运行时可配置的内核参数。这些宏定义在代码中使用,在编译时会根据预定义的值进行相应的文本替换。

总之,"cpp macro"指的是C/C++语言中的预处理宏,它们在编译前被预处理器处理,并在编译时进行文本替换。

(3)RCU_STALL_RAT_DELAY
CPU停滞检测器尝试使造成停滞的CPU打印自己的警告消息,因为这样通常可以获得更高质量的堆栈跟踪。但是,如果造成停滞的CPU在RCU_STALL_RAT_DELAY指定的jiffies数内没有检测到自己的停滞,那么其他某个CPU将会进行投诉。这个延迟通常设置为两个jiffies。(这是一个cpp宏,而不是内核配置参数)

(4)rcupdate.rcu_task_stall_timeout

这个引导/sysfs参数控制RCU-tasks停滞警告的间隔时间。值为零或更小的值会抑制RCU-tasks的停滞警告。正值设置停滞警告的间隔时间(以秒为单位)。RCU-tasks停滞警告以以下行开始:

INFO: rcu_tasks detected stalls on tasks:

然后继续输出每个导致当前RCU-tasks优雅期停滞的任务的sched_show_task()输出。

通过调整这些参数,你可以根据你的需求来定制RCU CPU停滞检测器的行为。请注意,对这些参数的更改可能需要在引导时或运行时进行,并且应谨慎评估其对系统性能和调试能力的影响。

四、RCU的CPU停滞检测器"Splats"的解释

(1)
对于非RCU任务的RCU版本,在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”。甚至可能同时由CPU和任务引起rcu_state停滞,这种情况下,引起问题的CPU和任务将在列表中全部列出。

CPU 2的"(3 GPs behind)“表示该CPU在过去的三个宽限期内没有与RCU核心进行交互。相比之下,CPU 16的”(0 ticks this GP)"表示该CPU在当前停滞的优化期内没有接收任何调度时钟中断。

消息中的"idle="部分打印了动态空闲状态。斜杠前面的十六进制数字是动态滴答计数器的低12位,如果CPU处于动态空闲模式,则该值为偶数;否则为奇数。两个斜杠之间的十六进制数字是嵌套值,如果在空闲循环中(如上所示),它将是一个小的非负数;否则将是一个非常大的正数。

消息中的"softirq="部分跟踪停滞的CPU执行的RCU软中断处理器的数量。斜杠前面的数字是该CPU在上次注意到一个宽限期开始时执行的软中断处理器数量,这可能是当前(停滞)优化期,也可能是之前的某个宽限期(例如,如果CPU长时间处于动态空闲模式)。斜杠后面的数字是从启动到当前时间执行的软中断处理器数量。如果这个后面的数字在重复的停滞警告消息中保持不变,可能是RCU的软中断处理器无法在该CPU上执行的情况。这可能发生在停滞的CPU被中断禁用自旋,或者在-rt内核中,如果一个高优先级进程饥饿RCU的软中断处理器。

"fqs="显示了自上次该CPU注意到优化期开始以来,宽限期内核线程在该CPU上进行的强制静默状态空闲/离线检测的次数。

"detected by"行指示哪个CPU检测到了停滞(在本例中是CPU 32),自宽限期开始以来经过的滴答数(在本例中是2603),优化期序列号(7075),以及所有CPU上排队的RCU回调的估计值(本例中为625)。

(2)
在具有CONFIG_RCU_FAST_NO_HZ的内核中,会打印更多信息
对于每个CPU:

0: (64628 ticks this GP) idle=dd5/3fffffffffffffff/0 softirq=82/543 last_accelerate: a345/d342 Nonlazy posted: ..D

“last_accelerate:“打印的是当该CPU最后一次从rcu_needs_cpu()中调用rcu_try_advance_all_cbs()或从rcu_prepare_for_idle()中调用rcu_accelerate_cbs()时,jiffies计数器的低16位(十六进制表示)。“Nonlazy posted:“指示懒惰回调(lazy callback)的状态。如果在上一个空闲期开始时所有回调都是懒惰回调,则显示"l”,如果当前没有非懒惰回调,则显示"L”(在这两种情况下,如果不符合条件,则显示”.”),“D"表示启用了动态空闲处理(dyntick-idle)(如果通过"nohz=“内核引导参数禁用了动态空闲处理,则显示”.”)。

如果宽限期恰好在停滞警告开始打印时结束,将出现虚假的停滞警告消息,其中将包括以下内容:

INFO: Stall ended before state dump start

这种情况很少见,但在实际情况下偶尔会发生。这种情况下,如果停滞警告和宽限期初始化发生的方式相互影响,可能会标记为零滴答停滞(zero-jiffy stall)。请注意,要想完全消除这种误报,需要使用stop_machine()等方法,但这对于这种问题来说有些过度。

如果所有的CPU和任务都经历了静止状态(quiescent states),但宽限期仍然未能结束,停滞警告消息将包括类似以下的内容:

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节点结构的->qsmask字段的值,通常为零。

如果相关的宽限期kthread在停滞警告之前无法运行,就像上面的"All QSes seen"行一样,将会打印以下额外的行:

kthread starved for 23807 jiffies! g7075 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x1 ->cpu=5

如果 grace-period kthread无法获得CPU时间,即使所有的CPU和任务都经历了所需的静止状态,也可能导致RCU CPU停滞警告。"g"数字显示当前宽限期序列号,"f"前面是对grace-period kthread的->gp_flags命令,"RCU_GP_WAIT_FQS"指示kthread正在等待一个短暂的超时,"state"前面是task_struct ->state字段的值,"cpu"表示grace-period kthread上次在CPU 5上运行。

五、一个Stall的多个警告

如果停滞持续的时间足够长,可能会打印多个停滞警告消息。随着消息的增多,它们之间的时间间隔也会增加。具体而言,第一条消息和第二条消息之间的时间间隔将大约是从停滞开始到第一条消息之间的间隔的三倍。

这种方法使得警告消息之间的时间间隔逐渐增加,随着停滞的持续,警告消息的显示变得更加分散和不频繁。这样做的目的是避免在停滞期间过多地向系统日志或控制台输出警告消息,同时仍然提供关于停滞的相关信息。

六、加急宽限期的暂停警告

如果快速宽限期(expedited grace period)检测到停滞,它将在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”。

在同一次运行中,完全有可能同时看到来自普通宽限期和快速宽限期的停滞警告。

参考资料

Linux 5.4.18

Documentation/RCU/stallwarn.txt

Logo

旨在为数千万中国开发者提供一个无缝且高效的云端环境,以支持学习、使用和贡献开源项目。

更多推荐