Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1675693 > unrolled thread

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

Started bySteven Rostedt <rostedt@goodmis.org>
First post2017-06-27 15:30 +0200
Last post2017-06-28 01:00 +0200
Articles 5 — 3 participants

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  Re: [BUG] ftrace: WARNING: suspicious RCU usage Steven Rostedt <rostedt@goodmis.org> - 2017-06-27 15:30 +0200
    Re: [BUG] ftrace: WARNING: suspicious RCU usage Masami Hiramatsu <mhiramat@kernel.org> - 2017-06-27 16:00 +0200
      Re: [BUG] ftrace: WARNING: suspicious RCU usage Steven Rostedt <rostedt@goodmis.org> - 2017-06-28 01:00 +0200
        Re: [BUG] ftrace: WARNING: suspicious RCU usage "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-06-28 02:50 +0200
      Re: [BUG] ftrace: WARNING: suspicious RCU usage Masami Hiramatsu <mhiramat@kernel.org> - 2017-06-28 01:00 +0200

#1675693 — Re: [BUG] ftrace: WARNING: suspicious RCU usage

FromSteven Rostedt <rostedt@goodmis.org>
Date2017-06-27 15:30 +0200
SubjectRe: [BUG] ftrace: WARNING: suspicious RCU usage
Message-ID<tWYJ4-14q-9@gated-at.bofh.it>
On Tue, 27 Jun 2017 20:51:26 +0900
Masami Hiramatsu <mhiramat@kernel.org> wrote:

> Hello Steve,
> 
> I've faced the following RCU warning while I ran ftracetest testcase
> "ftrace - function graph filters with stack tracer" on qemu.
> The kernel is ftrace/core branch.
> 
> [   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.


Do you have this commit in this branch?

Commit 03ecd3f4 "rcu/tracing: Add rcu_disabled to denote when
rcu_irq_enter() will not work"

-- Steve

> [   10.945754]  rcu_idle_exit+0x8c/0x90
> [   10.946612]  ? rcu_eqs_exit_common.isra.53+0x5/0x150
> [   10.947414]  ? rcu_idle_exit+0x8c/0x90
> [   10.948091]  do_idle+0x116/0x1c0
> [   10.948797]  cpu_startup_entry+0x1d/0x20
> [   10.949569]  start_secondary+0xfa/0x100
> [   10.950335]  secondary_startup_64+0x9f/0x9f
> [   10.951182] 
> 
> I attached full log and kconfig. I can reproduce it with just running
> following script.
> 
> ----
> cd tools/testing/selftests/ftrace
> while true; do
>         ./ftracetest test.d/ftrace/fgraph-filter-stack.tc
> done
> ----
> 
> Thank you,
>

[toc] | [next] | [standalone]

#1675718

FromMasami Hiramatsu <mhiramat@kernel.org>
Date2017-06-27 16:00 +0200
Message-ID<tWZc5-1gg-1@gated-at.bofh.it>
In reply to#1675693
On Tue, 27 Jun 2017 09:29:26 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Tue, 27 Jun 2017 20:51:26 +0900
> Masami Hiramatsu <mhiramat@kernel.org> wrote:
> 
> > Hello Steve,
> > 
> > I've faced the following RCU warning while I ran ftracetest testcase
> > "ftrace - function graph filters with stack tracer" on qemu.
> > The kernel is ftrace/core branch.
> > 
> > [   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.
> 
> 
> 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.

Thank you,

> 
> -- Steve
> 
> > [   10.945754]  rcu_idle_exit+0x8c/0x90
> > [   10.946612]  ? rcu_eqs_exit_common.isra.53+0x5/0x150
> > [   10.947414]  ? rcu_idle_exit+0x8c/0x90
> > [   10.948091]  do_idle+0x116/0x1c0
> > [   10.948797]  cpu_startup_entry+0x1d/0x20
> > [   10.949569]  start_secondary+0xfa/0x100
> > [   10.950335]  secondary_startup_64+0x9f/0x9f
> > [   10.951182] 
> > 
> > I attached full log and kconfig. I can reproduce it with just running
> > following script.
> > 
> > ----
> > cd tools/testing/selftests/ftrace
> > while true; do
> >         ./ftracetest test.d/ftrace/fgraph-filter-stack.tc
> > done
> > ----
> > 
> > Thank you,
> > 
> 


-- 
Masami Hiramatsu <mhiramat@kernel.org>

[toc] | [prev] | [next] | [standalone]

#1676236

FromSteven Rostedt <rostedt@goodmis.org>
Date2017-06-28 01:00 +0200
Message-ID<tX7CF-71T-1@gated-at.bofh.it>
In reply to#1675718
On Wed, 28 Jun 2017 07:52:22 +0900
Masami Hiramatsu <mhiramat@kernel.org> wrote:

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

Looks like a good fix to me. Paul want to take this one?

Acked-by: Steven Rostedt (VMware) <rostedt@goodmis.org>

-- Steve

[toc] | [prev] | [next] | [standalone]

#1676295

From"Paul E. McKenney" <paulmck@linux.vnet.ibm.com>
Date2017-06-28 02:50 +0200
Message-ID<tX9l7-89M-1@gated-at.bofh.it>
In reply to#1676236
On Tue, Jun 27, 2017 at 06:57:43PM -0400, Steven Rostedt wrote:
> On Wed, 28 Jun 2017 07:52:22 +0900
> Masami Hiramatsu <mhiramat@kernel.org> wrote:
> 
> > 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);
> >  	}
> >  }
> >  
> 
> Looks like a good fix to me. Paul want to take this one?
> 
> Acked-by: Steven Rostedt (VMware) <rostedt@goodmis.org>

Why not?

How urgent is this, as in what release do you need it in?  (Default at
this point being v4.14, but non-default available upon request.)

							Thanx, Paul

------------------------------------------------------------------------

commit 2165b0a9bb37f0560f261986783e7c02bb37c353
Author: Masami Hiramatsu <mhiramat@kernel.org>
Date:   Tue Jun 27 17:41:25 2017 -0700

    rcu/tracing: Set disable_rcu_irq_enter on rcu_eqs_exit()
    
    Set disable_rcu_irq_enter on not only rcu_eqs_enter_common() but also
    rcu_eqs_exit(), since rcu_eqs_exit() suffers from the same issue as was
    fixed for rcu_eqs_enter_common() by commit 03ecd3f48e57 ("rcu/tracing:
    Add rcu_disabled to denote when rcu_irq_enter() will not work").
    
    Signed-off-by: Masami Hiramatsu <mhiramat@kernel.org>
    Acked-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
    Signed-off-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>

diff --git a/kernel/rcu/tree.c b/kernel/rcu/tree.c
index ca3076b073e4..2a6b610ef54f 100644
--- a/kernel/rcu/tree.c
+++ b/kernel/rcu/tree.c
@@ -952,8 +952,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);
 	}
 }

[toc] | [prev] | [next] | [standalone]

#1676244

FromMasami Hiramatsu <mhiramat@kernel.org>
Date2017-06-28 01:00 +0200
Message-ID<tX7CF-71T-3@gated-at.bofh.it>
In reply to#1675718

[Multipart message — attachments visible in raw view] — view raw

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>

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web