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

["Paul E. McKenney" <paulmck@linux.vnet.ibm.com>]

On Mon, Jan 19, 2015 at 05:04:29PM +0800, Zhang Zhen wrote:
> On 2015/1/19 16:42, Paul E. McKenney wrote:
> > 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()".
> 
> Yes, i acquire the same spinlock twice in order to reproduce the problem.

Good, I was wondering about that.  ;-)

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

Which is consistent.

> If softlockup_thresh < rcu_cpu_stall_timeout, it will give soft lockup warning.
> If softlockup_thresh > rcu_cpu_stall_timeout, it will likely to give RCU CPU stall warning
> just like above and no give soft lockup warning.
> 
> It means that RCU CPU stall console spews leads to soft lockup disabled.
> Is this reasonable ?

It depends.  You will often see both of them, but they can interfere
with each other, especially if all these messages are going across a
serial line.  And sometimes the activity of the one will suppress the
other, though I would not expect that in your spinlock deadlock case.

							Thanx, Paul

> Thanks!
> 
> >>         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
> > 
> > 
> > .
> > 
> 
>