Re: [BUG] ftrace: WARNING: suspicious RCU usage

[Masami Hiramatsu <mhiramat@kernel.org>]

[-- Attachment #1: Type: text/plain, Size: 2443 bytes --]

Hi,

On Tue, 27 Jun 2017 22:53:56 +0900
Masami Hiramatsu <mhiramat@kernel.org> wrote:

> > > [   10.919174] =============================
> > > [   10.920077] WARNING: suspicious RCU usage
> > > [   10.920977] 4.12.0-rc5+ #1 Not tainted
> > > [   10.921828] -----------------------------
> > > [   10.922748] /home/mhiramat/ksrc/linux/include/trace/events/rcu.h:454 suspicious rcu_dereference_check() usage!
> > > [   10.924761] 
> > > [   10.924761] other info that might help us debug this:
> > > [   10.924761] 
> > > [   10.926775] 
> > > [   10.926775] RCU used illegally from idle CPU!
> > > [   10.926775] rcu_scheduler_active = 2, debug_locks = 1
> > > [   10.929176] RCU used illegally from extended quiescent state!
> > > [   10.930525] no locks held by swapper/7/0.
> > > [   10.931547] 
> > > [   10.931547] stack backtrace:
> > > [   10.932777] CPU: 7 PID: 0 Comm: swapper/7 Not tainted 4.12.0-rc5+ #1
> > > [   10.934025] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.3-1.fc25 04/01/2014
> > > [   10.935869] Call Trace:
> > > [   10.936550]  dump_stack+0x86/0xcf
> > > [   10.937359]  lockdep_rcu_suspicious+0xc5/0x100
> > > [   10.938327]  ? rcu_eqs_exit_common.isra.53+0x5/0x150
> > 
> > > [   10.939229]  rcu_irq_enter+0x18d/0x1a0
> > 
> > Strange, it triggered in rcu_irq_enter()?
> > 
> > > [   10.939902]  ? rcu_eqs_exit_common.isra.53+0x5/0x150
> > > [   10.940683]  check_stack+0xbb/0x2f0
> > > [   10.941333]  stack_trace_call+0x3f/0x50
> > > [   10.942010]  0xffffffffa0000077
> > > [   10.942620]  ? ftrace_graph_caller+0x78/0xa8
> > > [   10.943342]  ? rcu_eqs_exit_common.isra.53+0x5/0x150
> > > [   10.944214]  ? rcu_idle_exit+0x5/0x90
> > 
> > > [   10.944937]  rcu_eqs_exit_common.isra.53+0x5/0x150
> > 
> > Hmm, we are tracing rcu_eqs_exit_common.

Yes, the Commit 03ecd3f4 fixed only rcu_eqs_enter_common()
path, but not rcu_eqs_exit().

> > 
> > 
> > Do you have this commit in this branch?
> > 
> > Commit 03ecd3f4 "rcu/tracing: Add rcu_disabled to denote when
> > rcu_irq_enter() will not work"
> 
> Yes, that is merged.
> 
> Hmm, I'll check this is correctly enabled again, since this time
> I couldn't reproduce it.

I could reproduce it again with running full ftracetest (not
sure why, but with only fgraph-filter-stack.tc, it is hard to
be reproduced.

Please see attached patch, after applying that, I didn't see
this problem.

Thank you,

-- 
Masami Hiramatsu <mhiramat@kernel.org>

[-- Attachment #2: rcu-tracing-set --]
[-- Type: application/octet-stream, Size: 930 bytes --]

rcu/tracing: Set disable_rcu_irq_enter on rcu_eqs_exit too

From: Masami Hiramatsu <mhiramat@kernel.org>

Set disable_rcu_irq_enter on not only rcu_eqs_enter_common()
but also rcu_eqs_exit(), since there is same issue as
commit 03ecd3f48e57 ("rcu/tracing: Add rcu_disabled to
denote when rcu_irq_enter() will not work") fixed there.

Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
---
 kernel/rcu/tree.c |    2 ++
 1 file changed, 2 insertions(+)

diff --git a/kernel/rcu/tree.c b/kernel/rcu/tree.c
index e354e47..442b409 100644
--- a/kernel/rcu/tree.c
+++ b/kernel/rcu/tree.c
@@ -973,8 +973,10 @@ static void rcu_eqs_exit(bool user)
 	if (oldval & DYNTICK_TASK_NEST_MASK) {
 		rdtp->dynticks_nesting += DYNTICK_TASK_NEST_VALUE;
 	} else {
+		__this_cpu_inc(disable_rcu_irq_enter);
 		rdtp->dynticks_nesting = DYNTICK_TASK_EXIT_IDLE;
 		rcu_eqs_exit_common(oldval, user);
+		__this_cpu_dec(disable_rcu_irq_enter);
 	}
 }