[PATCH] team: add rescheduling jiffy delay on !rtnl_trylock

[PATCH] team: add rescheduling jiffy delay on !rtnl_trylock

[Joe Lawrence]

Hello Jiri,

I've been debugging a hang on RHEL7 that seems to originate in the
teaming driver and the team_notify_peers_work/team_mcast_rejoin_work
rtnl_trylock rescheduling logic.  Running a stand-alone minimal driver
mimicing the same schedule_delayed_work(.., 0) reproduces the problem on
RHEL7 and upstream kernels [1].

A quick summary of the hang:

1 - systemd-udevd issues an ioctl that heads down dev_ioctl (grabs the
    rtnl_mutex), dev_ifsioc, dev_change_name and finally
    synchronize_sched.  In every vmcore I've taken of the hang, this
    thread is waiting on the RCU.

2 - A kworker thread goes to 100% CPU.

3 - Inspecting the running thread on the CPU that rcusched reported as
    holding up the RCU grace period usually shows it in either
    team_notify_peers_work, team_mcast_rejoin_work, or somewhere in the
    workqueue code (process_one_work).  This is the same CPU/thread as
    #2.

4 - team_notify_peers_work and team_mcast_rejoin_work want the rtnl_lock
    that systemd-udevd in #1 has, so they try to play nice by calling
    rtnl_trylock and rescheduling on failure.  Unfortunately with 0
    jiffy delay, process_one_work will "execute immediately" (ie, after
    others already in queue, but before the next tick).  With the stock
    RHEL7 !CONFIG_PREEMPT at least, this creates a tight loop on
    process_one_work + rtnl_trylock that spins the CPU in #2.

5 - Sometime minutes later, RCU seems to be kicked by a side effect of
    a smp_apic_timer_interrupt.  (This was the only other interesting
    function reported by ftrace function tracer).

See the patch below for a potential workaround.  Giving at least 1 jiffy
should give process_one_work some breathing room before calling back
into team_notify_peers_work/team_mcast_rejoin_work and attempting to
acquire the rtnl_lock mutex.

Regards,

-- Joe

[1] http://marc.info/?l=linux-kernel&m=141192244232345&w=2

-->8--- -->8--- -->8--- -->8---

>From fc5bbf5771b5732f7479ac6e84bbfdde05710023 Mon Sep 17 00:00:00 2001
From: Joe Lawrence <joe.lawrence@stratus.com>
Date: Mon, 29 Sep 2014 11:09:05 -0400
Subject: [PATCH] team: add rescheduling jiffy delay on !rtnl_trylock

Give the CPU running the kworker handling team_notify_peers_work and
team_mcast_rejoin_work functions some scheduling air by specifying a
non-zero delay.

Signed-off-by: Joe Lawrence <joe.lawrence@stratus.com>
---
 drivers/net/team/team.c |    4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/drivers/net/team/team.c b/drivers/net/team/team.c
index ef10302..d46df38 100644
--- a/drivers/net/team/team.c
+++ b/drivers/net/team/team.c
@@ -633,7 +633,7 @@ static void team_notify_peers_work(struct work_struct *work)
 	team = container_of(work, struct team, notify_peers.dw.work);
 
 	if (!rtnl_trylock()) {
-		schedule_delayed_work(&team->notify_peers.dw, 0);
+		schedule_delayed_work(&team->notify_peers.dw, 1);
 		return;
 	}
 	call_netdevice_notifiers(NETDEV_NOTIFY_PEERS, team->dev);
@@ -673,7 +673,7 @@ static void team_mcast_rejoin_work(struct work_struct *work)
 	team = container_of(work, struct team, mcast_rejoin.dw.work);
 
 	if (!rtnl_trylock()) {
-		schedule_delayed_work(&team->mcast_rejoin.dw, 0);
+		schedule_delayed_work(&team->mcast_rejoin.dw, 1);
 		return;
 	}
 	call_netdevice_notifiers(NETDEV_RESEND_IGMP, team->dev);
-- 
1.7.10.4

