Re: [PATCH rcu 02/12] rcu: Avoid tracing a few functions executed in stop machine

[Paul E. McKenney]

On Wed, Jun 22, 2022 at 05:20:35PM +0530, Neeraj Upadhyay wrote:
> 
> 
> On 6/22/2022 3:51 AM, Paul E. McKenney wrote:
> > On Tue, Jun 21, 2022 at 11:17:10AM +0530, Neeraj Upadhyay wrote:
> > > 
> > > 
> > > On 6/21/2022 3:50 AM, Paul E. McKenney wrote:
> > > > From: Patrick Wang <patrick.wang.shcn@xxxxxxxxx>
> > > > 
> > > > Stop-machine recently started calling additional functions while waiting:
> > > > 
> > > > ----------------------------------------------------------------
> > > > Former stop machine wait loop:
> > > > do {
> > > >       cpu_relax(); => macro
> > > >       ...
> > > > } while (curstate != STOPMACHINE_EXIT);
> > > > -----------------------------------------------------------------
> > > > Current stop machine wait loop:
> > > > do {
> > > >       stop_machine_yield(cpumask); => function (notraced)
> > > >       ...
> > > >       touch_nmi_watchdog(); => function (notraced, inside calls also notraced)
> > > >       ...
> > > >       rcu_momentary_dyntick_idle(); => function (notraced, inside calls traced)
> > > > } while (curstate != MULTI_STOP_EXIT);
> > > > ------------------------------------------------------------------
> > > > 
> > > > These functions (and the functions that they call) must be marked
> > > > notrace to prevent them from being updated while they are executing.
> > > > The consequences of failing to mark these functions can be severe:
> > > > 
> > > >     rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
> > > >     rcu: 	1-...!: (0 ticks this GP) idle=14f/1/0x4000000000000000 softirq=3397/3397 fqs=0
> > > >     rcu: 	3-...!: (0 ticks this GP) idle=ee9/1/0x4000000000000000 softirq=5168/5168 fqs=0
> > > >     	(detected by 0, t=8137 jiffies, g=5889, q=2 ncpus=4)
> > > >     Task dump for CPU 1:
> > > >     task:migration/1     state:R  running task     stack:    0 pid:   19 ppid:     2 flags:0x00000000
> > > >     Stopper: multi_cpu_stop+0x0/0x18c <- stop_machine_cpuslocked+0x128/0x174
> > > >     Call Trace:
> > > >     Task dump for CPU 3:
> > > >     task:migration/3     state:R  running task     stack:    0 pid:   29 ppid:     2 flags:0x00000000
> > > >     Stopper: multi_cpu_stop+0x0/0x18c <- stop_machine_cpuslocked+0x128/0x174
> > > >     Call Trace:
> > > >     rcu: rcu_preempt kthread timer wakeup didn't happen for 8136 jiffies! g5889 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402
> > > >     rcu: 	Possible timer handling issue on cpu=2 timer-softirq=594
> > > >     rcu: rcu_preempt kthread starved for 8137 jiffies! g5889 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402 ->cpu=2
> > > >     rcu: 	Unless rcu_preempt kthread gets sufficient CPU time, OOM is now expected behavior.
> > > >     rcu: RCU grace-period kthread stack dump:
> > > >     task:rcu_preempt     state:I stack:    0 pid:   14 ppid:     2 flags:0x00000000
> > > >     Call Trace:
> > > >       schedule+0x56/0xc2
> > > >       schedule_timeout+0x82/0x184
> > > >       rcu_gp_fqs_loop+0x19a/0x318
> > > >       rcu_gp_kthread+0x11a/0x140
> > > >       kthread+0xee/0x118
> > > >       ret_from_exception+0x0/0x14
> > > >     rcu: Stack dump where RCU GP kthread last ran:
> > > >     Task dump for CPU 2:
> > > >     task:migration/2     state:R  running task     stack:    0 pid:   24 ppid:     2 flags:0x00000000
> > > >     Stopper: multi_cpu_stop+0x0/0x18c <- stop_machine_cpuslocked+0x128/0x174
> > > >     Call Trace:
> > > > 
> > > > This commit therefore marks these functions notrace:
> > > >    rcu_preempt_deferred_qs()
> > > >    rcu_preempt_need_deferred_qs()
> > > >    rcu_preempt_deferred_qs_irqrestore()
> > > > 
> > > 
> > > Only the preemptible RCU definitions are updated; so, this change is not
> > > required for non-preemptible RCU case?
> > 
> > It appears to me to be required.  How about as shown below?
> > 
> 
> Looks good to me.

