linux/kernel/trace
Steven Rostedt (VMware) 89529d8b8f tracing: Do no increment trace_clock_global() by one
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 aafe104aa9 was added.

Cc: stable@vger.kernel.org
Fixes: aafe104aa9 ("tracing: Restructure trace_clock_global() to never block")
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
2021-06-18 09:10:00 -04:00
..
blktrace.c block-5.12-2021-02-27 2021-02-28 11:23:38 -08:00
bpf_trace.c bpf, lockdown, audit: Fix buggy SELinux lockdown permission checks 2021-06-02 21:59:22 +02:00
bpf_trace.h bpf: Use dedicated bpf_trace_printk event instead of trace_printk() 2020-07-13 16:55:49 -07:00
error_report-traces.c tracing: add error_report_end trace point 2021-02-26 09:41:02 -08:00
fgraph.c tracing: Fix various typos in comments 2021-03-23 14:08:18 -04:00
ftrace_internal.h
ftrace.c ftrace: Do not blindly read the ip address in ftrace_bug() 2021-06-08 16:44:00 -04:00
Kconfig tracing: Fix help text of TRACEPOINT_BENCHMARK in Kconfig 2021-03-04 09:45:17 -05:00
kprobe_event_gen_test.c
Makefile tracing: add error_report_end trace point 2021-02-26 09:41:02 -08:00
power-traces.c
preemptirq_delay_test.c kernel: trace: preemptirq_delay_test: add cpu affinity 2021-02-02 17:02:07 -05:00
ring_buffer_benchmark.c sched,tracing: Convert to sched_set_fifo() 2020-07-29 11:43:53 +02:00
ring_buffer.c tracing: Remove unused argument from "ring_buffer_time_stamp() 2021-04-01 14:18:32 -04:00
rpm-traces.c
synth_event_gen_test.c tracing: Fix various typos in comments 2021-03-23 14:08:18 -04:00
trace_benchmark.c tracing: Fix some typos in comments 2020-11-10 20:39:40 -05:00
trace_benchmark.h
trace_boot.c tracing: Disable ftrace selftests when any tracer is running 2020-12-14 12:05:03 -05:00
trace_branch.c tracing: Merge irqflags + preempt counter. 2021-02-02 17:02:06 -05:00
trace_clock.c tracing: Do no increment trace_clock_global() by one 2021-06-18 09:10:00 -04:00
trace_dynevent.c tracing/dynevent: Fix a memory leak in an error handling path 2021-04-13 12:29:48 -04:00
trace_dynevent.h tracing/dynevent: Delegate parsing to create function 2021-02-09 12:52:15 -05:00
trace_entries.h tracing: Define new ftrace event "func_repeats" 2021-04-15 14:50:01 -04:00
trace_event_perf.c tracing: Fix various typos in comments 2021-03-23 14:08:18 -04:00
trace_events_filter_test.h
trace_events_filter.c tracing: Update create_system_filter() kernel-doc comment 2021-03-25 16:04:35 -04:00
trace_events_hist.c tracing: Use a no_filter_buffering_ref to stop using the filter buffer 2021-03-18 12:58:26 -04:00
trace_events_inject.c tracing: Merge irqflags + preempt counter. 2021-02-02 17:02:06 -05:00
trace_events_synth.c tracing: Fix various typos in comments 2021-03-23 14:08:18 -04:00
trace_events_trigger.c tracing: Pass buffer of event to trigger operations 2021-03-18 12:58:26 -04:00
trace_events.c tracing: Fix various typos in comments 2021-03-23 14:08:18 -04:00
trace_export.c tracing: Fix some typos in comments 2020-11-10 20:39:40 -05:00
trace_functions_graph.c tracing: Fix various typos in comments 2021-03-23 14:08:18 -04:00
trace_functions.c tracing: Add "func_no_repeats" option for function tracing 2021-04-15 14:50:02 -04:00
trace_hwlat.c tracing: Fix various typos in comments 2021-03-23 14:08:18 -04:00
trace_irqsoff.c tracing: Merge irqflags + preempt counter. 2021-02-02 17:02:06 -05:00
trace_kdb.c
trace_kprobe_selftest.c
trace_kprobe_selftest.h
trace_kprobe.c tracing: Fix various typos in comments 2021-03-23 14:08:18 -04:00
trace_mmiotrace.c tracing: Remove definition of DEBUG in trace_mmiotrace.c 2021-02-02 17:02:07 -05:00
trace_nop.c
trace_output.c ftrace: Reuse the output of the function tracer for func_repeats 2021-04-15 16:34:26 -04:00
trace_output.h ftrace: Add recording of functions that caused recursion 2020-11-06 08:42:26 -05:00
trace_preemptirq.c lockdep: fix order in trace_hardirqs_off_caller() 2020-09-14 10:08:07 +02:00
trace_printk.c tracing: Add a verifier to check string pointers for trace events 2021-03-18 12:58:27 -04:00
trace_probe_tmpl.h tracing: Fix various typos in comments 2021-03-23 14:08:18 -04:00
trace_probe.c tracing: Fix various typos in comments 2021-03-23 14:08:18 -04:00
trace_probe.h tracing: Fix various typos in comments 2021-03-23 14:08:18 -04:00
trace_recursion_record.c ftrace: Add recording of functions that caused recursion 2020-11-06 08:42:26 -05:00
trace_sched_switch.c
trace_sched_wakeup.c tracing: Merge irqflags + preempt counter. 2021-02-02 17:02:06 -05:00
trace_selftest_dynamic.c
trace_selftest.c tracing: Fix various typos in comments 2021-03-23 14:08:18 -04:00
trace_seq.c tracing: Fix various typos in comments 2021-03-23 14:08:18 -04:00
trace_stack.c ftrace: Have the callbacks receive a struct ftrace_regs instead of pt_regs 2020-11-13 12:14:55 -05: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: Merge irqflags + preempt counter. 2021-02-02 17:02:06 -05:00
trace_uprobe.c tracing/dynevent: Delegate parsing to create function 2021-02-09 12:52:15 -05:00
trace.c tracing: Do not stop recording comms if the trace file is being read 2021-06-18 09:10:00 -04:00
trace.h tracing: Add method for recording "func_repeats" events 2021-04-15 14:50:02 -04:00
tracing_map.c tracing: Fix some typos in comments 2020-11-10 20:39:40 -05:00
tracing_map.h tracing: Fix some typos in comments 2020-11-10 20:39:40 -05:00