[RFC PATCH 1/3] Tracepoint: fix documentation of RCU lockdep checks

[RFC PATCH 1/3] Tracepoint: fix documentation of RCU lockdep checks

[Mathieu Desnoyers]

The documentation on top of __DECLARE_TRACE() does not match its
implementation since the condition check has been added to the
RCU lockdep checks. Update the documentation to match its
implementation.

Fixes: a05d59a56733 "tracing: Add condition check to RCU lockdep checks"
Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
CC: Dave Hansen <dave@sr71.net>
CC: Steven Rostedt <rostedt@goodmis.org>
---
 include/linux/tracepoint.h | 9 +++++----
 1 file changed, 5 insertions(+), 4 deletions(-)

diff --git a/include/linux/tracepoint.h b/include/linux/tracepoint.h
index a5f7f3e..c8e3030 100644
--- a/include/linux/tracepoint.h
+++ b/include/linux/tracepoint.h
@@ -167,10 +167,11 @@ extern void syscall_unregfunc(void);
  * structure. Force alignment to the same alignment as the section start.
  *
  * When lockdep is enabled, we make sure to always do the RCU portions of
- * the tracepoint code, regardless of whether tracing is on or we match the
- * condition.  This lets us find RCU issues triggered with tracepoints even
- * when this tracepoint is off.  This code has no purpose other than poking
- * RCU a bit.
+ * the tracepoint code, regardless of whether tracing is on. However,
+ * don't check if the condition is false, due to interaction with idle
+ * instrumentation. This lets us find RCU issues triggered with tracepoints
+ * even when this tracepoint is off. This code has no purpose other than
+ * poking RCU a bit.
  */
 #define __DECLARE_TRACE(name, proto, args, cond, data_proto, data_args) \
 	extern struct tracepoint __tracepoint_##name;			\
-- 
2.1.4

[RFC PATCH 2/3] ftrace: add ftrace-buffer option

[Mathieu Desnoyers]

