[PATCH] rcu: ftrace: avoid tracing a few functions executed in multi_cpu_stop()

[PATCH] rcu: ftrace: avoid tracing a few functions executed in multi_cpu_stop()

[Patrick Wang]

A few functions are in the call chain of rcu_momentary_dyntick_idle()
which is executed in multi_cpu_stop() and marked notrace. They are running
in traced when ftrace modify code. This may cause non-ftrace_modify_code
CPUs stall:

[   72.686113] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
[   72.687344] rcu: 	1-...!: (0 ticks this GP) idle=14f/1/0x4000000000000000 softirq=3397/3397 fqs=0
[   72.687800] rcu: 	3-...!: (0 ticks this GP) idle=ee9/1/0x4000000000000000 softirq=5168/5168 fqs=0
[   72.688280] 	(detected by 0, t=8137 jiffies, g=5889, q=2 ncpus=4)
[   72.688739] Task dump for CPU 1:
[   72.688991] task:migration/1     state:R  running task     stack:    0 pid:   19 ppid:     2 flags:0x00000000
[   72.689594] Stopper: multi_cpu_stop+0x0/0x18c <- stop_machine_cpuslocked+0x128/0x174
[   72.690242] Call Trace:
[   72.690603] Task dump for CPU 3:
[   72.690761] task:migration/3     state:R  running task     stack:    0 pid:   29 ppid:     2 flags:0x00000000
[   72.691135] Stopper: multi_cpu_stop+0x0/0x18c <- stop_machine_cpuslocked+0x128/0x174
[   72.691474] Call Trace:
[   72.691733] rcu: rcu_preempt kthread timer wakeup didn't happen for 8136 jiffies! g5889 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402
[   72.692180] rcu: 	Possible timer handling issue on cpu=2 timer-softirq=594
[   72.692485] rcu: rcu_preempt kthread starved for 8137 jiffies! g5889 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402 ->cpu=2
[   72.692876] rcu: 	Unless rcu_preempt kthread gets sufficient CPU time, OOM is now expected behavior.
[   72.693232] rcu: RCU grace-period kthread stack dump:
[   72.693433] task:rcu_preempt     state:I stack:    0 pid:   14 ppid:     2 flags:0x00000000
[   72.693788] Call Trace:
[   72.694018] [<ffffffff807f3740>] schedule+0x56/0xc2
[   72.694306] [<ffffffff807f9cd8>] schedule_timeout+0x82/0x184
[   72.694539] [<ffffffff8007c456>] rcu_gp_fqs_loop+0x19a/0x318
[   72.694809] [<ffffffff8007e408>] rcu_gp_kthread+0x11a/0x140
[   72.695325] [<ffffffff800324d6>] kthread+0xee/0x118
[   72.695657] [<ffffffff8000398a>] ret_from_exception+0x0/0x14
[   72.696089] rcu: Stack dump where RCU GP kthread last ran:
[   72.696383] Task dump for CPU 2:
[   72.696562] task:migration/2     state:R  running task     stack:    0 pid:   24 ppid:     2 flags:0x00000000
[   72.697059] Stopper: multi_cpu_stop+0x0/0x18c <- stop_machine_cpuslocked+0x128/0x174
[   72.697471] Call Trace:

Mark rcu_preempt_deferred_qs(), rcu_preempt_need_deferred_qs() and
rcu_preempt_deferred_qs_irqrestore() notrace to avoid this.

Signed-off-by: Patrick Wang <patrick.wang.shcn@gmail.com>
---
 kernel/rcu/tree_plugin.h | 6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

