All of lore.kernel.org
 help / color / mirror / Atom feed
* [PATCH v7 1/2] tracing: Prepare to add preempt and irq trace events
@ 2017-09-29 21:22 Joel Fernandes
  2017-09-29 21:22 ` [PATCH v7 2/2] tracing: Add support for preempt and irq enable/disable events Joel Fernandes
  0 siblings, 1 reply; 17+ messages in thread
From: Joel Fernandes @ 2017-09-29 21:22 UTC (permalink / raw)
  To: linux-kernel; +Cc: kernel-team, Joel Fernandes, Steven Rostedt, Peter Zijlstra

In preparation of adding irqsoff and preemptsoff enable and disable trace
events, move required functions and code to make it easier to add these events
in a later patch. This patch is just code movement and no functional change.

Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: kernel-team@android.com
Signed-off-by: Joel Fernandes <joelaf@google.com>
---
 kernel/trace/trace_irqsoff.c | 100 ++++++++++++++++++++++++++++++++-----------
 1 file changed, 74 insertions(+), 26 deletions(-)

diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
index 7758bc0617cb..0e3033c00474 100644
--- a/kernel/trace/trace_irqsoff.c
+++ b/kernel/trace/trace_irqsoff.c
@@ -16,6 +16,7 @@
 
 #include "trace.h"
 
+#if defined(CONFIG_IRQSOFF_TRACER) || defined(CONFIG_PREEMPT_TRACER)
 static struct trace_array		*irqsoff_trace __read_mostly;
 static int				tracer_enabled __read_mostly;
 
@@ -462,64 +463,44 @@ void time_hardirqs_off(unsigned long a0, unsigned long a1)
 
 #else /* !CONFIG_PROVE_LOCKING */
 
-/*
- * Stubs:
- */
-
-void trace_softirqs_on(unsigned long ip)
-{
-}
-
-void trace_softirqs_off(unsigned long ip)
-{
-}
-
-inline void print_irqtrace_events(struct task_struct *curr)
-{
-}
-
 /*
  * We are only interested in hardirq on/off events:
  */
-void trace_hardirqs_on(void)
+static inline void tracer_hardirqs_on(void)
 {
 	if (!preempt_trace() && irq_trace())
 		stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
 }
-EXPORT_SYMBOL(trace_hardirqs_on);
 
-void trace_hardirqs_off(void)
+static inline void tracer_hardirqs_off(void)
 {
 	if (!preempt_trace() && irq_trace())
 		start_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
 }
-EXPORT_SYMBOL(trace_hardirqs_off);
 
-__visible void trace_hardirqs_on_caller(unsigned long caller_addr)
+static inline void tracer_hardirqs_on_caller(unsigned long caller_addr)
 {
 	if (!preempt_trace() && irq_trace())
 		stop_critical_timing(CALLER_ADDR0, caller_addr);
 }
-EXPORT_SYMBOL(trace_hardirqs_on_caller);
 
-__visible void trace_hardirqs_off_caller(unsigned long caller_addr)
+static inline void tracer_hardirqs_off_caller(unsigned long caller_addr)
 {
 	if (!preempt_trace() && irq_trace())
 		start_critical_timing(CALLER_ADDR0, caller_addr);
 }
-EXPORT_SYMBOL(trace_hardirqs_off_caller);
 
 #endif /* CONFIG_PROVE_LOCKING */
 #endif /*  CONFIG_IRQSOFF_TRACER */
 
 #ifdef CONFIG_PREEMPT_TRACER
-void trace_preempt_on(unsigned long a0, unsigned long a1)
+static inline void tracer_preempt_on(unsigned long a0, unsigned long a1)
 {
 	if (preempt_trace() && !irq_trace())
 		stop_critical_timing(a0, a1);
 }
 
-void trace_preempt_off(unsigned long a0, unsigned long a1)
+static inline void tracer_preempt_off(unsigned long a0, unsigned long a1)
 {
 	if (preempt_trace() && !irq_trace())
 		start_critical_timing(a0, a1);
@@ -781,3 +762,70 @@ __init static int init_irqsoff_tracer(void)
 	return 0;
 }
 core_initcall(init_irqsoff_tracer);
+#endif /* IRQSOFF_TRACER || PREEMPTOFF_TRACER */
+
+#ifndef CONFIG_IRQSOFF_TRACER
+static inline void tracer_hardirqs_on(void) { }
+static inline void tracer_hardirqs_off(void) { }
+static inline void tracer_hardirqs_on_caller(unsigned long caller_addr) { }
+static inline void tracer_hardirqs_off_caller(unsigned long caller_addr) { }
+#endif
+
+#ifndef CONFIG_PREEMPT_TRACER
+static inline void tracer_preempt_on(unsigned long a0, unsigned long a1) { }
+static inline void tracer_preempt_off(unsigned long a0, unsigned long a1) { }
+#endif
+
+#if defined(CONFIG_TRACE_IRQFLAGS) && !defined(CONFIG_PROVE_LOCKING)
+void trace_hardirqs_on(void)
+{
+	tracer_hardirqs_on();
+}
+EXPORT_SYMBOL(trace_hardirqs_on);
+
+void trace_hardirqs_off(void)
+{
+	tracer_hardirqs_off();
+}
+EXPORT_SYMBOL(trace_hardirqs_off);
+
+__visible void trace_hardirqs_on_caller(unsigned long caller_addr)
+{
+	tracer_hardirqs_on_caller(caller_addr);
+}
+EXPORT_SYMBOL(trace_hardirqs_on_caller);
+
+__visible void trace_hardirqs_off_caller(unsigned long caller_addr)
+{
+	tracer_hardirqs_off_caller(caller_addr);
+}
+EXPORT_SYMBOL(trace_hardirqs_off_caller);
+
+/*
+ * Stubs:
+ */
+
+void trace_softirqs_on(unsigned long ip)
+{
+}
+
+void trace_softirqs_off(unsigned long ip)
+{
+}
+
+inline void print_irqtrace_events(struct task_struct *curr)
+{
+}
+#endif
+
+#ifdef CONFIG_PREEMPT_TRACER
+void trace_preempt_on(unsigned long a0, unsigned long a1)
+{
+	tracer_preempt_on(a0, a1);
+}
+
+void trace_preempt_off(unsigned long a0, unsigned long a1)
+{
+	tracer_preempt_off(a0, a1);
+}
+#endif
-- 
2.14.2.822.g60be5d43e6-goog

^ permalink raw reply related	[flat|nested] 17+ messages in thread

* [PATCH v7 2/2] tracing: Add support for preempt and irq enable/disable events
  2017-09-29 21:22 [PATCH v7 1/2] tracing: Prepare to add preempt and irq trace events Joel Fernandes
@ 2017-09-29 21:22 ` Joel Fernandes
  2017-10-04 16:01   ` Peter Zijlstra
  2017-10-04 16:04   ` Peter Zijlstra
  0 siblings, 2 replies; 17+ messages in thread
From: Joel Fernandes @ 2017-09-29 21:22 UTC (permalink / raw)
  To: linux-kernel; +Cc: kernel-team, Joel Fernandes, Steven Rostedt, Peter Zilstra

Preempt and irq trace events can be used for tracing the start and
end of an atomic section which can be used by a trace viewer like
systrace to graphically view the start and end of an atomic section and
correlate them with latencies and scheduling issues.

This also serves as a prelude to using synthetic events or probes to
rewrite the preempt and irqsoff tracers, along with numerous benefits of
using trace events features for these events.

Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Peter Zilstra <peterz@infradead.org>
Cc: kernel-team@android.com
Signed-off-by: Joel Fernandes <joelaf@google.com>
---
 include/linux/ftrace.h            |  3 +-
 include/trace/events/preemptirq.h | 66 +++++++++++++++++++++++++++++++++++++++
 kernel/trace/Kconfig              |  9 ++++++
 kernel/trace/Makefile             |  1 +
 kernel/trace/trace_irqsoff.c      | 41 +++++++++++++++++++++++-
 5 files changed, 118 insertions(+), 2 deletions(-)
 create mode 100644 include/trace/events/preemptirq.h

diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
index 2e028854bac7..768e49b8c80f 100644
--- a/include/linux/ftrace.h
+++ b/include/linux/ftrace.h
@@ -742,7 +742,8 @@ static inline unsigned long get_lock_parent_ip(void)
   static inline void time_hardirqs_off(unsigned long a0, unsigned long a1) { }
 #endif
 
-#ifdef CONFIG_PREEMPT_TRACER
+#if defined(CONFIG_PREEMPT_TRACER) || \
+	(defined(CONFIG_DEBUG_PREEMPT) && defined(CONFIG_PREEMPTIRQ_EVENTS))
   extern void trace_preempt_on(unsigned long a0, unsigned long a1);
   extern void trace_preempt_off(unsigned long a0, unsigned long a1);
 #else
diff --git a/include/trace/events/preemptirq.h b/include/trace/events/preemptirq.h
new file mode 100644
index 000000000000..734b7e2a3890
--- /dev/null
+++ b/include/trace/events/preemptirq.h
@@ -0,0 +1,66 @@
+#ifdef CONFIG_PREEMPTIRQ_EVENTS
+
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM preemptirq
+
+#if !defined(_TRACE_PREEMPTIRQ_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_PREEMPTIRQ_H
+
+#include <linux/ktime.h>
+#include <linux/tracepoint.h>
+#include <linux/string.h>
+#include <asm/sections.h>
+
+DECLARE_EVENT_CLASS(preemptirq_template,
+
+	TP_PROTO(unsigned long ip, unsigned long parent_ip),
+
+	TP_ARGS(ip, parent_ip),
+
+	TP_STRUCT__entry(
+		__field(u32, caller_offs)
+		__field(u32, parent_offs)
+	),
+
+	TP_fast_assign(
+		__entry->caller_offs = (u32)(ip - (unsigned long)_stext);
+		__entry->parent_offs = (u32)(parent_ip - (unsigned long)_stext);
+	),
+
+	TP_printk("caller=%pF parent=%pF",
+		  (void *)((unsigned long)(_stext) + __entry->caller_offs),
+		  (void *)((unsigned long)(_stext) + __entry->parent_offs))
+);
+
+DEFINE_EVENT(preemptirq_template, irq_disable,
+	     TP_PROTO(unsigned long ip, unsigned long parent_ip),
+	     TP_ARGS(ip, parent_ip));
+
+DEFINE_EVENT(preemptirq_template, irq_enable,
+	     TP_PROTO(unsigned long ip, unsigned long parent_ip),
+	     TP_ARGS(ip, parent_ip));
+
+DEFINE_EVENT(preemptirq_template, preempt_disable,
+	     TP_PROTO(unsigned long ip, unsigned long parent_ip),
+	     TP_ARGS(ip, parent_ip));
+
+DEFINE_EVENT(preemptirq_template, preempt_enable,
+	     TP_PROTO(unsigned long ip, unsigned long parent_ip),
+	     TP_ARGS(ip, parent_ip));
+
+#endif /* _TRACE_PREEMPTIRQ_H */
+
+#include <trace/define_trace.h>
+
+#else /* !CONFIG_PREEMPTIRQ_EVENTS */
+
+#define trace_irq_enable(...)
+#define trace_irq_disable(...)
+#define trace_preempt_enable(...)
+#define trace_preempt_disable(...)
+#define trace_irq_enable_rcuidle(...)
+#define trace_irq_disable_rcuidle(...)
+#define trace_preempt_enable_rcuidle(...)
+#define trace_preempt_disable_rcuidle(...)
+
+#endif
diff --git a/kernel/trace/Kconfig b/kernel/trace/Kconfig
index 434c840e2d82..420666152de8 100644
--- a/kernel/trace/Kconfig
+++ b/kernel/trace/Kconfig
@@ -160,6 +160,15 @@ config FUNCTION_GRAPH_TRACER
 	  address on the current task structure into a stack of calls.
 
 
