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

From: Paul E. McKenney
Date: Mon Jan 19 2015 - 22:33:42 EST

Next message: Fu, Zhonghui: "Re: [PATCH] brcmfmac: avoid duplicated suspend/resume operation"
Previous message: Fu, Zhonghui: "[PATCH] brcmfmac: avoid duplicated suspend/resume operation"
In reply to: Zhang Zhen: "Re: RCU CPU stall console spews leads to soft lockup disabled is reasonable ?"
Next in thread: Don Zickus: "Re: RCU CPU stall console spews leads to soft lockup disabled is reasonable ?"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

On Tue, Jan 20, 2015 at 11:17:01AM +0800, Zhang Zhen wrote:
> On 2015/1/19 19:09, Paul E. McKenney wrote:
> > 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.
> >
> Ok, my expect is to get both RCU stall messages _and_ softlockup messages
> even though all these messages are going across a serial line.
> But in my test case the RCU stall messages suppress the other.

On some kernel versions, slow serial-line consoles can cause problems.
For example, on a 9600-baud line, only 21K characters output at one go
can cause RCU CPU stall warning. This happens on kernels that in some
cases disable interrupts when doing console printks.

> The simplest way is to change the RCU CPU stall warnings use the KERN_INFO
> loglevel.

That is not going to happen. RCU CPU stall warnings are an error, not
an informational message.

> Is there any better way to get both RCU stall messages _and_ softlockup messages
> in any case ?

Perhaps continuing along the path that you and Don Zickus were discussing
will reach a solution.

Thanx, Paul

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

--
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/

Next message: Fu, Zhonghui: "Re: [PATCH] brcmfmac: avoid duplicated suspend/resume operation"
Previous message: Fu, Zhonghui: "[PATCH] brcmfmac: avoid duplicated suspend/resume operation"
In reply to: Zhang Zhen: "Re: RCU CPU stall console spews leads to soft lockup disabled is reasonable ?"
Next in thread: Don Zickus: "Re: RCU CPU stall console spews leads to soft lockup disabled is reasonable ?"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]