diff --git a/kernel/rcu/tree_plugin.h b/kernel/rcu/tree_plugin.h
index c3d212bc5338..07b3e656aedd 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
+notrace static 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)
+notrace static 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)
+notrace static void rcu_preempt_deferred_qs(struct task_struct *t)
 {
 	unsigned long flags;
 
-- 
2.25.1

Re: [PATCH] rcu: ftrace: avoid tracing a few functions executed in multi_cpu_stop()

[Paul E. McKenney]

On Mon, Apr 18, 2022 at 12:37:35PM +0800, Patrick Wang wrote:
> A few functions are in the call chain of rcu_momentary_dyntick_idle()
> which is executed in multi_cpu_stop() and marked notrace. They are running
> in traced when ftrace modify code. This may cause non-ftrace_modify_code
> CPUs stall:
> 
> [   72.686113] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
> [   72.687344] rcu: 	1-...!: (0 ticks this GP) idle=14f/1/0x4000000000000000 softirq=3397/3397 fqs=0
> [   72.687800] rcu: 	3-...!: (0 ticks this GP) idle=ee9/1/0x4000000000000000 softirq=5168/5168 fqs=0
> [   72.688280] 	(detected by 0, t=8137 jiffies, g=5889, q=2 ncpus=4)
> [   72.688739] Task dump for CPU 1:
> [   72.688991] task:migration/1     state:R  running task     stack:    0 pid:   19 ppid:     2 flags:0x00000000
> [   72.689594] Stopper: multi_cpu_stop+0x0/0x18c <- stop_machine_cpuslocked+0x128/0x174
> [   72.690242] Call Trace:
> [   72.690603] Task dump for CPU 3:
> [   72.690761] task:migration/3     state:R  running task     stack:    0 pid:   29 ppid:     2 flags:0x00000000
> [   72.691135] Stopper: multi_cpu_stop+0x0/0x18c <- stop_machine_cpuslocked+0x128/0x174
> [   72.691474] Call Trace:
> [   72.691733] rcu: rcu_preempt kthread timer wakeup didn't happen for 8136 jiffies! g5889 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402
> [   72.692180] rcu: 	Possible timer handling issue on cpu=2 timer-softirq=594
> [   72.692485] rcu: rcu_preempt kthread starved for 8137 jiffies! g5889 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402 ->cpu=2
> [   72.692876] rcu: 	Unless rcu_preempt kthread gets sufficient CPU time, OOM is now expected behavior.
> [   72.693232] rcu: RCU grace-period kthread stack dump:
> [   72.693433] task:rcu_preempt     state:I stack:    0 pid:   14 ppid:     2 flags:0x00000000
> [   72.693788] Call Trace:
> [   72.694018] [<ffffffff807f3740>] schedule+0x56/0xc2
> [   72.694306] [<ffffffff807f9cd8>] schedule_timeout+0x82/0x184
> [   72.694539] [<ffffffff8007c456>] rcu_gp_fqs_loop+0x19a/0x318
> [   72.694809] [<ffffffff8007e408>] rcu_gp_kthread+0x11a/0x140
> [   72.695325] [<ffffffff800324d6>] kthread+0xee/0x118
> [   72.695657] [<ffffffff8000398a>] ret_from_exception+0x0/0x14
> [   72.696089] rcu: Stack dump where RCU GP kthread last ran:
> [   72.696383] Task dump for CPU 2:
> [   72.696562] task:migration/2     state:R  running task     stack:    0 pid:   24 ppid:     2 flags:0x00000000
> [   72.697059] Stopper: multi_cpu_stop+0x0/0x18c <- stop_machine_cpuslocked+0x128/0x174
> [   72.697471] Call Trace:
> 
> Mark rcu_preempt_deferred_qs(), rcu_preempt_need_deferred_qs() and
> rcu_preempt_deferred_qs_irqrestore() notrace to avoid this.
> 
> Signed-off-by: Patrick Wang <patrick.wang.shcn@gmail.com>

Good catch!

I have queued this for testing and further review.  I am especially
interested in the tracing guys' take on this.

							Thanx, Paul

> ---
>  kernel/rcu/tree_plugin.h | 6 +++---
>  1 file changed, 3 insertions(+), 3 deletions(-)
> 
> diff --git a/kernel/rcu/tree_plugin.h b/kernel/rcu/tree_plugin.h
> index c3d212bc5338..07b3e656aedd 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
> +notrace static 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)
> +notrace static 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)
> +notrace static void rcu_preempt_deferred_qs(struct task_struct *t)
>  {
>  	unsigned long flags;
>  
> -- 
> 2.25.1
> 

Re: [PATCH] rcu: ftrace: avoid tracing a few functions executed in multi_cpu_stop()

[Steven Rostedt]

On Mon, 18 Apr 2022 12:37:35 +0800
Patrick Wang <patrick.wang.shcn@gmail.com> wrote:

> A few functions are in the call chain of rcu_momentary_dyntick_idle()
> which is executed in multi_cpu_stop() and marked notrace. They are running
> in traced when ftrace modify code. This may cause non-ftrace_modify_code
> CPUs stall:

I'm confused by this. How is traced functions causing this exactly? Is this
on RISC-V?

> 
> [   72.686113] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
> [   72.687344] rcu: 	1-...!: (0 ticks this GP) idle=14f/1/0x4000000000000000 softirq=3397/3397 fqs=0
> [   72.687800] rcu: 	3-...!: (0 ticks this GP) idle=ee9/1/0x4000000000000000 softirq=5168/5168 fqs=0
> [   72.688280] 	(detected by 0, t=8137 jiffies, g=5889, q=2 ncpus=4)
> [   72.688739] Task dump for CPU 1:
> [   72.688991] task:migration/1     state:R  running task     stack:    0 pid:   19 ppid:     2 flags:0x00000000
> [   72.689594] Stopper: multi_cpu_stop+0x0/0x18c <- stop_machine_cpuslocked+0x128/0x174
> [   72.690242] Call Trace:
> [   72.690603] Task dump for CPU 3:
> [   72.690761] task:migration/3     state:R  running task     stack:    0 pid:   29 ppid:     2 flags:0x00000000
> [   72.691135] Stopper: multi_cpu_stop+0x0/0x18c <- stop_machine_cpuslocked+0x128/0x174
> [   72.691474] Call Trace:
> [   72.691733] rcu: rcu_preempt kthread timer wakeup didn't happen for 8136 jiffies! g5889 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402
> [   72.692180] rcu: 	Possible timer handling issue on cpu=2 timer-softirq=594
> [   72.692485] rcu: rcu_preempt kthread starved for 8137 jiffies! g5889 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402 ->cpu=2
> [   72.692876] rcu: 	Unless rcu_preempt kthread gets sufficient CPU time, OOM is now expected behavior.
> [   72.693232] rcu: RCU grace-period kthread stack dump:
> [   72.693433] task:rcu_preempt     state:I stack:    0 pid:   14 ppid:     2 flags:0x00000000
> [   72.693788] Call Trace:
> [   72.694018] [<ffffffff807f3740>] schedule+0x56/0xc2
> [   72.694306] [<ffffffff807f9cd8>] schedule_timeout+0x82/0x184
> [   72.694539] [<ffffffff8007c456>] rcu_gp_fqs_loop+0x19a/0x318
> [   72.694809] [<ffffffff8007e408>] rcu_gp_kthread+0x11a/0x140
> [   72.695325] [<ffffffff800324d6>] kthread+0xee/0x118
> [   72.695657] [<ffffffff8000398a>] ret_from_exception+0x0/0x14
> [   72.696089] rcu: Stack dump where RCU GP kthread last ran:
> [   72.696383] Task dump for CPU 2:
> [   72.696562] task:migration/2     state:R  running task     stack:    0 pid:   24 ppid:     2 flags:0x00000000
> [   72.697059] Stopper: multi_cpu_stop+0x0/0x18c <- stop_machine_cpuslocked+0x128/0x174
> [   72.697471] Call Trace:
> 
> Mark rcu_preempt_deferred_qs(), rcu_preempt_need_deferred_qs() and
> rcu_preempt_deferred_qs_irqrestore() notrace to avoid this.
> 

The rcu_momentary_dyntick_idle() was marked notrace because of RISC-V not
being able to call functions from within stop machine. If that's what is
being prevented, then I'm fine with this (although I'm thinking we need
different kinds of "notrace" for different architectures as one arch's
limitation should not be cause for another's).

But before I ack this patch, I want to understand the real issues here.

-- Steve

Re: [PATCH] rcu: ftrace: avoid tracing a few functions executed in multi_cpu_stop()

[patrick wang]

On Tue, Apr 19, 2022 at 2:34 AM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Mon, 18 Apr 2022 12:37:35 +0800
> Patrick Wang <patrick.wang.shcn@gmail.com> wrote:
>
> > A few functions are in the call chain of rcu_momentary_dyntick_idle()
> > which is executed in multi_cpu_stop() and marked notrace. They are running
> > in traced when ftrace modify code. This may cause non-ftrace_modify_code
> > CPUs stall:
>
> I'm confused by this. How is traced functions causing this exactly? Is this
> on RISC-V?

During ftrace modify code, these functions are running and their
instructions will
be modified by ftrace (I see the nop instructions in these functions
from the compiler).
When instructions are being modified, they shouldn't be executed. Or
the executor
may behave unpredictably.

Yes, it is on RISC-V.

>
> >
> > [   72.686113] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
> > [   72.687344] rcu:   1-...!: (0 ticks this GP) idle=14f/1/0x4000000000000000 softirq=3397/3397 fqs=0
> > [   72.687800] rcu:   3-...!: (0 ticks this GP) idle=ee9/1/0x4000000000000000 softirq=5168/5168 fqs=0
> > [   72.688280]        (detected by 0, t=8137 jiffies, g=5889, q=2 ncpus=4)
> > [   72.688739] Task dump for CPU 1:
> > [   72.688991] task:migration/1     state:R  running task     stack:    0 pid:   19 ppid:     2 flags:0x00000000
> > [   72.689594] Stopper: multi_cpu_stop+0x0/0x18c <- stop_machine_cpuslocked+0x128/0x174
> > [   72.690242] Call Trace:
> > [   72.690603] Task dump for CPU 3:
> > [   72.690761] task:migration/3     state:R  running task     stack:    0 pid:   29 ppid:     2 flags:0x00000000
> > [   72.691135] Stopper: multi_cpu_stop+0x0/0x18c <- stop_machine_cpuslocked+0x128/0x174
> > [   72.691474] Call Trace:
> > [   72.691733] rcu: rcu_preempt kthread timer wakeup didn't happen for 8136 jiffies! g5889 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402
> > [   72.692180] rcu:   Possible timer handling issue on cpu=2 timer-softirq=594
> > [   72.692485] rcu: rcu_preempt kthread starved for 8137 jiffies! g5889 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402 ->cpu=2
> > [   72.692876] rcu:   Unless rcu_preempt kthread gets sufficient CPU time, OOM is now expected behavior.
> > [   72.693232] rcu: RCU grace-period kthread stack dump:
> > [   72.693433] task:rcu_preempt     state:I stack:    0 pid:   14 ppid:     2 flags:0x00000000
> > [   72.693788] Call Trace:
> > [   72.694018] [<ffffffff807f3740>] schedule+0x56/0xc2
> > [   72.694306] [<ffffffff807f9cd8>] schedule_timeout+0x82/0x184
> > [   72.694539] [<ffffffff8007c456>] rcu_gp_fqs_loop+0x19a/0x318
> > [   72.694809] [<ffffffff8007e408>] rcu_gp_kthread+0x11a/0x140
> > [   72.695325] [<ffffffff800324d6>] kthread+0xee/0x118
> > [   72.695657] [<ffffffff8000398a>] ret_from_exception+0x0/0x14
> > [   72.696089] rcu: Stack dump where RCU GP kthread last ran:
> > [   72.696383] Task dump for CPU 2:
> > [   72.696562] task:migration/2     state:R  running task     stack:    0 pid:   24 ppid:     2 flags:0x00000000
> > [   72.697059] Stopper: multi_cpu_stop+0x0/0x18c <- stop_machine_cpuslocked+0x128/0x174
> > [   72.697471] Call Trace:
> >
> > Mark rcu_preempt_deferred_qs(), rcu_preempt_need_deferred_qs() and
> > rcu_preempt_deferred_qs_irqrestore() notrace to avoid this.
> >
>
> The rcu_momentary_dyntick_idle() was marked notrace because of RISC-V not
> being able to call functions from within stop machine. If that's what is
> being prevented,

Yes, that is.

> then I'm fine with this (although I'm thinking we need
> different kinds of "notrace" for different architectures as one arch's
> limitation should not be cause for another's).
>

Totally agree with this. The "notrace" currently is heavy, can effect all archs.

Thanks
Patrick


> But before I ack this patch, I want to understand the real issues here.
>
> -- Steve

Re: [PATCH] rcu: ftrace: avoid tracing a few functions executed in multi_cpu_stop()

[patrick wang]

On Tue, Apr 19, 2022 at 12:06 PM patrick wang
<patrick.wang.shcn@gmail.com> wrote:
>
> On Tue, Apr 19, 2022 at 2:34 AM Steven Rostedt <rostedt@goodmis.org> wrote:
> >
> > On Mon, 18 Apr 2022 12:37:35 +0800
> > Patrick Wang <patrick.wang.shcn@gmail.com> wrote:
> >
> > > A few functions are in the call chain of rcu_momentary_dyntick_idle()
> > > which is executed in multi_cpu_stop() and marked notrace. They are running
> > > in traced when ftrace modify code. This may cause non-ftrace_modify_code
> > > CPUs stall:
> >
> > I'm confused by this. How is traced functions causing this exactly? Is this
> > on RISC-V?
>
> During ftrace modify code, these functions are running and their
> instructions will
> be modified by ftrace (I see the nop instructions in these functions
> from the compiler).
> When instructions are being modified, they shouldn't be executed. Or
> the executor
> may behave unpredictably.
>

Sorry for the format. Need get used to gmail.

These functions are running within stop machine and ftrace modify
code by using stop machine to ensure the safety on some
architectures(e.g. RISC-V). These functions' instructions will be
modified during ftrace modifying code. When instructions are being
modified, they shouldn't be executed typically. Or the executor
may behave unpredictably.

>
> >
> > >
> > > [   72.686113] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
> > > [   72.687344] rcu:   1-...!: (0 ticks this GP) idle=14f/1/0x4000000000000000 softirq=3397/3397 fqs=0
> > > [   72.687800] rcu:   3-...!: (0 ticks this GP) idle=ee9/1/0x4000000000000000 softirq=5168/5168 fqs=0
> > > [   72.688280]        (detected by 0, t=8137 jiffies, g=5889, q=2 ncpus=4)
> > > [   72.688739] Task dump for CPU 1:
> > > [   72.688991] task:migration/1     state:R  running task     stack:    0 pid:   19 ppid:     2 flags:0x00000000
> > > [   72.689594] Stopper: multi_cpu_stop+0x0/0x18c <- stop_machine_cpuslocked+0x128/0x174
> > > [   72.690242] Call Trace:
> > > [   72.690603] Task dump for CPU 3:
> > > [   72.690761] task:migration/3     state:R  running task     stack:    0 pid:   29 ppid:     2 flags:0x00000000
> > > [   72.691135] Stopper: multi_cpu_stop+0x0/0x18c <- stop_machine_cpuslocked+0x128/0x174
> > > [   72.691474] Call Trace:
> > > [   72.691733] rcu: rcu_preempt kthread timer wakeup didn't happen for 8136 jiffies! g5889 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402
> > > [   72.692180] rcu:   Possible timer handling issue on cpu=2 timer-softirq=594
> > > [   72.692485] rcu: rcu_preempt kthread starved for 8137 jiffies! g5889 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402 ->cpu=2
> > > [   72.692876] rcu:   Unless rcu_preempt kthread gets sufficient CPU time, OOM is now expected behavior.
> > > [   72.693232] rcu: RCU grace-period kthread stack dump:
> > > [   72.693433] task:rcu_preempt     state:I stack:    0 pid:   14 ppid:     2 flags:0x00000000
> > > [   72.693788] Call Trace:
> > > [   72.694018] [<ffffffff807f3740>] schedule+0x56/0xc2
> > > [   72.694306] [<ffffffff807f9cd8>] schedule_timeout+0x82/0x184
> > > [   72.694539] [<ffffffff8007c456>] rcu_gp_fqs_loop+0x19a/0x318
> > > [   72.694809] [<ffffffff8007e408>] rcu_gp_kthread+0x11a/0x140
> > > [   72.695325] [<ffffffff800324d6>] kthread+0xee/0x118
> > > [   72.695657] [<ffffffff8000398a>] ret_from_exception+0x0/0x14
> > > [   72.696089] rcu: Stack dump where RCU GP kthread last ran:
> > > [   72.696383] Task dump for CPU 2:
> > > [   72.696562] task:migration/2     state:R  running task     stack:    0 pid:   24 ppid:     2 flags:0x00000000
> > > [   72.697059] Stopper: multi_cpu_stop+0x0/0x18c <- stop_machine_cpuslocked+0x128/0x174
> > > [   72.697471] Call Trace:
> > >
> > > Mark rcu_preempt_deferred_qs(), rcu_preempt_need_deferred_qs() and
> > > rcu_preempt_deferred_qs_irqrestore() notrace to avoid this.
> > >
> >
> > The rcu_momentary_dyntick_idle() was marked notrace because of RISC-V not
> > being able to call functions from within stop machine. If that's what is
> > being prevented,
>

Yes, that is. Commit 4230e2deaa48 (stop_machine, rcu: Mark
functions as notrace) marked rcu_momentary_dyntick_idle() notrace.
But this issue still exists to some extent.

Thanks,
Patrick

>
> > then I'm fine with this (although I'm thinking we need
> > different kinds of "notrace" for different architectures as one arch's
> > limitation should not be cause for another's).
> >
>
> Totally agree with this. The "notrace" currently is heavy, can effect all archs.
>
> Thanks
> Patrick
>
>
> > But before I ack this patch, I want to understand the real issues here.
> >
> > -- Steve

Re: [PATCH] rcu: ftrace: avoid tracing a few functions executed in multi_cpu_stop()

[Steven Rostedt]

On Wed, 20 Apr 2022 18:34:34 +0800
patrick wang <patrick.wang.shcn@gmail.com> wrote:

[ I had a power outage yesterday, just catching up now ]

> Sorry for the format. Need get used to gmail.
> 
> These functions are running within stop machine and ftrace modify
> code by using stop machine to ensure the safety on some
> architectures(e.g. RISC-V). These functions' instructions will be
> modified during ftrace modifying code. When instructions are being
> modified, they shouldn't be executed typically. Or the executor
> may behave unpredictably.

Interesting. On x86 when we used stop machine[*] it was not an issue to
modify the code that is being executed in stop machine. I'm curious to
exactly what the issue is if something does get traced in the stop machine
processing. Why does it crash?

-- Steve


[*] You really should come up with a better way than stop machine, because
the stop machine method is really disruptive, can you not use the break
point method for updates?

Re: [PATCH] rcu: ftrace: avoid tracing a few functions executed in multi_cpu_stop()

[Steven Rostedt]

On Wed, 20 Apr 2022 11:44:54 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> [*] You really should come up with a better way than stop machine, because
> the stop machine method is really disruptive, can you not use the break
> point method for updates?

Talk about dejavu!

  https://lore.kernel.org/all/mhng-62c2ef00-fb64-48c3-a2bb-43b2799161bf@palmer-ri-x1c9/

-- Steve

Re: [PATCH] rcu: ftrace: avoid tracing a few functions executed in multi_cpu_stop()

[patrick wang]

On Thu, Apr 21, 2022 at 12:26 AM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Wed, 20 Apr 2022 11:44:54 -0400
> Steven Rostedt <rostedt@goodmis.org> wrote:
>
>
> Interesting. On x86 when we used stop machine[*] it was not an issue to
> modify the code that is being executed in stop machine. I'm curious to
> exactly what the issue is if something does get traced in the stop machine
> processing. Why does it crash?

I looked up the commit history. When x86 turned to breakpoints, stop
machine's state machine loop had no calls during waiting. So there
was no function being called during modifying code. Which means
there were no other cpus would load those instructions to be updated
in this period. While the stop machine currently will call other functions
and the call chain is fairly deep. So it may not quite be suitable for ftrace
now because it can not make sure the instructions within its own call
chain are updated atomically.

> > [*] You really should come up with a better way than stop machine, because
> > the stop machine method is really disruptive, can you not use the break
> > point method for updates?
>
> Talk about dejavu!
>
>   https://lore.kernel.org/all/mhng-62c2ef00-fb64-48c3-a2bb-43b2799161bf@palmer-ri-x1c9/
>

Right, breakpoint should be better.

This stall happens on my qemu machine too, maybe it's qemu related.

Thanks,
Patrick

Re: [PATCH] rcu: ftrace: avoid tracing a few functions executed in multi_cpu_stop()

[Steven Rostedt]

On Thu, 21 Apr 2022 19:36:06 +0800
patrick wang <patrick.wang.shcn@gmail.com> wrote:

> On Thu, Apr 21, 2022 at 12:26 AM Steven Rostedt <rostedt@goodmis.org> wrote:
> >
> > On Wed, 20 Apr 2022 11:44:54 -0400
> > Steven Rostedt <rostedt@goodmis.org> wrote:
> >
> >
> > Interesting. On x86 when we used stop machine[*] it was not an issue to
> > modify the code that is being executed in stop machine. I'm curious to
> > exactly what the issue is if something does get traced in the stop machine
> > processing. Why does it crash?  
> 
> I looked up the commit history. When x86 turned to breakpoints, stop
> machine's state machine loop had no calls during waiting. So there
> was no function being called during modifying code. Which means
> there were no other cpus would load those instructions to be updated
> in this period. While the stop machine currently will call other functions
> and the call chain is fairly deep. So it may not quite be suitable for ftrace
> now because it can not make sure the instructions within its own call
> chain are updated atomically.

Are you saying that the RISC-V stop machine implementation has code being
called on the other CPUs while they wait?

-- Steve

Re: [PATCH] rcu: ftrace: avoid tracing a few functions executed in multi_cpu_stop()

[patrick wang]

On Thu, Apr 21, 2022 at 8:50 PM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Thu, 21 Apr 2022 19:36:06 +0800
> patrick wang <patrick.wang.shcn@gmail.com> wrote:
>
> > On Thu, Apr 21, 2022 at 12:26 AM Steven Rostedt <rostedt@goodmis.org> wrote:
> > >
> > > On Wed, 20 Apr 2022 11:44:54 -0400
> > > Steven Rostedt <rostedt@goodmis.org> wrote:
> > >
> > >
> > > Interesting. On x86 when we used stop machine[*] it was not an issue to
> > > modify the code that is being executed in stop machine. I'm curious to
> > > exactly what the issue is if something does get traced in the stop machine
> > > processing. Why does it crash?
> >
> > I looked up the commit history. When x86 turned to breakpoints, stop
> > machine's state machine loop had no calls during waiting. So there
> > was no function being called during modifying code. Which means
> > there were no other cpus would load those instructions to be updated
> > in this period. While the stop machine currently will call other functions
> > and the call chain is fairly deep. So it may not quite be suitable for ftrace
> > now because it can not make sure the instructions within its own call
> > chain are updated atomically.
>
> Are you saying that the RISC-V stop machine implementation has code being
> called on the other CPUs while they wait?
>

Yes, and not just RISC-V. It's arch-independent. It's the internal change of
stop machine implementation.

----------------------------------------------------------------
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);
------------------------------------------------------------------