+config PREEMPTIRQ_EVENTS
+	bool "Enable trace events for preempt and irq disable/enable"
+	select TRACE_IRQFLAGS
+	default n
+	help
+	  Enable tracing of disable and enable events for preemption and irqs.
+	  For tracing preempt disable/enable events, CONFIG_DEBUG_PREEMPT must
+	  be enabled.
+
 config IRQSOFF_TRACER
 	bool "Interrupts-off Latency Tracer"
 	default n
diff --git a/kernel/trace/Makefile b/kernel/trace/Makefile
index 90f2701d92a7..9f62eee61f14 100644
--- a/kernel/trace/Makefile
+++ b/kernel/trace/Makefile
@@ -34,6 +34,7 @@ obj-$(CONFIG_TRACING) += trace_printk.o
 obj-$(CONFIG_TRACING_MAP) += tracing_map.o
 obj-$(CONFIG_CONTEXT_SWITCH_TRACER) += trace_sched_switch.o
 obj-$(CONFIG_FUNCTION_TRACER) += trace_functions.o
+obj-$(CONFIG_PREEMPTIRQ_EVENTS) += trace_irqsoff.o
 obj-$(CONFIG_IRQSOFF_TRACER) += trace_irqsoff.o
 obj-$(CONFIG_PREEMPT_TRACER) += trace_irqsoff.o
 obj-$(CONFIG_SCHED_TRACER) += trace_sched_wakeup.o
diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
index 0e3033c00474..515ac851841a 100644
--- a/kernel/trace/trace_irqsoff.c
+++ b/kernel/trace/trace_irqsoff.c
@@ -16,6 +16,9 @@
 
 #include "trace.h"
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/preemptirq.h>
+
 #if defined(CONFIG_IRQSOFF_TRACER) || defined(CONFIG_PREEMPT_TRACER)
 static struct trace_array		*irqsoff_trace __read_mostly;
 static int				tracer_enabled __read_mostly;
@@ -776,27 +779,60 @@ static inline void tracer_preempt_on(unsigned long a0, unsigned long a1) { }
 static inline void tracer_preempt_off(unsigned long a0, unsigned long a1) { }
 #endif
 
+/*
+ * trace_hardirqs_off can be called even when IRQs are already off. It is
+ * pointless and inconsistent with trace_preempt_enable and
+ * trace_preempt_disable to trace this, lets prevent double counting it with a
+ * per-cpu variable. Also reuse the per-cpu variable for other trace_hardirqs_*
+ * functions since we already define it.
+ */
+static DEFINE_PER_CPU(int, tracing_irq_cpu);
+
 #if defined(CONFIG_TRACE_IRQFLAGS) && !defined(CONFIG_PROVE_LOCKING)
 void trace_hardirqs_on(void)
 {
+	if (!this_cpu_read(tracing_irq_cpu))
+		return;
+
+	trace_irq_enable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
 	tracer_hardirqs_on();
+
+	this_cpu_write(tracing_irq_cpu, 0);
 }
 EXPORT_SYMBOL(trace_hardirqs_on);
 
 void trace_hardirqs_off(void)
 {
+	if (this_cpu_read(tracing_irq_cpu))
+		return;
+
+	this_cpu_write(tracing_irq_cpu, 1);
+
+	trace_irq_disable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
 	tracer_hardirqs_off();
 }
 EXPORT_SYMBOL(trace_hardirqs_off);
 
 __visible void trace_hardirqs_on_caller(unsigned long caller_addr)
 {
+	if (!this_cpu_read(tracing_irq_cpu))
+		return;
+
+	trace_irq_enable_rcuidle(CALLER_ADDR0, caller_addr);
 	tracer_hardirqs_on_caller(caller_addr);
+
+	this_cpu_write(tracing_irq_cpu, 0);
 }
 EXPORT_SYMBOL(trace_hardirqs_on_caller);
 
 __visible void trace_hardirqs_off_caller(unsigned long caller_addr)
 {
+	if (this_cpu_read(tracing_irq_cpu))
+		return;
+
+	this_cpu_write(tracing_irq_cpu, 1);
+
+	trace_irq_disable_rcuidle(CALLER_ADDR0, caller_addr);
 	tracer_hardirqs_off_caller(caller_addr);
 }
 EXPORT_SYMBOL(trace_hardirqs_off_caller);
@@ -818,14 +854,17 @@ inline void print_irqtrace_events(struct task_struct *curr)
 }
 #endif
 
-#ifdef CONFIG_PREEMPT_TRACER
+#if defined(CONFIG_PREEMPT_TRACER) || \
+	(defined(CONFIG_DEBUG_PREEMPT) && defined(CONFIG_PREEMPTIRQ_EVENTS))
 void trace_preempt_on(unsigned long a0, unsigned long a1)
 {
+	trace_preempt_enable_rcuidle(a0, a1);
 	tracer_preempt_on(a0, a1);
 }
 
 void trace_preempt_off(unsigned long a0, unsigned long a1)
 {
+	trace_preempt_disable_rcuidle(a0, a1);
 	tracer_preempt_off(a0, a1);
 }
 #endif
-- 
2.14.2.822.g60be5d43e6-goog

^ permalink raw reply related	[flat|nested] 17+ messages in thread

* Re: [PATCH v7 2/2] tracing: Add support for preempt and irq enable/disable events
  2017-09-29 21:22 ` [PATCH v7 2/2] tracing: Add support for preempt and irq enable/disable events Joel Fernandes
@ 2017-10-04 16:01   ` Peter Zijlstra
  2017-10-04 16:43     ` Joel Fernandes
  2017-10-05 23:28     ` Joel Fernandes
  2017-10-04 16:04   ` Peter Zijlstra
  1 sibling, 2 replies; 17+ messages in thread
From: Peter Zijlstra @ 2017-10-04 16:01 UTC (permalink / raw)
  To: Joel Fernandes; +Cc: linux-kernel, kernel-team, Steven Rostedt

On Fri, Sep 29, 2017 at 02:22:45PM -0700, Joel Fernandes wrote:
> diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
> index 0e3033c00474..515ac851841a 100644
> --- a/kernel/trace/trace_irqsoff.c
> +++ b/kernel/trace/trace_irqsoff.c
> @@ -16,6 +16,9 @@
>  
>  #include "trace.h"
>  
> +#define CREATE_TRACE_POINTS
> +#include <trace/events/preemptirq.h>
> +
>  #if defined(CONFIG_IRQSOFF_TRACER) || defined(CONFIG_PREEMPT_TRACER)
>  static struct trace_array		*irqsoff_trace __read_mostly;
>  static int				tracer_enabled __read_mostly;
> @@ -776,27 +779,60 @@ static inline void tracer_preempt_on(unsigned long a0, unsigned long a1) { }
>  static inline void tracer_preempt_off(unsigned long a0, unsigned long a1) { }
>  #endif
>  
> +/*
> + * trace_hardirqs_off can be called even when IRQs are already off.

In fact it must be.. otherwise you'll get a complaint.

>     It is
> + * pointless and inconsistent with trace_preempt_enable and
> + * trace_preempt_disable to trace this, lets prevent double counting it with a
> + * per-cpu variable. Also reuse the per-cpu variable for other trace_hardirqs_*
> + * functions since we already define it.

Lockdep ignores redundant calls. But I'm not entirely sure what the
above is trying to say.

> + */
> +static DEFINE_PER_CPU(int, tracing_irq_cpu);
> +
>  #if defined(CONFIG_TRACE_IRQFLAGS) && !defined(CONFIG_PROVE_LOCKING)
>  void trace_hardirqs_on(void)
>  {
> +	if (!this_cpu_read(tracing_irq_cpu))
> +		return;
> +
> +	trace_irq_enable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
>  	tracer_hardirqs_on();
> +
> +	this_cpu_write(tracing_irq_cpu, 0);
>  }
>  EXPORT_SYMBOL(trace_hardirqs_on);
>  
>  void trace_hardirqs_off(void)
>  {
> +	if (this_cpu_read(tracing_irq_cpu))
> +		return;
> +
> +	this_cpu_write(tracing_irq_cpu, 1);
> +
> +	trace_irq_disable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
>  	tracer_hardirqs_off();
>  }
>  EXPORT_SYMBOL(trace_hardirqs_off);
>  
>  __visible void trace_hardirqs_on_caller(unsigned long caller_addr)
>  {
> +	if (!this_cpu_read(tracing_irq_cpu))
> +		return;
> +
> +	trace_irq_enable_rcuidle(CALLER_ADDR0, caller_addr);
>  	tracer_hardirqs_on_caller(caller_addr);
> +
> +	this_cpu_write(tracing_irq_cpu, 0);
>  }
>  EXPORT_SYMBOL(trace_hardirqs_on_caller);
>  
>  __visible void trace_hardirqs_off_caller(unsigned long caller_addr)
>  {
> +	if (this_cpu_read(tracing_irq_cpu))
> +		return;
> +
> +	this_cpu_write(tracing_irq_cpu, 1);
> +
> +	trace_irq_disable_rcuidle(CALLER_ADDR0, caller_addr);
>  	tracer_hardirqs_off_caller(caller_addr);
>  }
>  EXPORT_SYMBOL(trace_hardirqs_off_caller);

lockdep implements the trace_hardirq_*() in terms of *_caller(). Would
that make sense here?

^ permalink raw reply	[flat|nested] 17+ messages in thread

* Re: [PATCH v7 2/2] tracing: Add support for preempt and irq enable/disable events
  2017-09-29 21:22 ` [PATCH v7 2/2] tracing: Add support for preempt and irq enable/disable events Joel Fernandes
  2017-10-04 16:01   ` Peter Zijlstra
@ 2017-10-04 16:04   ` Peter Zijlstra
  2017-10-04 16:31     ` Joel Fernandes
  2017-10-04 16:44     ` Steven Rostedt
  1 sibling, 2 replies; 17+ messages in thread
