[RFC PATCH v7 3/5] tracing: Add preemptirqsoff timing events

[Binoy Jayan <binoy.jayan@linaro.org>]

Potential sources of latencies are code segments where interrupts,
preemption or both are disabled (aka critical sections). To create
histograms of potential sources of latency, the kernel stores the time
stamp at the start of a critical section, determines the time elapsed
when the end of the section is reached, and increments the frequency
counter of that latency value - irrespective of whether any concurrently
running process is affected by latency or not.

With the tracepoints for irqs off, preempt off and critical timing added
at the end of the critical sections, the potential sources of latencies
which occur in these sections can be measured in nanoseconds. With the
hist triggers in place, the histogram plots may be generated, with per-cpu
breakdown of events captured. It is based on linux kernel's event
infrastructure.

The following filter(s) may be used to with the histograms

'hist:key=latency.log2:val=hitcount:sort=latency'
'hist:key=ltype,latency:val=hitcount:sort=latency if cpu==1'
'hist:key=ltype:val=latency:sort=ltype if ltype==0 && cpu==2'

Where ltype is
1: IRQSOFF latency
2: PREEMPTOFF Latency
3: Critical Timings

Enable one or more of the following tracers to capture the associated
latencies i.e. irq/preempt/critical timing

In '/sys/kernel/debug/tracing'

echo irqsoff > current_tracer - irq and critical time latencies
echo preemptoff > current_tracer - preempt and critical time latencies
echo preemptirqsoff > current_tracer - irq, preempt and critical timing

[
- Initial work and idea by Carsten as part of PREEMPT_RT patch series
  Link: https://git.kernel.org/cgit/linux/kernel/git/rt/linux-stable-rt.git/commit/?h=v3.14-rt-rebase&id=56d50cc34943bbba12b8c5942ee1ae3b29f73acb
  No code was taken from the RT patch.
- RFC using hist infrastructure code by Daniel.
- Got it re-written in shape as Daniel suggested to take over author ship.
]

Cc: Carsten Emde <C.Emde@osadl.org>
Cc: Daniel Wagner <daniel.wagner@bmw-carit.de>
Signed-off-by: Binoy Jayan <binoy.jayan@linaro.org>
---
 include/trace/events/latency.h | 62 ++++++++++++++++++++++++++++++++++++++++++
 kernel/trace/trace_irqsoff.c   | 43 +++++++++++++++++++----------
 2 files changed, 91 insertions(+), 14 deletions(-)
 create mode 100644 include/trace/events/latency.h

diff --git a/include/trace/events/latency.h b/include/trace/events/latency.h
new file mode 100644
index 0000000..66442d5
--- /dev/null
+++ b/include/trace/events/latency.h
@@ -0,0 +1,62 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM latency
+
+#if !defined(_TRACE_HIST_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_HIST_H
+
+#include <linux/tracepoint.h>
+
+#ifndef __TRACE_LATENCY_TYPE
+#define __TRACE_LATENCY_TYPE
+
+enum latency_type {
+	LT_NONE,
+	LT_IRQ,
+	LT_PREEMPT,
+	LT_CRITTIME,
+	LT_MAX
+};
+
+TRACE_DEFINE_ENUM(LT_IRQ);
+TRACE_DEFINE_ENUM(LT_PREEMPT);
+TRACE_DEFINE_ENUM(LT_CRITTIME);
+
+#define show_ltype(type)			\
+	__print_symbolic(type,			\
+		{ LT_IRQ,	"IRQ" },	\
+		{ LT_PREEMPT,	"PREEMPT" },	\
+		{ LT_CRITTIME,	"CRIT_TIME" })
+#endif
+
+DECLARE_EVENT_CLASS(latency_template,
+	TP_PROTO(int ltype, u64 latency),
+
+	TP_ARGS(ltype, latency),
+
+	TP_STRUCT__entry(
+		__field(int,		ltype)
+		__field(u64,		latency)
+	),
+
+	TP_fast_assign(
+		__entry->ltype		= ltype;
+		__entry->latency	= latency;
+	),
+
+	TP_printk("ltype=%s(%d), latency=%lu", show_ltype(__entry->ltype),
+		  __entry->ltype, (unsigned long) __entry->latency)
+);
+
+/**
+ * latency_preemptirqsoff - called when a cpu exits state of preemption / irq
+ * @ltype:	type of the critical section. Refer 'show_ltype'
+ * @latency:	latency in nano seconds
+ */
+DEFINE_EVENT(latency_template, latency_preemptirqsoff,
+	    TP_PROTO(int ltype, u64 latency),
+	    TP_ARGS(ltype, latency));
+
+#endif /* _TRACE_HIST_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
index 03cdff8..4f7442d 100644
--- a/kernel/trace/trace_irqsoff.c
+++ b/kernel/trace/trace_irqsoff.c
@@ -13,9 +13,14 @@
 #include <linux/uaccess.h>
 #include <linux/module.h>
 #include <linux/ftrace.h>
+#include <linux/percpu-defs.h>
+#include <trace/events/sched.h>
 
 #include "trace.h"
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/latency.h>
+
 static struct trace_array		*irqsoff_trace __read_mostly;
 static int				tracer_enabled __read_mostly;
 
