tracing: Add trace events for preemption and irq disable/enable.

RFC PATCH Superseded Joel Fernandes 2 participants 6 messages Sep 7, 2017 – Sep 10, 2017

Subsystems (3)

Tracing ftrace Tracing OS noise / latency tracers

lore

Share & tools

lore

Joel Fernandes

author

2017-09-07 00:18 UTC #0 lore raw

v4 cover tracing: Add trace events for preemption and irq disable/enable.

These patches add trace events support for preempt and irq disable/enable events.

Changes since v3 (link [1]):
Previously the patch series used the terms "critical section" but Peter suggested that this name is confusing due to ambiguity, so I dropped calling it that in this series. See discussion in [1]. I also dropped the "preemptirq" combined event (which behaves similar to the preemptirqsoff tracer) for now and will keep that for a later patch once we can get this foundation series in.

Here's an example of how Android's systrace will be using it to show atomic sections as a gantt chart: http://imgur.com/download/TZplEVp

I also added a slightly unrelated fix for a config option (patch 3/3).

[1] https://patchwork.kernel.org/patch/9936045/

Joel Fernandes (3):
trace/irqsoff: Prepare to add preempt and irq trace events
trace: Add support for preempt and irq enable/disable events
ftrace: Use correct config option for preemption debug

 include/linux/ftrace.h            |   7 +-
 include/linux/irqflags.h          |   4 +-
 include/trace/events/preemptirq.h |  62 +++++++++++++
 kernel/trace/Kconfig              |   9 ++
 kernel/trace/Makefile             |   1 +
 kernel/trace/trace_irqsoff.c      | 178 +++++++++++++++++++++++++++++++-------
 6 files changed, 226 insertions(+), 35 deletions(-)
 create mode 100644 include/trace/events/preemptirq.h

Cc Steven Rostedt <[email protected]>

Cc Peter Zijlstra <[email protected]>

Cc [email protected]

Signature · 1 line

2.14.1.581.gf28d330327-goog

Joel Fernandes

author

2017-09-07 00:18 UTC #1 lore raw

RFC PATCH v4 1/3 tracing/irqsoff: Prepare to add preempt and irq trace events

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 adding a few wrappers, no functional change.

Cc Steven Rostedt <[email protected]>

Cc Peter Zijlstra <[email protected]>

Cc [email protected]

Signed-off-by Joel Fernandes <[email protected]>

---
 kernel/trace/trace_irqsoff.c | 123 ++++++++++++++++++++++++++++++++-----------
 1 file changed, 93 insertions(+), 30 deletions(-)

kernel/trace/trace_irqsoff.c +93 ~~-30~~

index 7758bc0617cb..38d65a0535e0 100644
@@ -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;

@@ -432,19 +433,17 @@ stop_critical_timing(unsigned long ip, unsigned long parent_ip)
 }
 
 /* start and stop critical timings used to for stoppage (in idle) */
-void start_critical_timings(void)
+static inline void start_critical_timings_tracer(void)
 {
 	if (preempt_trace() || irq_trace())
 		start_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
 }
-EXPORT_SYMBOL_GPL(start_critical_timings);
 
-void stop_critical_timings(void)
+static inline void stop_critical_timings_tracer(void)
 {
 	if (preempt_trace() || irq_trace())
 		stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
 }
-EXPORT_SYMBOL_GPL(stop_critical_timings);
 
 #ifdef CONFIG_IRQSOFF_TRACER
 #ifdef CONFIG_PROVE_LOCKING

@@ -462,64 +461,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 +760,87 @@ __init static int init_irqsoff_tracer(void)
 	return 0;
 }
 core_initcall(init_irqsoff_tracer);