From: Peter Zijlstra @ 2017-10-04 16:04 UTC (permalink / raw)
  To: Joel Fernandes; +Cc: linux-kernel, kernel-team, Steven Rostedt

On Fri, Sep 29, 2017 at 02:22:45PM -0700, Joel Fernandes wrote:
> +++ b/kernel/trace/trace_irqsoff.c

>  EXPORT_SYMBOL(trace_hardirqs_on);
>  EXPORT_SYMBOL(trace_hardirqs_off);
>  EXPORT_SYMBOL(trace_hardirqs_on_caller);
>  EXPORT_SYMBOL(trace_hardirqs_off_caller);

Steve, how does this compiler with lockdep enabled? Because:

kernel/locking/lockdep.c:EXPORT_SYMBOL(trace_hardirqs_on_caller);
kernel/locking/lockdep.c:EXPORT_SYMBOL(trace_hardirqs_on);
kernel/locking/lockdep.c:EXPORT_SYMBOL(trace_hardirqs_off_caller);
kernel/locking/lockdep.c:EXPORT_SYMBOL(trace_hardirqs_off);

^ permalink raw reply	[flat|nested] 17+ messages in thread

* Re: [PATCH v7 2/2] tracing: Add support for preempt and irq enable/disable events
  2017-10-04 16:04   ` Peter Zijlstra
@ 2017-10-04 16:31     ` Joel Fernandes
  2017-10-04 16:44     ` Steven Rostedt
  1 sibling, 0 replies; 17+ messages in thread
From: Joel Fernandes @ 2017-10-04 16:31 UTC (permalink / raw)
  To: Peter Zijlstra; +Cc: LKML, kernel-team, Steven Rostedt

Hi Peter,

On Wed, Oct 4, 2017 at 9:04 AM, Peter Zijlstra <peterz@infradead.org> wrote:
> On Fri, Sep 29, 2017 at 02:22:45PM -0700, Joel Fernandes wrote:
>> +++ b/kernel/trace/trace_irqsoff.c
>
>>  EXPORT_SYMBOL(trace_hardirqs_on);
>>  EXPORT_SYMBOL(trace_hardirqs_off);
>>  EXPORT_SYMBOL(trace_hardirqs_on_caller);
>>  EXPORT_SYMBOL(trace_hardirqs_off_caller);
>
> Steve, how does this compiler with lockdep enabled? Because:
>
> kernel/locking/lockdep.c:EXPORT_SYMBOL(trace_hardirqs_on_caller);
> kernel/locking/lockdep.c:EXPORT_SYMBOL(trace_hardirqs_on);
> kernel/locking/lockdep.c:EXPORT_SYMBOL(trace_hardirqs_off_caller);
> kernel/locking/lockdep.c:EXPORT_SYMBOL(trace_hardirqs_off);
>

These functions are defined in lockdep.c only with
CONFIG_PROVE_LOCKING, and in trace_irqsoff.c only for
!CONFIG_PROVE_LOCKING:
http://elixir.free-electrons.com/linux/latest/source/kernel/trace/trace_irqsoff.c#L463

I have tested these combinations and it compiles fine.

thanks,

- Joel

^ permalink raw reply	[flat|nested] 17+ messages in thread

* Re: [PATCH v7 2/2] tracing: Add support for preempt and irq enable/disable events
  2017-10-04 16:01   ` Peter Zijlstra
@ 2017-10-04 16:43     ` Joel Fernandes
  2017-10-06  8:59       ` Joel Fernandes
  2017-10-05 23:28     ` Joel Fernandes
  1 sibling, 1 reply; 17+ messages in thread
From: Joel Fernandes @ 2017-10-04 16:43 UTC (permalink / raw)
  To: Peter Zijlstra; +Cc: LKML, kernel-team, Steven Rostedt

Hi Peter,

On Wed, Oct 4, 2017 at 9:01 AM, Peter Zijlstra <peterz@infradead.org> wrote:
> On Fri, Sep 29, 2017 at 02:22:45PM -0700, Joel Fernandes wrote:
>> diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
>> index 0e3033c00474..515ac851841a 100644
>> --- a/kernel/trace/trace_irqsoff.c
>> +++ b/kernel/trace/trace_irqsoff.c
>> @@ -16,6 +16,9 @@
>>
>>  #include "trace.h"
>>
>> +#define CREATE_TRACE_POINTS
>> +#include <trace/events/preemptirq.h>
>> +
>>  #if defined(CONFIG_IRQSOFF_TRACER) || defined(CONFIG_PREEMPT_TRACER)
>>  static struct trace_array            *irqsoff_trace __read_mostly;
>>  static int                           tracer_enabled __read_mostly;
>> @@ -776,27 +779,60 @@ static inline void tracer_preempt_on(unsigned long a0, unsigned long a1) { }
>>  static inline void tracer_preempt_off(unsigned long a0, unsigned long a1) { }
>>  #endif
>>
>> +/*
>> + * trace_hardirqs_off can be called even when IRQs are already off.
>
> In fact it must be.. otherwise you'll get a complaint.
>
>>     It is
>> + * pointless and inconsistent with trace_preempt_enable and
>> + * trace_preempt_disable to trace this, lets prevent double counting it with a
>> + * per-cpu variable. Also reuse the per-cpu variable for other trace_hardirqs_*
>> + * functions since we already define it.
>
> Lockdep ignores redundant calls. But I'm not entirely sure what the
> above is trying to say.

I meant to say the same thing (that I'm trying to ignore redundant
calls). In the last review you mentioned that it needs explaining, so
I added a comment. Should I just remove the comment then? Or I could
just state in a single line that the per-CPU variable is used for
ignoring redundant calls.

>> + */
>> +static DEFINE_PER_CPU(int, tracing_irq_cpu);
>> +
>>  #if defined(CONFIG_TRACE_IRQFLAGS) && !defined(CONFIG_PROVE_LOCKING)
>>  void trace_hardirqs_on(void)
>>  {
>> +     if (!this_cpu_read(tracing_irq_cpu))
>> +             return;
>> +
>> +     trace_irq_enable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
>>       tracer_hardirqs_on();
>> +
>> +     this_cpu_write(tracing_irq_cpu, 0);
>>  }
>>  EXPORT_SYMBOL(trace_hardirqs_on);
>>
>>  void trace_hardirqs_off(void)
>>  {
>> +     if (this_cpu_read(tracing_irq_cpu))
>> +             return;
>> +
>> +     this_cpu_write(tracing_irq_cpu, 1);
>> +
>> +     trace_irq_disable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
>>       tracer_hardirqs_off();
>>  }
>>  EXPORT_SYMBOL(trace_hardirqs_off);
>>
>>  __visible void trace_hardirqs_on_caller(unsigned long caller_addr)
>>  {
>> +     if (!this_cpu_read(tracing_irq_cpu))
>> +             return;
>> +
>> +     trace_irq_enable_rcuidle(CALLER_ADDR0, caller_addr);
>>       tracer_hardirqs_on_caller(caller_addr);
>> +
>> +     this_cpu_write(tracing_irq_cpu, 0);
>>  }
>>  EXPORT_SYMBOL(trace_hardirqs_on_caller);
>>
>>  __visible void trace_hardirqs_off_caller(unsigned long caller_addr)
>>  {
>> +     if (this_cpu_read(tracing_irq_cpu))
>> +             return;
>> +
>> +     this_cpu_write(tracing_irq_cpu, 1);
>> +
>> +     trace_irq_disable_rcuidle(CALLER_ADDR0, caller_addr);
>>       tracer_hardirqs_off_caller(caller_addr);
>>  }
>>  EXPORT_SYMBOL(trace_hardirqs_off_caller);
>
> lockdep implements the trace_hardirq_*() in terms of *_caller(). Would
> that make sense here?

Yes, I think that makes sense and reduces code duplication, I can do
this in the next rev.

thanks,

- Joel

^ permalink raw reply	[flat|nested] 17+ messages in thread

* Re: [PATCH v7 2/2] tracing: Add support for preempt and irq enable/disable events
  2017-10-04 16:04   ` Peter Zijlstra
  2017-10-04 16:31     ` Joel Fernandes
@ 2017-10-04 16:44     ` Steven Rostedt
  2017-10-04 16:56       ` Joel Fernandes
  1 sibling, 1 reply; 17+ messages in thread
From: Steven Rostedt @ 2017-10-04 16:44 UTC (permalink / raw)
  To: Peter Zijlstra; +Cc: Joel Fernandes, linux-kernel, kernel-team

On Wed, 4 Oct 2017 18:04:34 +0200
Peter Zijlstra <peterz@infradead.org> wrote:

> On Fri, Sep 29, 2017 at 02:22:45PM -0700, Joel Fernandes wrote:
> > +++ b/kernel/trace/trace_irqsoff.c  
> 
> >  EXPORT_SYMBOL(trace_hardirqs_on);
> >  EXPORT_SYMBOL(trace_hardirqs_off);
> >  EXPORT_SYMBOL(trace_hardirqs_on_caller);
> >  EXPORT_SYMBOL(trace_hardirqs_off_caller);  
> 
> Steve, how does this compiler with lockdep enabled? Because:
> 
> kernel/locking/lockdep.c:EXPORT_SYMBOL(trace_hardirqs_on_caller);
> kernel/locking/lockdep.c:EXPORT_SYMBOL(trace_hardirqs_on);
> kernel/locking/lockdep.c:EXPORT_SYMBOL(trace_hardirqs_off_caller);
> kernel/locking/lockdep.c:EXPORT_SYMBOL(trace_hardirqs_off);

I'll have to see if it does, I haven't applied them yet. Looks like
they were removed from the:

#ifdef CONFIG_PROVE_LOCKING

[..]

#else /* !CONFIG_PROVE_LOCKING */

<here>

#endif


I don't see the protection in the patches. I will definitely test that
before pushing it anywhere.

-- Steve

^ permalink raw reply	[flat|nested] 17+ messages in thread

* Re: [PATCH v7 2/2] tracing: Add support for preempt and irq enable/disable events
  2017-10-04 16:44     ` Steven Rostedt
