Messages in this thread | | | Date | Mon, 19 Jan 2015 03:09:35 -0800 | From | "Paul E. McKenney" <> | Subject | Re: RCU CPU stall console spews leads to soft lockup disabled is reasonable ? |
| |
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 > > > > > > . > > > >
| |