Re: [PATCH v5 2/2] tracing: Add support for preempt and irq enable/disable events
From: Steven Rostedt
Date: Wed Sep 20 2017 - 14:23:22 EST
On Tue, 12 Sep 2017 11:11:09 -0700
Joel Fernandes <joelaf@xxxxxxxxxx> wrote:
> 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@xxxxxxxxxxx>
> Cc: Peter Zilstra <peterz@xxxxxxxxxxxxx>
> Cc: kernel-team@xxxxxxxxxxx
> Signed-off-by: Joel Fernandes <joelaf@xxxxxxxxxx>
> ---
> 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",
No '\n', otherwise you add a lot of whitespace to the trace:
====
<idle>-0 [002] d..1 252.533022: preempt_enable: caller=cpuidle_enter_state+0xfe/0x3a0 parent=cpuidle_enter+0x17/0x20
rcu_preempt-8 [002] ...1 252.533063: preempt_enable: caller=schedule+0x4a/0x90 parent=schedule+0x4a/0x90
rcu_preempt-8 [002] d..1 252.533065: preempt_disable: caller=_raw_spin_lock_irqsave+0x2f/0x60 parent=lock_timer_base+0x81/0xa0
rcu_preempt-8 [002] ...1 252.533066: preempt_enable: caller=_raw_spin_unlock_irqrestore+0x4a/0x80 parent=try_to_del_timer_sync+0x44/0x60
rcu_preempt-8 [002] d..1 252.533067: preempt_disable: caller=_raw_spin_lock_irqsave+0x2f/0x60 parent=prepare_to_swait+0x22/0x70
rcu_preempt-8 [002] ...1 252.533067: preempt_enable: caller=_raw_spin_unlock_irqrestore+0x4a/0x80 parent=prepare_to_swait+0x63/0x70
====
> + (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 26c688740742..361a17f83c4e 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;
> @@ -777,14 +780,29 @@ 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
>
> +static DEFINE_PER_CPU(int, tracing_irq_cpu);
> +static DEFINE_PER_CPU(int, tracing_preempt_cpu);
> +
> 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);
> @@ -792,24 +810,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);
> @@ -831,14 +873,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
Need to fold in the following patch as well. Otherwise RCU may have
issues (run with lockdep enabled and you'll see all the splats).
-- Steve
diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
index 361a17f..7dcb431 100644
--- a/kernel/trace/trace_irqsoff.c
+++ b/kernel/trace/trace_irqsoff.c
@@ -786,10 +786,10 @@ static DEFINE_PER_CPU(int, tracing_preempt_cpu);
void start_critical_timings(void)
{
if (this_cpu_read(tracing_preempt_cpu))
- trace_preempt_enable(CALLER_ADDR0, CALLER_ADDR1);
+ trace_preempt_enable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
if (this_cpu_read(tracing_irq_cpu))
- trace_irq_enable(CALLER_ADDR0, CALLER_ADDR1);
+ trace_irq_enable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
start_critical_timings_tracer();
}
@@ -798,10 +798,10 @@ 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);
+ trace_preempt_disable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
if (this_cpu_read(tracing_irq_cpu))
- trace_irq_disable(CALLER_ADDR0, CALLER_ADDR1);
+ trace_irq_disable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
stop_critical_timings_tracer();
}
@@ -813,7 +813,7 @@ void trace_hardirqs_on(void)
if (!this_cpu_read(tracing_irq_cpu))
return;
- trace_irq_enable(CALLER_ADDR0, CALLER_ADDR1);
+ trace_irq_enable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
tracer_hardirqs_on();
this_cpu_write(tracing_irq_cpu, 0);
@@ -827,7 +827,7 @@ void trace_hardirqs_off(void)
this_cpu_write(tracing_irq_cpu, 1);
- trace_irq_disable(CALLER_ADDR0, CALLER_ADDR1);
+ trace_irq_disable_rcuidle(CALLER_ADDR0, CALLER_ADDR1);
tracer_hardirqs_off();
}
EXPORT_SYMBOL(trace_hardirqs_off);
@@ -837,7 +837,7 @@ __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);
+ trace_irq_enable_rcuidle(CALLER_ADDR0, caller_addr);
tracer_hardirqs_on_caller(caller_addr);
this_cpu_write(tracing_irq_cpu, 0);
@@ -851,9 +851,9 @@ __visible void trace_hardirqs_off_caller(unsigned long caller_addr)
this_cpu_write(tracing_irq_cpu, 1);
- trace_irq_disable(CALLER_ADDR0, caller_addr);
- tracer_hardirqs_off_caller(caller_addr);
-}
+ trace_irq_disable_rcuidle(CALLER_ADDR0, caller_addr);
+ tracer_hardirqs_off_caller(caller_addr);}
+
EXPORT_SYMBOL(trace_hardirqs_off_caller);
/*
@@ -880,7 +880,7 @@ void trace_preempt_on(unsigned long a0, unsigned long a1)
if (!this_cpu_read(tracing_preempt_cpu))
return;
- trace_preempt_enable(a0, a1);
+ trace_preempt_enable_rcuidle(a0, a1);
tracer_preempt_on(a0, a1);
this_cpu_write(tracing_preempt_cpu, 0);
@@ -893,7 +893,7 @@ void trace_preempt_off(unsigned long a0, unsigned long a1)
this_cpu_write(tracing_preempt_cpu, 1);
- trace_preempt_disable(a0, a1);
+ trace_preempt_disable_rcuidle(a0, a1);
tracer_preempt_off(a0, a1);
}
#endif