Thanks,
Patrick

Re: [PATCH] rcu: ftrace: avoid tracing a few functions executed in multi_cpu_stop()

[Steven Rostedt]

On Fri, 22 Apr 2022 18:45:46 +0800
patrick wang <patrick.wang.shcn@gmail.com> wrote:

> Yes, and not just RISC-V. It's arch-independent. It's the internal change of
> stop machine implementation.
> 
> ----------------------------------------------------------------
> 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);
> ------------------------------------------------------------------

That makes much more sense. Can you add that to the change log.

Reviewed-by: Steven Rostedt (Google) <rostedt@goodmis.org>

-- Steve

Re: [PATCH] rcu: ftrace: avoid tracing a few functions executed in multi_cpu_stop()

[patrick wang]

On Fri, Apr 22, 2022 at 11:52 PM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Fri, 22 Apr 2022 18:45:46 +0800
> patrick wang <patrick.wang.shcn@gmail.com> wrote:
>
> > Yes, and not just RISC-V. It's arch-independent. It's the internal change of
> > stop machine implementation.
> >
> > ----------------------------------------------------------------
> > 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);
> > ------------------------------------------------------------------
>
> That makes much more sense. Can you add that to the change log.
>

Sure, I will rewrite the log message. And thank you for the comments
and advices.

Thanks,
Patrick


> Reviewed-by: Steven Rostedt (Google) <rostedt@goodmis.org>
>
> -- Steve