new file mode 100644
@@ -0,0 +1,37 @@
+#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, int cpu, cycles_t latency),
+
+ TP_ARGS(ltype, cpu, latency),
+
+ TP_STRUCT__entry(
+ __field(int, ltype)
+ __field(int, cpu)
+ __field(cycles_t, latency)
+ ),
+
+ TP_fast_assign(
+ __entry->ltype = ltype;
+ __entry->cpu = cpu;
+ __entry->latency = latency;
+ ),
+
+ TP_printk("ltype=%d, cpu=%d, latency=%lu",
+ __entry->ltype, __entry->cpu, (unsigned long) __entry->latency)
+);
+
+DEFINE_EVENT(latency_template, latency_preempt,
+ TP_PROTO(int ltype, int cpu, cycles_t latency),
+ TP_ARGS(ltype, cpu, latency));
+
+#endif /* _TRACE_HIST_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
@@ -13,14 +13,27 @@
#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;
-static DEFINE_PER_CPU(int, tracing_cpu);
+enum latency_type {
+ TS_IRQ,
+ TS_PREEMPT,
+ TS_CRITTIME,
+ TS_MAX
+};
+static DEFINE_PER_CPU(int, tracing_cpu);
+static DEFINE_PER_CPU(cycle_t, lat_ts[TS_MAX]);
static DEFINE_RAW_SPINLOCK(max_trace_lock);
enum {
@@ -419,9 +432,19 @@ stop_critical_timing(unsigned long ip, unsigned long parent_ip)
atomic_dec(&data->disabled);
}
+static inline void latency_trace(enum latency_type type)
+{
+ trace_latency_preempt(type, raw_smp_processor_id(),
+ (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())
+ this_cpu_write(lat_ts[TS_CRITTIME],
+ (cycle_t) trace_clock_local());
+
if (preempt_trace() || irq_trace())
start_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
}
@@ -431,6 +454,10 @@ void stop_critical_timings(void)
{
if (preempt_trace() || irq_trace())
stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
+
+ if (trace_latency_preempt_enabled())
+ latency_trace(TS_CRITTIME);
+
}
EXPORT_SYMBOL_GPL(stop_critical_timings);
@@ -438,6 +465,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(TS_IRQ);
+ }
if (!preempt_trace() && irq_trace())
stop_critical_timing(a0, a1);
}
@@ -446,6 +476,11 @@ 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()) {
+ this_cpu_write(lat_ts[TS_IRQ],
+ (cycle_t) trace_clock_local());
+ }
}
#else /* !CONFIG_PROVE_LOCKING */
@@ -503,6 +538,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(TS_PREEMPT);
+
if (preempt_trace() && !irq_trace())
stop_critical_timing(a0, a1);
}
@@ -511,6 +549,11 @@ 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()) {
+ this_cpu_write(lat_ts[TS_PREEMPT],
+ (cycle_t) trace_clock_local());
+ }
}
#endif /* CONFIG_PREEMPT_TRACER */
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=cpu,latency:val=hitcount:sort=latency if cpu==1' 'hist:key=ltype,cpu:val=latency:sort=ltype,cpu if ltype==0' 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 | 37 ++++++++++++++++++++++++++++++++++ kernel/trace/trace_irqsoff.c | 45 +++++++++++++++++++++++++++++++++++++++++- 2 files changed, 81 insertions(+), 1 deletion(-) 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