@ 2017-10-04 16:56       ` Joel Fernandes
  2017-10-04 17:03         ` Steven Rostedt
  0 siblings, 1 reply; 17+ messages in thread
From: Joel Fernandes @ 2017-10-04 16:56 UTC (permalink / raw)
  To: Steven Rostedt; +Cc: Peter Zijlstra, LKML, kernel-team

Hi Steven,

On Wed, Oct 4, 2017 at 9:44 AM, Steven Rostedt <rostedt@goodmis.org> wrote:
> On Wed, 4 Oct 2017 18:04:34 +0200
> Peter Zijlstra <peterz@infradead.org> wrote:
>
>> On Fri, Sep 29, 2017 at 02:22:45PM -0700, Joel Fernandes wrote:
>> > +++ b/kernel/trace/trace_irqsoff.c
>>
>> >  EXPORT_SYMBOL(trace_hardirqs_on);
>> >  EXPORT_SYMBOL(trace_hardirqs_off);
>> >  EXPORT_SYMBOL(trace_hardirqs_on_caller);
>> >  EXPORT_SYMBOL(trace_hardirqs_off_caller);
>>
>> Steve, how does this compiler with lockdep enabled? Because:
>>
>> kernel/locking/lockdep.c:EXPORT_SYMBOL(trace_hardirqs_on_caller);
>> kernel/locking/lockdep.c:EXPORT_SYMBOL(trace_hardirqs_on);
>> kernel/locking/lockdep.c:EXPORT_SYMBOL(trace_hardirqs_off_caller);
>> kernel/locking/lockdep.c:EXPORT_SYMBOL(trace_hardirqs_off);
>
> I'll have to see if it does, I haven't applied them yet. Looks like
> they were removed from the:
>
> #ifdef CONFIG_PROVE_LOCKING
>
> [..]
>
> #else /* !CONFIG_PROVE_LOCKING */
>
> <here>
>
> #endif
>
>
> I don't see the protection in the patches. I will definitely test that
> before pushing it anywhere.

The protection added by CONFIG_PROVE_LOCKING was already there before
my patches. I just moved the code around in patch 1/2, nothing changed
in that patch. I already tested the combination of PROVE_LOCKING
enabled and disabled and several other combinations on your -next
tree. It all compiled fine. Here is my test script FWIW:
(By the way, do you mean that another tree/branch than your -next or
Linus's master has protection removed? If so, could you let me know
which tree/branch?)

#!/bin/bash -x

set -e

function disable_all() {
        make x86_64_defconfig
        ./scripts/config --disable CONFIG_PREEMPTIRQ_EVENTS
        ./scripts/config --disable CONFIG_IRQSOFF_TRACER
        ./scripts/config --disable CONFIG_PREEMPT_TRACER
        ./scripts/config --disable CONFIG_PREEMPT
        ./scripts/config --disable CONFIG_PROVE_LOCKING
}

function build_all() {
        make olddefconfig
        make -j8
}

disable_all
./scripts/config --enable CONFIG_IRQSOFF_TRACER
build_all

disable_all
./scripts/config --enable CONFIG_PREEMPT
./scripts/config --enable CONFIG_PREEMPTIRQ_EVENTS
build_all

disable_all
./scripts/config --enable CONFIG_PROVE_LOCKING
build_all

disable_all
./scripts/config --enable CONFIG_PROVE_LOCKING
./scripts/config --enable CONFIG_PREEMPT
./scripts/config --enable CONFIG_PREEMPT_TRACER
build_all

disable_all
./scripts/config --enable CONFIG_PROVE_LOCKING
./scripts/config --enable CONFIG_IRQSOFF_TRACER
build_all

disable_all
./scripts/config --enable CONFIG_PROVE_LOCKING
./scripts/config --enable CONFIG_PREEMPT
./scripts/config --enable CONFIG_PREEMPTIRQ_EVENTS
build_all

disable_all
./scripts/config --enable CONFIG_PROVE_LOCKING
./scripts/config --enable CONFIG_PREEMPT
./scripts/config --enable CONFIG_PREEMPTIRQ_EVENTS
./scripts/config --enable CONFIG_PREEMPT_TRACER
./scripts/config --enable CONFIG_IRQSOFF_TRACER
build_all

^ permalink raw reply	[flat|nested] 17+ messages in thread

* Re: [PATCH v7 2/2] tracing: Add support for preempt and irq enable/disable events
  2017-10-04 16:56       ` Joel Fernandes
@ 2017-10-04 17:03         ` Steven Rostedt
  2017-10-04 20:13           ` Joel Fernandes
  0 siblings, 1 reply; 17+ messages in thread
From: Steven Rostedt @ 2017-10-04 17:03 UTC (permalink / raw)
  To: Joel Fernandes; +Cc: Peter Zijlstra, LKML, kernel-team

On Wed, 4 Oct 2017 09:56:33 -0700
Joel Fernandes <joelaf@google.com> wrote:

> > I don't see the protection in the patches. I will definitely test that
> > before pushing it anywhere.  
> 
> The protection added by CONFIG_PROVE_LOCKING was already there before
> my patches. I just moved the code around in patch 1/2, nothing changed
> in that patch. I already tested the combination of PROVE_LOCKING
> enabled and disabled and several other combinations on your -next
> tree. It all compiled fine. Here is my test script FWIW:
> (By the way, do you mean that another tree/branch than your -next or
> Linus's master has protection removed? If so, could you let me know
> which tree/branch?)

Using Linus's master is usually fine, but if you want to see what I'm
working on, just look at the ftrace/core branch of my linux-trace.git
tree on kernel.org. Note, that branch often rebases. My for-next branch
does not.

Also note, I'm currently looking to pull in Tom Zanussi's hist patch
series, and then I'll get to yours afterward.

-- Steve

^ permalink raw reply	[flat|nested] 17+ messages in thread

* Re: [PATCH v7 2/2] tracing: Add support for preempt and irq enable/disable events
  2017-10-04 17:03         ` Steven Rostedt
@ 2017-10-04 20:13           ` Joel Fernandes
  0 siblings, 0 replies; 17+ messages in thread
From: Joel Fernandes @ 2017-10-04 20:13 UTC (permalink / raw)
  To: Steven Rostedt; +Cc: Peter Zijlstra, LKML, kernel-team

On Wed, Oct 4, 2017 at 10:03 AM, Steven Rostedt <rostedt@goodmis.org> wrote:
> On Wed, 4 Oct 2017 09:56:33 -0700
> Joel Fernandes <joelaf@google.com> wrote:
>
>> > I don't see the protection in the patches. I will definitely test that
>> > before pushing it anywhere.
>>
>> The protection added by CONFIG_PROVE_LOCKING was already there before
>> my patches. I just moved the code around in patch 1/2, nothing changed
>> in that patch. I already tested the combination of PROVE_LOCKING
>> enabled and disabled and several other combinations on your -next
>> tree. It all compiled fine. Here is my test script FWIW:
>> (By the way, do you mean that another tree/branch than your -next or
>> Linus's master has protection removed? If so, could you let me know
>> which tree/branch?)
>
> Using Linus's master is usually fine, but if you want to see what I'm
> working on, just look at the ftrace/core branch of my linux-trace.git
> tree on kernel.org. Note, that branch often rebases. My for-next branch
> does not.

Got it, thanks.

> Also note, I'm currently looking to pull in Tom Zanussi's hist patch
> series, and then I'll get to yours afterward.

Sounds good, thanks a lot!

Regards,
Joel

^ permalink raw reply	[flat|nested] 17+ messages in thread

* Re: [PATCH v7 2/2] tracing: Add support for preempt and irq enable/disable events
  2017-10-04 16:01   ` Peter Zijlstra
  2017-10-04 16:43     ` Joel Fernandes
@ 2017-10-05 23:28     ` Joel Fernandes
  2017-10-05 23:29       ` Joel Fernandes
  2017-10-06  7:07       ` Peter Zijlstra
  1 sibling, 2 replies; 17+ messages in thread
From: Joel Fernandes @ 2017-10-05 23:28 UTC (permalink / raw)
  To: Peter Zijlstra; +Cc: LKML, kernel-team, Steven Rostedt

Hi Peter,

On Wed, Oct 4, 2017 at 9:01 AM, Peter Zijlstra <peterz@infradead.org> wrote:
> On Fri, Sep 29, 2017 at 02:22:45PM -0700, Joel Fernandes wrote:
[...]
>> + */
>> +static DEFINE_PER_CPU(int, tracing_irq_cpu);
>> +
>>  #if defined(CONFIG_TRACE_IRQFLAGS) && !defined(CONFIG_PROVE_LOCKING)
>>  void trace_hardirqs_on(void)
>>  {
>> +     if (!this_cpu_read(tracing_irq_cpu))
>> +             return;
>> +
>> +     trace_irq_enable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
>>       tracer_hardirqs_on();
>> +
>> +     this_cpu_write(tracing_irq_cpu, 0);
>>  }
>>  EXPORT_SYMBOL(trace_hardirqs_on);
>>
>>  void trace_hardirqs_off(void)
>>  {
>> +     if (this_cpu_read(tracing_irq_cpu))
>> +             return;
>> +
>> +     this_cpu_write(tracing_irq_cpu, 1);
>> +
>> +     trace_irq_disable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
>>       tracer_hardirqs_off();
>>  }
>>  EXPORT_SYMBOL(trace_hardirqs_off);
>>
>>  __visible void trace_hardirqs_on_caller(unsigned long caller_addr)
>>  {
>> +     if (!this_cpu_read(tracing_irq_cpu))
>> +             return;
>> +
>> +     trace_irq_enable_rcuidle(CALLER_ADDR0, caller_addr);
>>       tracer_hardirqs_on_caller(caller_addr);
>> +
>> +     this_cpu_write(tracing_irq_cpu, 0);
>>  }
>>  EXPORT_SYMBOL(trace_hardirqs_on_caller);
>>
>>  __visible void trace_hardirqs_off_caller(unsigned long caller_addr)
>>  {
>> +     if (this_cpu_read(tracing_irq_cpu))
>> +             return;
>> +
>> +     this_cpu_write(tracing_irq_cpu, 1);
>> +
>> +     trace_irq_disable_rcuidle(CALLER_ADDR0, caller_addr);
>>       tracer_hardirqs_off_caller(caller_addr);
>>  }
>>  EXPORT_SYMBOL(trace_hardirqs_off_caller);
>
> lockdep implements the trace_hardirq_*() in terms of *_caller(). Would
> that make sense here?

