Re: Can RCU stall lead to hard lockups?
On Tue, Feb 06, 2018 at 08:55:04PM -0600, Serge E. Hallyn wrote:
> On Tue, Feb 06, 2018 at 06:53:37PM -0800, Paul E. McKenney wrote:
> > On Tue, Feb 06, 2018 at 08:33:03PM -0600, Serge E. Hallyn wrote:
> > > On Sat, Feb 03, 2018 at 12:50:32PM -0800, Paul E. McKenney wrote:
> > > > On Fri, Feb 02, 2018 at 05:44:30PM -0600, Serge E. Hallyn wrote:
> > > > > Quoting Paul E. McKenney (paul...@linux.vnet.ibm.com):
> > > > > > On Tue, Jan 09, 2018 at 06:11:14AM -0800, Tejun Heo wrote:
> > > > > > > Hello, Paul.
> > > > > > >
> > > > > > > On Mon, Jan 08, 2018 at 08:24:25PM -0800, Paul E. McKenney wrote:
> > > > > > > > > I don't know the RCU code at all but it *looks* like the
> > > > > > > > > first CPU is
> > > > > > > > > taking a sweet while flushing printk buffer while holding a
> > > > > > > > > lock (the
> > > > > > > > > console is IPMI serial console, which faithfully emulates
> > > > > > > > > 115200 baud
> > > > > > > > > rate), and everyone else seems stuck waiting for that
> > > > > > > > > spinlock in
> > > > > > > > > rcu_check_callbacks().
> > > > > > > > >
> > > > > > > > > Does this sound possible?
> > > > > > > >
> > > > > > > > 115200 baud? Ouch!!! That -will- result in trouble from
> > > > > > > > console
> > > > > > > > printing, and often also in RCU CPU stall warnings.
> > > > > > >
> > > > > > > It could even be slower than 115200, and we occassionally see RCU
> > > > > > > stall warnings caused by printk storms, for example, while the
> > > > > > > kernel
> > > > > > > is trying to dump a lot of info after an OOM. That's an issue we
> > > > > > > probably want to improve from printk side; however, they don't
> > > > > > > usually
> > > > > > > lead to NMI hard lockup detector kicking in and crashing the
> > > > > > > machine,
> > > > > > > which is the peculiarity here.
> > > > > > >
> > > > > > > Hmmm... show_state_filter(), the function which dumps all task
> > > > > > > backtraces, share a similar problem and it avoids it by explicitly
> > > > > > > calling touch_nmi_watchdog(). Maybe we can do something like the
> > > > > > > following from RCU too?
> > > > > >
> > > > > > If this fixes things for you, I would welcome such a patch.
> > > > >
> > > > > Hi - would this also be relevant to 4.9-stable and 4.4-stable, or
> > > > > has something elsewhere changed after 4.9 that actually triggers this?
> > > >
> > > > As far as I can tell, slow console lines have been prone to RCU CPU
> > > > stall
> > > > warnings for a very long time.
> > >
> > > Ok, thanks Paul.
> > >
> > > Tejun were you going to push this?
> >
> > I have it queued for the next merge window. 3eea9623926f ("rcu: Call
> > touch_nmi_watchdog() while printing stall warnings") in -rcu.
>
> D'oh - thanks!
Not a problem at all! Had I lost this commit, it would not have been the
first time. ;-)
Thanx, Paul
Re: Can RCU stall lead to hard lockups?
On Tue, Feb 06, 2018 at 08:55:04PM -0600, Serge E. Hallyn wrote:
> On Tue, Feb 06, 2018 at 06:53:37PM -0800, Paul E. McKenney wrote:
> > On Tue, Feb 06, 2018 at 08:33:03PM -0600, Serge E. Hallyn wrote:
> > > On Sat, Feb 03, 2018 at 12:50:32PM -0800, Paul E. McKenney wrote:
> > > > On Fri, Feb 02, 2018 at 05:44:30PM -0600, Serge E. Hallyn wrote:
> > > > > Quoting Paul E. McKenney (paul...@linux.vnet.ibm.com):
> > > > > > On Tue, Jan 09, 2018 at 06:11:14AM -0800, Tejun Heo wrote:
> > > > > > > Hello, Paul.
> > > > > > >
> > > > > > > On Mon, Jan 08, 2018 at 08:24:25PM -0800, Paul E. McKenney wrote:
> > > > > > > > > I don't know the RCU code at all but it *looks* like the
> > > > > > > > > first CPU is
> > > > > > > > > taking a sweet while flushing printk buffer while holding a
> > > > > > > > > lock (the
> > > > > > > > > console is IPMI serial console, which faithfully emulates
> > > > > > > > > 115200 baud
> > > > > > > > > rate), and everyone else seems stuck waiting for that
> > > > > > > > > spinlock in
> > > > > > > > > rcu_check_callbacks().
> > > > > > > > >
> > > > > > > > > Does this sound possible?
> > > > > > > >
> > > > > > > > 115200 baud? Ouch!!! That -will- result in trouble from
> > > > > > > > console
> > > > > > > > printing, and often also in RCU CPU stall warnings.
> > > > > > >
> > > > > > > It could even be slower than 115200, and we occassionally see RCU
> > > > > > > stall warnings caused by printk storms, for example, while the
> > > > > > > kernel
> > > > > > > is trying to dump a lot of info after an OOM. That's an issue we
> > > > > > > probably want to improve from printk side; however, they don't
> > > > > > > usually
> > > > > > > lead to NMI hard lockup detector kicking in and crashing the
> > > > > > > machine,
> > > > > > > which is the peculiarity here.
> > > > > > >
> > > > > > > Hmmm... show_state_filter(), the function which dumps all task
> > > > > > > backtraces, share a similar problem and it avoids it by explicitly
> > > > > > > calling touch_nmi_watchdog(). Maybe we can do something like the
> > > > > > > following from RCU too?
> > > > > >
> > > > > > If this fixes things for you, I would welcome such a patch.
> > > > >
> > > > > Hi - would this also be relevant to 4.9-stable and 4.4-stable, or
> > > > > has something elsewhere changed after 4.9 that actually triggers this?
> > > >
> > > > As far as I can tell, slow console lines have been prone to RCU CPU
> > > > stall
> > > > warnings for a very long time.
> > >
> > > Ok, thanks Paul.
> > >
> > > Tejun were you going to push this?
> >
> > I have it queued for the next merge window. 3eea9623926f ("rcu: Call
> > touch_nmi_watchdog() while printing stall warnings") in -rcu.
>
> D'oh - thanks!
Not a problem at all! Had I lost this commit, it would not have been the
first time. ;-)
Thanx, Paul
Re: Can RCU stall lead to hard lockups?
On Tue, Feb 06, 2018 at 06:53:37PM -0800, Paul E. McKenney wrote:
> On Tue, Feb 06, 2018 at 08:33:03PM -0600, Serge E. Hallyn wrote:
> > On Sat, Feb 03, 2018 at 12:50:32PM -0800, Paul E. McKenney wrote:
> > > On Fri, Feb 02, 2018 at 05:44:30PM -0600, Serge E. Hallyn wrote:
> > > > Quoting Paul E. McKenney (paul...@linux.vnet.ibm.com):
> > > > > On Tue, Jan 09, 2018 at 06:11:14AM -0800, Tejun Heo wrote:
> > > > > > Hello, Paul.
> > > > > >
> > > > > > On Mon, Jan 08, 2018 at 08:24:25PM -0800, Paul E. McKenney wrote:
> > > > > > > > I don't know the RCU code at all but it *looks* like the first
> > > > > > > > CPU is
> > > > > > > > taking a sweet while flushing printk buffer while holding a
> > > > > > > > lock (the
> > > > > > > > console is IPMI serial console, which faithfully emulates
> > > > > > > > 115200 baud
> > > > > > > > rate), and everyone else seems stuck waiting for that spinlock
> > > > > > > > in
> > > > > > > > rcu_check_callbacks().
> > > > > > > >
> > > > > > > > Does this sound possible?
> > > > > > >
> > > > > > > 115200 baud? Ouch!!! That -will- result in trouble from console
> > > > > > > printing, and often also in RCU CPU stall warnings.
> > > > > >
> > > > > > It could even be slower than 115200, and we occassionally see RCU
> > > > > > stall warnings caused by printk storms, for example, while the
> > > > > > kernel
> > > > > > is trying to dump a lot of info after an OOM. That's an issue we
> > > > > > probably want to improve from printk side; however, they don't
> > > > > > usually
> > > > > > lead to NMI hard lockup detector kicking in and crashing the
> > > > > > machine,
> > > > > > which is the peculiarity here.
> > > > > >
> > > > > > Hmmm... show_state_filter(), the function which dumps all task
> > > > > > backtraces, share a similar problem and it avoids it by explicitly
> > > > > > calling touch_nmi_watchdog(). Maybe we can do something like the
> > > > > > following from RCU too?
> > > > >
> > > > > If this fixes things for you, I would welcome such a patch.
> > > >
> > > > Hi - would this also be relevant to 4.9-stable and 4.4-stable, or
> > > > has something elsewhere changed after 4.9 that actually triggers this?
> > >
> > > As far as I can tell, slow console lines have been prone to RCU CPU stall
> > > warnings for a very long time.
> >
> > Ok, thanks Paul.
> >
> > Tejun were you going to push this?
>
> I have it queued for the next merge window. 3eea9623926f ("rcu: Call
> touch_nmi_watchdog() while printing stall warnings") in -rcu.
D'oh - thanks!
-serge
Re: Can RCU stall lead to hard lockups?
On Tue, Feb 06, 2018 at 06:53:37PM -0800, Paul E. McKenney wrote:
> On Tue, Feb 06, 2018 at 08:33:03PM -0600, Serge E. Hallyn wrote:
> > On Sat, Feb 03, 2018 at 12:50:32PM -0800, Paul E. McKenney wrote:
> > > On Fri, Feb 02, 2018 at 05:44:30PM -0600, Serge E. Hallyn wrote:
> > > > Quoting Paul E. McKenney (paul...@linux.vnet.ibm.com):
> > > > > On Tue, Jan 09, 2018 at 06:11:14AM -0800, Tejun Heo wrote:
> > > > > > Hello, Paul.
> > > > > >
> > > > > > On Mon, Jan 08, 2018 at 08:24:25PM -0800, Paul E. McKenney wrote:
> > > > > > > > I don't know the RCU code at all but it *looks* like the first
> > > > > > > > CPU is
> > > > > > > > taking a sweet while flushing printk buffer while holding a
> > > > > > > > lock (the
> > > > > > > > console is IPMI serial console, which faithfully emulates
> > > > > > > > 115200 baud
> > > > > > > > rate), and everyone else seems stuck waiting for that spinlock
> > > > > > > > in
> > > > > > > > rcu_check_callbacks().
> > > > > > > >
> > > > > > > > Does this sound possible?
> > > > > > >
> > > > > > > 115200 baud? Ouch!!! That -will- result in trouble from console
> > > > > > > printing, and often also in RCU CPU stall warnings.
> > > > > >
> > > > > > It could even be slower than 115200, and we occassionally see RCU
> > > > > > stall warnings caused by printk storms, for example, while the
> > > > > > kernel
> > > > > > is trying to dump a lot of info after an OOM. That's an issue we
> > > > > > probably want to improve from printk side; however, they don't
> > > > > > usually
> > > > > > lead to NMI hard lockup detector kicking in and crashing the
> > > > > > machine,
> > > > > > which is the peculiarity here.
> > > > > >
> > > > > > Hmmm... show_state_filter(), the function which dumps all task
> > > > > > backtraces, share a similar problem and it avoids it by explicitly
> > > > > > calling touch_nmi_watchdog(). Maybe we can do something like the
> > > > > > following from RCU too?
> > > > >
> > > > > If this fixes things for you, I would welcome such a patch.
> > > >
> > > > Hi - would this also be relevant to 4.9-stable and 4.4-stable, or
> > > > has something elsewhere changed after 4.9 that actually triggers this?
> > >
> > > As far as I can tell, slow console lines have been prone to RCU CPU stall
> > > warnings for a very long time.
> >
> > Ok, thanks Paul.
> >
> > Tejun were you going to push this?
>
> I have it queued for the next merge window. 3eea9623926f ("rcu: Call
> touch_nmi_watchdog() while printing stall warnings") in -rcu.
D'oh - thanks!
-serge
Re: Can RCU stall lead to hard lockups?
On Tue, Feb 06, 2018 at 08:33:03PM -0600, Serge E. Hallyn wrote:
> On Sat, Feb 03, 2018 at 12:50:32PM -0800, Paul E. McKenney wrote:
> > On Fri, Feb 02, 2018 at 05:44:30PM -0600, Serge E. Hallyn wrote:
> > > Quoting Paul E. McKenney (paul...@linux.vnet.ibm.com):
> > > > On Tue, Jan 09, 2018 at 06:11:14AM -0800, Tejun Heo wrote:
> > > > > Hello, Paul.
> > > > >
> > > > > On Mon, Jan 08, 2018 at 08:24:25PM -0800, Paul E. McKenney wrote:
> > > > > > > I don't know the RCU code at all but it *looks* like the first
> > > > > > > CPU is
> > > > > > > taking a sweet while flushing printk buffer while holding a lock
> > > > > > > (the
> > > > > > > console is IPMI serial console, which faithfully emulates 115200
> > > > > > > baud
> > > > > > > rate), and everyone else seems stuck waiting for that spinlock in
> > > > > > > rcu_check_callbacks().
> > > > > > >
> > > > > > > Does this sound possible?
> > > > > >
> > > > > > 115200 baud? Ouch!!! That -will- result in trouble from console
> > > > > > printing, and often also in RCU CPU stall warnings.
> > > > >
> > > > > It could even be slower than 115200, and we occassionally see RCU
> > > > > stall warnings caused by printk storms, for example, while the kernel
> > > > > is trying to dump a lot of info after an OOM. That's an issue we
> > > > > probably want to improve from printk side; however, they don't usually
> > > > > lead to NMI hard lockup detector kicking in and crashing the machine,
> > > > > which is the peculiarity here.
> > > > >
> > > > > Hmmm... show_state_filter(), the function which dumps all task
> > > > > backtraces, share a similar problem and it avoids it by explicitly
> > > > > calling touch_nmi_watchdog(). Maybe we can do something like the
> > > > > following from RCU too?
> > > >
> > > > If this fixes things for you, I would welcome such a patch.
> > >
> > > Hi - would this also be relevant to 4.9-stable and 4.4-stable, or
> > > has something elsewhere changed after 4.9 that actually triggers this?
> >
> > As far as I can tell, slow console lines have been prone to RCU CPU stall
> > warnings for a very long time.
>
> Ok, thanks Paul.
>
> Tejun were you going to push this?
I have it queued for the next merge window. 3eea9623926f ("rcu: Call
touch_nmi_watchdog() while printing stall warnings") in -rcu.
Thanx, Paul
> > > thanks,
> > > -serge
> > >
> > > > Thanx, Paul
> > > >
> > > > > diff --git a/kernel/rcu/tree_plugin.h b/kernel/rcu/tree_plugin.h
> > > > > index db85ca3..3c4c4d3 100644
> > > > > --- a/kernel/rcu/tree_plugin.h
> > > > > +++ b/kernel/rcu/tree_plugin.h
> > > > > @@ -561,8 +561,14 @@ static void
> > > > > rcu_print_detail_task_stall_rnp(struct rcu_node *rnp)
> > > > > }
> > > > > t = list_entry(rnp->gp_tasks->prev,
> > > > > struct task_struct, rcu_node_entry);
> > > > > - list_for_each_entry_continue(t, >blkd_tasks,
> > > > > rcu_node_entry)
> > > > > + list_for_each_entry_continue(t, >blkd_tasks,
> > > > > rcu_node_entry) {
> > > > > + touch_nmi_watchdog();
> > > > > + /*
> > > > > + * We could be printing a lot of these messages while
> > > > > + * holding a spinlock. Avoid triggering hard lockup.
> > > > > + */
> > > > > sched_show_task(t);
> > > > > + }
> > > > > raw_spin_unlock_irqrestore_rcu_node(rnp, flags);
> > > > > }
> > > > >
> > > > > @@ -1678,6 +1684,12 @@ static void print_cpu_stall_info(struct
> > > > > rcu_state *rsp, int cpu)
> > > > > char *ticks_title;
> > > > > unsigned long ticks_value;
> > > > >
> > > > > + /*
> > > > > + * We could be printing a lot of these messages while holding a
> > > > > + * spinlock. Avoid triggering hard lockup.
> > > > > + */
> > > > > + touch_nmi_watchdog();
> > > > > +
> > > > > if (rsp->gpnum == rdp->gpnum) {
> > > > > ticks_title = "ticks this GP";
> > > > > ticks_value = rdp->ticks_this_gp;
> > > > >
> > >
>
Re: Can RCU stall lead to hard lockups?
On Tue, Feb 06, 2018 at 08:33:03PM -0600, Serge E. Hallyn wrote:
> On Sat, Feb 03, 2018 at 12:50:32PM -0800, Paul E. McKenney wrote:
> > On Fri, Feb 02, 2018 at 05:44:30PM -0600, Serge E. Hallyn wrote:
> > > Quoting Paul E. McKenney (paul...@linux.vnet.ibm.com):
> > > > On Tue, Jan 09, 2018 at 06:11:14AM -0800, Tejun Heo wrote:
> > > > > Hello, Paul.
> > > > >
> > > > > On Mon, Jan 08, 2018 at 08:24:25PM -0800, Paul E. McKenney wrote:
> > > > > > > I don't know the RCU code at all but it *looks* like the first
> > > > > > > CPU is
> > > > > > > taking a sweet while flushing printk buffer while holding a lock
> > > > > > > (the
> > > > > > > console is IPMI serial console, which faithfully emulates 115200
> > > > > > > baud
> > > > > > > rate), and everyone else seems stuck waiting for that spinlock in
> > > > > > > rcu_check_callbacks().
> > > > > > >
> > > > > > > Does this sound possible?
> > > > > >
> > > > > > 115200 baud? Ouch!!! That -will- result in trouble from console
> > > > > > printing, and often also in RCU CPU stall warnings.
> > > > >
> > > > > It could even be slower than 115200, and we occassionally see RCU
> > > > > stall warnings caused by printk storms, for example, while the kernel
> > > > > is trying to dump a lot of info after an OOM. That's an issue we
> > > > > probably want to improve from printk side; however, they don't usually
> > > > > lead to NMI hard lockup detector kicking in and crashing the machine,
> > > > > which is the peculiarity here.
> > > > >
> > > > > Hmmm... show_state_filter(), the function which dumps all task
> > > > > backtraces, share a similar problem and it avoids it by explicitly
> > > > > calling touch_nmi_watchdog(). Maybe we can do something like the
> > > > > following from RCU too?
> > > >
> > > > If this fixes things for you, I would welcome such a patch.
> > >
> > > Hi - would this also be relevant to 4.9-stable and 4.4-stable, or
> > > has something elsewhere changed after 4.9 that actually triggers this?
> >
> > As far as I can tell, slow console lines have been prone to RCU CPU stall
> > warnings for a very long time.
>
> Ok, thanks Paul.
>
> Tejun were you going to push this?
I have it queued for the next merge window. 3eea9623926f ("rcu: Call
touch_nmi_watchdog() while printing stall warnings") in -rcu.
Thanx, Paul
> > > thanks,
> > > -serge
> > >
> > > > Thanx, Paul
> > > >
> > > > > diff --git a/kernel/rcu/tree_plugin.h b/kernel/rcu/tree_plugin.h
> > > > > index db85ca3..3c4c4d3 100644
> > > > > --- a/kernel/rcu/tree_plugin.h
> > > > > +++ b/kernel/rcu/tree_plugin.h
> > > > > @@ -561,8 +561,14 @@ static void
> > > > > rcu_print_detail_task_stall_rnp(struct rcu_node *rnp)
> > > > > }
> > > > > t = list_entry(rnp->gp_tasks->prev,
> > > > > struct task_struct, rcu_node_entry);
> > > > > - list_for_each_entry_continue(t, >blkd_tasks,
> > > > > rcu_node_entry)
> > > > > + list_for_each_entry_continue(t, >blkd_tasks,
> > > > > rcu_node_entry) {
> > > > > + touch_nmi_watchdog();
> > > > > + /*
> > > > > + * We could be printing a lot of these messages while
> > > > > + * holding a spinlock. Avoid triggering hard lockup.
> > > > > + */
> > > > > sched_show_task(t);
> > > > > + }
> > > > > raw_spin_unlock_irqrestore_rcu_node(rnp, flags);
> > > > > }
> > > > >
> > > > > @@ -1678,6 +1684,12 @@ static void print_cpu_stall_info(struct
> > > > > rcu_state *rsp, int cpu)
> > > > > char *ticks_title;
> > > > > unsigned long ticks_value;
> > > > >
> > > > > + /*
> > > > > + * We could be printing a lot of these messages while holding a
> > > > > + * spinlock. Avoid triggering hard lockup.
> > > > > + */
> > > > > + touch_nmi_watchdog();
> > > > > +
> > > > > if (rsp->gpnum == rdp->gpnum) {
> > > > > ticks_title = "ticks this GP";
> > > > > ticks_value = rdp->ticks_this_gp;
> > > > >
> > >
>
Re: Can RCU stall lead to hard lockups?
On Sat, Feb 03, 2018 at 12:50:32PM -0800, Paul E. McKenney wrote:
> On Fri, Feb 02, 2018 at 05:44:30PM -0600, Serge E. Hallyn wrote:
> > Quoting Paul E. McKenney (paul...@linux.vnet.ibm.com):
> > > On Tue, Jan 09, 2018 at 06:11:14AM -0800, Tejun Heo wrote:
> > > > Hello, Paul.
> > > >
> > > > On Mon, Jan 08, 2018 at 08:24:25PM -0800, Paul E. McKenney wrote:
> > > > > > I don't know the RCU code at all but it *looks* like the first CPU
> > > > > > is
> > > > > > taking a sweet while flushing printk buffer while holding a lock
> > > > > > (the
> > > > > > console is IPMI serial console, which faithfully emulates 115200
> > > > > > baud
> > > > > > rate), and everyone else seems stuck waiting for that spinlock in
> > > > > > rcu_check_callbacks().
> > > > > >
> > > > > > Does this sound possible?
> > > > >
> > > > > 115200 baud? Ouch!!! That -will- result in trouble from console
> > > > > printing, and often also in RCU CPU stall warnings.
> > > >
> > > > It could even be slower than 115200, and we occassionally see RCU
> > > > stall warnings caused by printk storms, for example, while the kernel
> > > > is trying to dump a lot of info after an OOM. That's an issue we
> > > > probably want to improve from printk side; however, they don't usually
> > > > lead to NMI hard lockup detector kicking in and crashing the machine,
> > > > which is the peculiarity here.
> > > >
> > > > Hmmm... show_state_filter(), the function which dumps all task
> > > > backtraces, share a similar problem and it avoids it by explicitly
> > > > calling touch_nmi_watchdog(). Maybe we can do something like the
> > > > following from RCU too?
> > >
> > > If this fixes things for you, I would welcome such a patch.
> >
> > Hi - would this also be relevant to 4.9-stable and 4.4-stable, or
> > has something elsewhere changed after 4.9 that actually triggers this?
>
> As far as I can tell, slow console lines have been prone to RCU CPU stall
> warnings for a very long time.
>
> Thanx, Paul
Ok, thanks Paul.
Tejun were you going to push this?
> > thanks,
> > -serge
> >
> > > Thanx, Paul
> > >
> > > > diff --git a/kernel/rcu/tree_plugin.h b/kernel/rcu/tree_plugin.h
> > > > index db85ca3..3c4c4d3 100644
> > > > --- a/kernel/rcu/tree_plugin.h
> > > > +++ b/kernel/rcu/tree_plugin.h
> > > > @@ -561,8 +561,14 @@ static void rcu_print_detail_task_stall_rnp(struct
> > > > rcu_node *rnp)
> > > > }
> > > > t = list_entry(rnp->gp_tasks->prev,
> > > >struct task_struct, rcu_node_entry);
> > > > - list_for_each_entry_continue(t, >blkd_tasks,
> > > > rcu_node_entry)
> > > > + list_for_each_entry_continue(t, >blkd_tasks,
> > > > rcu_node_entry) {
> > > > + touch_nmi_watchdog();
> > > > + /*
> > > > +* We could be printing a lot of these messages while
> > > > +* holding a spinlock. Avoid triggering hard lockup.
> > > > +*/
> > > > sched_show_task(t);
> > > > + }
> > > > raw_spin_unlock_irqrestore_rcu_node(rnp, flags);
> > > > }
> > > >
> > > > @@ -1678,6 +1684,12 @@ static void print_cpu_stall_info(struct
> > > > rcu_state *rsp, int cpu)
> > > > char *ticks_title;
> > > > unsigned long ticks_value;
> > > >
> > > > + /*
> > > > +* We could be printing a lot of these messages while holding a
> > > > +* spinlock. Avoid triggering hard lockup.
> > > > +*/
> > > > + touch_nmi_watchdog();
> > > > +
> > > > if (rsp->gpnum == rdp->gpnum) {
> > > > ticks_title = "ticks this GP";
> > > > ticks_value = rdp->ticks_this_gp;
> > > >
> >
Re: Can RCU stall lead to hard lockups?
On Sat, Feb 03, 2018 at 12:50:32PM -0800, Paul E. McKenney wrote:
> On Fri, Feb 02, 2018 at 05:44:30PM -0600, Serge E. Hallyn wrote:
> > Quoting Paul E. McKenney (paul...@linux.vnet.ibm.com):
> > > On Tue, Jan 09, 2018 at 06:11:14AM -0800, Tejun Heo wrote:
> > > > Hello, Paul.
> > > >
> > > > On Mon, Jan 08, 2018 at 08:24:25PM -0800, Paul E. McKenney wrote:
> > > > > > I don't know the RCU code at all but it *looks* like the first CPU
> > > > > > is
> > > > > > taking a sweet while flushing printk buffer while holding a lock
> > > > > > (the
> > > > > > console is IPMI serial console, which faithfully emulates 115200
> > > > > > baud
> > > > > > rate), and everyone else seems stuck waiting for that spinlock in
> > > > > > rcu_check_callbacks().
> > > > > >
> > > > > > Does this sound possible?
> > > > >
> > > > > 115200 baud? Ouch!!! That -will- result in trouble from console
> > > > > printing, and often also in RCU CPU stall warnings.
> > > >
> > > > It could even be slower than 115200, and we occassionally see RCU
> > > > stall warnings caused by printk storms, for example, while the kernel
> > > > is trying to dump a lot of info after an OOM. That's an issue we
> > > > probably want to improve from printk side; however, they don't usually
> > > > lead to NMI hard lockup detector kicking in and crashing the machine,
> > > > which is the peculiarity here.
> > > >
> > > > Hmmm... show_state_filter(), the function which dumps all task
> > > > backtraces, share a similar problem and it avoids it by explicitly
> > > > calling touch_nmi_watchdog(). Maybe we can do something like the
> > > > following from RCU too?
> > >
> > > If this fixes things for you, I would welcome such a patch.
> >
> > Hi - would this also be relevant to 4.9-stable and 4.4-stable, or
> > has something elsewhere changed after 4.9 that actually triggers this?
>
> As far as I can tell, slow console lines have been prone to RCU CPU stall
> warnings for a very long time.
>
> Thanx, Paul
Ok, thanks Paul.
Tejun were you going to push this?
> > thanks,
> > -serge
> >
> > > Thanx, Paul
> > >
> > > > diff --git a/kernel/rcu/tree_plugin.h b/kernel/rcu/tree_plugin.h
> > > > index db85ca3..3c4c4d3 100644
> > > > --- a/kernel/rcu/tree_plugin.h
> > > > +++ b/kernel/rcu/tree_plugin.h
> > > > @@ -561,8 +561,14 @@ static void rcu_print_detail_task_stall_rnp(struct
> > > > rcu_node *rnp)
> > > > }
> > > > t = list_entry(rnp->gp_tasks->prev,
> > > >struct task_struct, rcu_node_entry);
> > > > - list_for_each_entry_continue(t, >blkd_tasks,
> > > > rcu_node_entry)
> > > > + list_for_each_entry_continue(t, >blkd_tasks,
> > > > rcu_node_entry) {
> > > > + touch_nmi_watchdog();
> > > > + /*
> > > > +* We could be printing a lot of these messages while
> > > > +* holding a spinlock. Avoid triggering hard lockup.
> > > > +*/
> > > > sched_show_task(t);
> > > > + }
> > > > raw_spin_unlock_irqrestore_rcu_node(rnp, flags);
> > > > }
> > > >
> > > > @@ -1678,6 +1684,12 @@ static void print_cpu_stall_info(struct
> > > > rcu_state *rsp, int cpu)
> > > > char *ticks_title;
> > > > unsigned long ticks_value;
> > > >
> > > > + /*
> > > > +* We could be printing a lot of these messages while holding a
> > > > +* spinlock. Avoid triggering hard lockup.
> > > > +*/
> > > > + touch_nmi_watchdog();
> > > > +
> > > > if (rsp->gpnum == rdp->gpnum) {
> > > > ticks_title = "ticks this GP";
> > > > ticks_value = rdp->ticks_this_gp;
> > > >
> >
Re: Can RCU stall lead to hard lockups?
On Fri, Feb 02, 2018 at 05:44:30PM -0600, Serge E. Hallyn wrote:
> Quoting Paul E. McKenney (paul...@linux.vnet.ibm.com):
> > On Tue, Jan 09, 2018 at 06:11:14AM -0800, Tejun Heo wrote:
> > > Hello, Paul.
> > >
> > > On Mon, Jan 08, 2018 at 08:24:25PM -0800, Paul E. McKenney wrote:
> > > > > I don't know the RCU code at all but it *looks* like the first CPU is
> > > > > taking a sweet while flushing printk buffer while holding a lock (the
> > > > > console is IPMI serial console, which faithfully emulates 115200 baud
> > > > > rate), and everyone else seems stuck waiting for that spinlock in
> > > > > rcu_check_callbacks().
> > > > >
> > > > > Does this sound possible?
> > > >
> > > > 115200 baud? Ouch!!! That -will- result in trouble from console
> > > > printing, and often also in RCU CPU stall warnings.
> > >
> > > It could even be slower than 115200, and we occassionally see RCU
> > > stall warnings caused by printk storms, for example, while the kernel
> > > is trying to dump a lot of info after an OOM. That's an issue we
> > > probably want to improve from printk side; however, they don't usually
> > > lead to NMI hard lockup detector kicking in and crashing the machine,
> > > which is the peculiarity here.
> > >
> > > Hmmm... show_state_filter(), the function which dumps all task
> > > backtraces, share a similar problem and it avoids it by explicitly
> > > calling touch_nmi_watchdog(). Maybe we can do something like the
> > > following from RCU too?
> >
> > If this fixes things for you, I would welcome such a patch.
>
> Hi - would this also be relevant to 4.9-stable and 4.4-stable, or
> has something elsewhere changed after 4.9 that actually triggers this?
As far as I can tell, slow console lines have been prone to RCU CPU stall
warnings for a very long time.
Thanx, Paul
> thanks,
> -serge
>
> > Thanx, Paul
> >
> > > diff --git a/kernel/rcu/tree_plugin.h b/kernel/rcu/tree_plugin.h
> > > index db85ca3..3c4c4d3 100644
> > > --- a/kernel/rcu/tree_plugin.h
> > > +++ b/kernel/rcu/tree_plugin.h
> > > @@ -561,8 +561,14 @@ static void rcu_print_detail_task_stall_rnp(struct
> > > rcu_node *rnp)
> > > }
> > > t = list_entry(rnp->gp_tasks->prev,
> > > struct task_struct, rcu_node_entry);
> > > - list_for_each_entry_continue(t, >blkd_tasks, rcu_node_entry)
> > > + list_for_each_entry_continue(t, >blkd_tasks, rcu_node_entry) {
> > > + touch_nmi_watchdog();
> > > + /*
> > > + * We could be printing a lot of these messages while
> > > + * holding a spinlock. Avoid triggering hard lockup.
> > > + */
> > > sched_show_task(t);
> > > + }
> > > raw_spin_unlock_irqrestore_rcu_node(rnp, flags);
> > > }
> > >
> > > @@ -1678,6 +1684,12 @@ static void print_cpu_stall_info(struct rcu_state
> > > *rsp, int cpu)
> > > char *ticks_title;
> > > unsigned long ticks_value;
> > >
> > > + /*
> > > + * We could be printing a lot of these messages while holding a
> > > + * spinlock. Avoid triggering hard lockup.
> > > + */
> > > + touch_nmi_watchdog();
> > > +
> > > if (rsp->gpnum == rdp->gpnum) {
> > > ticks_title = "ticks this GP";
> > > ticks_value = rdp->ticks_this_gp;
> > >
>
Re: Can RCU stall lead to hard lockups?
On Fri, Feb 02, 2018 at 05:44:30PM -0600, Serge E. Hallyn wrote:
> Quoting Paul E. McKenney (paul...@linux.vnet.ibm.com):
> > On Tue, Jan 09, 2018 at 06:11:14AM -0800, Tejun Heo wrote:
> > > Hello, Paul.
> > >
> > > On Mon, Jan 08, 2018 at 08:24:25PM -0800, Paul E. McKenney wrote:
> > > > > I don't know the RCU code at all but it *looks* like the first CPU is
> > > > > taking a sweet while flushing printk buffer while holding a lock (the
> > > > > console is IPMI serial console, which faithfully emulates 115200 baud
> > > > > rate), and everyone else seems stuck waiting for that spinlock in
> > > > > rcu_check_callbacks().
> > > > >
> > > > > Does this sound possible?
> > > >
> > > > 115200 baud? Ouch!!! That -will- result in trouble from console
> > > > printing, and often also in RCU CPU stall warnings.
> > >
> > > It could even be slower than 115200, and we occassionally see RCU
> > > stall warnings caused by printk storms, for example, while the kernel
> > > is trying to dump a lot of info after an OOM. That's an issue we
> > > probably want to improve from printk side; however, they don't usually
> > > lead to NMI hard lockup detector kicking in and crashing the machine,
> > > which is the peculiarity here.
> > >
> > > Hmmm... show_state_filter(), the function which dumps all task
> > > backtraces, share a similar problem and it avoids it by explicitly
> > > calling touch_nmi_watchdog(). Maybe we can do something like the
> > > following from RCU too?
> >
> > If this fixes things for you, I would welcome such a patch.
>
> Hi - would this also be relevant to 4.9-stable and 4.4-stable, or
> has something elsewhere changed after 4.9 that actually triggers this?
As far as I can tell, slow console lines have been prone to RCU CPU stall
warnings for a very long time.
Thanx, Paul
> thanks,
> -serge
>
> > Thanx, Paul
> >
> > > diff --git a/kernel/rcu/tree_plugin.h b/kernel/rcu/tree_plugin.h
> > > index db85ca3..3c4c4d3 100644
> > > --- a/kernel/rcu/tree_plugin.h
> > > +++ b/kernel/rcu/tree_plugin.h
> > > @@ -561,8 +561,14 @@ static void rcu_print_detail_task_stall_rnp(struct
> > > rcu_node *rnp)
> > > }
> > > t = list_entry(rnp->gp_tasks->prev,
> > > struct task_struct, rcu_node_entry);
> > > - list_for_each_entry_continue(t, >blkd_tasks, rcu_node_entry)
> > > + list_for_each_entry_continue(t, >blkd_tasks, rcu_node_entry) {
> > > + touch_nmi_watchdog();
> > > + /*
> > > + * We could be printing a lot of these messages while
> > > + * holding a spinlock. Avoid triggering hard lockup.
> > > + */
> > > sched_show_task(t);
> > > + }
> > > raw_spin_unlock_irqrestore_rcu_node(rnp, flags);
> > > }
> > >
> > > @@ -1678,6 +1684,12 @@ static void print_cpu_stall_info(struct rcu_state
> > > *rsp, int cpu)
> > > char *ticks_title;
> > > unsigned long ticks_value;
> > >
> > > + /*
> > > + * We could be printing a lot of these messages while holding a
> > > + * spinlock. Avoid triggering hard lockup.
> > > + */
> > > + touch_nmi_watchdog();
> > > +
> > > if (rsp->gpnum == rdp->gpnum) {
> > > ticks_title = "ticks this GP";
> > > ticks_value = rdp->ticks_this_gp;
> > >
>
Re: Can RCU stall lead to hard lockups?
Quoting Paul E. McKenney (paul...@linux.vnet.ibm.com):
> On Tue, Jan 09, 2018 at 06:11:14AM -0800, Tejun Heo wrote:
> > Hello, Paul.
> >
> > On Mon, Jan 08, 2018 at 08:24:25PM -0800, Paul E. McKenney wrote:
> > > > I don't know the RCU code at all but it *looks* like the first CPU is
> > > > taking a sweet while flushing printk buffer while holding a lock (the
> > > > console is IPMI serial console, which faithfully emulates 115200 baud
> > > > rate), and everyone else seems stuck waiting for that spinlock in
> > > > rcu_check_callbacks().
> > > >
> > > > Does this sound possible?
> > >
> > > 115200 baud? Ouch!!! That -will- result in trouble from console
> > > printing, and often also in RCU CPU stall warnings.
> >
> > It could even be slower than 115200, and we occassionally see RCU
> > stall warnings caused by printk storms, for example, while the kernel
> > is trying to dump a lot of info after an OOM. That's an issue we
> > probably want to improve from printk side; however, they don't usually
> > lead to NMI hard lockup detector kicking in and crashing the machine,
> > which is the peculiarity here.
> >
> > Hmmm... show_state_filter(), the function which dumps all task
> > backtraces, share a similar problem and it avoids it by explicitly
> > calling touch_nmi_watchdog(). Maybe we can do something like the
> > following from RCU too?
>
> If this fixes things for you, I would welcome such a patch.
Hi - would this also be relevant to 4.9-stable and 4.4-stable, or
has something elsewhere changed after 4.9 that actually triggers this?
thanks,
-serge
> Thanx, Paul
>
> > diff --git a/kernel/rcu/tree_plugin.h b/kernel/rcu/tree_plugin.h
> > index db85ca3..3c4c4d3 100644
> > --- a/kernel/rcu/tree_plugin.h
> > +++ b/kernel/rcu/tree_plugin.h
> > @@ -561,8 +561,14 @@ static void rcu_print_detail_task_stall_rnp(struct
> > rcu_node *rnp)
> > }
> > t = list_entry(rnp->gp_tasks->prev,
> >struct task_struct, rcu_node_entry);
> > - list_for_each_entry_continue(t, >blkd_tasks, rcu_node_entry)
> > + list_for_each_entry_continue(t, >blkd_tasks, rcu_node_entry) {
> > + touch_nmi_watchdog();
> > + /*
> > +* We could be printing a lot of these messages while
> > +* holding a spinlock. Avoid triggering hard lockup.
> > +*/
> > sched_show_task(t);
> > + }
> > raw_spin_unlock_irqrestore_rcu_node(rnp, flags);
> > }
> >
> > @@ -1678,6 +1684,12 @@ static void print_cpu_stall_info(struct rcu_state
> > *rsp, int cpu)
> > char *ticks_title;
> > unsigned long ticks_value;
> >
> > + /*
> > +* We could be printing a lot of these messages while holding a
> > +* spinlock. Avoid triggering hard lockup.
> > +*/
> > + touch_nmi_watchdog();
> > +
> > if (rsp->gpnum == rdp->gpnum) {
> > ticks_title = "ticks this GP";
> > ticks_value = rdp->ticks_this_gp;
> >
Re: Can RCU stall lead to hard lockups?
Quoting Paul E. McKenney (paul...@linux.vnet.ibm.com):
> On Tue, Jan 09, 2018 at 06:11:14AM -0800, Tejun Heo wrote:
> > Hello, Paul.
> >
> > On Mon, Jan 08, 2018 at 08:24:25PM -0800, Paul E. McKenney wrote:
> > > > I don't know the RCU code at all but it *looks* like the first CPU is
> > > > taking a sweet while flushing printk buffer while holding a lock (the
> > > > console is IPMI serial console, which faithfully emulates 115200 baud
> > > > rate), and everyone else seems stuck waiting for that spinlock in
> > > > rcu_check_callbacks().
> > > >
> > > > Does this sound possible?
> > >
> > > 115200 baud? Ouch!!! That -will- result in trouble from console
> > > printing, and often also in RCU CPU stall warnings.
> >
> > It could even be slower than 115200, and we occassionally see RCU
> > stall warnings caused by printk storms, for example, while the kernel
> > is trying to dump a lot of info after an OOM. That's an issue we
> > probably want to improve from printk side; however, they don't usually
> > lead to NMI hard lockup detector kicking in and crashing the machine,
> > which is the peculiarity here.
> >
> > Hmmm... show_state_filter(), the function which dumps all task
> > backtraces, share a similar problem and it avoids it by explicitly
> > calling touch_nmi_watchdog(). Maybe we can do something like the
> > following from RCU too?
>
> If this fixes things for you, I would welcome such a patch.
Hi - would this also be relevant to 4.9-stable and 4.4-stable, or
has something elsewhere changed after 4.9 that actually triggers this?
thanks,
-serge
> Thanx, Paul
>
> > diff --git a/kernel/rcu/tree_plugin.h b/kernel/rcu/tree_plugin.h
> > index db85ca3..3c4c4d3 100644
> > --- a/kernel/rcu/tree_plugin.h
> > +++ b/kernel/rcu/tree_plugin.h
> > @@ -561,8 +561,14 @@ static void rcu_print_detail_task_stall_rnp(struct
> > rcu_node *rnp)
> > }
> > t = list_entry(rnp->gp_tasks->prev,
> >struct task_struct, rcu_node_entry);
> > - list_for_each_entry_continue(t, >blkd_tasks, rcu_node_entry)
> > + list_for_each_entry_continue(t, >blkd_tasks, rcu_node_entry) {
> > + touch_nmi_watchdog();
> > + /*
> > +* We could be printing a lot of these messages while
> > +* holding a spinlock. Avoid triggering hard lockup.
> > +*/
> > sched_show_task(t);
> > + }
> > raw_spin_unlock_irqrestore_rcu_node(rnp, flags);
> > }
> >
> > @@ -1678,6 +1684,12 @@ static void print_cpu_stall_info(struct rcu_state
> > *rsp, int cpu)
> > char *ticks_title;
> > unsigned long ticks_value;
> >
> > + /*
> > +* We could be printing a lot of these messages while holding a
> > +* spinlock. Avoid triggering hard lockup.
> > +*/
> > + touch_nmi_watchdog();
> > +
> > if (rsp->gpnum == rdp->gpnum) {
> > ticks_title = "ticks this GP";
> > ticks_value = rdp->ticks_this_gp;
> >
Re: Can RCU stall lead to hard lockups?
On Tue, Jan 09, 2018 at 06:11:14AM -0800, Tejun Heo wrote:
> Hello, Paul.
>
> On Mon, Jan 08, 2018 at 08:24:25PM -0800, Paul E. McKenney wrote:
> > > I don't know the RCU code at all but it *looks* like the first CPU is
> > > taking a sweet while flushing printk buffer while holding a lock (the
> > > console is IPMI serial console, which faithfully emulates 115200 baud
> > > rate), and everyone else seems stuck waiting for that spinlock in
> > > rcu_check_callbacks().
> > >
> > > Does this sound possible?
> >
> > 115200 baud? Ouch!!! That -will- result in trouble from console
> > printing, and often also in RCU CPU stall warnings.
>
> It could even be slower than 115200, and we occassionally see RCU
> stall warnings caused by printk storms, for example, while the kernel
> is trying to dump a lot of info after an OOM. That's an issue we
> probably want to improve from printk side; however, they don't usually
> lead to NMI hard lockup detector kicking in and crashing the machine,
> which is the peculiarity here.
>
> Hmmm... show_state_filter(), the function which dumps all task
> backtraces, share a similar problem and it avoids it by explicitly
> calling touch_nmi_watchdog(). Maybe we can do something like the
> following from RCU too?
If this fixes things for you, I would welcome such a patch.
Thanx, Paul
> diff --git a/kernel/rcu/tree_plugin.h b/kernel/rcu/tree_plugin.h
> index db85ca3..3c4c4d3 100644
> --- a/kernel/rcu/tree_plugin.h
> +++ b/kernel/rcu/tree_plugin.h
> @@ -561,8 +561,14 @@ static void rcu_print_detail_task_stall_rnp(struct
> rcu_node *rnp)
> }
> t = list_entry(rnp->gp_tasks->prev,
> struct task_struct, rcu_node_entry);
> - list_for_each_entry_continue(t, >blkd_tasks, rcu_node_entry)
> + list_for_each_entry_continue(t, >blkd_tasks, rcu_node_entry) {
> + touch_nmi_watchdog();
> + /*
> + * We could be printing a lot of these messages while
> + * holding a spinlock. Avoid triggering hard lockup.
> + */
> sched_show_task(t);
> + }
> raw_spin_unlock_irqrestore_rcu_node(rnp, flags);
> }
>
> @@ -1678,6 +1684,12 @@ static void print_cpu_stall_info(struct rcu_state
> *rsp, int cpu)
> char *ticks_title;
> unsigned long ticks_value;
>
> + /*
> + * We could be printing a lot of these messages while holding a
> + * spinlock. Avoid triggering hard lockup.
> + */
> + touch_nmi_watchdog();
> +
> if (rsp->gpnum == rdp->gpnum) {
> ticks_title = "ticks this GP";
> ticks_value = rdp->ticks_this_gp;
>
Re: Can RCU stall lead to hard lockups?
On Tue, Jan 09, 2018 at 06:11:14AM -0800, Tejun Heo wrote:
> Hello, Paul.
>
> On Mon, Jan 08, 2018 at 08:24:25PM -0800, Paul E. McKenney wrote:
> > > I don't know the RCU code at all but it *looks* like the first CPU is
> > > taking a sweet while flushing printk buffer while holding a lock (the
> > > console is IPMI serial console, which faithfully emulates 115200 baud
> > > rate), and everyone else seems stuck waiting for that spinlock in
> > > rcu_check_callbacks().
> > >
> > > Does this sound possible?
> >
> > 115200 baud? Ouch!!! That -will- result in trouble from console
> > printing, and often also in RCU CPU stall warnings.
>
> It could even be slower than 115200, and we occassionally see RCU
> stall warnings caused by printk storms, for example, while the kernel
> is trying to dump a lot of info after an OOM. That's an issue we
> probably want to improve from printk side; however, they don't usually
> lead to NMI hard lockup detector kicking in and crashing the machine,
> which is the peculiarity here.
>
> Hmmm... show_state_filter(), the function which dumps all task
> backtraces, share a similar problem and it avoids it by explicitly
> calling touch_nmi_watchdog(). Maybe we can do something like the
> following from RCU too?
If this fixes things for you, I would welcome such a patch.
Thanx, Paul
> diff --git a/kernel/rcu/tree_plugin.h b/kernel/rcu/tree_plugin.h
> index db85ca3..3c4c4d3 100644
> --- a/kernel/rcu/tree_plugin.h
> +++ b/kernel/rcu/tree_plugin.h
> @@ -561,8 +561,14 @@ static void rcu_print_detail_task_stall_rnp(struct
> rcu_node *rnp)
> }
> t = list_entry(rnp->gp_tasks->prev,
> struct task_struct, rcu_node_entry);
> - list_for_each_entry_continue(t, >blkd_tasks, rcu_node_entry)
> + list_for_each_entry_continue(t, >blkd_tasks, rcu_node_entry) {
> + touch_nmi_watchdog();
> + /*
> + * We could be printing a lot of these messages while
> + * holding a spinlock. Avoid triggering hard lockup.
> + */
> sched_show_task(t);
> + }
> raw_spin_unlock_irqrestore_rcu_node(rnp, flags);
> }
>
> @@ -1678,6 +1684,12 @@ static void print_cpu_stall_info(struct rcu_state
> *rsp, int cpu)
> char *ticks_title;
> unsigned long ticks_value;
>
> + /*
> + * We could be printing a lot of these messages while holding a
> + * spinlock. Avoid triggering hard lockup.
> + */
> + touch_nmi_watchdog();
> +
> if (rsp->gpnum == rdp->gpnum) {
> ticks_title = "ticks this GP";
> ticks_value = rdp->ticks_this_gp;
>
Re: Can RCU stall lead to hard lockups?
Hello, Paul.
On Mon, Jan 08, 2018 at 08:24:25PM -0800, Paul E. McKenney wrote:
> > I don't know the RCU code at all but it *looks* like the first CPU is
> > taking a sweet while flushing printk buffer while holding a lock (the
> > console is IPMI serial console, which faithfully emulates 115200 baud
> > rate), and everyone else seems stuck waiting for that spinlock in
> > rcu_check_callbacks().
> >
> > Does this sound possible?
>
> 115200 baud? Ouch!!! That -will- result in trouble from console
> printing, and often also in RCU CPU stall warnings.
It could even be slower than 115200, and we occassionally see RCU
stall warnings caused by printk storms, for example, while the kernel
is trying to dump a lot of info after an OOM. That's an issue we
probably want to improve from printk side; however, they don't usually
lead to NMI hard lockup detector kicking in and crashing the machine,
which is the peculiarity here.
Hmmm... show_state_filter(), the function which dumps all task
backtraces, share a similar problem and it avoids it by explicitly
calling touch_nmi_watchdog(). Maybe we can do something like the
following from RCU too?
diff --git a/kernel/rcu/tree_plugin.h b/kernel/rcu/tree_plugin.h
index db85ca3..3c4c4d3 100644
--- a/kernel/rcu/tree_plugin.h
+++ b/kernel/rcu/tree_plugin.h
@@ -561,8 +561,14 @@ static void rcu_print_detail_task_stall_rnp(struct
rcu_node *rnp)
}
t = list_entry(rnp->gp_tasks->prev,
struct task_struct, rcu_node_entry);
- list_for_each_entry_continue(t, >blkd_tasks, rcu_node_entry)
+ list_for_each_entry_continue(t, >blkd_tasks, rcu_node_entry) {
+ touch_nmi_watchdog();
+ /*
+* We could be printing a lot of these messages while
+* holding a spinlock. Avoid triggering hard lockup.
+*/
sched_show_task(t);
+ }
raw_spin_unlock_irqrestore_rcu_node(rnp, flags);
}
@@ -1678,6 +1684,12 @@ static void print_cpu_stall_info(struct rcu_state *rsp,
int cpu)
char *ticks_title;
unsigned long ticks_value;
+ /*
+* We could be printing a lot of these messages while holding a
+* spinlock. Avoid triggering hard lockup.
+*/
+ touch_nmi_watchdog();
+
if (rsp->gpnum == rdp->gpnum) {
ticks_title = "ticks this GP";
ticks_value = rdp->ticks_this_gp;
Re: Can RCU stall lead to hard lockups?
Hello, Paul.
On Mon, Jan 08, 2018 at 08:24:25PM -0800, Paul E. McKenney wrote:
> > I don't know the RCU code at all but it *looks* like the first CPU is
> > taking a sweet while flushing printk buffer while holding a lock (the
> > console is IPMI serial console, which faithfully emulates 115200 baud
> > rate), and everyone else seems stuck waiting for that spinlock in
> > rcu_check_callbacks().
> >
> > Does this sound possible?
>
> 115200 baud? Ouch!!! That -will- result in trouble from console
> printing, and often also in RCU CPU stall warnings.
It could even be slower than 115200, and we occassionally see RCU
stall warnings caused by printk storms, for example, while the kernel
is trying to dump a lot of info after an OOM. That's an issue we
probably want to improve from printk side; however, they don't usually
lead to NMI hard lockup detector kicking in and crashing the machine,
which is the peculiarity here.
Hmmm... show_state_filter(), the function which dumps all task
backtraces, share a similar problem and it avoids it by explicitly
calling touch_nmi_watchdog(). Maybe we can do something like the
following from RCU too?
diff --git a/kernel/rcu/tree_plugin.h b/kernel/rcu/tree_plugin.h
index db85ca3..3c4c4d3 100644
--- a/kernel/rcu/tree_plugin.h
+++ b/kernel/rcu/tree_plugin.h
@@ -561,8 +561,14 @@ static void rcu_print_detail_task_stall_rnp(struct
rcu_node *rnp)
}
t = list_entry(rnp->gp_tasks->prev,
struct task_struct, rcu_node_entry);
- list_for_each_entry_continue(t, >blkd_tasks, rcu_node_entry)
+ list_for_each_entry_continue(t, >blkd_tasks, rcu_node_entry) {
+ touch_nmi_watchdog();
+ /*
+* We could be printing a lot of these messages while
+* holding a spinlock. Avoid triggering hard lockup.
+*/
sched_show_task(t);
+ }
raw_spin_unlock_irqrestore_rcu_node(rnp, flags);
}
@@ -1678,6 +1684,12 @@ static void print_cpu_stall_info(struct rcu_state *rsp,
int cpu)
char *ticks_title;
unsigned long ticks_value;
+ /*
+* We could be printing a lot of these messages while holding a
+* spinlock. Avoid triggering hard lockup.
+*/
+ touch_nmi_watchdog();
+
if (rsp->gpnum == rdp->gpnum) {
ticks_title = "ticks this GP";
ticks_value = rdp->ticks_this_gp;
Re: Can RCU stall lead to hard lockups?
On Mon, Jan 08, 2018 at 07:52:07PM -0800, Tejun Heo wrote: > Hello, Paul. > > So, I was looking at a machine which triggered crashdump from NMI hard > lockup. The dmesg was filled up with backtraces - many were stuck in > reclaim path, which seems to be the culprit, the others were stuck in > RCU path. It looks like by the time crashdump was created, all CPUs > got stuck in RCU path. > > One of the CPUs looked like the following. > > PID: 4149739 TASK: 881a46baa880 CPU: 13 COMMAND: "CPUThreadPool8" >#0 [881fff945e48] crash_nmi_callback at 8103f7d0 >#1 [881fff945e58] nmi_handle at 81020653 >#2 [881fff945eb0] default_do_nmi at 81020c36 >#3 [881fff945ed0] do_nmi at 81020d32 >#4 [881fff945ef0] end_repeat_nmi at 81956a7e > [exception RIP: io_serial_in+21] > RIP: 81630e55 RSP: 881fff943b88 RFLAGS: 0002 > RAX: ca00 RBX: 8230e188 RCX: > RDX: 02fd RSI: 0005 RDI: 8230e188 > RBP: 881fff943bb0 R8: R9: 820cb3c4 > R10: 0019 R11: 2000 R12: 26e1 > R13: 0020 R14: 820cd398 R15: 0035 > ORIG_RAX: CS: 0010 SS: > --- --- >#5 [881fff943b88] io_serial_in at 81630e55 >#6 [881fff943b90] wait_for_xmitr at 8163175c >#7 [881fff943bb8] serial8250_console_putchar at 816317dc >#8 [881fff943bd8] uart_console_write at 8162ac00 >#9 [881fff943c08] serial8250_console_write at 81634691 > #10 [881fff943c80] univ8250_console_write at 8162f7c2 > #11 [881fff943c90] console_unlock at 810dfc55 > #12 [881fff943cf0] vprintk_emit at 810dffb5 > #13 [881fff943d50] vprintk_default at 810e01bf > #14 [881fff943d60] vprintk_func at 810e1127 > #15 [881fff943d70] printk at 8119a8a4 > #16 [881fff943dd0] print_cpu_stall_info at 810eb78c > #17 [881fff943e88] rcu_check_callbacks at 810ef133 > #18 [881fff943ee8] update_process_times at 810f3497 > #19 [881fff943f10] tick_sched_timer at 81103037 > #20 [881fff943f38] __hrtimer_run_queues at 810f3f38 > #21 [881fff943f88] hrtimer_interrupt at 810f442b You don't have a low-bandwidth console, do you? (For example, the output being directed to slow mass storage, across a slow network link, or the like.) > The CPU which triggered hardlockup: > > PID: 4149709 TASK: 88010f88c380 CPU: 26 COMMAND: "CPUThreadPool35" >#0 [883fff1059d0] machine_kexec at 8104a874 >#1 [883fff105a30] __crash_kexec at 86cc >#2 [883fff105af0] __crash_kexec at 8795 >#3 [883fff105b08] panic at 8119a6ae >#4 [883fff105b98] watchdog_overflow_callback at 81135dbd >#5 [883fff105bb0] __perf_event_overflow at 81186866 >#6 [883fff105be8] perf_event_overflow at 81192bc4 >#7 [883fff105bf8] intel_pmu_handle_irq at 8100b265 >#8 [883fff105df8] perf_event_nmi_handler at 8100489f >#9 [883fff105e58] nmi_handle at 81020653 > #10 [883fff105eb0] default_do_nmi at 81020b94 > #11 [883fff105ed0] do_nmi at 81020d32 > #12 [883fff105ef0] end_repeat_nmi at 81956a7e > [exception RIP: queued_spin_lock_slowpath+248] > RIP: 810da958 RSP: 883fff103e68 RFLAGS: 0046 > RAX: RBX: 0046 RCX: 006d > RDX: 883fff49a950 RSI: 00d10101 RDI: 81e54300 > RBP: 883fff103e80 R8: 883fff11a950 R9: > R10: 0e5873ba R11: 010f R12: 81e54300 > R13: R14: 88010f88c380 R15: 81e54300 > ORIG_RAX: CS: 0010 SS: 0018 > --- --- > #13 [883fff103e68] queued_spin_lock_slowpath at 810da958 > #14 [883fff103e70] _raw_spin_lock_irqsave at 8195550b > #15 [883fff103e88] rcu_check_callbacks at 810eed18 > #16 [883fff103ee8] update_process_times at 810f3497 > #17 [883fff103f10] tick_sched_timer at 81103037 > #18 [883fff103f38] __hrtimer_run_queues at 810f3f38 > #19 [883fff103f88] hrtimer_interrupt at 810f442b > --- --- > bt: read error: kernel virtual address: ffd8 type: "pt_regs" This might be unable to acquire the spinlock that CPU 13 was holding while printing to the console. > All other CPUs have something similar to the following: > > PID: 4150460 TASK: 88162c891b00 CPU: 8 COMMAND: "GlobalIOThreadP" >#0 [881fff805e48]
Re: Can RCU stall lead to hard lockups?
On Mon, Jan 08, 2018 at 07:52:07PM -0800, Tejun Heo wrote: > Hello, Paul. > > So, I was looking at a machine which triggered crashdump from NMI hard > lockup. The dmesg was filled up with backtraces - many were stuck in > reclaim path, which seems to be the culprit, the others were stuck in > RCU path. It looks like by the time crashdump was created, all CPUs > got stuck in RCU path. > > One of the CPUs looked like the following. > > PID: 4149739 TASK: 881a46baa880 CPU: 13 COMMAND: "CPUThreadPool8" >#0 [881fff945e48] crash_nmi_callback at 8103f7d0 >#1 [881fff945e58] nmi_handle at 81020653 >#2 [881fff945eb0] default_do_nmi at 81020c36 >#3 [881fff945ed0] do_nmi at 81020d32 >#4 [881fff945ef0] end_repeat_nmi at 81956a7e > [exception RIP: io_serial_in+21] > RIP: 81630e55 RSP: 881fff943b88 RFLAGS: 0002 > RAX: ca00 RBX: 8230e188 RCX: > RDX: 02fd RSI: 0005 RDI: 8230e188 > RBP: 881fff943bb0 R8: R9: 820cb3c4 > R10: 0019 R11: 2000 R12: 26e1 > R13: 0020 R14: 820cd398 R15: 0035 > ORIG_RAX: CS: 0010 SS: > --- --- >#5 [881fff943b88] io_serial_in at 81630e55 >#6 [881fff943b90] wait_for_xmitr at 8163175c >#7 [881fff943bb8] serial8250_console_putchar at 816317dc >#8 [881fff943bd8] uart_console_write at 8162ac00 >#9 [881fff943c08] serial8250_console_write at 81634691 > #10 [881fff943c80] univ8250_console_write at 8162f7c2 > #11 [881fff943c90] console_unlock at 810dfc55 > #12 [881fff943cf0] vprintk_emit at 810dffb5 > #13 [881fff943d50] vprintk_default at 810e01bf > #14 [881fff943d60] vprintk_func at 810e1127 > #15 [881fff943d70] printk at 8119a8a4 > #16 [881fff943dd0] print_cpu_stall_info at 810eb78c > #17 [881fff943e88] rcu_check_callbacks at 810ef133 > #18 [881fff943ee8] update_process_times at 810f3497 > #19 [881fff943f10] tick_sched_timer at 81103037 > #20 [881fff943f38] __hrtimer_run_queues at 810f3f38 > #21 [881fff943f88] hrtimer_interrupt at 810f442b You don't have a low-bandwidth console, do you? (For example, the output being directed to slow mass storage, across a slow network link, or the like.) > The CPU which triggered hardlockup: > > PID: 4149709 TASK: 88010f88c380 CPU: 26 COMMAND: "CPUThreadPool35" >#0 [883fff1059d0] machine_kexec at 8104a874 >#1 [883fff105a30] __crash_kexec at 86cc >#2 [883fff105af0] __crash_kexec at 8795 >#3 [883fff105b08] panic at 8119a6ae >#4 [883fff105b98] watchdog_overflow_callback at 81135dbd >#5 [883fff105bb0] __perf_event_overflow at 81186866 >#6 [883fff105be8] perf_event_overflow at 81192bc4 >#7 [883fff105bf8] intel_pmu_handle_irq at 8100b265 >#8 [883fff105df8] perf_event_nmi_handler at 8100489f >#9 [883fff105e58] nmi_handle at 81020653 > #10 [883fff105eb0] default_do_nmi at 81020b94 > #11 [883fff105ed0] do_nmi at 81020d32 > #12 [883fff105ef0] end_repeat_nmi at 81956a7e > [exception RIP: queued_spin_lock_slowpath+248] > RIP: 810da958 RSP: 883fff103e68 RFLAGS: 0046 > RAX: RBX: 0046 RCX: 006d > RDX: 883fff49a950 RSI: 00d10101 RDI: 81e54300 > RBP: 883fff103e80 R8: 883fff11a950 R9: > R10: 0e5873ba R11: 010f R12: 81e54300 > R13: R14: 88010f88c380 R15: 81e54300 > ORIG_RAX: CS: 0010 SS: 0018 > --- --- > #13 [883fff103e68] queued_spin_lock_slowpath at 810da958 > #14 [883fff103e70] _raw_spin_lock_irqsave at 8195550b > #15 [883fff103e88] rcu_check_callbacks at 810eed18 > #16 [883fff103ee8] update_process_times at 810f3497 > #17 [883fff103f10] tick_sched_timer at 81103037 > #18 [883fff103f38] __hrtimer_run_queues at 810f3f38 > #19 [883fff103f88] hrtimer_interrupt at 810f442b > --- --- > bt: read error: kernel virtual address: ffd8 type: "pt_regs" This might be unable to acquire the spinlock that CPU 13 was holding while printing to the console. > All other CPUs have something similar to the following: > > PID: 4150460 TASK: 88162c891b00 CPU: 8 COMMAND: "GlobalIOThreadP" >#0 [881fff805e48]
