linux/kernel/trace
Steven Rostedt (Red Hat) f17a519485 tracing: Use current_uid() for critical time tracing
The irqsoff tracer records the max time that interrupts are disabled.
There are hooks in the assembly code that calls back into the tracer when
interrupts are disabled or enabled.

When they are enabled, the tracer checks if the amount of time they
were disabled is larger than the previous recorded max interrupts off
time. If it is, it creates a snapshot of the currently running trace
to store where the last largest interrupts off time was held and how
it happened.

During testing, this RCU lockdep dump appeared:

[ 1257.829021] ===============================
[ 1257.829021] [ INFO: suspicious RCU usage. ]
[ 1257.829021] 3.10.0-rc1-test+ #171 Tainted: G        W
[ 1257.829021] -------------------------------
[ 1257.829021] /home/rostedt/work/git/linux-trace.git/include/linux/rcupdate.h:780 rcu_read_lock() used illegally while idle!
[ 1257.829021]
[ 1257.829021] other info that might help us debug this:
[ 1257.829021]
[ 1257.829021]
[ 1257.829021] RCU used illegally from idle CPU!
[ 1257.829021] rcu_scheduler_active = 1, debug_locks = 0
[ 1257.829021] RCU used illegally from extended quiescent state!
[ 1257.829021] 2 locks held by trace-cmd/4831:
[ 1257.829021]  #0:  (max_trace_lock){......}, at: [<ffffffff810e2b77>] stop_critical_timing+0x1a3/0x209
[ 1257.829021]  #1:  (rcu_read_lock){.+.+..}, at: [<ffffffff810dae5a>] __update_max_tr+0x88/0x1ee
[ 1257.829021]
[ 1257.829021] stack backtrace:
[ 1257.829021] CPU: 3 PID: 4831 Comm: trace-cmd Tainted: G        W    3.10.0-rc1-test+ #171
[ 1257.829021] Hardware name: To Be Filled By O.E.M. To Be Filled By O.E.M./To be filled by O.E.M., BIOS SDBLI944.86P 05/08/2007
[ 1257.829021]  0000000000000001 ffff880065f49da8 ffffffff8153dd2b ffff880065f49dd8
[ 1257.829021]  ffffffff81092a00 ffff88006bd78680 ffff88007add7500 0000000000000003
[ 1257.829021]  ffff88006bd78680 ffff880065f49e18 ffffffff810daebf ffffffff810dae5a
[ 1257.829021] Call Trace:
[ 1257.829021]  [<ffffffff8153dd2b>] dump_stack+0x19/0x1b
[ 1257.829021]  [<ffffffff81092a00>] lockdep_rcu_suspicious+0x109/0x112
[ 1257.829021]  [<ffffffff810daebf>] __update_max_tr+0xed/0x1ee
[ 1257.829021]  [<ffffffff810dae5a>] ? __update_max_tr+0x88/0x1ee
[ 1257.829021]  [<ffffffff811002b9>] ? user_enter+0xfd/0x107
[ 1257.829021]  [<ffffffff810dbf85>] update_max_tr_single+0x11d/0x12d
[ 1257.829021]  [<ffffffff811002b9>] ? user_enter+0xfd/0x107
[ 1257.829021]  [<ffffffff810e2b15>] stop_critical_timing+0x141/0x209
[ 1257.829021]  [<ffffffff8109569a>] ? trace_hardirqs_on+0xd/0xf
[ 1257.829021]  [<ffffffff811002b9>] ? user_enter+0xfd/0x107
[ 1257.829021]  [<ffffffff810e3057>] time_hardirqs_on+0x2a/0x2f
[ 1257.829021]  [<ffffffff811002b9>] ? user_enter+0xfd/0x107
[ 1257.829021]  [<ffffffff8109550c>] trace_hardirqs_on_caller+0x16/0x197
[ 1257.829021]  [<ffffffff8109569a>] trace_hardirqs_on+0xd/0xf
[ 1257.829021]  [<ffffffff811002b9>] user_enter+0xfd/0x107
[ 1257.829021]  [<ffffffff810029b4>] do_notify_resume+0x92/0x97
[ 1257.829021]  [<ffffffff8154bdca>] int_signal+0x12/0x17

What happened was entering into the user code, the interrupts were enabled
and a max interrupts off was recorded. The trace buffer was saved along with
various information about the task: comm, pid, uid, priority, etc.

The uid is recorded with task_uid(tsk). But this is a macro that uses rcu_read_lock()
to retrieve the data, and this happened to happen where RCU is blind (user_enter).

As only the preempt and irqs off tracers can have this happen, and they both
only have the tsk == current, if tsk == current, use current_uid() instead of
task_uid(), as current_uid() does not use RCU as only current can change its uid.

