diff options
author | Steven Rostedt (Red Hat) <rostedt@goodmis.org> | 2013-11-04 18:34:44 -0500 |
---|---|---|
committer | Steven Rostedt <rostedt@goodmis.org> | 2013-11-05 16:04:26 -0500 |
commit | b5aa3a472b6d13d57a7521a663290dea2fb483a7 (patch) | |
tree | 00a245e4f0e64d4c8320e1354bd73e7ce7e45080 | |
parent | 9418fb208059d6f916bdb116653e166c5db9456d (diff) |
ftrace: Have control op function callback only trace when RCU is watching
Dave Jones reported that trinity would be able to trigger the following
back trace:
===============================
[ INFO: suspicious RCU usage. ]
3.10.0-rc2+ #38 Not tainted
-------------------------------
include/linux/rcupdate.h:771 rcu_read_lock() used illegally while idle!
other info that might help us debug this:
RCU used illegally from idle CPU! rcu_scheduler_active = 1, debug_locks = 0
RCU used illegally from extended quiescent state!
1 lock held by trinity-child1/18786:
#0: (rcu_read_lock){.+.+..}, at: [<ffffffff8113dd48>] __perf_event_overflow+0x108/0x310
stack backtrace:
CPU: 3 PID: 18786 Comm: trinity-child1 Not tainted 3.10.0-rc2+ #38
0000000000000000 ffff88020767bac8 ffffffff816e2f6b ffff88020767baf8
ffffffff810b5897 ffff88021de92520 0000000000000000 ffff88020767bbf8
0000000000000000 ffff88020767bb78 ffffffff8113ded4 ffffffff8113dd48
Call Trace:
[<ffffffff816e2f6b>] dump_stack+0x19/0x1b
[<ffffffff810b5897>] lockdep_rcu_suspicious+0xe7/0x120
[<ffffffff8113ded4>] __perf_event_overflow+0x294/0x310
[<ffffffff8113dd48>] ? __perf_event_overflow+0x108/0x310
[<ffffffff81309289>] ? __const_udelay+0x29/0x30
[<ffffffff81076054>] ? __rcu_read_unlock+0x54/0xa0
[<ffffffff816f4000>] ? ftrace_call+0x5/0x2f
[<ffffffff8113dfa1>] perf_swevent_overflow+0x51/0xe0
[<ffffffff8113e08f>] perf_swevent_event+0x5f/0x90
[<ffffffff8113e1c9>] perf_tp_event+0x109/0x4f0
[<ffffffff8113e36f>] ? perf_tp_event+0x2af/0x4f0
[<ffffffff81074630>] ? __rcu_read_lock+0x20/0x20
[<ffffffff8112d79f>] perf_ftrace_function_call+0xbf/0xd0
[<ffffffff8110e1e1>] ? ftrace_ops_control_func+0x181/0x210
[<ffffffff81074630>] ? __rcu_read_lock+0x20/0x20
[<ffffffff81100cae>] ? rcu_eqs_enter_common+0x5e/0x470
[<ffffffff8110e1e1>] ftrace_ops_control_func+0x181/0x210
[<ffffffff816f4000>] ftrace_call+0x5/0x2f
[<ffffffff8110e229>] ? ftrace_ops_control_func+0x1c9/0x210
[<ffffffff816f4000>] ? ftrace_call+0x5/0x2f
[<ffffffff81074635>] ? debug_lockdep_rcu_enabled+0x5/0x40
[<ffffffff81074635>] ? debug_lockdep_rcu_enabled+0x5/0x40
[<ffffffff81100cae>] ? rcu_eqs_enter_common+0x5e/0x470
[<ffffffff8110112a>] rcu_eqs_enter+0x6a/0xb0
[<ffffffff81103673>] rcu_user_enter+0x13/0x20
[<ffffffff8114541a>] user_enter+0x6a/0xd0
[<ffffffff8100f6d8>] syscall_trace_leave+0x78/0x140
[<ffffffff816f46af>] int_check_syscall_exit_work+0x34/0x3d
------------[ cut here ]------------
Perf uses rcu_read_lock() but as the function tracer can trace functions
even when RCU is not currently active, this makes the rcu_read_lock()
used by perf ineffective.
As perf is currently the only user of the ftrace_ops_control_func() and
perf is also the only function callback that actively uses rcu_read_lock(),
the quick fix is to prevent the ftrace_ops_control_func() from calling
its callbacks if RCU is not active.
With Paul's new "rcu_is_watching()" we can tell if RCU is active or not.
Reported-by: Dave Jones <davej@redhat.com>
Cc: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Jiri Olsa <jolsa@redhat.com>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
-rw-r--r-- | kernel/trace/ftrace.c | 9 |
1 files changed, 9 insertions, 0 deletions
diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c index 44e826a79665..080b7d41e17f 100644 --- a/kernel/trace/ftrace.c +++ b/kernel/trace/ftrace.c | |||
@@ -4388,12 +4388,21 @@ ftrace_ops_control_func(unsigned long ip, unsigned long parent_ip, | |||
4388 | */ | 4388 | */ |
4389 | preempt_disable_notrace(); | 4389 | preempt_disable_notrace(); |
4390 | trace_recursion_set(TRACE_CONTROL_BIT); | 4390 | trace_recursion_set(TRACE_CONTROL_BIT); |
4391 | |||
4392 | /* | ||
4393 | * Control funcs (perf) uses RCU. Only trace if | ||
4394 | * RCU is currently active. | ||
4395 | */ | ||
4396 | if (!rcu_is_watching()) | ||
4397 | goto out; | ||
4398 | |||
4391 | do_for_each_ftrace_op(op, ftrace_control_list) { | 4399 | do_for_each_ftrace_op(op, ftrace_control_list) { |
4392 | if (!(op->flags & FTRACE_OPS_FL_STUB) && | 4400 | if (!(op->flags & FTRACE_OPS_FL_STUB) && |
4393 | !ftrace_function_local_disabled(op) && | 4401 | !ftrace_function_local_disabled(op) && |
4394 | ftrace_ops_test(op, ip, regs)) | 4402 | ftrace_ops_test(op, ip, regs)) |
4395 | op->func(ip, parent_ip, op, regs); | 4403 | op->func(ip, parent_ip, op, regs); |
4396 | } while_for_each_ftrace_op(op); | 4404 | } while_for_each_ftrace_op(op); |
4405 | out: | ||
4397 | trace_recursion_clear(TRACE_CONTROL_BIT); | 4406 | trace_recursion_clear(TRACE_CONTROL_BIT); |
4398 | preempt_enable_notrace(); | 4407 | preempt_enable_notrace(); |
4399 | } | 4408 | } |