linux/kernel/trace
Steven Rostedt (VMware) c64da3294a tracing: Restructure trace_clock_global() to never block
commit aafe104aa9096827a429bc1358f8260ee565b7cc upstream.

It was reported that a fix to the ring buffer recursion detection would
cause a hung machine when performing suspend / resume testing. The
following backtrace was extracted from debugging that case:

Call Trace:
 trace_clock_global+0x91/0xa0
 __rb_reserve_next+0x237/0x460
 ring_buffer_lock_reserve+0x12a/0x3f0
 trace_buffer_lock_reserve+0x10/0x50
 __trace_graph_return+0x1f/0x80
 trace_graph_return+0xb7/0xf0
 ? trace_clock_global+0x91/0xa0
 ftrace_return_to_handler+0x8b/0xf0
 ? pv_hash+0xa0/0xa0
 return_to_handler+0x15/0x30
 ? ftrace_graph_caller+0xa0/0xa0
 ? trace_clock_global+0x91/0xa0
 ? __rb_reserve_next+0x237/0x460
 ? ring_buffer_lock_reserve+0x12a/0x3f0
 ? trace_event_buffer_lock_reserve+0x3c/0x120
 ? trace_event_buffer_reserve+0x6b/0xc0
 ? trace_event_raw_event_device_pm_callback_start+0x125/0x2d0
 ? dpm_run_callback+0x3b/0xc0
 ? pm_ops_is_empty+0x50/0x50
 ? platform_get_irq_byname_optional+0x90/0x90
 ? trace_device_pm_callback_start+0x82/0xd0
 ? dpm_run_callback+0x49/0xc0

With the following RIP:

RIP: 0010:native_queued_spin_lock_slowpath+0x69/0x200

Since the fix to the recursion detection would allow a single recursion to
happen while tracing, this lead to the trace_clock_global() taking a spin
lock and then trying to take it again:

ring_buffer_lock_reserve() {
  trace_clock_global() {
    arch_spin_lock() {
      queued_spin_lock_slowpath() {
        /* lock taken */
        (something else gets traced by function graph tracer)
          ring_buffer_lock_reserve() {
            trace_clock_global() {
              arch_spin_lock() {
                queued_spin_lock_slowpath() {
                /* DEAD LOCK! */

Tracing should *never* block, as it can lead to strange lockups like the
above.

Restructure the trace_clock_global() code to instead of simply taking a
lock to update the recorded "prev_time" simply use it, as two events
happening on two different CPUs that calls this at the same time, really
doesn't matter which one goes first. Use a trylock to grab the lock for
updating the prev_time, and if it fails, simply try again the next time.
If it failed to be taken, that means something else is already updating
it.

Link: https://lkml.kernel.org/r/20210430121758.650b6e8a@gandalf.local.home

Cc: stable@vger.kernel.org
Tested-by: Konstantin Kharlamov <hi-angel@yandex.ru>
Tested-by: Todd Brandt <todd.e.brandt@linux.intel.com>
Fixes: b02414c8f0 ("ring-buffer: Fix recursion protection transitions between interrupt context") # started showing the problem
Fixes: 14131f2f98 ("tracing: implement trace_clock_*() APIs") # where the bug happened
Bugzilla: https://bugzilla.kernel.org/show_bug.cgi?id=212761
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
2021-05-11 14:04:18 +02:00
..
Kconfig tracing/kprobes: Do the notrace functions check without kprobes on ftrace 2021-01-19 18:26:12 +01:00
Makefile
blktrace.c blktrace: ensure our debugfs dir exists 2020-09-03 11:26:42 +02:00
bpf_trace.c bpf: Fix bpf_put_raw_tracepoint()'s use of __module_address() 2020-12-30 11:51:18 +01:00
fgraph.c fgraph: Initialize tracing_graph_pause at task creation 2021-02-10 09:25:29 +01:00
ftrace.c ftrace: Handle commands when closing set_ftrace_filter file 2021-05-11 14:04:01 +02:00
ftrace_internal.h treewide: Rename rcu_dereference_raw_notrace() to _check() 2019-08-01 14:16:21 -07:00
power-traces.c
preemptirq_delay_test.c
ring_buffer.c tracing: Fix race in trace_open and buffer resize call 2021-01-30 13:54:10 +01:00
ring_buffer_benchmark.c tracing: Use CONFIG_PREEMPTION 2019-07-31 19:03:35 +02:00
rpm-traces.c
trace.c tracing: Map all PIDs to command lines 2021-05-11 14:04:18 +02:00
trace.h ftrace: Handle tracing when switching between context 2020-11-10 12:37:28 +01:00
trace_benchmark.c
trace_benchmark.h
trace_branch.c
trace_clock.c tracing: Restructure trace_clock_global() to never block 2021-05-11 14:04:18 +02:00
trace_dynevent.c tracing: Add tracing_check_open_get_tr() 2019-10-12 20:44:07 -04:00
trace_dynevent.h tracing/dynevent: Pass extra arguments to match operation 2019-08-31 12:19:38 -04:00
trace_entries.h tracing: Set kernel_stack's caller size properly 2020-10-01 13:17:29 +02:00
trace_event_perf.c tracing: Fix race in perf_trace_buf initialization 2019-10-21 19:38:28 -04:00
trace_events.c tracing: Do not count ftrace events in top level enable output 2021-02-17 10:35:14 +01:00
trace_events_filter.c tracing: Avoid memory leak in process_system_preds() 2020-01-09 10:20:00 +01:00
trace_events_filter_test.h
trace_events_hist.c tracing: fix double free 2020-10-01 13:18:23 +02:00
trace_events_trigger.c tracing: Fix event trigger to accept redundant spaces 2020-06-30 15:37:10 -04:00
trace_export.c
trace_functions.c
trace_functions_graph.c fgraph: Remove redundant ftrace_graph_notrace_addr() test 2019-07-30 21:50:03 -04:00
trace_hwlat.c tracing: Remove WARN_ON in start_thread() 2020-12-08 10:40:28 +01:00
trace_irqsoff.c
trace_kdb.c tracing: Silence GCC 9 array bounds warning 2019-05-25 23:04:30 -04:00
trace_kprobe.c tracing/kprobe: Fix to support kretprobe events on unloaded modules 2021-02-13 13:52:54 +01:00
trace_kprobe_selftest.c
trace_kprobe_selftest.h
trace_mmiotrace.c
trace_nop.c
trace_output.c tracing: Make the space reserved for the pid wider 2020-10-07 08:01:27 +02:00
trace_output.h
trace_preemptirq.c lockdep: fix order in trace_hardirqs_off_caller() 2020-10-01 13:18:14 +02:00
trace_printk.c tracing: Add locked_down checks to the open calls of files created for tracefs 2019-10-12 20:48:06 -04:00
trace_probe.c tracing/probe: Fix memleak in fetch_op_data operations 2020-06-24 17:50:51 +02:00
trace_probe.h tracing/uprobe: Fix to make trace_uprobe_filter alignment safe 2020-02-05 21:22:53 +00:00
trace_probe_tmpl.h tracing/probe: Support user-space dereference 2019-05-25 23:04:42 -04:00
trace_sched_switch.c tracing: Fix sched switch start/stop refcount racy updates 2020-02-11 04:35:07 -08:00
trace_sched_wakeup.c kernel/trace: Fix do not unregister tracepoints when register sched_migrate_task fail 2020-01-14 20:08:22 +01:00
trace_selftest.c ftrace: Handle tracing when switching between context 2020-11-10 12:37:28 +01:00
trace_selftest_dynamic.c
trace_seq.c
trace_stack.c tracing: Have stack tracer compile when MCOUNT_INSN_SIZE is not defined 2020-01-14 20:08:22 +01:00
trace_stat.c tracing: Fix very unlikely race of registering two stat tracers 2020-02-24 08:36:30 +01:00
trace_stat.h
trace_syscalls.c
trace_uprobe.c tracing/probe: Fix bpf_task_fd_query() for kprobes and uprobes 2020-06-24 17:50:43 +02:00
tracing_map.c tracing: Have the histogram compare functions convert to u64 first 2020-01-09 10:20:00 +01:00
tracing_map.h