+#else /* IRQSOFF_TRACER || PREEMPTOFF_TRACER */
+
+#define start_critical_timings_tracer() do { } while (0)
+#define stop_critical_timings_tracer() do { } while (0)
+
+#endif
+
+#ifndef CONFIG_IRQSOFF_TRACER
+#define tracer_hardirqs_on() do { } while (0)
+#define tracer_hardirqs_off() do { } while (0)
+#define tracer_hardirqs_on_caller(x) do { } while (0)
+#define tracer_hardirqs_off_caller(x) do { } while (0)
+#endif
+
+#ifndef CONFIG_PREEMPT_TRACER
+#define tracer_preempt_on(x, y) do { } while (0)
+#define tracer_preempt_off(x, y) do { } while (0)
+#endif
+
+void start_critical_timings(void)
+{
+	start_critical_timings_tracer();
+}
+EXPORT_SYMBOL_GPL(start_critical_timings);
+
+void stop_critical_timings(void)
+{
+	stop_critical_timings_tracer();
+}
+EXPORT_SYMBOL_GPL(stop_critical_timings);
+
+#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

Signature · 1 line

2.14.1.581.gf28d330327-goog

Steven Rostedt

maintainer

2017-09-10 09:16 UTC #2 lore raw

Re: [PATCH RFC v4 1/3] tracing/irqsoff: Prepare to add preempt and irq trace events

Quoted 8 lines · On Wed, 6 Sep 2017 17:17:50 -0700 Joel Fernandes <[email protected]> wrote:

kernel/trace/trace_irqsoff.c +8 -0

+#else /* IRQSOFF_TRACER || PREEMPTOFF_TRACER */
+
+#define start_critical_timings_tracer() do { } while (0)
+#define stop_critical_timings_tracer() do { } while (0)
+
+#endif
+
+#ifndef CONFIG_IRQSOFF_TRACER

kernel/trace/trace_irqsoff.c __init static int init_irqsoff_tracer(void) · line 780

Quoted 10 lines

kernel/trace/trace_irqsoff.c +10 -0

+#define tracer_hardirqs_on() do { } while (0)
+#define tracer_hardirqs_off() do { } while (0)
+#define tracer_hardirqs_on_caller(x) do { } while (0)
+#define tracer_hardirqs_off_caller(x) do { } while (0)
+#endif
+
+#ifndef CONFIG_PREEMPT_TRACER
+#define tracer_preempt_on(x, y) do { } while (0)
+#define tracer_preempt_off(x, y) do { } while (0)
+#endif

Is there a reason the above is #define and not static inline? The preferred method is static inline as that allows the compiler to check types. #define is used if one of the parameters has a struct or something that is not defined.

-- Steve

Joel Fernandes

author

2017-09-10 22:21 UTC #3 lore raw

Re: [PATCH RFC v4 1/3] tracing/irqsoff: Prepare to add preempt and irq trace events

Hi Steven,

Quoted 19 lines · Steven Rostedt

Quoted 15 lines · On Wed, 6 Sep 2017 17:17:50 -0700 Joel Fernandes <[email protected]> wrote:

kernel/trace/trace_irqsoff.c +15 -0

+#else /* IRQSOFF_TRACER || PREEMPTOFF_TRACER */
+
+#define start_critical_timings_tracer() do { } while (0)
+#define stop_critical_timings_tracer() do { } while (0)
+
+#endif
+
+#ifndef CONFIG_IRQSOFF_TRACER
+#define tracer_hardirqs_on() do { } while (0)
+#define tracer_hardirqs_off() do { } while (0)
+#define tracer_hardirqs_on_caller(x) do { } while (0)
+#define tracer_hardirqs_off_caller(x) do { } while (0)
+#endif
+
+#ifndef CONFIG_PREEMPT_TRACER

Quoted 8 lines

kernel/trace/trace_irqsoff.c __init static int init_irqsoff_tracer(void) · line 780
Quoted 3 lines
kernel/trace/trace_irqsoff.c +3 -0
+#define tracer_preempt_on(x, y) do { } while (0)
+#define tracer_preempt_off(x, y) do { } while (0)
+#endif
Is there a reason the above is #define and not static inline? The preferred method is static inline as that allows the compiler to check types. #define is used if one of the parameters has a struct or something that is not defined.