In lockdep code, when trace_hardirqs_off is called,
trace_hardirqs_off_caller would pass CALLER_ADDR0 as
trace_hardirqs_off.

Because of this, the first argument passed to time_hardirqs_off would
always be an offset within trace_hardirqs_off:
time_hardirqs_off(CALLER_ADDR0, ip);

Is that intended? Seems to me that in the lockdep implementation of
trace_hardirqs_* in terms of *_caller(), we would completely miss the
second-last return address (CALLER_ADDR1) of trace_hardirqs_off().
Also for the above reasons, I don't think it doesn't make sense to use
this reuse logic for the tracer. Atleast I feel it might change the
current behavior of the preempt/irqsoff tracer which I don't intend to
change with my current patch set.

thanks,

- Joel

^ permalink raw reply	[flat|nested] 17+ messages in thread

* Re: [PATCH v7 2/2] tracing: Add support for preempt and irq enable/disable events
  2017-10-05 23:28     ` Joel Fernandes
@ 2017-10-05 23:29       ` Joel Fernandes
  2017-10-06  7:07       ` Peter Zijlstra
  1 sibling, 0 replies; 17+ messages in thread
From: Joel Fernandes @ 2017-10-05 23:29 UTC (permalink / raw)
  To: Peter Zijlstra; +Cc: LKML, kernel-team, Steven Rostedt

On Thu, Oct 5, 2017 at 4:28 PM, Joel Fernandes <joelaf@google.com> wrote:
> Hi Peter,
>
> On Wed, Oct 4, 2017 at 9:01 AM, Peter Zijlstra <peterz@infradead.org> wrote:
>> On Fri, Sep 29, 2017 at 02:22:45PM -0700, Joel Fernandes wrote:
[...]
>>>  EXPORT_SYMBOL(trace_hardirqs_off);
>>>
>>>  __visible void trace_hardirqs_on_caller(unsigned long caller_addr)
>>>  {
>>> +     if (!this_cpu_read(tracing_irq_cpu))
>>> +             return;
>>> +
>>> +     trace_irq_enable_rcuidle(CALLER_ADDR0, caller_addr);
>>>       tracer_hardirqs_on_caller(caller_addr);
>>> +
>>> +     this_cpu_write(tracing_irq_cpu, 0);
>>>  }
>>>  EXPORT_SYMBOL(trace_hardirqs_on_caller);
>>>
>>>  __visible void trace_hardirqs_off_caller(unsigned long caller_addr)
>>>  {
>>> +     if (this_cpu_read(tracing_irq_cpu))
>>> +             return;
>>> +
>>> +     this_cpu_write(tracing_irq_cpu, 1);
>>> +
>>> +     trace_irq_disable_rcuidle(CALLER_ADDR0, caller_addr);
>>>       tracer_hardirqs_off_caller(caller_addr);
>>>  }
>>>  EXPORT_SYMBOL(trace_hardirqs_off_caller);
>>
>> lockdep implements the trace_hardirq_*() in terms of *_caller(). Would
>> that make sense here?
>
> In lockdep code, when trace_hardirqs_off is called,
> trace_hardirqs_off_caller would pass CALLER_ADDR0 as
> trace_hardirqs_off.
>
> Because of this, the first argument passed to time_hardirqs_off would
> always be an offset within trace_hardirqs_off:
> time_hardirqs_off(CALLER_ADDR0, ip);
>
> Is that intended? Seems to me that in the lockdep implementation of
> trace_hardirqs_* in terms of *_caller(), we would completely miss the
> second-last return address (CALLER_ADDR1) of trace_hardirqs_off().
> Also for the above reasons, I don't think it doesn't make sense to use
> this reuse logic for the tracer. Atleast I feel it might change the
> current behavior of the preempt/irqsoff tracer which I don't intend to

Sorry, I got lost with double-negatives here, I meant "I don't think
it makes sense to.."

thanks,

- Joel

^ permalink raw reply	[flat|nested] 17+ messages in thread

* Re: [PATCH v7 2/2] tracing: Add support for preempt and irq enable/disable events
  2017-10-05 23:28     ` Joel Fernandes
  2017-10-05 23:29       ` Joel Fernandes
@ 2017-10-06  7:07       ` Peter Zijlstra
  2017-10-06  7:28         ` Joel Fernandes
  1 sibling, 1 reply; 17+ messages in thread
From: Peter Zijlstra @ 2017-10-06  7:07 UTC (permalink / raw)
  To: Joel Fernandes; +Cc: LKML, kernel-team, Steven Rostedt, Ingo Molnar

On Thu, Oct 05, 2017 at 04:28:10PM -0700, Joel Fernandes wrote:
> > lockdep implements the trace_hardirq_*() in terms of *_caller(). Would
> > that make sense here?
> 
> In lockdep code, when trace_hardirqs_off is called,
> trace_hardirqs_off_caller would pass CALLER_ADDR0 as
> trace_hardirqs_off.
> 
> Because of this, the first argument passed to time_hardirqs_off would
> always be an offset within trace_hardirqs_off:
> time_hardirqs_off(CALLER_ADDR0, ip);
> 
> Is that intended? Seems to me that in the lockdep implementation of
> trace_hardirqs_* in terms of *_caller(), we would completely miss the
> second-last return address (CALLER_ADDR1) of trace_hardirqs_off().
> Also for the above reasons, I don't think it doesn't make sense to use
> this reuse logic for the tracer. Atleast I feel it might change the
> current behavior of the preempt/irqsoff tracer which I don't intend to
> change with my current patch set.

Hurm.. so I've no clue. I never looked at any of this. I think Ingo
wrote that before I came joined the fun. He might (although unlikely,
because its been _many_ years) still have some memories.

But given that lockdep enabled kernels never got those arguments right,
how useful are they? I mean, nobody seems to have noticed much.

^ permalink raw reply	[flat|nested] 17+ messages in thread

* Re: [PATCH v7 2/2] tracing: Add support for preempt and irq enable/disable events
  2017-10-06  7:07       ` Peter Zijlstra
@ 2017-10-06  7:28         ` Joel Fernandes
  2017-10-06 13:38           ` Steven Rostedt
  0 siblings, 1 reply; 17+ messages in thread
From: Joel Fernandes @ 2017-10-06  7:28 UTC (permalink / raw)
  To: Peter Zijlstra; +Cc: LKML, kernel-team, Steven Rostedt, Ingo Molnar

Hi Peter,

On Fri, Oct 6, 2017 at 12:07 AM, Peter Zijlstra <peterz@infradead.org> wrote:
> On Thu, Oct 05, 2017 at 04:28:10PM -0700, Joel Fernandes wrote:
>> > lockdep implements the trace_hardirq_*() in terms of *_caller(). Would
>> > that make sense here?
>>
>> In lockdep code, when trace_hardirqs_off is called,
>> trace_hardirqs_off_caller would pass CALLER_ADDR0 as
>> trace_hardirqs_off.
>>
>> Because of this, the first argument passed to time_hardirqs_off would
>> always be an offset within trace_hardirqs_off:
>> time_hardirqs_off(CALLER_ADDR0, ip);
>>
>> Is that intended? Seems to me that in the lockdep implementation of
>> trace_hardirqs_* in terms of *_caller(), we would completely miss the
>> second-last return address (CALLER_ADDR1) of trace_hardirqs_off().
>> Also for the above reasons, I don't think it doesn't make sense to use
>> this reuse logic for the tracer. Atleast I feel it might change the
>> current behavior of the preempt/irqsoff tracer which I don't intend to
>> change with my current patch set.
>
> Hurm.. so I've no clue. I never looked at any of this. I think Ingo
> wrote that before I came joined the fun. He might (although unlikely,
> because its been _many_ years) still have some memories.
>
> But given that lockdep enabled kernels never got those arguments right,
> how useful are they? I mean, nobody seems to have noticed much.

Oh ok. So I traced this down to the original patch that added
time_hardirqs_off to lockdep. I *think* it was added just to keep the
irqsoff tracer working while lockdep is enabled, so that both lockdep
and the tracer would work at the same time. So I guess nobody noticed
any issues because nobody noticed or cared to check if irqsoff tracer
showed the same results with lockdep enabled vs disabled.

I think the correct way this should be rewritten is lockdep should use
register_trace_* to register callbacks onto the new tracepoints I'm
adding. I am working on a patch that does something like this and gets
rid of the time_* functions. I will try to have an RFC out by the
weekend if I hopefully don't hit any roadblocks.

thanks!

- Joel

^ permalink raw reply	[flat|nested] 17+ messages in thread

* Re: [PATCH v7 2/2] tracing: Add support for preempt and irq enable/disable events
  2017-10-04 16:43     ` Joel Fernandes
@ 2017-10-06  8:59       ` Joel Fernandes
  0 siblings, 0 replies; 17+ messages in thread
From: Joel Fernandes @ 2017-10-06  8:59 UTC (permalink / raw)
  To: Peter Zijlstra; +Cc: LKML, kernel-team, Steven Rostedt

Hi Peter,

