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

[Daniel Wagner]

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 */