Sure, I'll make use of static inline in the next version. thanks!

-Joel

Joel Fernandes

author

2017-09-07 00:18 UTC #4 lore raw

RFC PATCH v4 2/3 tracing: Add support for preempt and irq enable/disable events

In reply to Joel Fernandes

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 <[email protected]>

Cc Peter Zilstra <[email protected]>

Cc [email protected]

Signed-off-by Joel Fernandes <[email protected]>

---
 include/linux/ftrace.h            |  3 +-
 include/linux/irqflags.h          |  4 +--
 include/trace/events/preemptirq.h | 62 +++++++++++++++++++++++++++++++++++++++
 kernel/trace/Kconfig              |  9 ++++++
 kernel/trace/Makefile             |  1 +
 kernel/trace/trace_irqsoff.c      | 57 ++++++++++++++++++++++++++++++++++-
 6 files changed, 132 insertions(+), 4 deletions(-)
 create mode 100644 include/trace/events/preemptirq.h

include/linux/ftrace.h +2 -1

index 6383115e9d2c..5790ba7a85bd 100644
@@ -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

include/linux/irqflags.h +2 -2

index 5dd1272d1ab2..6ad6732a4e98 100644
@@ -44,8 +44,8 @@
 # define INIT_TRACE_IRQFLAGS
 #endif
 
-#if defined(CONFIG_IRQSOFF_TRACER) || \
-	defined(CONFIG_PREEMPT_TRACER)
+#if defined(CONFIG_IRQSOFF_TRACER) || defined(CONFIG_PREEMPT_TRACER) || \
+	defined(CONFIG_PREEMPTIRQ_EVENTS)
  extern void stop_critical_timings(void);
  extern void start_critical_timings(void);
 #else

include/trace/events/preemptirq.h new file +62 -0

62 lines not on this page · raw message

kernel/trace/Kconfig +9 -0

index 434c840e2d82..420666152de8 100644
@@ -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

kernel/trace/Makefile +1 -0

index 90f2701d92a7..9f62eee61f14 100644
@@ -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

kernel/trace/trace_irqsoff.c +56 -1

118 lines not on this page · raw message

Signature · 1 line

2.14.1.581.gf28d330327-goog

Joel Fernandes

author

2017-09-07 00:18 UTC #5 lore raw

RFC PATCH v4 3/3 ftrace: Use correct config option for preemption debug

In reply to Joel Fernandes

I notice that CONFIG_PREEMPT_DEBUG doesn't exist, though this code uses it. I think it wants CONFIG_DEBUG_PREEMPT. Replace it with the same.

Cc Steven Rostedt <[email protected]>

Cc Peter Zijlstra <[email protected]>

Cc [email protected]

Signed-off-by Joel Fernandes <[email protected]>

---
 include/linux/ftrace.h | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

include/linux/ftrace.h +2 -2

index 5790ba7a85bd..768e49b8c80f 100644
@@ -307,7 +307,7 @@ DECLARE_PER_CPU(int, disable_stack_tracer);
 static inline void stack_tracer_disable(void)
 {
 	/* Preemption or interupts must be disabled */
-	if (IS_ENABLED(CONFIG_PREEMPT_DEBUG))
+	if (IS_ENABLED(CONFIG_DEBUG_PREEMPT))
 		WARN_ON_ONCE(!preempt_count() || !irqs_disabled());
 	this_cpu_inc(disable_stack_tracer);
 }

@@ -320,7 +320,7 @@ static inline void stack_tracer_disable(void)
  */
 static inline void stack_tracer_enable(void)
 {
-	if (IS_ENABLED(CONFIG_PREEMPT_DEBUG))
+	if (IS_ENABLED(CONFIG_DEBUG_PREEMPT))
 		WARN_ON_ONCE(!preempt_count() || !irqs_disabled());
 	this_cpu_dec(disable_stack_tracer);
 }

Signature · 1 line

2.14.1.581.gf28d330327-goog