diff mbox

[v4,2/3] tracing: Add trace_irqsoff tracepoints

Message ID 1472552924-22297-3-git-send-email-binoy.jayan@linaro.org
State New
Headers show

Commit Message

Binoy Jayan Aug. 30, 2016, 10:28 a.m. UTC 
This work is based on work by Daniel Wagner. A few tracepoints are added
at the end of the critical section. With the hist trigger in place, the
hist trigger 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

'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
0: IRQSOFF latency
1: PREEMPTOFF Latency
2: Critical Timings

This captures only the latencies introduced by disabled irqs and
preemption. Additional per process data has to be captured to calculate
the effective latencies introduced for individual processes.

Initial work - latency.patch

[1] https://git.kernel.org/cgit/linux/kernel/git/rt/linux-stable-rt.git/commit/?h=v3.14-rt-rebase&id=56d50cc34943bbba12b8c5942ee1ae3b29f73acb

Signed-off-by: Binoy Jayan <binoy.jayan@linaro.org>

---
 include/trace/events/latency.h | 35 +++++++++++++++++++++++++++++++++++
 kernel/trace/trace_irqsoff.c   | 42 ++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 77 insertions(+)
 create mode 100644 include/trace/events/latency.h

-- 
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
a Linux Foundation Collaborative Project

Comments

Binoy Jayan Aug. 30, 2016, 11:49 a.m. UTC | #1 
Hi Daniel,

On 30 August 2016 at 17:00, Daniel Wagner <daniel.wagner@bmw-carit.de> wrote:
> Hi Binoy,

>

>

> As Masami has pointed out, the prefix trace_ should not be used. Also having

> trace_latency_ and latency_trace_ is kind of confusing. What about

> {start|stop}_latency_timing()? It would match the existing

> {start|stop}_critical_timing(). Or is it too close and it leads to

> confusion?

>

> Another idea is {start|stop}_latency_preempt(). This matches the

> trace_latency_preempt_enable() function.

>


Sure, I'll make this change. And how about the 'cpu' field not being
available to be used
as a key field or as a value field when we do not define it explicitly
(mentioned in the
other email). Can we live with that ?

Thanks,
Binoy
Binoy Jayan Aug. 31, 2016, 11:39 a.m. UTC | #2 
Hi Steven/Daniel,

On 30 August 2016 at 19:38, Steven Rostedt <rostedt@goodmis.org> wrote:
>> +

>> +     TP_printk("ltype=%d, latency=%lu",

>> +             __entry->ltype, (unsigned long) __entry->latency)

>

> The print of ltype should be text and not a number. Well, you could

> have both text and a number, but a number is useless for those looking

> at traces.


I am using '__print_symbolic' to display ltype as a string but it
still shows up in
the histogram as a number. Would you suggest to change this as well?

Thanks,
Binoy
diff mbox

Patch

diff --git a/include/trace/events/latency.h b/include/trace/events/latency.h
new file mode 100644
index 0000000..e89be12
--- /dev/null
+++ b/include/trace/events/latency.h
@@ -0,0 +1,35 @@ 
+#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>
+
+DECLARE_EVENT_CLASS(latency_template,
+	TP_PROTO(int ltype, cycles_t latency),
+
+	TP_ARGS(ltype, latency),
+
+	TP_STRUCT__entry(
+		__field(int,		ltype)
+		__field(cycles_t,	latency)
+	),
+
+	TP_fast_assign(
+		__entry->ltype		= ltype;
+		__entry->latency	= latency;
+	),
+
+	TP_printk("ltype=%d, latency=%lu",
+		__entry->ltype, (unsigned long) __entry->latency)
+);
+
+DEFINE_EVENT(latency_template, latency_preempt,
+	    TP_PROTO(int ltype, cycles_t 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..f70ab69 100644
--- a/kernel/trace/trace_irqsoff.c
+++ b/kernel/trace/trace_irqsoff.c
@@ -13,13 +13,26 @@ 
 #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>
+
+enum latency_type {
+	LT_IRQ,
+	LT_PREEMPT,
+	LT_CRITTIME,
+	LT_MAX
+};
+
 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(cycle_t, lat_ts[LT_MAX]);
 
 static DEFINE_RAW_SPINLOCK(max_trace_lock);
 
@@ -419,9 +432,23 @@  stop_critical_timing(unsigned long ip, unsigned long parent_ip)
 	atomic_dec(&data->disabled);
 }
 
+static inline void trace_latency_preempt_mark_ts(enum latency_type ltype)
+{
+	this_cpu_write(lat_ts[ltype], (cycle_t) trace_clock_local());
+}
+
+static inline void latency_trace(enum latency_type type)
+{
+	trace_latency_preempt(type,
+		(cycle_t) trace_clock_local() - this_cpu_read(lat_ts[type]));
+}
+
 /* start and stop critical timings used to for stoppage (in idle) */
 void start_critical_timings(void)
 {
+	if (trace_latency_preempt_enabled())
+		trace_latency_preempt_mark_ts(LT_CRITTIME);
+
 	if (preempt_trace() || irq_trace())
 		start_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
 }
@@ -431,6 +458,9 @@  void stop_critical_timings(void)
 {
 	if (preempt_trace() || irq_trace())
 		stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
+
+	if (trace_latency_preempt_enabled())
+		latency_trace(LT_CRITTIME);
 }
 EXPORT_SYMBOL_GPL(stop_critical_timings);
 
@@ -438,6 +468,9 @@  EXPORT_SYMBOL_GPL(stop_critical_timings);
 #ifdef CONFIG_PROVE_LOCKING
 void time_hardirqs_on(unsigned long a0, unsigned long a1)
 {
+	if (trace_latency_preempt_enabled())
+		latency_trace(LT_IRQ);
+
 	if (!preempt_trace() && irq_trace())
 		stop_critical_timing(a0, a1);
 }
@@ -446,6 +479,9 @@  void time_hardirqs_off(unsigned long a0, unsigned long a1)
 {
 	if (!preempt_trace() && irq_trace())
 		start_critical_timing(a0, a1);
+
+	if (trace_latency_preempt_enabled())
+		trace_latency_preempt_mark_ts(LT_IRQ);
 }
 
 #else /* !CONFIG_PROVE_LOCKING */
@@ -503,6 +539,9 @@  EXPORT_SYMBOL(trace_hardirqs_off_caller);
 #ifdef CONFIG_PREEMPT_TRACER
 void trace_preempt_on(unsigned long a0, unsigned long a1)
 {
+	if (trace_latency_preempt_enabled())
+		latency_trace(LT_PREEMPT);
+
 	if (preempt_trace() && !irq_trace())
 		stop_critical_timing(a0, a1);
 }
@@ -511,6 +550,9 @@  void trace_preempt_off(unsigned long a0, unsigned long a1)
 {
 	if (preempt_trace() && !irq_trace())
 		start_critical_timing(a0, a1);
+
+	if (trace_latency_preempt_enabled())
+		trace_latency_preempt_mark_ts(LT_PREEMPT);
 }
 #endif /* CONFIG_PREEMPT_TRACER */