Re: [PATCH] team: add rescheduling jiffy delay on !rtnl_trylock

[Tejun Heo]

(cc'ing Paul and quoting the whole body)

Paul, this is a fix for RCU sched stall observed w/ a work item
requeueing itself waiting for the RCU grace period.  As the self
requeueing work item ends up being executed by the same kworker, the
worker task never stops running in the absence of a higher priority
task and it seems to delay RCU grace period for a very long time on
!PREEMPT kernels.  As each work item denotes a boundary which no
synchronization construct stretches across, I wonder whether it'd be a
good idea to add a notification for the end of RCU critical section
between executions of work items.

Thanks.

On Mon, Sep 29, 2014 at 11:54:45AM -0400, Joe Lawrence wrote:
> Hello Jiri,
> 
> I've been debugging a hang on RHEL7 that seems to originate in the
> teaming driver and the team_notify_peers_work/team_mcast_rejoin_work
> rtnl_trylock rescheduling logic.  Running a stand-alone minimal driver
> mimicing the same schedule_delayed_work(.., 0) reproduces the problem on
> RHEL7 and upstream kernels [1].
> 
> A quick summary of the hang:
> 
> 1 - systemd-udevd issues an ioctl that heads down dev_ioctl (grabs the
>     rtnl_mutex), dev_ifsioc, dev_change_name and finally
>     synchronize_sched.  In every vmcore I've taken of the hang, this
>     thread is waiting on the RCU.
> 
> 2 - A kworker thread goes to 100% CPU.
> 
> 3 - Inspecting the running thread on the CPU that rcusched reported as
>     holding up the RCU grace period usually shows it in either
>     team_notify_peers_work, team_mcast_rejoin_work, or somewhere in the
>     workqueue code (process_one_work).  This is the same CPU/thread as
>     #2.
> 
> 4 - team_notify_peers_work and team_mcast_rejoin_work want the rtnl_lock
>     that systemd-udevd in #1 has, so they try to play nice by calling
>     rtnl_trylock and rescheduling on failure.  Unfortunately with 0
>     jiffy delay, process_one_work will "execute immediately" (ie, after
>     others already in queue, but before the next tick).  With the stock
>     RHEL7 !CONFIG_PREEMPT at least, this creates a tight loop on
>     process_one_work + rtnl_trylock that spins the CPU in #2.
> 
> 5 - Sometime minutes later, RCU seems to be kicked by a side effect of
>     a smp_apic_timer_interrupt.  (This was the only other interesting
>     function reported by ftrace function tracer).
> 
> See the patch below for a potential workaround.  Giving at least 1 jiffy
> should give process_one_work some breathing room before calling back
> into team_notify_peers_work/team_mcast_rejoin_work and attempting to
> acquire the rtnl_lock mutex.
> 
> Regards,
> 
> -- Joe
> 
> [1] http://marc.info/?l=linux-kernel&m=141192244232345&w=2
> 
> -->8--- -->8--- -->8--- -->8---
> 
> From fc5bbf5771b5732f7479ac6e84bbfdde05710023 Mon Sep 17 00:00:00 2001
> From: Joe Lawrence <joe.lawrence@stratus.com>
> Date: Mon, 29 Sep 2014 11:09:05 -0400
> Subject: [PATCH] team: add rescheduling jiffy delay on !rtnl_trylock
> 
> Give the CPU running the kworker handling team_notify_peers_work and
> team_mcast_rejoin_work functions some scheduling air by specifying a
> non-zero delay.
> 
> Signed-off-by: Joe Lawrence <joe.lawrence@stratus.com>
> ---
>  drivers/net/team/team.c |    4 ++--
>  1 file changed, 2 insertions(+), 2 deletions(-)
> 
> diff --git a/drivers/net/team/team.c b/drivers/net/team/team.c
> index ef10302..d46df38 100644
> --- a/drivers/net/team/team.c
> +++ b/drivers/net/team/team.c
> @@ -633,7 +633,7 @@ static void team_notify_peers_work(struct work_struct *work)
>  	team = container_of(work, struct team, notify_peers.dw.work);
>  
>  	if (!rtnl_trylock()) {
> -		schedule_delayed_work(&team->notify_peers.dw, 0);
> +		schedule_delayed_work(&team->notify_peers.dw, 1);
>  		return;
>  	}
>  	call_netdevice_notifiers(NETDEV_NOTIFY_PEERS, team->dev);
> @@ -673,7 +673,7 @@ static void team_mcast_rejoin_work(struct work_struct *work)
>  	team = container_of(work, struct team, mcast_rejoin.dw.work);
>  
>  	if (!rtnl_trylock()) {
> -		schedule_delayed_work(&team->mcast_rejoin.dw, 0);
> +		schedule_delayed_work(&team->mcast_rejoin.dw, 1);
>  		return;
>  	}
>  	call_netdevice_notifiers(NETDEV_RESEND_IGMP, team->dev);
> -- 
> 1.7.10.4
> 

-- 
tejun

Re: [PATCH] team: add rescheduling jiffy delay on !rtnl_trylock

[Paul E. McKenney]

On Mon, Sep 29, 2014 at 12:06:01PM -0400, Tejun Heo wrote:
> (cc'ing Paul and quoting the whole body)
> 
> Paul, this is a fix for RCU sched stall observed w/ a work item
> requeueing itself waiting for the RCU grace period.  As the self
> requeueing work item ends up being executed by the same kworker, the
> worker task never stops running in the absence of a higher priority
> task and it seems to delay RCU grace period for a very long time on
> !PREEMPT kernels.  As each work item denotes a boundary which no
> synchronization construct stretches across, I wonder whether it'd be a
> good idea to add a notification for the end of RCU critical section
> between executions of work items.

It sounds like a great idea to me!  I suggest invoking
rcu_note_context_switch() between executions of work items.

							Thanx, Paul

> Thanks.
> 
> On Mon, Sep 29, 2014 at 11:54:45AM -0400, Joe Lawrence wrote:
> > Hello Jiri,
> > 
> > I've been debugging a hang on RHEL7 that seems to originate in the
> > teaming driver and the team_notify_peers_work/team_mcast_rejoin_work
> > rtnl_trylock rescheduling logic.  Running a stand-alone minimal driver
> > mimicing the same schedule_delayed_work(.., 0) reproduces the problem on
> > RHEL7 and upstream kernels [1].
> > 
> > A quick summary of the hang:
> > 
> > 1 - systemd-udevd issues an ioctl that heads down dev_ioctl (grabs the
> >     rtnl_mutex), dev_ifsioc, dev_change_name and finally
> >     synchronize_sched.  In every vmcore I've taken of the hang, this
> >     thread is waiting on the RCU.
> > 
> > 2 - A kworker thread goes to 100% CPU.
> > 
> > 3 - Inspecting the running thread on the CPU that rcusched reported as
> >     holding up the RCU grace period usually shows it in either
> >     team_notify_peers_work, team_mcast_rejoin_work, or somewhere in the
> >     workqueue code (process_one_work).  This is the same CPU/thread as
> >     #2.
> > 
> > 4 - team_notify_peers_work and team_mcast_rejoin_work want the rtnl_lock
> >     that systemd-udevd in #1 has, so they try to play nice by calling
> >     rtnl_trylock and rescheduling on failure.  Unfortunately with 0
> >     jiffy delay, process_one_work will "execute immediately" (ie, after
> >     others already in queue, but before the next tick).  With the stock
> >     RHEL7 !CONFIG_PREEMPT at least, this creates a tight loop on
> >     process_one_work + rtnl_trylock that spins the CPU in #2.
> > 
> > 5 - Sometime minutes later, RCU seems to be kicked by a side effect of
> >     a smp_apic_timer_interrupt.  (This was the only other interesting
> >     function reported by ftrace function tracer).
> > 
> > See the patch below for a potential workaround.  Giving at least 1 jiffy
> > should give process_one_work some breathing room before calling back
> > into team_notify_peers_work/team_mcast_rejoin_work and attempting to
> > acquire the rtnl_lock mutex.
> > 
> > Regards,
> > 
> > -- Joe
> > 
> > [1] http://marc.info/?l=linux-kernel&m=141192244232345&w=2
> > 
> > -->8--- -->8--- -->8--- -->8---
> > 
> > From fc5bbf5771b5732f7479ac6e84bbfdde05710023 Mon Sep 17 00:00:00 2001
> > From: Joe Lawrence <joe.lawrence@stratus.com>
> > Date: Mon, 29 Sep 2014 11:09:05 -0400
> > Subject: [PATCH] team: add rescheduling jiffy delay on !rtnl_trylock
> > 
> > Give the CPU running the kworker handling team_notify_peers_work and
> > team_mcast_rejoin_work functions some scheduling air by specifying a
> > non-zero delay.
> > 
> > Signed-off-by: Joe Lawrence <joe.lawrence@stratus.com>
> > ---
> >  drivers/net/team/team.c |    4 ++--
> >  1 file changed, 2 insertions(+), 2 deletions(-)
> > 
> > diff --git a/drivers/net/team/team.c b/drivers/net/team/team.c
> > index ef10302..d46df38 100644
> > --- a/drivers/net/team/team.c
> > +++ b/drivers/net/team/team.c
> > @@ -633,7 +633,7 @@ static void team_notify_peers_work(struct work_struct *work)
> >  	team = container_of(work, struct team, notify_peers.dw.work);
> >  
> >  	if (!rtnl_trylock()) {
> > -		schedule_delayed_work(&team->notify_peers.dw, 0);
> > +		schedule_delayed_work(&team->notify_peers.dw, 1);
> >  		return;
> >  	}
> >  	call_netdevice_notifiers(NETDEV_NOTIFY_PEERS, team->dev);
> > @@ -673,7 +673,7 @@ static void team_mcast_rejoin_work(struct work_struct *work)
> >  	team = container_of(work, struct team, mcast_rejoin.dw.work);
> >  
> >  	if (!rtnl_trylock()) {
> > -		schedule_delayed_work(&team->mcast_rejoin.dw, 0);
> > +		schedule_delayed_work(&team->mcast_rejoin.dw, 1);
> >  		return;
> >  	}
> >  	call_netdevice_notifiers(NETDEV_RESEND_IGMP, team->dev);
> > -- 
> > 1.7.10.4
> > 
> 
> -- 
> tejun
> 

Re: [PATCH] team: add rescheduling jiffy delay on !rtnl_trylock

[Joe Lawrence]

On Wed, 1 Oct 2014 23:43:08 -0700
"Paul E. McKenney" <paulmck@linux.vnet.ibm.com> wrote:

> On Mon, Sep 29, 2014 at 12:06:01PM -0400, Tejun Heo wrote:
> > (cc'ing Paul and quoting the whole body)
> > 
> > Paul, this is a fix for RCU sched stall observed w/ a work item
> > requeueing itself waiting for the RCU grace period.  As the self
> > requeueing work item ends up being executed by the same kworker, the
> > worker task never stops running in the absence of a higher priority
> > task and it seems to delay RCU grace period for a very long time on
> > !PREEMPT kernels.  As each work item denotes a boundary which no
> > synchronization construct stretches across, I wonder whether it'd be a
> > good idea to add a notification for the end of RCU critical section
> > between executions of work items.
> 
> It sounds like a great idea to me!  I suggest invoking
> rcu_note_context_switch() between executions of work items.
> 
> 							Thanx, Paul

I gave this a spin, probably inserting the call in the wrong place:

diff --git a/kernel/workqueue.c b/kernel/workqueue.c
index 5dbe22a..77f128e 100644
--- a/kernel/workqueue.c
+++ b/kernel/workqueue.c
@@ -2045,7 +2045,8 @@ __acquires(&pool->lock)
         * indefinitely requeue itself while all other CPUs are trapped in
         * stop_machine.
         */
-       cond_resched();
+       if (!cond_resched())
+               rcu_note_context_switch(raw_smp_processor_id());
 
        spin_lock_irq(&pool->lock);

this results in RCU grace periods progressing (dyntick remains
fixed) as advertised, even with the test-module from [1] loaded:

Fri Oct  3 14:37:14 2014
  4 c=9635 g=9636 pq=1 qp=0 dt=51693/140000000000000/0 df=163 of=0 ql=0/1 qs=...D b=10 ci=0 nci=34184 co=0 ca=0

Fri Oct  3 14:50:24 2014
  4 c=13072 g=13073 pq=1 qp=0 dt=51693/140000000000000/0 df=163 of=0 ql=0/1 qs=...D b=10 ci=0 nci=34191 co=0 ca=0

I'll leave it up to Tejun to determine where/how that call should be
made.

Thanks!

-- Joe

[1] http://marc.info/?l=linux-kernel&m=141192244232345

Re: [PATCH] team: add rescheduling jiffy delay on !rtnl_trylock

[Paul E. McKenney]

On Fri, Oct 03, 2014 at 03:37:01PM -0400, Joe Lawrence wrote:
> On Wed, 1 Oct 2014 23:43:08 -0700
> "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> wrote:
> 
> > On Mon, Sep 29, 2014 at 12:06:01PM -0400, Tejun Heo wrote:
> > > (cc'ing Paul and quoting the whole body)
> > > 
> > > Paul, this is a fix for RCU sched stall observed w/ a work item
> > > requeueing itself waiting for the RCU grace period.  As the self
> > > requeueing work item ends up being executed by the same kworker, the
> > > worker task never stops running in the absence of a higher priority
> > > task and it seems to delay RCU grace period for a very long time on
> > > !PREEMPT kernels.  As each work item denotes a boundary which no
> > > synchronization construct stretches across, I wonder whether it'd be a
> > > good idea to add a notification for the end of RCU critical section
> > > between executions of work items.
> > 
> > It sounds like a great idea to me!  I suggest invoking
> > rcu_note_context_switch() between executions of work items.
> > 
> > 							Thanx, Paul
> 
> I gave this a spin, probably inserting the call in the wrong place:
> 
> diff --git a/kernel/workqueue.c b/kernel/workqueue.c
> index 5dbe22a..77f128e 100644
> --- a/kernel/workqueue.c
> +++ b/kernel/workqueue.c
> @@ -2045,7 +2045,8 @@ __acquires(&pool->lock)
>          * indefinitely requeue itself while all other CPUs are trapped in
>          * stop_machine.
>          */
> -       cond_resched();
> +       if (!cond_resched())
> +               rcu_note_context_switch(raw_smp_processor_id());
> 
>         spin_lock_irq(&pool->lock);

If the cond_resched() is in the right place, then you should be good.

FWIW, there is a cond_resched_rcu_qs() that should be going into the next
merge window that could be used in place of the above two lines.  This is
commit bde6c3aa9930 in -tip.

> this results in RCU grace periods progressing (dyntick remains
> fixed) as advertised, even with the test-module from [1] loaded:
> 
> Fri Oct  3 14:37:14 2014
>   4 c=9635 g=9636 pq=1 qp=0 dt=51693/140000000000000/0 df=163 of=0 ql=0/1 qs=...D b=10 ci=0 nci=34184 co=0 ca=0
> 
> Fri Oct  3 14:50:24 2014
>   4 c=13072 g=13073 pq=1 qp=0 dt=51693/140000000000000/0 df=163 of=0 ql=0/1 qs=...D b=10 ci=0 nci=34191 co=0 ca=0

Nice!

							Thanx, Paul

> I'll leave it up to Tejun to determine where/how that call should be
> made.
> 
> Thanks!
> 
> -- Joe
> 
> [1] http://marc.info/?l=linux-kernel&m=141192244232345
> 

Re: [PATCH] team: add rescheduling jiffy delay on !rtnl_trylock

[Tejun Heo]

Hello,

On Sat, Oct 04, 2014 at 01:37:32AM -0700, Paul E. McKenney wrote:
> On Fri, Oct 03, 2014 at 03:37:01PM -0400, Joe Lawrence wrote:
> > I gave this a spin, probably inserting the call in the wrong place:
> > 
> > diff --git a/kernel/workqueue.c b/kernel/workqueue.c
> > index 5dbe22a..77f128e 100644
> > --- a/kernel/workqueue.c
> > +++ b/kernel/workqueue.c
> > @@ -2045,7 +2045,8 @@ __acquires(&pool->lock)
> >          * indefinitely requeue itself while all other CPUs are trapped in
> >          * stop_machine.
> >          */
> > -       cond_resched();
> > +       if (!cond_resched())
> > +               rcu_note_context_switch(raw_smp_processor_id());
> > 
> >         spin_lock_irq(&pool->lock);
> 
> If the cond_resched() is in the right place, then you should be good.

Yeah, it looks good to me.

> FWIW, there is a cond_resched_rcu_qs() that should be going into the next
> merge window that could be used in place of the above two lines.  This is
> commit bde6c3aa9930 in -tip.

That sounds even better.

Joe, can you please send a patch with proper SOB and description?

Thanks.

-- 
tejun

Re: [PATCH] team: add rescheduling jiffy delay on !rtnl_trylock

[Joe Lawrence]

On 10/04/2014 10:13 PM, Tejun Heo wrote:
> Hello,
> 
> On Sat, Oct 04, 2014 at 01:37:32AM -0700, Paul E. McKenney wrote:
>> FWIW, there is a cond_resched_rcu_qs() that should be going into the next
>> merge window that could be used in place of the above two lines.  This is
>> commit bde6c3aa9930 in -tip.
> 
> That sounds even better.
> 
> Joe, can you please send a patch with proper SOB and description?
> 
> Thanks.

New patch tested and posted on lkml w/everyone CC'd.

I wasn't sure if cond_resched_rcu_qs will be backported, so how should
-stable handle this condition?

Regards,

-- Joe

Re: [PATCH] team: add rescheduling jiffy delay on !rtnl_trylock

[Paul E. McKenney]

On Sun, Oct 05, 2014 at 08:53:08AM -0400, Joe Lawrence wrote:
> On 10/04/2014 10:13 PM, Tejun Heo wrote:
> > Hello,
> > 
> > On Sat, Oct 04, 2014 at 01:37:32AM -0700, Paul E. McKenney wrote:
> >> FWIW, there is a cond_resched_rcu_qs() that should be going into the next
> >> merge window that could be used in place of the above two lines.  This is
> >> commit bde6c3aa9930 in -tip.
> > 
> > That sounds even better.
> > 
> > Joe, can you please send a patch with proper SOB and description?
> > 
> > Thanks.
> 
> New patch tested and posted on lkml w/everyone CC'd.
> 
> I wasn't sure if cond_resched_rcu_qs will be backported, so how should
> -stable handle this condition?

If it is needed to backport a fix, it can of course be backported.
The various -stable maintainers also have the option of avoiding
the need for a backport by expanding it inline.  I am happy to let
them choose.  ;-)

							Thanx, Paul

Re: [PATCH] team: add rescheduling jiffy delay on !rtnl_trylock

[Tejun Heo]

Hello, Paul, Joe.

On Sun, Oct 05, 2014 at 07:08:55AM -0700, Paul E. McKenney wrote:
> > I wasn't sure if cond_resched_rcu_qs will be backported, so how should
> > -stable handle this condition?
> 
> If it is needed to backport a fix, it can of course be backported.
> The various -stable maintainers also have the option of avoiding
> the need for a backport by expanding it inline.  I am happy to let
> them choose.  ;-)

Let's go for separate cond_resched + rcu_qs calls first and then apply
a separate patch to use cond_resched_rcu_qs() so that the first one
can be marked for -stable.

Thanks.

-- 
tejun