kernel_optimize_test/kernel/trace
Steven Rostedt (VMware) a33614d52e 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:47:40 +02:00
..
blktrace.c block: add a bdget_part helper 2020-10-05 10:38:33 -06:00
bpf_trace.c bpf: Unbreak BPF_PROG_TYPE_KPROBE when kprobe is called via do_int3 2021-02-17 11:02:25 +01:00
bpf_trace.h bpf: Use dedicated bpf_trace_printk event instead of trace_printk() 2020-07-13 16:55:49 -07:00
fgraph.c fgraph: Initialize tracing_graph_pause at task creation 2021-02-10 09:29:16 +01:00
ftrace_internal.h x86/ftrace: Have ftrace trampolines turn read-only at the end of system boot up 2020-05-12 18:24:34 -04:00
ftrace.c ftrace: Handle commands when closing set_ftrace_filter file 2021-05-11 14:47:12 +02:00
Kconfig tracing/kprobes: Do the notrace functions check without kprobes on ftrace 2021-01-19 18:27:19 +01:00
kprobe_event_gen_test.c tracing: Add kprobe event command generation test module 2020-01-30 09:46:28 -05:00
Makefile Kbuild updates for v5.9 2020-08-09 14:10:26 -07:00
power-traces.c
preemptirq_delay_test.c tracing: Wait for preempt irq delay thread to execute 2020-05-11 17:00:34 -04:00
ring_buffer_benchmark.c sched,tracing: Convert to sched_set_fifo() 2020-07-29 11:43:53 +02:00
ring_buffer.c ring-buffer: Force before_stamp and write_stamp to be different on discard 2021-03-09 11:11:12 +01:00
rpm-traces.c
synth_event_gen_test.c tracing: Add support for dynamic strings to synthetic events 2020-10-05 19:32:18 -04:00
trace_benchmark.c trace: Use pr_warn instead of pr_warning 2019-10-18 15:01:57 +02:00
trace_benchmark.h
trace_boot.c tracing: Disable ftrace selftests when any tracer is running 2020-12-30 11:54:28 +01:00
trace_branch.c tracing: Make struct ring_buffer less ambiguous 2020-01-13 13:19:38 -05:00
trace_clock.c tracing: Restructure trace_clock_global() to never block 2021-05-11 14:47:40 +02:00
trace_dynevent.c tracing: Delete repeated words in comments 2020-09-21 21:06:02 -04:00
trace_dynevent.h tracing: Remove check_arg() callbacks from dynevent args 2020-02-01 13:09:23 -05:00
trace_entries.h tracing: Make ftrace packed events have align of 1 2020-06-16 21:21:02 -04:00
trace_event_perf.c Merge branch 'perf/urgent' into perf/core, to pick up fixes 2019-10-28 12:38:26 +01:00
trace_events_filter_test.h
trace_events_filter.c treewide: Use fallthrough pseudo-keyword 2020-08-23 17:36:59 -05:00
trace_events_hist.c tracing: Check return value of __create_val_fields() before using its result 2020-10-15 12:00:59 -04:00
trace_events_inject.c tracing: Initialize val to zero in parse_entry of inject code 2020-01-02 19:04:57 -05:00
trace_events_synth.c tracing: Make -ENOMEM the default error for parse_synth_field() 2020-11-02 15:58:32 -05:00
trace_events_trigger.c tracing: Fix event trigger to accept redundant spaces 2020-06-23 21:51:40 -04:00
trace_events.c tracing: Do not count ftrace events in top level enable output 2021-02-17 11:02:20 +01:00
trace_export.c treewide: Convert macro and uses of __section(foo) to __section("foo") 2020-10-25 14:51:49 -07:00
trace_functions_graph.c tracing: make tracing_init_dentry() returns an integer instead of a d_entry pointer 2020-09-18 22:17:14 -04:00
trace_functions.c tracing: Enable creating new instance early boot 2020-09-21 21:06:04 -04:00
trace_hwlat.c tracing: Remove WARN_ON in start_thread() 2020-11-30 21:43:07 -05:00
trace_irqsoff.c tracing: Use pause-on-trace with the latency tracers 2021-02-10 09:29:16 +01:00
trace_kdb.c tracing: Rename trace_buffer to array_buffer 2020-01-13 13:19:38 -05:00
trace_kprobe_selftest.c
trace_kprobe_selftest.h
trace_kprobe.c tracing/kprobe: Fix to support kretprobe events on unloaded modules 2021-02-10 09:29:16 +01:00
trace_mmiotrace.c tracing: Make struct ring_buffer less ambiguous 2020-01-13 13:19:38 -05:00
trace_nop.c
trace_output.c tracing: Make the space reserved for the pid wider 2020-09-18 12:42:11 -04:00
trace_output.h
trace_preemptirq.c lockdep: fix order in trace_hardirqs_off_caller() 2020-09-14 10:08:07 +02:00
trace_printk.c Updates for tracing and bootconfig: 2020-10-15 15:51:28 -07:00
trace_probe_tmpl.h
trace_probe.c tracing/probe: Fix memleak in fetch_op_data operations 2020-06-16 21:21:02 -04:00
trace_probe.h tracing: Move is_good_name() from trace_probe.h to trace.h 2020-10-15 12:01:13 -04:00
trace_sched_switch.c tracing: Fix sched switch start/stop refcount racy updates 2020-01-30 09:46:10 -05:00
trace_sched_wakeup.c tracing: Make struct ring_buffer less ambiguous 2020-01-13 13:19:38 -05:00
trace_selftest_dynamic.c
trace_selftest.c tracing: Disable ftrace selftests when any tracer is running 2020-12-30 11:54:28 +01:00
trace_seq.c tracing: Remove unused TRACE_SEQ_BUF_USED 2020-01-21 18:39:54 -05:00
trace_stack.c tracing: make tracing_init_dentry() returns an integer instead of a d_entry pointer 2020-09-18 22:17:14 -04:00
trace_stat.c tracing: make tracing_init_dentry() returns an integer instead of a d_entry pointer 2020-09-18 22:17:14 -04:00
trace_stat.h tracing: Use generic type for comparator function 2019-11-14 13:15:11 -05:00
trace_synth.h tracing: Add support for dynamic strings to synthetic events 2020-10-05 19:32:18 -04:00
trace_syscalls.c Tracing updates: 2020-02-06 07:12:11 +00:00
trace_uprobe.c tracing/uprobes: Support perf-style return probe 2020-09-21 21:06:03 -04:00
trace.c tracing: Map all PIDs to command lines 2021-05-11 14:47:40 +02:00
trace.h tracing: Disable ftrace selftests when any tracer is running 2020-12-30 11:54:28 +01:00
tracing_map.c tracing: Delete repeated words in comments 2020-09-21 21:06:02 -04:00
tracing_map.h