linux-stable/kernel/trace
Steven Rostedt (VMware) 1fca009203 tracing: Restructure trace_clock_global() to never block
commit aafe104aa9 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-22 10:57:25 +02:00
..
blktrace.c blktrace: fix debugfs use after free 2020-11-10 10:29:03 +01:00
bpf_trace.c
ftrace.c ftrace: Handle commands when closing set_ftrace_filter file 2021-05-22 10:57:22 +02:00
Kconfig Stop the ad-hoc games with -Wno-maybe-initialized 2020-05-20 08:17:10 +02:00
Makefile
power-traces.c
ring_buffer.c tracing: Fix race in trace_open and buffer resize call 2021-01-30 13:31:16 +01:00
ring_buffer_benchmark.c
rpm-traces.c
trace.c tracing: Map all PIDs to command lines 2021-05-22 10:57:23 +02:00
trace.h tracing: Fix userstacktrace option for instances 2020-12-11 13:39:06 +01:00
trace_benchmark.c
trace_benchmark.h
trace_branch.c Revert "x86/uaccess, ftrace: Fix ftrace_likely_update() vs. SMAP" 2019-07-03 13:15:57 +02:00
trace_clock.c tracing: Restructure trace_clock_global() to never block 2021-05-22 10:57:25 +02:00
trace_entries.h tracing: Set kernel_stack's caller size properly 2020-10-01 13:12:32 +02:00
trace_event_perf.c
trace_events.c tracing: Do not count ftrace events in top level enable output 2021-02-23 14:00:31 +01:00
trace_events_filter.c
trace_events_filter_test.h
trace_events_hist.c tracing: Use strncpy instead of memcpy for string keys in hist triggers 2019-03-23 14:35:19 +01:00
trace_events_trigger.c tracing: Fix event trigger to accept redundant spaces 2020-06-30 15:38:08 -04:00
trace_export.c
trace_functions.c
trace_functions_graph.c tracing/fgraph: Fix set_graph_function from showing interrupts 2019-05-16 19:42:27 +02:00
trace_hwlat.c tracing/hwlat: Honor the tracing_cpumask 2020-08-21 09:48:19 +02:00
trace_irqsoff.c tracing/fgraph: Fix set_graph_function from showing interrupts 2019-05-16 19:42:27 +02:00
trace_kdb.c tracing: Silence GCC 9 array bounds warning 2019-06-25 11:36:50 +08:00
trace_kprobe.c ftrace/kprobe: Show the maxactive number on kprobe_events 2020-04-24 08:00:50 +02:00
trace_mmiotrace.c
trace_nop.c
trace_output.c
trace_output.h
trace_printk.c
trace_probe.c
trace_probe.h
trace_sched_switch.c tracing: Fix sched switch start/stop refcount racy updates 2020-02-14 16:32:07 -05:00
trace_sched_wakeup.c kernel/trace: Fix do not unregister tracepoints when register sched_migrate_task fail 2020-01-14 20:05:40 +01:00
trace_selftest.c ftrace: Handle tracing when switching between context 2020-11-10 10:29:04 +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:05:40 +01:00
trace_stat.c tracing: Fix very unlikely race of registering two stat tracers 2020-02-28 16:35:58 +01:00
trace_stat.h
trace_syscalls.c
trace_uprobe.c tracing/uprobes: Fix output for multiple string arguments 2019-02-20 10:20:53 +01:00
tracing_map.c tracing: Have the histogram compare functions convert to u64 first 2020-01-09 10:17:56 +01:00
tracing_map.h