This fixes the RCU suspicious splat.

Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
2013-06-06 12:35:30 -04:00
..
Kconfig ring-buffer: Select IRQ_WORK 2013-05-03 19:24:17 -04:00
Makefile trace: Stop compiling in trace_clock unconditionally 2012-09-13 22:52:08 -04:00
blktrace.c Merge branch 'for-3.10/drivers' of git://git.kernel.dk/linux-block 2013-05-08 11:51:05 -07:00
ftrace.c ftrace: Use the rcu _notrace variants for rcu_dereference_raw() and friends 2013-05-28 22:48:00 -04:00
power-traces.c PM / tracing: remove deprecated power trace API 2013-01-26 00:39:12 +01:00
ring_buffer.c ring-buffer: Do not poll non allocated cpu buffers 2013-05-28 10:53:20 -04:00
ring_buffer_benchmark.c tracing: Use NUMA allocation for per-cpu ring buffer pages 2011-06-14 22:04:39 -04:00
rpm-traces.c PM / Runtime: Introduce trace points for tracing rpm_* functions 2011-09-27 22:53:27 +02:00
trace.c tracing: Use current_uid() for critical time tracing 2013-06-06 12:35:30 -04:00
trace.h Merge branch 'perf-core-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip 2013-04-30 07:41:01 -07:00
trace_branch.c tracing: Fix the branch tracer that broke with buffer change 2013-03-15 00:35:54 -04:00
trace_clock.c tracing: Add "uptime" trace clock that uses jiffies 2013-03-15 00:36:09 -04:00
trace_entries.h tracing: Add trace_puts() for even faster trace_printk() tracing 2013-03-15 00:35:55 -04:00
trace_event_perf.c perf/core improvements and fixes: 2012-08-21 11:27:00 +02:00
trace_events.c tracing: Return -EBUSY when event_enable_func() fails to get module 2013-05-16 11:01:16 -04:00
trace_events_filter.c tracing: Fix leaks of filter preds 2013-05-15 13:49:18 -04:00
trace_events_filter_test.h tracing/filter: Add startup tests for events filter 2011-08-19 14:35:59 -04:00
trace_export.c tracing: Fix some section mismatch warnings 2013-03-15 00:34:54 -04:00
trace_functions.c tracing: Add function probe to trigger stack traces 2013-03-15 00:36:05 -04:00
trace_functions_graph.c tracing: Consolidate max_tr into main trace_array structure 2013-03-15 00:35:40 -04:00
trace_irqsoff.c tracing: Add function-trace option to disable function tracing of latency tracers 2013-03-15 00:36:08 -04:00
trace_kdb.c tracing: Consolidate max_tr into main trace_array structure 2013-03-15 00:35:40 -04:00
trace_kprobe.c tracing/kprobes: Make print_*probe_event static 2013-05-15 13:50:24 -04:00
trace_mmiotrace.c tracing: Consolidate max_tr into main trace_array structure 2013-03-15 00:35:40 -04:00
trace_nop.c tracing/ftrace: make nop-tracer use polling wait for events on pipe 2009-03-23 09:22:15 +01:00
trace_output.c Tracing updates for Linux 3.10 2013-04-29 13:55:38 -07:00
trace_output.h tracing: Rename trace_event_mutex to trace_event_sem 2013-03-15 13:22:10 -04:00
trace_printk.c tracing: Add percpu buffers for trace_printk() 2012-04-23 21:15:55 -04:00
trace_probe.c tracing: Replace strict_strto* with kstrto* 2012-10-31 16:45:23 -04:00
trace_probe.h uprobes/tracing: Introduce is_trace_uprobe_enabled() 2013-02-08 18:24:30 +01:00
trace_sched_switch.c tracing: Consolidate max_tr into main trace_array structure 2013-03-15 00:35:40 -04:00
trace_sched_wakeup.c tracing: Add function-trace option to disable function tracing of latency tracers 2013-03-15 00:36:08 -04:00
trace_selftest.c tracing: Fix bad parameter passed in branch selftest 2013-05-29 16:00:03 -04:00
trace_selftest_dynamic.c ftrace: Add self-tests for multiple function trace users 2011-05-18 19:24:51 -04:00
trace_stack.c Tracing updates for Linux 3.10 2013-04-29 13:55:38 -07:00
trace_stat.c tracing: Check return value of tracing_init_dentry() 2013-04-12 23:02:32 -04:00
trace_stat.h tracing/stat: Add stat_release() callback 2009-07-10 12:14:05 +02:00
trace_syscalls.c tracing: Fix comment about prefix in arch_syscall_match_sym_name() 2013-03-15 13:22:09 -04:00
trace_uprobe.c uprobes/perf: Avoid perf_trace_buf_prepare/submit if ->perf_events is empty 2013-04-15 17:39:52 +02:00