On 10/04/2017 09:43 AM, Joel Fernandes wrote:
[..]
>>> + */
>>> +static DEFINE_PER_CPU(int, tracing_irq_cpu);
>>> +
>>>  #if defined(CONFIG_TRACE_IRQFLAGS) && !defined(CONFIG_PROVE_LOCKING)
>>>  void trace_hardirqs_on(void)
>>>  {
>>> +     if (!this_cpu_read(tracing_irq_cpu))
>>> +             return;
>>> +
>>> +     trace_irq_enable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
>>>       tracer_hardirqs_on();
>>> +
>>> +     this_cpu_write(tracing_irq_cpu, 0);
>>>  }
>>>  EXPORT_SYMBOL(trace_hardirqs_on);
>>>
>>>  void trace_hardirqs_off(void)
>>>  {
>>> +     if (this_cpu_read(tracing_irq_cpu))
>>> +             return;
>>> +
>>> +     this_cpu_write(tracing_irq_cpu, 1);
>>> +
>>> +     trace_irq_disable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
>>>       tracer_hardirqs_off();
>>>  }
>>>  EXPORT_SYMBOL(trace_hardirqs_off);
>>>
>>>  __visible void trace_hardirqs_on_caller(unsigned long caller_addr)
>>>  {
>>> +     if (!this_cpu_read(tracing_irq_cpu))
>>> +             return;
>>> +
>>> +     trace_irq_enable_rcuidle(CALLER_ADDR0, caller_addr);
>>>       tracer_hardirqs_on_caller(caller_addr);
>>> +
>>> +     this_cpu_write(tracing_irq_cpu, 0);
>>>  }
>>>  EXPORT_SYMBOL(trace_hardirqs_on_caller);
>>>
>>>  __visible void trace_hardirqs_off_caller(unsigned long caller_addr)
>>>  {
>>> +     if (this_cpu_read(tracing_irq_cpu))
>>> +             return;
>>> +
>>> +     this_cpu_write(tracing_irq_cpu, 1);
>>> +
>>> +     trace_irq_disable_rcuidle(CALLER_ADDR0, caller_addr);
>>>       tracer_hardirqs_off_caller(caller_addr);
>>>  }
>>>  EXPORT_SYMBOL(trace_hardirqs_off_caller);
>>
>> lockdep implements the trace_hardirq_*() in terms of *_caller(). Would
>> that make sense here?
> 
> Yes, I think that makes sense and reduces code duplication, I can do
> this in the next rev.

I rewrote the patches to use standalone tracepoints with hooks on them for
the various users (lockdep and *irqsoff tracers), it looks much cleaner now
and gets rid of the time_ calls in lockdep as well. It also makes the trace
events available when PROVE_LOCKING is enabled as you wanted. I still have
to test lockdep with it but it builds fine, and I tested the preemptirqsoff
tracer and the standalone trace events..

---8<---
From: Joel Fernandes <joelaf@google.com>
Subject: [PATCH RFC] tracing: Add preempt and irq disable/enable tracepoints

- add new tracepoints
- convert lockdep to add hooks onto them
- convert preempt/irqoff tracer to add hooks onto them.

Signed-off-by: Joel Fernandes <joelaf@google.com>
---
 include/linux/ftrace.h            |  10 +--
 include/linux/irqflags.h          |   5 ++
 include/linux/lockdep.h           |   6 +-
 include/trace/events/preemptirq.h |  70 ++++++++++++++++++++
 init/main.c                       |   2 +-
 kernel/locking/lockdep.c          |  30 +++------
 kernel/sched/core.c               |   2 +-
 kernel/trace/Kconfig              |  25 +++++++
 kernel/trace/Makefile             |   1 +
 kernel/trace/trace_irqsoff.c      | 133 ++++++++++++++------------------------
 kernel/trace/trace_preemptirq.c   |  69 ++++++++++++++++++++
 11 files changed, 233 insertions(+), 120 deletions(-)
 create mode 100644 include/trace/events/preemptirq.h
 create mode 100644 kernel/trace/trace_preemptirq.c

diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
index 2e028854bac7..4d9b3dbfa494 100644
--- a/include/linux/ftrace.h
+++ b/include/linux/ftrace.h
@@ -734,15 +734,7 @@ static inline unsigned long get_lock_parent_ip(void)
 	return CALLER_ADDR2;
 }
 
-#ifdef CONFIG_IRQSOFF_TRACER
-  extern void time_hardirqs_on(unsigned long a0, unsigned long a1);
-  extern void time_hardirqs_off(unsigned long a0, unsigned long a1);
-#else
-  static inline void time_hardirqs_on(unsigned long a0, unsigned long a1) { }
-  static inline void time_hardirqs_off(unsigned long a0, unsigned long a1) { }
-#endif
-
-#ifdef CONFIG_PREEMPT_TRACER
+#ifdef CONFIG_TRACE_PREEMPT_TOGGLE
   extern void trace_preempt_on(unsigned long a0, unsigned long a1);
   extern void trace_preempt_off(unsigned long a0, unsigned long a1);
 #else
diff --git a/include/linux/irqflags.h b/include/linux/irqflags.h
index 5dd1272d1ab2..0d323931def6 100644
--- a/include/linux/irqflags.h
+++ b/include/linux/irqflags.h
@@ -15,8 +15,13 @@
 #include <asm/irqflags.h>
 
 #ifdef CONFIG_TRACE_IRQFLAGS
+#ifdef CONFIG_PROVE_LOCKING
   extern void trace_softirqs_on(unsigned long ip);
   extern void trace_softirqs_off(unsigned long ip);
+#else
+  static inline void trace_softirqs_on(unsigned long ip) { }
+  static inline void trace_softirqs_off(unsigned long ip) { }
+#endif
   extern void trace_hardirqs_on(void);
   extern void trace_hardirqs_off(void);
 # define trace_hardirq_context(p)	((p)->hardirq_context)
