Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753005AbdIGASN (ORCPT ); Wed, 6 Sep 2017 20:18:13 -0400 Received: from mail-pg0-f48.google.com ([74.125.83.48]:37010 "EHLO mail-pg0-f48.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1752718AbdIGASM (ORCPT ); Wed, 6 Sep 2017 20:18:12 -0400 X-Google-Smtp-Source: ADKCNb6T+TEUqs26bBu8F/hJPOekQd9koYHl6eDklQTjH7sNVZ+A19gxgRovgpmyLFKdBQQWhjjR2g== From: Joel Fernandes To: linux-kernel@vger.kernel.org Cc: Joel Fernandes , Steven Rostedt , Peter Zilstra , kernel-team@android.com, Ingo Molnar Subject: [PATCH RFC v4 2/3] tracing: Add support for preempt and irq enable/disable events Date: Wed, 6 Sep 2017 17:17:51 -0700 Message-Id: <20170907001752.27015-3-joelaf@google.com> X-Mailer: git-send-email 2.14.1.581.gf28d330327-goog In-Reply-To: <20170907001752.27015-1-joelaf@google.com> References: <20170907001752.27015-1-joelaf@google.com> Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 8545 Lines: 280 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 Cc: Peter Zilstra Cc: kernel-team@android.com Signed-off-by: Joel Fernandes --- 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 +#include +#include +#include + +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 + +#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 + #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