linux-kernel - Re: [BUG] ftrace: WARNING: suspicious RCU usage

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <20170627092926.0d712e3a@gandalf.local.home>
Date:   Tue, 27 Jun 2017 09:29:26 -0400
From:   Steven Rostedt <rostedt@...dmis.org>
To:     Masami Hiramatsu <mhiramat@...nel.org>
Cc:     linux-kernel@...r.kernel.org,
        "Paul E. McKenney" <paulmck@...ux.vnet.ibm.com>
Subject: Re: [BUG] ftrace: WARNING: suspicious RCU usage

On Tue, 27 Jun 2017 20:51:26 +0900
Masami Hiramatsu <mhiramat@...nel.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,
>