diff --git a/include/linux/lockdep.h b/include/linux/lockdep.h
index fffe49f188e6..6e7c71e546a3 100644
--- a/include/linux/lockdep.h
+++ b/include/linux/lockdep.h
@@ -263,7 +263,7 @@ struct held_lock {
 /*
  * Initialization, self-test and debugging-output methods:
  */
-extern void lockdep_info(void);
+extern void lockdep_init(void);
 extern void lockdep_reset(void);
 extern void lockdep_reset_lock(struct lockdep_map *lock);
 extern void lockdep_free_key_range(void *start, unsigned long size);
@@ -419,7 +419,7 @@ static inline void lockdep_on(void)
 # define lockdep_set_current_reclaim_state(g)	do { } while (0)
 # define lockdep_clear_current_reclaim_state()	do { } while (0)
 # define lockdep_trace_alloc(g)			do { } while (0)
-# define lockdep_info()				do { } while (0)
+# define lockdep_init()				do { } while (0)
 # define lockdep_init_map(lock, name, key, sub) \
 		do { (void)(name); (void)(key); } while (0)
 # define lockdep_set_class(lock, key)		do { (void)(key); } while (0)
@@ -523,7 +523,7 @@ do {								\
 
 #endif /* CONFIG_LOCKDEP */
 
-#ifdef CONFIG_TRACE_IRQFLAGS
+#if defined(CONFIG_TRACE_IRQFLAGS) && defined(CONFIG_PROVE_LOCKING)
 extern void print_irqtrace_events(struct task_struct *curr);
 #else
 static inline void print_irqtrace_events(struct task_struct *curr)
diff --git a/include/trace/events/preemptirq.h b/include/trace/events/preemptirq.h
new file mode 100644
index 000000000000..f9a86f2d4802
--- /dev/null
+++ b/include/trace/events/preemptirq.h
@@ -0,0 +1,70 @@
+#ifdef CONFIG_PREEMPTIRQ_TRACEPOINTS
+
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM preemptirq
+
+#if !defined(_TRACE_PREEMPTIRQ_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_PREEMPTIRQ_H
+
+#include <linux/ktime.h>
+#include <linux/tracepoint.h>
+#include <linux/string.h>
+#include <asm/sections.h>
+
+DECLARE_EVENT_CLASS(preemptirq_template,
+
+	TP_PROTO(unsigned long ip, unsigned long parent_ip),
+
+	TP_ARGS(ip, parent_ip),
+
+	TP_STRUCT__entry(
+		__field(u32, caller_offs)
+		__field(u32, parent_offs)
+	),
+
+	TP_fast_assign(
+		__entry->caller_offs = (u32)(ip - (unsigned long)_stext);
+		__entry->parent_offs = (u32)(parent_ip - (unsigned long)_stext);
+	),
+
+	TP_printk("caller=%pF parent=%pF",
+		  (void *)((unsigned long)(_stext) + __entry->caller_offs),
+		  (void *)((unsigned long)(_stext) + __entry->parent_offs))
+);
+
+#ifdef CONFIG_TRACE_IRQFLAGS
+DEFINE_EVENT(preemptirq_template, irq_disable,
+	     TP_PROTO(unsigned long ip, unsigned long parent_ip),
+	     TP_ARGS(ip, parent_ip));
+
+DEFINE_EVENT(preemptirq_template, irq_enable,
+	     TP_PROTO(unsigned long ip, unsigned long parent_ip),
+	     TP_ARGS(ip, parent_ip));
+#endif
+
+#ifdef CONFIG_TRACE_PREEMPT_TOGGLE
+DEFINE_EVENT(preemptirq_template, preempt_disable,
+	     TP_PROTO(unsigned long ip, unsigned long parent_ip),
+	     TP_ARGS(ip, parent_ip));
+
+DEFINE_EVENT(preemptirq_template, preempt_enable,
+	     TP_PROTO(unsigned long ip, unsigned long parent_ip),
+	     TP_ARGS(ip, parent_ip));
+#endif
+
+#endif /* _TRACE_PREEMPTIRQ_H */
+
+#include <trace/define_trace.h>
+
+#else /* !CONFIG_PREEMPTIRQ_TRACEPOINT */
+
+#define trace_irq_enable(...)
+#define trace_irq_disable(...)
+#define trace_preempt_enable(...)
+#define trace_preempt_disable(...)
+#define trace_irq_enable_rcuidle(...)
+#define trace_irq_disable_rcuidle(...)
+#define trace_preempt_enable_rcuidle(...)
+#define trace_preempt_disable_rcuidle(...)
+
+#endif
diff --git a/init/main.c b/init/main.c
index 052481fbe363..9d8049bf448d 100644
--- a/init/main.c
+++ b/init/main.c
@@ -632,7 +632,7 @@ asmlinkage __visible void __init start_kernel(void)
 		panic("Too many boot %s vars at `%s'", panic_later,
 		      panic_param);
 
-	lockdep_info();
+	lockdep_init();
 
 	/*
 	 * Need to run this when irqs are enabled, because it wants
diff --git a/kernel/locking/lockdep.c b/kernel/locking/lockdep.c
index 7d2499bec5fe..bd0686665a4d 100644
--- a/kernel/locking/lockdep.c
+++ b/kernel/locking/lockdep.c
@@ -55,6 +55,7 @@
 
 #include "lockdep_internals.h"
 
+#include <trace/events/preemptirq.h>
 #define CREATE_TRACE_POINTS
 #include <trace/events/lock.h>
 
@@ -2710,10 +2711,9 @@ static void __trace_hardirqs_on_caller(unsigned long ip)
 	debug_atomic_inc(hardirqs_on_events);
 }
 
-__visible void trace_hardirqs_on_caller(unsigned long ip)
+static void lockdep_hardirqs_on(void *none, unsigned long ip,
+				unsigned long ignore)
 {
-	time_hardirqs_on(CALLER_ADDR0, ip);
-
 	if (unlikely(!debug_locks || current->lockdep_recursion))
 		return;
 
@@ -2752,23 +2752,15 @@ __visible void trace_hardirqs_on_caller(unsigned long ip)
 	__trace_hardirqs_on_caller(ip);
 	current->lockdep_recursion = 0;
 }
-EXPORT_SYMBOL(trace_hardirqs_on_caller);
-
-void trace_hardirqs_on(void)
-{
-	trace_hardirqs_on_caller(CALLER_ADDR0);
-}
-EXPORT_SYMBOL(trace_hardirqs_on);
 
 /*
  * Hardirqs were disabled:
  */
-__visible void trace_hardirqs_off_caller(unsigned long ip)
+static void lockdep_hardirqs_off(void *none, unsigned long ip,
+				 unsigned long ignore)
 {
 	struct task_struct *curr = current;
 
-	time_hardirqs_off(CALLER_ADDR0, ip);
-
 	if (unlikely(!debug_locks || current->lockdep_recursion))
 		return;
 
@@ -2790,13 +2782,6 @@ __visible void trace_hardirqs_off_caller(unsigned long ip)
 	} else
 		debug_atomic_inc(redundant_hardirqs_off);
 }
-EXPORT_SYMBOL(trace_hardirqs_off_caller);
-
-void trace_hardirqs_off(void)
-{
-	trace_hardirqs_off_caller(CALLER_ADDR0);
-}
-EXPORT_SYMBOL(trace_hardirqs_off);
 
 /*
  * Softirqs will be enabled:
@@ -4281,8 +4266,11 @@ void lockdep_reset_lock(struct lockdep_map *lock)
 	raw_local_irq_restore(flags);
 }
 
-void __init lockdep_info(void)
+void __init lockdep_init(void)
 {
+	register_trace_irq_disable(lockdep_hardirqs_off, NULL);
+	register_trace_irq_enable(lockdep_hardirqs_on, NULL);
+
 	printk("Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar\n");
 
 	printk("... MAX_LOCKDEP_SUBCLASSES:  %lu\n", MAX_LOCKDEP_SUBCLASSES);
diff --git a/kernel/sched/core.c b/kernel/sched/core.c
index 0869b20fba81..ee5514b97b03 100644
--- a/kernel/sched/core.c
+++ b/kernel/sched/core.c
@@ -3037,7 +3037,7 @@ u64 scheduler_tick_max_deferment(void)
 #endif
 
 #if defined(CONFIG_PREEMPT) && (defined(CONFIG_DEBUG_PREEMPT) || \
-				defined(CONFIG_PREEMPT_TRACER))
+				defined(CONFIG_TRACE_PREEMPT_TOGGLE))
 /*
  * If the value passed in is equal to the current preempt count
  * then we just disabled preemption. Start timing the latency.
diff --git a/kernel/trace/Kconfig b/kernel/trace/Kconfig
index 434c840e2d82..c4079931d5c1 100644
--- a/kernel/trace/Kconfig
+++ b/kernel/trace/Kconfig
@@ -159,6 +159,30 @@ config FUNCTION_GRAPH_TRACER
 	  the return value. This is done by setting the current return
 	  address on the current task structure into a stack of calls.
 
+config TRACE_PREEMPT_TOGGLE
+	bool
+	help
+	  Enables hooks which will be called when preemption is first disabled,
+	  and last enabled.
+
+config PREEMPTIRQ_TRACEPOINTS
+	# Used to create the preempt and irq tracepoints
+	bool
+	depends on TRACE_PREEMPT_TOGGLE || TRACE_IRQFLAGS
+	default y
+	help
+	  Create preempt/irq toggle tracepoints if needed, so that other parts
+	  of the kernel can use them to generate or add hooks to them.
+
+config PREEMPTIRQ_EVENTS
+	bool "Enable trace events for preempt and irq disable/enable"
+	select TRACE_IRQFLAGS
+	select TRACE_PREEMPT_TOGGLE if PREEMPT
+	help
+	  Enable tracing of disable and enable events for preemption and irqs.
+	  For tracing preempt disable/enable events, DEBUG_PREEMPT must be
+	  enabled. For tracing irq disable/enable events, PROVE_LOCKING must
+	  be disabled.
 
 config IRQSOFF_TRACER
 	bool "Interrupts-off Latency Tracer"
@@ -195,6 +219,7 @@ config PREEMPT_TRACER
 	select RING_BUFFER_ALLOW_SWAP
 	select TRACER_SNAPSHOT
 	select TRACER_SNAPSHOT_PER_CPU_SWAP
+	select TRACE_PREEMPT_TOGGLE
 	help
 	  This option measures the time spent in preemption-off critical
 	  sections, with microsecond accuracy.
diff --git a/kernel/trace/Makefile b/kernel/trace/Makefile
index 90f2701d92a7..53f536f3a763 100644
--- a/kernel/trace/Makefile
+++ b/kernel/trace/Makefile
@@ -34,6 +34,7 @@ obj-$(CONFIG_TRACING) += trace_printk.o
 obj-$(CONFIG_TRACING_MAP) += tracing_map.o
 obj-$(CONFIG_CONTEXT_SWITCH_TRACER) += trace_sched_switch.o
 obj-$(CONFIG_FUNCTION_TRACER) += trace_functions.o
+obj-$(CONFIG_PREEMPTIRQ_TRACEPOINTS) += trace_preemptirq.o
 obj-$(CONFIG_IRQSOFF_TRACER) += trace_irqsoff.o
 obj-$(CONFIG_PREEMPT_TRACER) += trace_irqsoff.o
 obj-$(CONFIG_SCHED_TRACER) += trace_sched_wakeup.o
diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
index 7758bc0617cb..0c95a86d8541 100644
--- a/kernel/trace/trace_irqsoff.c
+++ b/kernel/trace/trace_irqsoff.c
@@ -13,7 +13,7 @@
 #include <linux/uaccess.h>
 #include <linux/module.h>
 #include <linux/ftrace.h>
-
+#include <trace/events/preemptirq.h>
 #include "trace.h"
 
 static struct trace_array		*irqsoff_trace __read_mostly;
@@ -446,86 +446,6 @@ void stop_critical_timings(void)
 }
 EXPORT_SYMBOL_GPL(stop_critical_timings);
 
-#ifdef CONFIG_IRQSOFF_TRACER
-#ifdef CONFIG_PROVE_LOCKING
-void time_hardirqs_on(unsigned long a0, unsigned long a1)
-{
-	if (!preempt_trace() && irq_trace())
-		stop_critical_timing(a0, a1);
-}
-
-void time_hardirqs_off(unsigned long a0, unsigned long a1)
-{
-	if (!preempt_trace() && irq_trace())
-		start_critical_timing(a0, a1);
-}
-
-#else /* !CONFIG_PROVE_LOCKING */
-
-/*
- * Stubs:
- */
-
-void trace_softirqs_on(unsigned long ip)
-{
-}
-
-void trace_softirqs_off(unsigned long ip)
-{
-}
-
-inline void print_irqtrace_events(struct task_struct *curr)
-{
-}
-
-/*
- * We are only interested in hardirq on/off events:
- */
-void trace_hardirqs_on(void)
-{
-	if (!preempt_trace() && irq_trace())
-		stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
-}
-EXPORT_SYMBOL(trace_hardirqs_on);
-
-void trace_hardirqs_off(void)
-{
-	if (!preempt_trace() && irq_trace())
-		start_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
-}
-EXPORT_SYMBOL(trace_hardirqs_off);
-
-__visible void trace_hardirqs_on_caller(unsigned long caller_addr)
-{
-	if (!preempt_trace() && irq_trace())
-		stop_critical_timing(CALLER_ADDR0, caller_addr);
-}
-EXPORT_SYMBOL(trace_hardirqs_on_caller);
-
-__visible void trace_hardirqs_off_caller(unsigned long caller_addr)
-{
-	if (!preempt_trace() && irq_trace())
-		start_critical_timing(CALLER_ADDR0, caller_addr);
-}
-EXPORT_SYMBOL(trace_hardirqs_off_caller);
-
-#endif /* CONFIG_PROVE_LOCKING */
-#endif /*  CONFIG_IRQSOFF_TRACER */
-
-#ifdef CONFIG_PREEMPT_TRACER
-void trace_preempt_on(unsigned long a0, unsigned long a1)
-{
-	if (preempt_trace() && !irq_trace())
-		stop_critical_timing(a0, a1);
-}
-
-void trace_preempt_off(unsigned long a0, unsigned long a1)
-{
-	if (preempt_trace() && !irq_trace())
-		start_critical_timing(a0, a1);
-}
-#endif /* CONFIG_PREEMPT_TRACER */
-
 #ifdef CONFIG_FUNCTION_TRACER
 static bool function_enabled;
 
@@ -675,10 +595,28 @@ static void irqsoff_tracer_stop(struct trace_array *tr)
 }
 
 #ifdef CONFIG_IRQSOFF_TRACER
+/*
+ * We are only interested in hardirq on/off events:
+ */
+static void tracer_hardirqs_on(void *none, unsigned long a0, unsigned long a1)
+{
+	if (!preempt_trace() && irq_trace())
+		stop_critical_timing(a0, a1);
+}
+
+static void tracer_hardirqs_off(void *none, unsigned long a0, unsigned long a1)
+{
+	if (!preempt_trace() && irq_trace())
+		start_critical_timing(a0, a1);
+}
+
 static int irqsoff_tracer_init(struct trace_array *tr)
 {
 	trace_type = TRACER_IRQS_OFF;
 
+	register_trace_irq_disable(tracer_hardirqs_off, NULL);
+	register_trace_irq_enable(tracer_hardirqs_on, NULL);
+
 	return __irqsoff_tracer_init(tr);
 }
 static struct tracer irqsoff_tracer __read_mostly =
@@ -701,15 +639,33 @@ static struct tracer irqsoff_tracer __read_mostly =
 	.use_max_tr	= true,
 };
 # define register_irqsoff(trace) register_tracer(&trace)
+
 #else