Thank you!  May I apply your Reviewed-by to both of these?  (1/12 and
2/12.)

							Thanx, Paul

> Thanks
> Neeraj
> 
> > 							Thanx, Paul
> > 
> > ------------------------------------------------------------------------
> > 
> > commit 06cfe0c675c93884c3ffc75ec24ece7d0acd7a32
> > Author: Patrick Wang <patrick.wang.shcn@xxxxxxxxx>
> > Date:   Tue Apr 26 18:45:02 2022 +0800
> > 
> >      rcu: Avoid tracing a few functions executed in stop machine
> >      Stop-machine recently started calling additional functions while waiting:
> >      ----------------------------------------------------------------
> >      Former stop machine wait loop:
> >      do {
> >          cpu_relax(); => macro
> >          ...
> >      } while (curstate != STOPMACHINE_EXIT);
> >      -----------------------------------------------------------------
> >      Current stop machine wait loop:
> >      do {
> >          stop_machine_yield(cpumask); => function (notraced)
> >          ...
> >          touch_nmi_watchdog(); => function (notraced, inside calls also notraced)
> >          ...
> >          rcu_momentary_dyntick_idle(); => function (notraced, inside calls traced)
> >      } while (curstate != MULTI_STOP_EXIT);
> >      ------------------------------------------------------------------
> >      These functions (and the functions that they call) must be marked
> >      notrace to prevent them from being updated while they are executing.
> >      The consequences of failing to mark these functions can be severe:
> >        rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
> >        rcu:  1-...!: (0 ticks this GP) idle=14f/1/0x4000000000000000 softirq=3397/3397 fqs=0
> >        rcu:  3-...!: (0 ticks this GP) idle=ee9/1/0x4000000000000000 softirq=5168/5168 fqs=0
> >              (detected by 0, t=8137 jiffies, g=5889, q=2 ncpus=4)
> >        Task dump for CPU 1:
> >        task:migration/1     state:R  running task     stack:    0 pid:   19 ppid:     2 flags:0x00000000
> >        Stopper: multi_cpu_stop+0x0/0x18c <- stop_machine_cpuslocked+0x128/0x174
> >        Call Trace:
> >        Task dump for CPU 3:
> >        task:migration/3     state:R  running task     stack:    0 pid:   29 ppid:     2 flags:0x00000000
> >        Stopper: multi_cpu_stop+0x0/0x18c <- stop_machine_cpuslocked+0x128/0x174
> >        Call Trace:
> >        rcu: rcu_preempt kthread timer wakeup didn't happen for 8136 jiffies! g5889 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402
> >        rcu:  Possible timer handling issue on cpu=2 timer-softirq=594
> >        rcu: rcu_preempt kthread starved for 8137 jiffies! g5889 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402 ->cpu=2
> >        rcu:  Unless rcu_preempt kthread gets sufficient CPU time, OOM is now expected behavior.
> >        rcu: RCU grace-period kthread stack dump:
> >        task:rcu_preempt     state:I stack:    0 pid:   14 ppid:     2 flags:0x00000000
> >        Call Trace:
> >          schedule+0x56/0xc2
> >          schedule_timeout+0x82/0x184
> >          rcu_gp_fqs_loop+0x19a/0x318
> >          rcu_gp_kthread+0x11a/0x140
> >          kthread+0xee/0x118
> >          ret_from_exception+0x0/0x14
> >        rcu: Stack dump where RCU GP kthread last ran:
> >        Task dump for CPU 2:
> >        task:migration/2     state:R  running task     stack:    0 pid:   24 ppid:     2 flags:0x00000000
> >        Stopper: multi_cpu_stop+0x0/0x18c <- stop_machine_cpuslocked+0x128/0x174
> >        Call Trace:
> >      This commit therefore marks these functions notrace:
> >       rcu_preempt_deferred_qs()
> >       rcu_preempt_need_deferred_qs()
> >       rcu_preempt_deferred_qs_irqrestore()
> >      [ paulmck: Apply feedback from Neeraj Upadhyay. ]
> >      Signed-off-by: Patrick Wang <patrick.wang.shcn@xxxxxxxxx>
> >      Acked-by: Steven Rostedt (Google) <rostedt@xxxxxxxxxxx>
> >      Signed-off-by: Paul E. McKenney <paulmck@xxxxxxxxxx>
> > 
> > diff --git a/kernel/rcu/tree_plugin.h b/kernel/rcu/tree_plugin.h
> > index c8ba0fe17267c..7a07f2ca153e2 100644
> > --- a/kernel/rcu/tree_plugin.h
> > +++ b/kernel/rcu/tree_plugin.h
> > @@ -460,7 +460,7 @@ static bool rcu_preempt_has_tasks(struct rcu_node *rnp)
> >    * be quite short, for example, in the case of the call from
> >    * rcu_read_unlock_special().
> >    */
> > -static void
> > +static notrace void
> >   rcu_preempt_deferred_qs_irqrestore(struct task_struct *t, unsigned long flags)
> >   {
> >   	bool empty_exp;
> > @@ -581,7 +581,7 @@ rcu_preempt_deferred_qs_irqrestore(struct task_struct *t, unsigned long flags)
> >    * is disabled.  This function cannot be expected to understand these
> >    * nuances, so the caller must handle them.
> >    */
> > -static bool rcu_preempt_need_deferred_qs(struct task_struct *t)
> > +static notrace bool rcu_preempt_need_deferred_qs(struct task_struct *t)
> >   {
> >   	return (__this_cpu_read(rcu_data.cpu_no_qs.b.exp) ||
> >   		READ_ONCE(t->rcu_read_unlock_special.s)) &&
> > @@ -595,7 +595,7 @@ static bool rcu_preempt_need_deferred_qs(struct task_struct *t)
> >    * evaluate safety in terms of interrupt, softirq, and preemption
> >    * disabling.
> >    */
> > -static void rcu_preempt_deferred_qs(struct task_struct *t)
> > +static notrace void rcu_preempt_deferred_qs(struct task_struct *t)
> >   {
> >   	unsigned long flags;
> > @@ -926,7 +926,7 @@ static bool rcu_preempt_has_tasks(struct rcu_node *rnp)
> >    * Because there is no preemptible RCU, there can be no deferred quiescent
> >    * states.
> >    */
> > -static bool rcu_preempt_need_deferred_qs(struct task_struct *t)
> > +static notrace bool rcu_preempt_need_deferred_qs(struct task_struct *t)
> >   {
> >   	return false;
> >   }
> > @@ -935,7 +935,7 @@ static bool rcu_preempt_need_deferred_qs(struct task_struct *t)
> >   // period for a quiescent state from this CPU.  Note that requests from
> >   // tasks are handled when removing the task from the blocked-tasks list
> >   // below.
> > -static void rcu_preempt_deferred_qs(struct task_struct *t)
> > +static notrace void rcu_preempt_deferred_qs(struct task_struct *t)
> >   {
> >   	struct rcu_data *rdp = this_cpu_ptr(&rcu_data);