@@ -298,11 +303,18 @@ static bool report_latency(struct trace_array *tr, cycle_t delta)
 	return true;
 }
 
+static inline void latency_preemptirqsoff_timing(enum latency_type type,
+						 cycle_t delta)
+{
+	trace_latency_preemptirqsoff(type, (u64) delta);
+}
+
 static void
 check_critical_timing(struct trace_array *tr,
 		      struct trace_array_cpu *data,
 		      unsigned long parent_ip,
-		      int cpu)
+		      int cpu,
+		      enum latency_type ltype)
 {
 	cycle_t T0, T1, delta;
 	unsigned long flags;
@@ -312,6 +324,7 @@ check_critical_timing(struct trace_array *tr,
 	T1 = ftrace_now(cpu);
 	delta = T1-T0;
 
+	latency_preemptirqsoff_timing(ltype, delta);
 	local_save_flags(flags);
 
 	pc = preempt_count();
@@ -351,7 +364,8 @@ out:
 }
 
 static inline void
-start_critical_timing(unsigned long ip, unsigned long parent_ip)
+start_critical_timing(unsigned long ip, unsigned long parent_ip,
+		      enum latency_type ltype)
 {
 	int cpu;
 	struct trace_array *tr = irqsoff_trace;
@@ -387,7 +401,8 @@ start_critical_timing(unsigned long ip, unsigned long parent_ip)
 }
 
 static inline void
-stop_critical_timing(unsigned long ip, unsigned long parent_ip)
+stop_critical_timing(unsigned long ip, unsigned long parent_ip,
+		     enum latency_type ltype)
 {
 	int cpu;
 	struct trace_array *tr = irqsoff_trace;
@@ -414,7 +429,7 @@ stop_critical_timing(unsigned long ip, unsigned long parent_ip)
 
 	local_save_flags(flags);
 	__trace_function(tr, ip, parent_ip, flags, preempt_count());
-	check_critical_timing(tr, data, parent_ip ? : ip, cpu);
+	check_critical_timing(tr, data, parent_ip ? : ip, cpu, ltype);
 	data->critical_start = 0;
 	atomic_dec(&data->disabled);
 }
@@ -423,14 +438,14 @@ stop_critical_timing(unsigned long ip, unsigned long parent_ip)
 void start_critical_timings(void)
 {
 	if (preempt_trace() || irq_trace())
-		start_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
+		start_critical_timing(CALLER_ADDR0, CALLER_ADDR1, LT_CRITTIME);
 }
 EXPORT_SYMBOL_GPL(start_critical_timings);
 
 void stop_critical_timings(void)
 {
 	if (preempt_trace() || irq_trace())
-		stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
+		stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1, LT_CRITTIME);
 }
 EXPORT_SYMBOL_GPL(stop_critical_timings);
 
@@ -439,13 +454,13 @@ EXPORT_SYMBOL_GPL(stop_critical_timings);
 void time_hardirqs_on(unsigned long a0, unsigned long a1)
 {
 	if (!preempt_trace() && irq_trace())
-		stop_critical_timing(a0, a1);
+		stop_critical_timing(a0, a1, LT_IRQ);
 }
 
 void time_hardirqs_off(unsigned long a0, unsigned long a1)
 {
 	if (!preempt_trace() && irq_trace())
-		start_critical_timing(a0, a1);
+		start_critical_timing(a0, a1, LT_IRQ);
 }
 
 #else /* !CONFIG_PROVE_LOCKING */
@@ -472,28 +487,28 @@ inline void print_irqtrace_events(struct task_struct *curr)
 void trace_hardirqs_on(void)
 {
 	if (!preempt_trace() && irq_trace())
-		stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
+		stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1, LT_IRQ);
 }
 EXPORT_SYMBOL(trace_hardirqs_on);
 
 void trace_hardirqs_off(void)
 {
 	if (!preempt_trace() && irq_trace())
-		start_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
+		start_critical_timing(CALLER_ADDR0, CALLER_ADDR1, LT_IRQ);
 }
 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);
+		stop_critical_timing(CALLER_ADDR0, caller_addr, LT_IRQ);
 }
 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);
+		start_critical_timing(CALLER_ADDR0, caller_addr, LT_IRQ);
 }
 EXPORT_SYMBOL(trace_hardirqs_off_caller);
 
@@ -504,13 +519,13 @@ EXPORT_SYMBOL(trace_hardirqs_off_caller);
 void trace_preempt_on(unsigned long a0, unsigned long a1)
 {
 	if (preempt_trace() && !irq_trace())
-		stop_critical_timing(a0, a1);
+		stop_critical_timing(a0, a1, LT_PREEMPT);
 }
 
 void trace_preempt_off(unsigned long a0, unsigned long a1)
 {
 	if (preempt_trace() && !irq_trace())
-		start_critical_timing(a0, a1);
+		start_critical_timing(a0, a1, LT_PREEMPT);
 }
 #endif /* CONFIG_PREEMPT_TRACER */
 
-- 
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
a Linux Foundation Collaborative Project