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]
--
2.14.1.581.gf28d330327-goog
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(-)
diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
index 7758bc0617cb..38d65a0535e0 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;
@@ -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
--
2.14.1.581.gf28d330327-goog
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
diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
index 6383115e9d2c..5790ba7a85bd 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/linux/irqflags.h b/include/linux/irqflags.h
index 5dd1272d1ab2..6ad6732a4e98 100644
--- a/include/linux/irqflags.h
+++ b/include/linux/irqflags.h
@@ -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
diff --git a/include/trace/events/preemptirq.h b/include/trace/events/preemptirq.h
new file mode 100644
index 000000000000..601935e32cd1
--- /dev/null
+++ b/include/trace/events/preemptirq.h
@@ -0,0 +1,62 @@
+#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\n",
+ (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(...)
+
+#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 38d65a0535e0..89ff6bd685a2 100644
--- a/kernel/trace/trace_irqsoff.c
+++ b/kernel/trace/trace_irqsoff.c
@@ -16,12 +16,18 @@
#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;
static DEFINE_PER_CPU(int, tracing_cpu);
+static DEFINE_PER_CPU(int, tracing_irq_cpu);
+static DEFINE_PER_CPU(int, tracing_preempt_cpu);
+
static DEFINE_RAW_SPINLOCK(max_trace_lock);
enum {
@@ -781,12 +787,24 @@ core_initcall(init_irqsoff_tracer);
void start_critical_timings(void)
{
+ if (this_cpu_read(tracing_preempt_cpu))
+ trace_preempt_enable(CALLER_ADDR0, CALLER_ADDR1);
+
+ if (this_cpu_read(tracing_irq_cpu))
+ trace_irq_enable(CALLER_ADDR0, CALLER_ADDR1);
+
start_critical_timings_tracer();
}
EXPORT_SYMBOL_GPL(start_critical_timings);
void stop_critical_timings(void)
{
+ if (this_cpu_read(tracing_preempt_cpu))
+ trace_preempt_disable(CALLER_ADDR0, CALLER_ADDR1);
+
+ if (this_cpu_read(tracing_irq_cpu))
+ trace_irq_disable(CALLER_ADDR0, CALLER_ADDR1);
+
stop_critical_timings_tracer();
}
EXPORT_SYMBOL_GPL(stop_critical_timings);
@@ -794,24 +812,48 @@ EXPORT_SYMBOL_GPL(stop_critical_timings);
#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(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(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(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(CALLER_ADDR0, caller_addr);
tracer_hardirqs_off_caller(caller_addr);
}
EXPORT_SYMBOL(trace_hardirqs_off_caller);
@@ -833,14 +875,27 @@ 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)
{
+ if (!this_cpu_read(tracing_preempt_cpu))
+ return;
+
+ trace_preempt_enable(a0, a1);
tracer_preempt_on(a0, a1);
+
+ this_cpu_write(tracing_preempt_cpu, 0);
}
void trace_preempt_off(unsigned long a0, unsigned long a1)
{
+ if (this_cpu_read(tracing_preempt_cpu))
+ return;
+
+ this_cpu_write(tracing_preempt_cpu, 1);
+
+ trace_preempt_disable(a0, a1);
tracer_preempt_off(a0, a1);
}
#endif
--
2.14.1.581.gf28d330327-goog
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(-)
diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
index 5790ba7a85bd..768e49b8c80f 100644
--- a/include/linux/ftrace.h
+++ b/include/linux/ftrace.h
@@ -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);
}
--
2.14.1.581.gf28d330327-goog
On Wed, 6 Sep 2017 17:17:50 -0700
Joel Fernandes <[email protected]> wrote:
> +#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
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
Hi Steven,
On Sun, Sep 10, 2017 at 2:06 AM, Steven Rostedt <[email protected]> wrote:
> On Wed, 6 Sep 2017 17:17:50 -0700
> Joel Fernandes <[email protected]> wrote:
>
>
>> +#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
>
> 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