Re: RCU CPU stall console spews leads to soft lockup disabled is reasonable ?

[Paul E. McKenney]

On Mon, Jan 19, 2015 at 04:07:15PM +0800, Zhang Zhen wrote:
> Hi,
> 
> On my x86_64 qemu virtual machine, RCU CPU stall console spews may
> lead to soft lockup disabled.
> 
> If softlockup_thresh > rcu_cpu_stall_timeout (softlockup_thresh = 2 * watchdog_thresh):
> 
> / #
> / # busybox cat /sys/module/rcupdate/parameters/rcu_cpu_stall_timeout
> 21
> / # echo 60 > /proc/sys/kernel/watchdog_thresh
> / # busybox insmod softlockup_test.ko
> [   44.959044] INFO: rcu_preempt detected stalls on CPUs/tasks: {} (detected by 0, t=21002 jiffies, g=85, c=84, q=4)
> [   44.959044] INFO: Stall ended before state dump start
> [  107.964045] INFO: rcu_preempt detected stalls on CPUs/tasks: {} (detected by 0, t=84007 jiffies, g=85, c=84, q=4)
> [  107.964045] INFO: Stall ended before state dump start
> [  170.969060] INFO: rcu_preempt detected stalls on CPUs/tasks: {} (detected by 0, t=147012 jiffies, g=85, c=84, q=4)
> [  170.969060] INFO: Stall ended before state dump start
> [  233.974057] INFO: rcu_preempt detected stalls on CPUs/tasks: {} (detected by 0, t=210017 jiffies, g=85, c=84, q=4)
> [  233.974057] INFO: Stall ended before state dump start
> [  296.979059] INFO: rcu_preempt detected stalls on CPUs/tasks: {} (detected by 0, t=273022 jiffies, g=85, c=84, q=4)
> [  296.979059] INFO: Stall ended before state dump start
> [  359.984058] INFO: rcu_preempt detected stalls on CPUs/tasks: {} (detected by 0, t=336027 jiffies, g=85, c=84, q=4)
> [  359.984058] INFO: Stall ended before state dump start
> [  422.989059] INFO: rcu_preempt detected stalls on CPUs/tasks: {} (detected by 0, t=399032 jiffies, g=85, c=84, q=4)
> [  422.989059] INFO: Stall ended before state dump start
> [  485.994056] INFO: rcu_preempt detected stalls on CPUs/tasks: {} (detected by 0, t=462037 jiffies, g=85, c=84, q=4)
> [  485.994056] INFO: Stall ended before state dump start
> [  548.999059] INFO: rcu_preempt detected stalls on CPUs/tasks: {} (detected by 0, t=525042 jiffies, g=85, c=84, q=4)
> [  548.999059] INFO: Stall ended before state dump start
> [  612.004061] INFO: rcu_preempt detected stalls on CPUs/tasks: {} (detected by 0, t=588047 jiffies, g=85, c=84, q=4)
> [  612.004061] INFO: Stall ended before state dump start
> [  675.009058] INFO: rcu_preempt detected stalls on CPUs/tasks: {} (detected by 0, t=651052 jiffies, g=85, c=84, q=4)
> [  675.009058] INFO: Stall ended before state dump start
> 
> If softlockup_thresh < rcu_cpu_stall_timeout:
> 
> / #
> / # busybox cat /sys/module/rcupdate/parameters/rcu_cpu_stall_timeout
> 21
> / # echo 5 > /proc/sys/kernel/watchdog_thresh
> / # busybox insmod softlockup_test.ko
> [   38.450061] BUG: soft lockup - CPU#0 stuck for 11s! [busybox:53]
> [   52.450061] BUG: soft lockup - CPU#0 stuck for 11s! [busybox:53]
> [   66.450073] BUG: soft lockup - CPU#0 stuck for 11s! [busybox:53]
> [   80.450060] BUG: soft lockup - CPU#0 stuck for 11s! [busybox:53]
> [   94.450061] BUG: soft lockup - CPU#0 stuck for 11s! [busybox:53]
> 
> The softlockup_test.ko source code is:
> //
> #include <linux/kernel.h>
> #include <linux/module.h>
> #include <linux/spinlock.h>
> #include <linux/slab.h>
> 
> static int hello_start(void)
> {
>         DEFINE_SPINLOCK(hello_lock);
>         spin_lock_init(&hello_lock);
>         spin_lock(&hello_lock);
>         spin_lock(&hello_lock);

Did you really intend to acquire the same spinlock twice in a row,
forcing a self-deadlock?  If not, I of course suggest changing the second
"spin_lock()" to "spin_unlock()".

If your .config has CONFIG_TREE_RCU=y, the above is quite likely to
give you an RCU CPU stall warning.

>         return 0;
> }
> 
> static int __init test_init(void)
> {
>         hello_start();
> 
>         printk(KERN_INFO "Module init\n");
>         return 0;
> }
> 
> static void __exit test_exit(void)
> {
>         printk(KERN_INFO "Module exit!\n");
> }
> 
> module_init(test_init)
> module_exit(test_exit)
> MODULE_LICENSE("GPL");
> //
> 
> My kernel version is v3.10.63, and i checked the kernel source code,
> 
> update_process_times
> 	-> run_local_timers
> 		-> hrtimer_run_queues
> 			-> __run_hrtimer
> 				-> watchdog_timer_fn
> 					-> is_softlockup
> 					
> 	-> rcu_check_callbacks
> 		-> __rcu_pending
> 			-> check_cpu_stall
> 				-> print_cpu_stall
> 
> If softlockup_thresh > rcu_cpu_stall_timeout, print_cpu_stall will print log to serial port.
> 
> The 8250 serial driver will call serial8250_console_write => touch_nmi_watchdog() which reset
> watchdog_touch_ts to 0. So the softlockup will not be triggered.
> 
> Is this reasonable? Why?

Is exactly what reasonable?  ;-)

Yes, it is reasonable that your code triggers an RCU CPU stall warning.

No, it is not reasonable that the RCU CPU stall warning does not include
a stack trace, and the fix for that bug will be going into the next merge
window.

Yes, is is reasonable that varying the softlockup and RCU CPU stall
timeouts might change the behavior.

No, your code is not reasonable, except perhaps as a test of the
generation of softlockup and RCU CPU stall warnings.  If you are not
trying to test softlockup and RCU CPU stall warnings, you should of course
not try to acquire any non-recursive exclusive lock that you already hold.

> If it is not reasonable, we should adjust the printk loglevel from *KERN_ERR* to *KERN_INFO*
> in print_cpu_stall.

Given that RCU CPU stall warnings are supposed to be pointing out errors
elsewhere in the kernel, and in this case are pointing out errors elsewhere
in the kernel, namely in your hello_start() function, it is reasonable
that the RCU CPU stall warnings use the KERN_ERR loglevel.

Or am I missing something here?

							Thanx, Paul

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/