Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::1:20 as permitted sender) client-ip=2620:137:e000::1:20;
Date:   Mon, 18 Apr 2022 09:28:15 -0700
From:   "Paul E. McKenney" <paulmck@kernel.org>
To:     Patrick Wang <patrick.wang.shcn@gmail.com>
Cc:     rostedt@goodmis.org, frederic@kernel.org, quic_neeraju@quicinc.com,
        josh@joshtriplett.org, mathieu.desnoyers@efficios.com,
        jiangshanlai@gmail.com, joel@joelfernandes.org,
        rcu@vger.kernel.org, linux-kernel@vger.kernel.org,
        peterz@infradead.org
Subject: Re: [PATCH] rcu: ftrace: avoid tracing a few functions executed in
 multi_cpu_stop()
Message-ID: <20220418162815.GV4285@paulmck-ThinkPad-P17-Gen-1>
Reply-To: paulmck@kernel.org
References: <20220418043735.11441-1-patrick.wang.shcn@gmail.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <20220418043735.11441-1-patrick.wang.shcn@gmail.com>
Precedence: bulk

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
>