Re: [PATCH 2/3] tracing: Add trace_irqsoff tracepoints

From: Daniel Wagner <wagi@monom.org>
To: Binoy Jayan <binoy.jayan@linaro.org>
Cc: Arnd Bergmann <arnd@arndb.de>,
	linaro-kernel@lists.linaro.org,
	Daniel Wagner <daniel.wagner@bmw-carit.de>,
	Carsten Emde <C.Emde@osadl.org>,
	linux-kernel@vger.kernel.org,
	"Steven Rostedt (Red Hat)" <rostedt@goodmis.org>
Subject: Re: [PATCH 2/3] tracing: Add trace_irqsoff tracepoints
Date: Thu, 18 Aug 2016 10:44:12 +0200	[thread overview]
Message-ID: <20160818084412.b24japksnn6hq45n@nobby.bmw-carit.de> (raw)
In-Reply-To: <1471504166-27665-3-git-send-email-binoy.jayan@linaro.org>

On Thu, Aug 18, 2016 at 12:39:25PM +0530, Binoy Jayan wrote:
>  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, ts_irqs);
> +static DEFINE_PER_CPU(cycle_t, ts_preempt);
> +static DEFINE_PER_CPU(cycle_t, ts_critical_timings);
>  static DEFINE_RAW_SPINLOCK(max_trace_lock);

What about creating cycle_t array and introduce only one tracepoint
type which containts the type? I think it should be possible to get
the right plot via hist's filter option:

'hist:key=latency.bucket:val=hitcount:sort=latency if cpu==0 && type==0'

Obviously, there is a performance impact. It would be good to see some
numbers.

cheers,
daniel

Just as rough idea (not tested):

diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
index 03cdff8..012544c 100644
--- a/kernel/trace/trace_irqsoff.c
+++ b/kernel/trace/trace_irqsoff.c
@@ -19,7 +19,15 @@
 static struct trace_array		*irqsoff_trace __read_mostly;
 static int				tracer_enabled __read_mostly;
 
+enum latency_type {
+	LAT_IRQ,
+	LAT_PREEMPT,
+	LAT_CRITTIME,
+	LAT_MAX
+};
+
 static DEFINE_PER_CPU(int, tracing_cpu);
+static DEFINE_PER_CPU(cycle_t[LAT_MAX], lat_data);
 
 static DEFINE_RAW_SPINLOCK(max_trace_lock);
 
@@ -350,6 +358,19 @@ out:
 	__trace_function(tr, CALLER_ADDR0, parent_ip, flags, pc);
 }
 
+static inline void lat_timestamp(enum latency_type type)
+{
+	int cpu = raw_smp_processor_id();
+	per_cpu(lat_data[type], cpu) = ftrace_now(cpu);
+}
+
+static inline void lat_trace(enum latency_type type)
+{
+	int cpu = raw_smp_processor_id();
+	trace_latency_preempt(type,
+			ftrace_now(cpu) - per_cpu(lat_data[type], cpu));
+}
+
 static inline void
 start_critical_timing(unsigned long ip, unsigned long parent_ip)
 {
@@ -422,6 +443,9 @@ stop_critical_timing(unsigned long ip, unsigned long parent_ip)
 /* start and stop critical timings used to for stoppage (in idle) */
 void start_critical_timings(void)
 {
+	if (trace_latency_preempt_enabled())
+		lat_timestamp(LAT_CRITTIME);
+
 	if (preempt_trace() || irq_trace())
 		start_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
 }
@@ -431,6 +455,9 @@ void stop_critical_timings(void)
 {
 	if (preempt_trace() || irq_trace())
 		stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
+
+	if (trace_latency_preempt_enabled())
+		lat_trace(LAT_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_enable())
+		lat_trace(LAT_CRITTIME);
+
 	if (!preempt_trace() && irq_trace())
 		stop_critical_timing(a0, a1);
 }
@@ -446,6 +476,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())
+		lat_timestamp(LAT_IRQ);
 }
 
 #else /* !CONFIG_PROVE_LOCKING */