In order to use ftrace tracers to generate tracepoints without doing
tracing to its own hardcoded ring buffers, add a ftrace-buffer option
(default: 1). When set to 0, it disables tracing into the ftrace
hardcoded buffers.

Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
CC: Thomas Gleixner <tglx@linutronix.de>
CC: Steven Rostedt <rostedt@goodmis.org>
CC: Ingo Molnar <mingo@redhat.com>
CC: Peter Zijlstra <peterz@infradead.org>
---
 kernel/trace/trace.c         |  4 +++-
 kernel/trace/trace.h         |  1 +
 kernel/trace/trace_irqsoff.c | 19 +++++++++++--------
 3 files changed, 15 insertions(+), 9 deletions(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 6e79408..d664f0e 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -472,7 +472,8 @@ static inline void trace_access_lock_init(void)
 unsigned long trace_flags = TRACE_ITER_PRINT_PARENT | TRACE_ITER_PRINTK |
 	TRACE_ITER_ANNOTATE | TRACE_ITER_CONTEXT_INFO | TRACE_ITER_SLEEP_TIME |
 	TRACE_ITER_GRAPH_TIME | TRACE_ITER_RECORD_CMD | TRACE_ITER_OVERWRITE |
-	TRACE_ITER_IRQ_INFO | TRACE_ITER_MARKERS | TRACE_ITER_FUNCTION;
+	TRACE_ITER_IRQ_INFO | TRACE_ITER_MARKERS | TRACE_ITER_FUNCTION |
+	TRACE_ITER_FTRACE_BUFFER;
 
 static void tracer_tracing_on(struct trace_array *tr)
 {
@@ -862,6 +863,7 @@ static const char *trace_options[] = {
 	"irq-info",
 	"markers",
 	"function-trace",
+	"ftrace-buffer",
 	NULL
 };
 
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 74bde81..29968e1 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -930,6 +930,7 @@ enum trace_iterator_flags {
 	TRACE_ITER_IRQ_INFO		= 0x800000,
 	TRACE_ITER_MARKERS		= 0x1000000,
 	TRACE_ITER_FUNCTION		= 0x2000000,
+	TRACE_ITER_FTRACE_BUFFER	= 0x4000000,
 };
 
 /*
diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
index 8523ea3..3e5635d 100644
--- a/kernel/trace/trace_irqsoff.c
+++ b/kernel/trace/trace_irqsoff.c
@@ -334,9 +334,11 @@ check_critical_timing(struct trace_array *tr,
 	if (!report_latency(tr, delta))
 		goto out_unlock;
 
-	__trace_function(tr, CALLER_ADDR0, parent_ip, flags, pc);
-	/* Skip 5 functions to get to the irq/preempt enable function */
-	__trace_stack(tr, flags, 5, pc);
+	if (trace_flags & TRACE_ITER_FTRACE_BUFFER) {
+		__trace_function(tr, CALLER_ADDR0, parent_ip, flags, pc);
+		/* Skip 5 functions to get to the irq/preempt enable function */
+		__trace_stack(tr, flags, 5, pc);
+	}
 
 	if (data->critical_sequence != max_sequence)
 		goto out_unlock;
@@ -356,7 +358,8 @@ out_unlock:
 out:
 	data->critical_sequence = max_sequence;
 	data->preempt_timestamp = ftrace_now(cpu);
-	__trace_function(tr, CALLER_ADDR0, parent_ip, flags, pc);
+	if (trace_flags & TRACE_ITER_FTRACE_BUFFER)
+		__trace_function(tr, CALLER_ADDR0, parent_ip, flags, pc);
 }
 
 static inline void
@@ -387,9 +390,8 @@ start_critical_timing(unsigned long ip, unsigned long parent_ip)
 	data->critical_start = parent_ip ? : ip;
 
 	local_save_flags(flags);
-
-	__trace_function(tr, ip, parent_ip, flags, preempt_count());
-
+	if (trace_flags & TRACE_ITER_FTRACE_BUFFER)
+		__trace_function(tr, ip, parent_ip, flags, preempt_count());
 	per_cpu(tracing_cpu, cpu) = 1;
 
 	atomic_dec(&data->disabled);
@@ -422,7 +424,8 @@ stop_critical_timing(unsigned long ip, unsigned long parent_ip)
 	atomic_inc(&data->disabled);
 
 	local_save_flags(flags);
-	__trace_function(tr, ip, parent_ip, flags, preempt_count());
+	if (trace_flags & TRACE_ITER_FTRACE_BUFFER)
+		__trace_function(tr, ip, parent_ip, flags, preempt_count());
 	check_critical_timing(tr, data, parent_ip ? : ip, cpu);
 	data->critical_start = 0;
 	atomic_dec(&data->disabled);
-- 
2.1.4

[RFC PATCH v2 3/3] trace: emit tracepoint in preempt and irqs off tracer

[Mathieu Desnoyers]

Allow Ftrace, Perf, and LTTng to hook on the irqsoff tracer and trace
irqsoff and preemptoff critical sections.

How to setup the irqsoff tracer for this use-case (needed for use with
Ftrace, Perf, or LTTng): if the tracing_thresh value is set, all
durations beyond the specified threshold will emit a
"core_critical_timing_hit" tracepoint. If unset, then the max duration
will be tracked. The current max duration can be reset using the
tracing_max_latency file.

echo 0 > /sys/kernel/debug/tracing/options/function-trace  # don't need function tracing
echo 0 > /sys/kernel/debug/tracing/options/ftrace-buffer
echo preemptirqsoff > /sys/kernel/debug/tracing/current_tracer
echo 2 > /sys/kernel/debug/tracing/tracing_thresh      # set threshold (e.g. 2 µs)
echo 1 > /sys/kernel/debug/tracing/tracing_on

The following two commands can also be useful to tweak the
irqsoff tracer:
echo 0 > /sys/kernel/debug/tracing/tracing_max_latency # reset max latency
echo 0 > /sys/kernel/debug/tracing/tracing_thresh      # disable threshold

*** An example usage of Ftrace hooking on this tracepoint: ***

echo 1 > /sys/kernel/debug/tracing/events/core/core_critical_timing_hit/enable
cat /sys/kernel/debug/tracing/trace_pipe
[...]
    bash-2380   19d..3 52794942us : core_critical_timing_hit: ip=0xffffffff811021de parent_ip=0xffffffff818d1b17 delta_ns=3402 irqs_disabled=0 preempt_disabled=1 in_softirq=0 in_irq=0 in_nmi=0

*** An example usage of Perf hooking on this tracepoint: ***

perf record -g -e core:core_critical_timing_hit -c 1 sleep 30
perf report -g

+  100.00%   100.00%  sleep    [kernel.vmlinux]  [k] check_critical_timing
+   92.75%     0.00%  sleep    [kernel.vmlinux]  [k] preempt_count_sub
+   92.75%     0.00%  sleep    [kernel.vmlinux]  [k] trace_preempt_on
+   65.22%     0.00%  sleep    [kernel.vmlinux]  [k] page_fault
+   65.22%     0.00%  sleep    [kernel.vmlinux]  [k] do_page_fault
+   63.77%     0.00%  sleep    [kernel.vmlinux]  [k] __do_page_fault
+   63.77%     0.00%  sleep    [kernel.vmlinux]  [k] handle_mm_fault
+   56.52%     0.00%  sleep    [kernel.vmlinux]  [k] _raw_spin_unlock
+   30.43%     0.00%  sleep    ld-2.19.so        [.] _dl_sysdep_start
[...]

*** An example usage of LTTng hooking on this tracepoint: ***

(as root)
lttng-sessiond -d

(then, as root or tracing group)
lttng create --live
lttng enable-event -k core_critical_timing_hit
lttng start
lttng view
[...]
[17:34:17.090669588] (+1.569689755) compudjdev core_critical_timing_hit: { cpu_id = 3 }, { ip = 0xFFFFFFFF81102135, parent_ip = 0xFFFFFFFFA0798E13, delta_ns = 252994, irqs_disabled = 0, preempt_disabled = 1, in_softirq = 0, in_irq = 0, in_nmi = 0 }

Tracepoints core_critical_timing_start and core_critical_timing_stop are
also available. They trigger at a much higher rate than
core_critical_timing_hit.

Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@efficios.com>
CC: Thomas Gleixner <tglx@linutronix.de>
CC: Steven Rostedt <rostedt@goodmis.org>
CC: Ingo Molnar <mingo@redhat.com>
CC: Peter Zijlstra <peterz@infradead.org>
---
Changes since v1:
- Remove unneeded tracepoint jump label bypass.
- Enhance TP_printk() formatting.
- Use new ftrace-buffer option in changelog.
- Add core_critical_timing_start/stop tracepoints.
---
 include/trace/events/core.h  | 96 ++++++++++++++++++++++++++++++++++++++++++++
 kernel/trace/trace_irqsoff.c | 17 ++++++--
 2 files changed, 109 insertions(+), 4 deletions(-)
 create mode 100644 include/trace/events/core.h

diff --git a/include/trace/events/core.h b/include/trace/events/core.h
new file mode 100644
index 0000000..ccc3430
--- /dev/null
+++ b/include/trace/events/core.h
@@ -0,0 +1,96 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM core
+
+#if !defined(_TRACE_CORE_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_CORE_H
+
+#include <linux/tracepoint.h>
+#include <linux/irqflags.h>
+#include <linux/preempt.h>
+
+/*
+ * Tracepoint for critical timings max/threshold hit.
+ */
+TRACE_EVENT(core_critical_timing_hit,
+
+	TP_PROTO(unsigned long ip, unsigned long parent_ip,
+			unsigned long flags, int preempt_cnt,
+			cycles_t delta_ns),
+
+	TP_ARGS(ip, parent_ip, flags, preempt_cnt, delta_ns),
+
+	TP_STRUCT__entry(
+		__field(	unsigned long, ip		)
+		__field(	unsigned long, parent_ip	)
+		__field(	cycles_t, delta_ns		)
+		__field(	unsigned long, flags		)
+		__field(	int, preempt_cnt		)
+	),
+
+	TP_fast_assign(
+		__entry->ip		= ip;
+		__entry->parent_ip	= parent_ip;
+		__entry->delta_ns	= delta_ns;
+		__entry->flags		= flags;
+		__entry->preempt_cnt	= preempt_cnt;
+	),
+
+	TP_printk("ip=0x%lx parent_ip=0x%lx delta_ns=%llu irqs_disabled=%u preempt_disabled=%u in_softirq=%u in_irq=%u in_nmi=%u",
+		  __entry->ip, __entry->parent_ip,
+		  (unsigned long long) __entry->delta_ns,
+		  !!raw_irqs_disabled_flags(__entry->flags),
+		  !!(__entry->preempt_cnt & PREEMPT_MASK),
+		  !!(__entry->preempt_cnt & SOFTIRQ_MASK),
+		  !!(__entry->preempt_cnt & HARDIRQ_MASK),
+		  !!(__entry->preempt_cnt & NMI_MASK))
+);
+
+/*
+ * Tracepoint for critical timings start/stop.
+ */
+DECLARE_EVENT_CLASS(core_critical_timing,
+
+	TP_PROTO(unsigned long ip, unsigned long parent_ip,
+			unsigned long flags, int preempt_cnt),
+
+	TP_ARGS(ip, parent_ip, flags, preempt_cnt),
+
+	TP_STRUCT__entry(
+		__field(	unsigned long, ip		)
+		__field(	unsigned long, parent_ip	)
+		__field(	unsigned long, flags		)
+		__field(	int, preempt_cnt		)
+	),
+
+	TP_fast_assign(
+		__entry->ip		= ip;
+		__entry->parent_ip	= parent_ip;
+		__entry->flags		= flags;
+		__entry->preempt_cnt	= preempt_cnt;
+	),
+
+	TP_printk("ip=0x%lx parent_ip=0x%lx irqs_disabled=%u preempt_disabled=%u in_softirq=%u in_irq=%u in_nmi=%u",
+		  __entry->ip, __entry->parent_ip,
+		  !!raw_irqs_disabled_flags(__entry->flags),
+		  !!(__entry->preempt_cnt & PREEMPT_MASK),
+		  !!(__entry->preempt_cnt & SOFTIRQ_MASK),
+		  !!(__entry->preempt_cnt & HARDIRQ_MASK),
+		  !!(__entry->preempt_cnt & NMI_MASK))
+);
+
+DEFINE_EVENT(core_critical_timing, core_critical_timing_start,
+	TP_PROTO(unsigned long ip, unsigned long parent_ip,
+		unsigned long flags, int preempt_cnt),
+	TP_ARGS(ip, parent_ip, flags, preempt_cnt)
+);
+
+DEFINE_EVENT(core_critical_timing, core_critical_timing_stop,
+	TP_PROTO(unsigned long ip, unsigned long parent_ip,
+		unsigned long flags, int preempt_cnt),
+	TP_ARGS(ip, parent_ip, flags, preempt_cnt)
+);
+
+#endif /* _TRACE_CORE_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
index 3e5635d..abfb77e 100644
--- a/kernel/trace/trace_irqsoff.c
+++ b/kernel/trace/trace_irqsoff.c
@@ -14,6 +14,9 @@
 #include <linux/module.h>
 #include <linux/ftrace.h>
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/core.h>
+
 #include "trace.h"
 
 static struct trace_array		*irqsoff_trace __read_mostly;
@@ -339,6 +342,8 @@ check_critical_timing(struct trace_array *tr,
 		/* Skip 5 functions to get to the irq/preempt enable function */
 		__trace_stack(tr, flags, 5, pc);
 	}
+	trace_core_critical_timing_hit(CALLER_ADDR0, parent_ip, flags, pc,
+			delta);
 
 	if (data->critical_sequence != max_sequence)
 		goto out_unlock;
@@ -365,7 +370,7 @@ out:
 static inline void
 start_critical_timing(unsigned long ip, unsigned long parent_ip)
 {
-	int cpu;
+	int cpu, pc;
 	struct trace_array *tr = irqsoff_trace;
 	struct trace_array_cpu *data;
 	unsigned long flags;
@@ -390,8 +395,10 @@ start_critical_timing(unsigned long ip, unsigned long parent_ip)
 	data->critical_start = parent_ip ? : ip;
 
 	local_save_flags(flags);
+	pc = preempt_count();
 	if (trace_flags & TRACE_ITER_FTRACE_BUFFER)
-		__trace_function(tr, ip, parent_ip, flags, preempt_count());
+		__trace_function(tr, ip, parent_ip, flags, pc);
+	trace_core_critical_timing_start(ip, parent_ip, flags, pc);
 	per_cpu(tracing_cpu, cpu) = 1;
 
 	atomic_dec(&data->disabled);
@@ -400,7 +407,7 @@ start_critical_timing(unsigned long ip, unsigned long parent_ip)
 static inline void
 stop_critical_timing(unsigned long ip, unsigned long parent_ip)
 {
-	int cpu;
+	int cpu, pc;
 	struct trace_array *tr = irqsoff_trace;
 	struct trace_array_cpu *data;
 	unsigned long flags;
@@ -424,8 +431,10 @@ stop_critical_timing(unsigned long ip, unsigned long parent_ip)
 	atomic_inc(&data->disabled);
 
 	local_save_flags(flags);
+	pc = preempt_count();
 	if (trace_flags & TRACE_ITER_FTRACE_BUFFER)
-		__trace_function(tr, ip, parent_ip, flags, preempt_count());
+		__trace_function(tr, ip, parent_ip, flags, pc);
+	trace_core_critical_timing_stop(ip, parent_ip, flags, pc);
 	check_critical_timing(tr, data, parent_ip ? : ip, cpu);
 	data->critical_start = 0;
 	atomic_dec(&data->disabled);
-- 
2.1.4