kernel_optimize_test/kernel/trace
Steven Rostedt (VMware) c9fd0ab39f tracing: Do no increment trace_clock_global() by one
commit 89529d8b8f8daf92d9979382b8d2eb39966846ea upstream.

The trace_clock_global() tries to make sure the events between CPUs is
somewhat in order. A global value is used and updated by the latest read
of a clock. If one CPU is ahead by a little, and is read by another CPU, a
lock is taken, and if the timestamp of the other CPU is behind, it will
simply use the other CPUs timestamp.

The lock is also only taken with a "trylock" due to tracing, and strange
recursions can happen. The lock is not taken at all in NMI context.

In the case where the lock is not able to be taken, the non synced
timestamp is returned. But it will not be less than the saved global
timestamp.

The problem arises because when the time goes "backwards" the time
returned is the saved timestamp plus 1. If the lock is not taken, and the
plus one to the timestamp is returned, there's a small race that can cause
the time to go backwards!

	CPU0				CPU1
	----				----
				trace_clock_global() {
				    ts = clock() [ 1000 ]
				    trylock(clock_lock) [ success ]
				    global_ts = ts; [ 1000 ]

				    <interrupted by NMI>
 trace_clock_global() {
    ts = clock() [ 999 ]
    if (ts < global_ts)
	ts = global_ts + 1 [ 1001 ]

    trylock(clock_lock) [ fail ]

    return ts [ 1001]
 }
				    unlock(clock_lock);
				    return ts; [ 1000 ]
				}

 trace_clock_global() {
    ts = clock() [ 1000 ]
    if (ts < global_ts) [ false 1000 == 1000 ]

    trylock(clock_lock) [ success ]
    global_ts = ts; [ 1000 ]
    unlock(clock_lock)

    return ts; [ 1000 ]
 }

The above case shows to reads of trace_clock_global() on the same CPU, but
the second read returns one less than the first read. That is, time when
backwards, and this is not what is allowed by trace_clock_global().

This was triggered by heavy tracing and the ring buffer checker that tests
for the clock going backwards:

 Ring buffer clock went backwards: 20613921464 -> 20613921463
 ------------[ cut here ]------------
 WARNING: CPU: 2 PID: 0 at kernel/trace/ring_buffer.c:3412 check_buffer+0x1b9/0x1c0
 Modules linked in:
 [..]
 [CPU: 2]TIME DOES NOT MATCH expected:20620711698 actual:20620711697 delta:6790234 before:20613921463 after:20613921463
   [20613915818] PAGE TIME STAMP
   [20613915818] delta:0
   [20613915819] delta:1
   [20613916035] delta:216
   [20613916465] delta:430
   [20613916575] delta:110
   [20613916749] delta:174
   [20613917248] delta:499
   [20613917333] delta:85
   [20613917775] delta:442
   [20613917921] delta:146
   [20613918321] delta:400
   [20613918568] delta:247
   [20613918768] delta:200
   [20613919306] delta:538
   [20613919353] delta:47
   [20613919980] delta:627
   [20613920296] delta:316
   [20613920571] delta:275
   [20613920862] delta:291
   [20613921152] delta:290
   [20613921464] delta:312
   [20613921464] delta:0 TIME EXTEND
   [20613921464] delta:0

This happened more than once, and always for an off by one result. It also
started happening after commit aafe104aa9096 was added.

Cc: stable@vger.kernel.org
Fixes: aafe104aa9096 ("tracing: Restructure trace_clock_global() to never block")
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
2021-06-23 14:42:50 +02:00
..
blktrace.c block: add a bdget_part helper 2020-10-05 10:38:33 -06:00
bpf_trace.c bpf, lockdown, audit: Fix buggy SELinux lockdown permission checks 2021-06-10 13:39:19 +02: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: Do not blindly read the ip address in ftrace_bug() 2021-06-16 12:01:40 +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_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: Do no increment trace_clock_global() by one 2021-06-23 14:42:50 +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
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
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: Do not stop recording comms if the trace file is being read 2021-06-23 14:42:50 +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