+static inline void tracer_hardirqs_on(unsigned long a0, unsigned long a1) { }
+static inline void tracer_hardirqs_off(unsigned long a0, unsigned long a1) { }
 # define register_irqsoff(trace) do { } while (0)
-#endif
+#endif /*  CONFIG_IRQSOFF_TRACER */
 
 #ifdef CONFIG_PREEMPT_TRACER
+static void tracer_preempt_on(void *none, unsigned long a0, unsigned long a1)
+{
+	if (preempt_trace() && !irq_trace())
+		stop_critical_timing(a0, a1);
+}
+
+static void tracer_preempt_off(void *none, unsigned long a0, unsigned long a1)
+{
+	if (preempt_trace() && !irq_trace())
+		start_critical_timing(a0, a1);
+}
+
 static int preemptoff_tracer_init(struct trace_array *tr)
 {
 	trace_type = TRACER_PREEMPT_OFF;
 
+	register_trace_preempt_disable(tracer_preempt_off, NULL);
+	register_trace_preempt_enable(tracer_preempt_on, NULL);
+
 	return __irqsoff_tracer_init(tr);
 }
 
@@ -733,17 +689,24 @@ static struct tracer preemptoff_tracer __read_mostly =
 	.use_max_tr	= true,
 };
 # define register_preemptoff(trace) register_tracer(&trace)
+
 #else
+static inline void tracer_preempt_on(unsigned long a0, unsigned long a1) { }
+static inline void tracer_preempt_off(unsigned long a0, unsigned long a1) { }
 # define register_preemptoff(trace) do { } while (0)
-#endif
+#endif /* CONFIG_PREEMPT_TRACER */
 
-#if defined(CONFIG_IRQSOFF_TRACER) && \
-	defined(CONFIG_PREEMPT_TRACER)
+#if defined(CONFIG_IRQSOFF_TRACER) && defined(CONFIG_PREEMPT_TRACER)
 
 static int preemptirqsoff_tracer_init(struct trace_array *tr)
 {
 	trace_type = TRACER_IRQS_OFF | TRACER_PREEMPT_OFF;
 
+	register_trace_irq_disable(tracer_hardirqs_off, NULL);
+	register_trace_irq_enable(tracer_hardirqs_on, NULL);
+	register_trace_preempt_disable(tracer_preempt_off, NULL);
+	register_trace_preempt_enable(tracer_preempt_on, NULL);
+
 	return __irqsoff_tracer_init(tr);
 }
 
diff --git a/kernel/trace/trace_preemptirq.c b/kernel/trace/trace_preemptirq.c
new file mode 100644
index 000000000000..62d94b170978
--- /dev/null
+++ b/kernel/trace/trace_preemptirq.c
@@ -0,0 +1,69 @@
+/*
+ * preemptoff and irqoff tracepoints
+ */
+
+#include <linux/kallsyms.h>
+#include <linux/uaccess.h>
+#include <linux/module.h>
+#include <linux/ftrace.h>
+
+#define CREATE_TRACE_POINTS
+#include <trace/events/preemptirq.h>
+
+/* Per-cpu variable to prevent redundant calls when IRQs already off */
+static DEFINE_PER_CPU(int, tracing_irq_cpu);
+
+#ifdef CONFIG_TRACE_IRQFLAGS
+void trace_hardirqs_on(void)
+{
+	if (!this_cpu_read(tracing_irq_cpu))
+		return;
+
+	trace_irq_enable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
+	this_cpu_write(tracing_irq_cpu, 0);
+}
+EXPORT_SYMBOL(trace_hardirqs_on);
+
+void trace_hardirqs_off(void)
+{
+	if (this_cpu_read(tracing_irq_cpu))
+		return;
+
+	this_cpu_write(tracing_irq_cpu, 1);
+	trace_irq_disable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
+}
+EXPORT_SYMBOL(trace_hardirqs_off);
+
+__visible void trace_hardirqs_on_caller(unsigned long caller_addr)
+{
+	if (!this_cpu_read(tracing_irq_cpu))
+		return;
+
+	trace_irq_enable_rcuidle(CALLER_ADDR0, caller_addr);
+	this_cpu_write(tracing_irq_cpu, 0);
+}
+EXPORT_SYMBOL(trace_hardirqs_on_caller);
+
+__visible void trace_hardirqs_off_caller(unsigned long caller_addr)
+{
+	if (this_cpu_read(tracing_irq_cpu))
+		return;
+
+	this_cpu_write(tracing_irq_cpu, 1);
+	trace_irq_disable_rcuidle(CALLER_ADDR0, caller_addr);
+}
+EXPORT_SYMBOL(trace_hardirqs_off_caller);
+
+#endif
+
+#ifdef CONFIG_DEBUG_PREEMPT
+void trace_preempt_on(unsigned long a0, unsigned long a1)
+{
+	trace_preempt_enable_rcuidle(a0, a1);
+}
+
+void trace_preempt_off(unsigned long a0, unsigned long a1)
+{
+	trace_preempt_disable_rcuidle(a0, a1);
+}
+#endif
-- 
2.14.2.920.gcf0c67979c-goog

^ permalink raw reply related	[flat|nested] 17+ messages in thread

* Re: [PATCH v7 2/2] tracing: Add support for preempt and irq enable/disable events
  2017-10-06  7:28         ` Joel Fernandes
@ 2017-10-06 13:38           ` Steven Rostedt
  2017-10-06 17:27             ` Joel Fernandes
  0 siblings, 1 reply; 17+ messages in thread
From: Steven Rostedt @ 2017-10-06 13:38 UTC (permalink / raw)
  To: Joel Fernandes; +Cc: Peter Zijlstra, LKML, kernel-team, Ingo Molnar

On Fri, 6 Oct 2017 00:28:21 -0700
Joel Fernandes <joelaf@google.com> wrote:

 
> Oh ok. So I traced this down to the original patch that added
> time_hardirqs_off to lockdep. I *think* it was added just to keep the
> irqsoff tracer working while lockdep is enabled, so that both lockdep
> and the tracer would work at the same time. So I guess nobody noticed
> any issues because nobody noticed or cared to check if irqsoff tracer
> showed the same results with lockdep enabled vs disabled.

As one of the main users of preemptirqsoff tracer, I can tell you that
we didn't care ;-)

Yes, it was added to keep them both working. It's dangerous to use
CALLER_ADDR1, as lockdep can be called by the top frame, and ADDR1
would go off the stack frame and cause a fault. I just put in ADDR0
as filler as it required something to be added.

We added a stack dump on new max latencies to figure out where the
problem occurred.

-- Steve


> 
> I think the correct way this should be rewritten is lockdep should use
> register_trace_* to register callbacks onto the new tracepoints I'm
> adding. I am working on a patch that does something like this and gets
> rid of the time_* functions. I will try to have an RFC out by the
> weekend if I hopefully don't hit any roadblocks.
> 
> thanks!
> 
> - Joel

^ permalink raw reply	[flat|nested] 17+ messages in thread

* Re: [PATCH v7 2/2] tracing: Add support for preempt and irq enable/disable events
  2017-10-06 13:38           ` Steven Rostedt
@ 2017-10-06 17:27             ` Joel Fernandes
  0 siblings, 0 replies; 17+ messages in thread
From: Joel Fernandes @ 2017-10-06 17:27 UTC (permalink / raw)
  To: Steven Rostedt; +Cc: Peter Zijlstra, LKML, kernel-team, Ingo Molnar

Hi Steve,

On Fri, Oct 6, 2017 at 6:38 AM, Steven Rostedt <rostedt@goodmis.org> wrote:
> On Fri, 6 Oct 2017 00:28:21 -0700
> Joel Fernandes <joelaf@google.com> wrote:
>
>
>> Oh ok. So I traced this down to the original patch that added
>> time_hardirqs_off to lockdep. I *think* it was added just to keep the
>> irqsoff tracer working while lockdep is enabled, so that both lockdep
>> and the tracer would work at the same time. So I guess nobody noticed
>> any issues because nobody noticed or cared to check if irqsoff tracer
>> showed the same results with lockdep enabled vs disabled.
>
> As one of the main users of preemptirqsoff tracer, I can tell you that
> we didn't care ;-)

Hahah :-)

> Yes, it was added to keep them both working. It's dangerous to use
> CALLER_ADDR1, as lockdep can be called by the top frame, and ADDR1
> would go off the stack frame and cause a fault. I just put in ADDR0
> as filler as it required something to be added.

Ok. Then maybe I wrecked lockdep a bit in my patch from last night
that added tracepoint probes for it onto the new tracepoints [1].
Although it booted fine without any warnings. Considering your above
comment, do you see this an issue?

Initially I didn't mess around with lockdep but then Peter told me he
felt its weird PROVE_LOCKING makes the tracepoints unavailable. So
that led me to the probes patch (which includes all the lesson's
learnt from my v8 series [2]).

(Steve, btw I think the PATCH v8 series [2] can be a first step and a
safe solution for 4.15 while I work on the probe approach [1] but I
leave it to you how you want to time it :-)).

> We added a stack dump on new max latencies to figure out where the
> problem occurred.

Got it, that makes sense. thanks a lot for the history of it.

thanks,

- Joel

[1] https://lkml.org/lkml/2017/10/6/106
[2] https://lkml.org/lkml/2017/10/5/896

[...]

^ permalink raw reply	[flat|nested] 17+ messages in thread

end of thread, other threads:[~2017-10-06 17:27 UTC | newest]

Thread overview: 17+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2017-09-29 21:22 [PATCH v7 1/2] tracing: Prepare to add preempt and irq trace events Joel Fernandes
2017-09-29 21:22 ` [PATCH v7 2/2] tracing: Add support for preempt and irq enable/disable events Joel Fernandes
2017-10-04 16:01   ` Peter Zijlstra
2017-10-04 16:43     ` Joel Fernandes
2017-10-06  8:59       ` Joel Fernandes
2017-10-05 23:28     ` Joel Fernandes
2017-10-05 23:29       ` Joel Fernandes
2017-10-06  7:07       ` Peter Zijlstra
2017-10-06  7:28         ` Joel Fernandes
2017-10-06 13:38           ` Steven Rostedt
2017-10-06 17:27             ` Joel Fernandes
2017-10-04 16:04   ` Peter Zijlstra
2017-10-04 16:31     ` Joel Fernandes
2017-10-04 16:44     ` Steven Rostedt
2017-10-04 16:56       ` Joel Fernandes
2017-10-04 17:03         ` Steven Rostedt
2017-10-04 20:13           ` Joel Fernandes

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.