[PATCH 0/6] Add tracepoints to trace all system IRQs

[PATCH 0/6] Add tracepoints to trace all system IRQs

[Vaibhav Nagarnaik]

This is a patch series aiming to trace all the system IRQs. The
tracepoints make it easier to find out when interrupts occur and how
much time is spent in kernel space versus user space.

Patches 1-5 add tracepoints to the generic kernel IRQ handlers to
benefit all the architectures, as suggested by Frederic. Patch#6 adds
trace events to trace all platform specific interrupt vectors which do
not have any generic handlers. This patch traces x86 IRQ vectors but can
be used by other architectures to trace their vectors too.


Vaibhav Nagarnaik (6):
  trace,x86: Add tracepoint to x86 timer interrupt handler
  trace: Add tracepoints to timer interrupt handlers
  trace: Add tracepoints to IRQ work run handler
  trace: Add tracepoints to reschedule interrupt handler
  trace: Add tracepoints to call function interrupt handlers
  trace,x86: Add platform_irq_vector_{entry|exit} trace events

 arch/x86/include/asm/irq_vectors.h       |   43 ++++
 arch/x86/kernel/apic/apic.c              |    4 +
 arch/x86/kernel/cpu/mcheck/therm_throt.c |    2 +
 arch/x86/kernel/cpu/mcheck/threshold.c   |    2 +
 arch/x86/kernel/irq.c                    |    2 +
 arch/x86/kernel/time.c                   |   15 +-
 arch/x86/kernel/traps.c                  |    2 +
 arch/x86/mm/tlb.c                        |    2 +
 include/trace/events/irq.h               |  370 ++++++++++++++++++++++++++++++
 kernel/hrtimer.c                         |    6 +
 kernel/irq_work.c                        |    4 +
 kernel/sched.c                           |    4 +
 kernel/smp.c                             |    5 +
 kernel/time/tick-broadcast.c             |   16 ++-
 kernel/time/tick-common.c                |    8 +-
 kernel/time/tick-sched.c                 |    4 +
 16 files changed, 480 insertions(+), 9 deletions(-)

-- 
1.7.3.1

[PATCH 1/6] trace,x86: Add tracepoint to x86 timer interrupt handler

[Vaibhav Nagarnaik]

The x86 timer interrupt handler is the only handler not traced in the
irq/irq_handler_{entry|exit} trace events.

Add tracepoints to the interrupt handler to trace it.

Signed-off-by: Vaibhav Nagarnaik <vnagarnaik@google.com>
---
 arch/x86/kernel/time.c |   15 +++++++++------
 1 files changed, 9 insertions(+), 6 deletions(-)

diff --git a/arch/x86/kernel/time.c b/arch/x86/kernel/time.c
index 00cbb27..dcaf19a 100644
--- a/arch/x86/kernel/time.c
+++ b/arch/x86/kernel/time.c
@@ -51,6 +51,13 @@ unsigned long profile_pc(struct pt_regs *regs)
 }
 EXPORT_SYMBOL(profile_pc);
 
+static irqreturn_t timer_interrupt(int irq, void *dev_id);
+static struct irqaction irq0  = {
+	.handler = timer_interrupt,
+	.flags = IRQF_DISABLED | IRQF_NOBALANCING | IRQF_IRQPOLL | IRQF_TIMER,
+	.name = "timer"
+};
+
 /*
  * Default timer interrupt handler for PIT/HPET
  */
@@ -59,7 +66,9 @@ static irqreturn_t timer_interrupt(int irq, void *dev_id)
 	/* Keep nmi watchdog up to date */
 	inc_irq_stat(irq0_irqs);
 
+	trace_irq_handler_entry(irq, &irq0);
 	global_clock_event->event_handler(global_clock_event);
+	trace_irq_handler_exit(irq, &irq0, 1);
 
 	/* MCA bus quirk: Acknowledge irq0 by setting bit 7 in port 0x61 */
 	if (MCA_bus)
@@ -68,12 +77,6 @@ static irqreturn_t timer_interrupt(int irq, void *dev_id)
 	return IRQ_HANDLED;
 }
 
-static struct irqaction irq0  = {
-	.handler = timer_interrupt,
-	.flags = IRQF_DISABLED | IRQF_NOBALANCING | IRQF_IRQPOLL | IRQF_TIMER,
-	.name = "timer"
-};
-
 void __init setup_default_timer_irq(void)
 {
 	setup_irq(0, &irq0);
-- 
1.7.3.1

[PATCH 2/6] trace: Add tracepoints to timer interrupt handlers

[Vaibhav Nagarnaik]

Add tracepoints to generic kernel timer interrupt handlers to trace the
hardware timer interrupts.

This is a part of overall effort to trace all the interrupts happening
in a system to figure out what time is spent in kernel space versus user
space.

Signed-off-by: Vaibhav Nagarnaik <vnagarnaik@google.com>
---
 include/trace/events/irq.h   |  156 ++++++++++++++++++++++++++++++++++++++++++
 kernel/hrtimer.c             |    6 ++
 kernel/time/tick-broadcast.c |   16 ++++-
 kernel/time/tick-common.c    |    8 ++-
 kernel/time/tick-sched.c     |    4 +
 5 files changed, 187 insertions(+), 3 deletions(-)

diff --git a/include/trace/events/irq.h b/include/trace/events/irq.h
index 4b4c7d9..e6e72e0 100644
--- a/include/trace/events/irq.h
+++ b/include/trace/events/irq.h
@@ -139,6 +139,162 @@ DEFINE_EVENT(softirq, softirq_raise,
 	TP_ARGS(vec_nr)
 );
 
+DECLARE_EVENT_CLASS(timer_interrupt,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore),
+
+	TP_STRUCT__entry(
+		__field(	unsigned int,	ignore	)
+	),
+
+	TP_fast_assign(
+		__entry->ignore = ignore;
+	),
+
+	TP_printk("%u", __entry->ignore)
+);
+
+/**
+ * hrtimer_interrupt_entry - called immediately after entering the hrtimer
+ * handler
+ *
+ * When used in combination with the hrtimer_interrupt_exit tracepoint
+ * we can determine the hrtimer handler runtime.
+ */
+DEFINE_EVENT(timer_interrupt, hrtimer_interrupt_entry,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
+/**
+ * hrtimer_interrupt_exit - called just before the hrtimer handler returns
+ *
+ * When used in combination with the hrtimer_interrupt_entry tracepoint
+ * we can determine the hrtimer handler runtime.
+ */
+DEFINE_EVENT(timer_interrupt, hrtimer_interrupt_exit,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
+/**
+ * timer_broadcast_entry - called immediately after entering the broadcast
+ * timer handler
+ *
+ * When used in combination with the timer_broadcast_exit tracepoint
+ * we can determine the broadcast timer handler runtime.
+ */
+DEFINE_EVENT(timer_interrupt, timer_broadcast_entry,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
+/**
+ * timer_broadcast_exit - called just before the broadcast timer handler
+ * returns
+ *
+ * When used in combination with the timer_broadcast_entry tracepoint
+ * we can determine the broadcast timer handler runtime.
+ */
+DEFINE_EVENT(timer_interrupt, timer_broadcast_exit,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
+/**
+ * timer_oneshot_entry - called immediately after entering the oneshot
+ * timer handler
+ *
+ * When used in combination with the timer_oneshot_exit tracepoint
+ * we can determine the oneshot timer handler runtime.
+ */
+DEFINE_EVENT(timer_interrupt, timer_oneshot_entry,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
+/**
+ * timer_oneshot_exit - called just before the oneshot timer handler
+ * returns
+ *
+ * When used in combination with the timer_oneshot_entry tracepoint
+ * we can determine the oneshot timer handler runtime.
+ */
+DEFINE_EVENT(timer_interrupt, timer_oneshot_exit,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
+/**
+ * timer_periodic_entry - called immediately after entering the periodic
+ * timer handler
+ *
+ * When used in combination with the timer_periodic_exit tracepoint
+ * we can determine the periodic timer handler runtime.
+ */
+DEFINE_EVENT(timer_interrupt, timer_periodic_entry,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
+/**
+ * timer_periodic_exit - called just before the periodic timer handler
+ * returns
+ *
+ * When used in combination with the timer_periodic_entry tracepoint
+ * we can determine the periodic timer handler runtime.
+ */
+DEFINE_EVENT(timer_interrupt, timer_periodic_exit,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
+/**
+ * timer_nohz_entry - called immediately after entering the nohz
+ * timer handler
+ *
+ * When used in combination with the timer_nohz_exit tracepoint
+ * we can determine the nohz timer handler runtime.
+ */
+DEFINE_EVENT(timer_interrupt, timer_nohz_entry,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
+/**
+ * timer_nohz_exit - called just before the nohz timer handler
+ * returns
+ *
+ * When used in combination with the timer_nohz_entry tracepoint
+ * we can determine the nohz timer handler runtime.
+ */
+DEFINE_EVENT(timer_interrupt, timer_nohz_exit,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
 #endif /*  _TRACE_IRQ_H */
 
 /* This part must be outside protection */
diff --git a/kernel/hrtimer.c b/kernel/hrtimer.c
index a9205e3..3bf83d5 100644
--- a/kernel/hrtimer.c
+++ b/kernel/hrtimer.c
@@ -48,6 +48,7 @@
 
 #include <asm/uaccess.h>
 
+#include <trace/events/irq.h>
 #include <trace/events/timer.h>
 
 /*
@@ -1244,6 +1245,8 @@ void hrtimer_interrupt(struct clock_event_device *dev)
 	ktime_t expires_next, now, entry_time, delta;
 	int i, retries = 0;
 
+	trace_hrtimer_interrupt_entry(0);
+
 	BUG_ON(!cpu_base->hres_active);
 	cpu_base->nr_events++;
 	dev->next_event.tv64 = KTIME_MAX;
@@ -1316,6 +1319,7 @@ retry:
 	if (expires_next.tv64 == KTIME_MAX ||
 	    !tick_program_event(expires_next, 0)) {
 		cpu_base->hang_detected = 0;
+		trace_hrtimer_interrupt_exit(0);
 		return;
 	}
 
@@ -1355,6 +1359,8 @@ retry:
 	tick_program_event(expires_next, 1);
 	printk_once(KERN_WARNING "hrtimer: interrupt took %llu ns\n",
 		    ktime_to_ns(delta));
+
+	trace_hrtimer_interrupt_exit(0);
 }
 
 /*
diff --git a/kernel/time/tick-broadcast.c b/kernel/time/tick-broadcast.c
index c7218d1..fc3b9d6 100644
--- a/kernel/time/tick-broadcast.c
+++ b/kernel/time/tick-broadcast.c
@@ -20,6 +20,7 @@
 #include <linux/sched.h>
 
 #include "tick-internal.h"
+#include <trace/events/irq.h>
 
 /*
  * Broadcast support for broken x86 hardware, where the local apic
@@ -176,13 +177,17 @@ static void tick_handle_periodic_broadcast(struct clock_event_device *dev)
 {
 	ktime_t next;
 
+	trace_timer_broadcast_entry(0);
+
 	tick_do_periodic_broadcast();
 
 	/*
 	 * The device is in periodic mode. No reprogramming necessary:
 	 */
-	if (dev->mode == CLOCK_EVT_MODE_PERIODIC)
+	if (dev->mode == CLOCK_EVT_MODE_PERIODIC) {
+		trace_timer_broadcast_exit(0);
 		return;
+	}
 
 	/*
 	 * Setup the next period for devices, which do not have
@@ -194,10 +199,13 @@ static void tick_handle_periodic_broadcast(struct clock_event_device *dev)
 	for (next = dev->next_event; ;) {
 		next = ktime_add(next, tick_period);
 
-		if (!clockevents_program_event(dev, next, ktime_get()))
+		if (!clockevents_program_event(dev, next, ktime_get())) {
+			trace_timer_broadcast_exit(0);
 			return;
+		}
 		tick_do_periodic_broadcast();
 	}
+	trace_timer_broadcast_exit(0);
 }
 
 /*
@@ -404,6 +412,8 @@ static void tick_handle_oneshot_broadcast(struct clock_event_device *dev)
 	ktime_t now, next_event;
 	int cpu;
 
+	trace_timer_oneshot_entry(0);
+
 	raw_spin_lock(&tick_broadcast_lock);
 again:
 	dev->next_event.tv64 = KTIME_MAX;
@@ -443,6 +453,8 @@ again:
 			goto again;
 	}
 	raw_spin_unlock(&tick_broadcast_lock);
+
+	trace_timer_oneshot_exit(0);
 }
 
 /*
diff --git a/kernel/time/tick-common.c b/kernel/time/tick-common.c
index 119528d..a7f81af 100644
--- a/kernel/time/tick-common.c
+++ b/kernel/time/tick-common.c
@@ -18,6 +18,7 @@
 #include <linux/percpu.h>
 #include <linux/profile.h>
 #include <linux/sched.h>
+#include <trace/events/irq.h>
 
 #include <asm/irq_regs.h>
 
@@ -84,6 +85,8 @@ void tick_handle_periodic(struct clock_event_device *dev)
 	int cpu = smp_processor_id();
 	ktime_t next;
 
+	trace_timer_periodic_entry(0);
+
 	tick_periodic(cpu);
 
 	if (dev->mode != CLOCK_EVT_MODE_ONESHOT)
@@ -94,8 +97,10 @@ void tick_handle_periodic(struct clock_event_device *dev)
 	 */
 	next = ktime_add(dev->next_event, tick_period);
 	for (;;) {
-		if (!clockevents_program_event(dev, next, ktime_get()))
+		if (!clockevents_program_event(dev, next, ktime_get())) {
+			trace_timer_periodic_exit(0);
 			return;
+		}
 		/*
 		 * Have to be careful here. If we're in oneshot mode,
 		 * before we call tick_periodic() in a loop, we need
@@ -109,6 +114,7 @@ void tick_handle_periodic(struct clock_event_device *dev)
 			tick_periodic(cpu);
 		next = ktime_add(next, tick_period);
 	}
+	trace_timer_periodic_exit(0);
 }
 
 /*
diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
index d5097c4..54e7b07 100644
--- a/kernel/time/tick-sched.c
+++ b/kernel/time/tick-sched.c
@@ -20,6 +20,7 @@
 #include <linux/profile.h>
 #include <linux/sched.h>
 #include <linux/module.h>
+#include <trace/events/irq.h>
 
 #include <asm/irq_regs.h>
 
@@ -568,6 +569,8 @@ static void tick_nohz_handler(struct clock_event_device *dev)
 	int cpu = smp_processor_id();
 	ktime_t now = ktime_get();
 
+	trace_timer_nohz_entry(0);
+
 	dev->next_event.tv64 = KTIME_MAX;
 
 	/*
@@ -604,6 +607,7 @@ static void tick_nohz_handler(struct clock_event_device *dev)
 		now = ktime_get();
 		tick_do_update_jiffies64(now);
 	}
+	trace_timer_nohz_exit(0);
 }
 
 /**
-- 
1.7.3.1

[PATCH 3/6] trace: Add tracepoints to IRQ work run handler

[Vaibhav Nagarnaik]

This is a part of overall effort to trace all the interrupts happening
in a system to figure out what time is spent in kernel space versus user
space.

Signed-off-by: Vaibhav Nagarnaik <vnagarnaik@google.com>
---
 include/trace/events/irq.h |   44 ++++++++++++++++++++++++++++++++++++++++++++
 kernel/irq_work.c          |    4 ++++
 2 files changed, 48 insertions(+), 0 deletions(-)

diff --git a/include/trace/events/irq.h b/include/trace/events/irq.h
index e6e72e0..d8fab89 100644
--- a/include/trace/events/irq.h
+++ b/include/trace/events/irq.h
@@ -295,6 +295,50 @@ DEFINE_EVENT(timer_interrupt, timer_nohz_exit,
 	TP_ARGS(ignore)
 );
 
+DECLARE_EVENT_CLASS(irq_work,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore),
+
+	TP_STRUCT__entry(
+		__field(	unsigned int,	ignore	)
+	),
+
+	TP_fast_assign(
+		__entry->ignore = ignore;
+	),
+
+	TP_printk("%u", __entry->ignore)
+);
+
+/**
+ * irq_work_run_entry - called immediately after entering the irq work
+ * handler
+ *
+ * When used in combination with the irq_work_run_exit tracepoint
+ * we can determine the irq work handler runtime.
+ */
+DEFINE_EVENT(irq_work, irq_work_run_entry,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
+/**
+ * irq_work_run_exit - called just before the irq work handler returns
+ *
+ * When used in combination with the irq_work_run_entry tracepoint
+ * we can determine the irq work handler runtime.
+ */
+DEFINE_EVENT(irq_work, irq_work_run_exit,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
 #endif /*  _TRACE_IRQ_H */
 
 /* This part must be outside protection */
diff --git a/kernel/irq_work.c b/kernel/irq_work.c
index c58fa7d..7e78122 100644
--- a/kernel/irq_work.c
+++ b/kernel/irq_work.c
@@ -9,6 +9,7 @@
 #include <linux/module.h>
 #include <linux/irq_work.h>
 #include <linux/hardirq.h>
+#include <trace/events/irq.h>
 
 /*
  * An entry can be in one of four states:
@@ -125,6 +126,8 @@ void irq_work_run(void)
 	if (this_cpu_read(irq_work_list) == NULL)
 		return;
 
+	trace_irq_work_run_entry(0);
+
 	BUG_ON(!in_irq());
 	BUG_ON(!irqs_disabled());
 
@@ -149,6 +152,7 @@ void irq_work_run(void)
 			      next_flags(NULL, IRQ_WORK_BUSY),
 			      NULL);
 	}
+	trace_irq_work_run_exit(0);
 }
 EXPORT_SYMBOL_GPL(irq_work_run);
 
-- 
1.7.3.1

Re: [PATCH 3/6] trace: Add tracepoints to IRQ work run handler

[Frederic Weisbecker]

On Thu, Jul 14, 2011 at 02:38:12PM -0700, Vaibhav Nagarnaik wrote:
> This is a part of overall effort to trace all the interrupts happening
> in a system to figure out what time is spent in kernel space versus user
> space.
> 
> Signed-off-by: Vaibhav Nagarnaik <vnagarnaik@google.com>
> ---
>  include/trace/events/irq.h |   44 ++++++++++++++++++++++++++++++++++++++++++++
>  kernel/irq_work.c          |    4 ++++
>  2 files changed, 48 insertions(+), 0 deletions(-)
> 
> diff --git a/include/trace/events/irq.h b/include/trace/events/irq.h
> index e6e72e0..d8fab89 100644
> --- a/include/trace/events/irq.h
> +++ b/include/trace/events/irq.h
> @@ -295,6 +295,50 @@ DEFINE_EVENT(timer_interrupt, timer_nohz_exit,
>  	TP_ARGS(ignore)
>  );
>  
> +DECLARE_EVENT_CLASS(irq_work,
> +
> +	TP_PROTO(unsigned int ignore),
> +
> +	TP_ARGS(ignore),
> +
> +	TP_STRUCT__entry(
> +		__field(	unsigned int,	ignore	)
> +	),
> +
> +	TP_fast_assign(
> +		__entry->ignore = ignore;
> +	),
> +
> +	TP_printk("%u", __entry->ignore)
> +);
> +
> +/**
> + * irq_work_run_entry - called immediately after entering the irq work
> + * handler
> + *
> + * When used in combination with the irq_work_run_exit tracepoint
> + * we can determine the irq work handler runtime.
> + */
> +DEFINE_EVENT(irq_work, irq_work_run_entry,
> +
> +	TP_PROTO(unsigned int ignore),
> +
> +	TP_ARGS(ignore)
> +);
> +
> +/**
> + * irq_work_run_exit - called just before the irq work handler returns
> + *
> + * When used in combination with the irq_work_run_entry tracepoint
> + * we can determine the irq work handler runtime.
> + */
> +DEFINE_EVENT(irq_work, irq_work_run_exit,
> +
> +	TP_PROTO(unsigned int ignore),
> +
> +	TP_ARGS(ignore)
> +);
> +
>  #endif /*  _TRACE_IRQ_H */
>  
>  /* This part must be outside protection */
> diff --git a/kernel/irq_work.c b/kernel/irq_work.c
> index c58fa7d..7e78122 100644
> --- a/kernel/irq_work.c
> +++ b/kernel/irq_work.c
> @@ -9,6 +9,7 @@
>  #include <linux/module.h>
>  #include <linux/irq_work.h>
>  #include <linux/hardirq.h>
> +#include <trace/events/irq.h>
>  
>  /*
>   * An entry can be in one of four states:
> @@ -125,6 +126,8 @@ void irq_work_run(void)
>  	if (this_cpu_read(irq_work_list) == NULL)
>  		return;

If you don't want to miss any of these interrupts, I suggest you
call trace_irq_work_run_entry(0) before the above check.

Also I'm adding Peter who maintains this.

>  
> +	trace_irq_work_run_entry(0);
> +
>  	BUG_ON(!in_irq());
>  	BUG_ON(!irqs_disabled());
>  
> @@ -149,6 +152,7 @@ void irq_work_run(void)
>  			      next_flags(NULL, IRQ_WORK_BUSY),
>  			      NULL);
>  	}
> +	trace_irq_work_run_exit(0);
>  }
>  EXPORT_SYMBOL_GPL(irq_work_run);
>  
> -- 
> 1.7.3.1
> 

Re: [PATCH 3/6] trace: Add tracepoints to IRQ work run handler

[Vaibhav Nagarnaik]

On Thu, Jul 14, 2011 at 3:09 PM, Frederic Weisbecker <fweisbec@gmail.com> wrote:
> On Thu, Jul 14, 2011 at 02:38:12PM -0700, Vaibhav Nagarnaik wrote:
>> This is a part of overall effort to trace all the interrupts happening
>> in a system to figure out what time is spent in kernel space versus user
>> space.
>>
>> Signed-off-by: Vaibhav Nagarnaik <vnagarnaik@google.com>
>> ---
>>  include/trace/events/irq.h |   44 ++++++++++++++++++++++++++++++++++++++++++++
>>  kernel/irq_work.c          |    4 ++++
>>  2 files changed, 48 insertions(+), 0 deletions(-)
>>
>> diff --git a/include/trace/events/irq.h b/include/trace/events/irq.h
>> index e6e72e0..d8fab89 100644
>> --- a/include/trace/events/irq.h
>> +++ b/include/trace/events/irq.h
>> @@ -295,6 +295,50 @@ DEFINE_EVENT(timer_interrupt, timer_nohz_exit,
>>       TP_ARGS(ignore)
>>  );
>>
>> +DECLARE_EVENT_CLASS(irq_work,
>> +
>> +     TP_PROTO(unsigned int ignore),
>> +
>> +     TP_ARGS(ignore),
>> +
>> +     TP_STRUCT__entry(
>> +             __field(        unsigned int,   ignore  )
>> +     ),
>> +
>> +     TP_fast_assign(
>> +             __entry->ignore = ignore;
>> +     ),
>> +
>> +     TP_printk("%u", __entry->ignore)
>> +);
>> +
>> +/**
>> + * irq_work_run_entry - called immediately after entering the irq work
>> + * handler
>> + *
>> + * When used in combination with the irq_work_run_exit tracepoint
>> + * we can determine the irq work handler runtime.
>> + */
>> +DEFINE_EVENT(irq_work, irq_work_run_entry,
>> +
>> +     TP_PROTO(unsigned int ignore),
>> +
>> +     TP_ARGS(ignore)
>> +);
>> +
>> +/**
>> + * irq_work_run_exit - called just before the irq work handler returns
>> + *
>> + * When used in combination with the irq_work_run_entry tracepoint
>> + * we can determine the irq work handler runtime.
>> + */
>> +DEFINE_EVENT(irq_work, irq_work_run_exit,
>> +
>> +     TP_PROTO(unsigned int ignore),
>> +
>> +     TP_ARGS(ignore)
>> +);
>> +
>>  #endif /*  _TRACE_IRQ_H */
>>
>>  /* This part must be outside protection */
>> diff --git a/kernel/irq_work.c b/kernel/irq_work.c
>> index c58fa7d..7e78122 100644
>> --- a/kernel/irq_work.c
>> +++ b/kernel/irq_work.c
>> @@ -9,6 +9,7 @@
>>  #include <linux/module.h>
>>  #include <linux/irq_work.h>
>>  #include <linux/hardirq.h>
>> +#include <trace/events/irq.h>
>>
>>  /*
>>   * An entry can be in one of four states:
>> @@ -125,6 +126,8 @@ void irq_work_run(void)
>>       if (this_cpu_read(irq_work_list) == NULL)
>>               return;
>
> If you don't want to miss any of these interrupts, I suggest you
> call trace_irq_work_run_entry(0) before the above check.
>
> Also I'm adding Peter who maintains this.

Thanks for the catch. I will update it.

>
>>
>> +     trace_irq_work_run_entry(0);
>> +
>>       BUG_ON(!in_irq());
>>       BUG_ON(!irqs_disabled());
>>
>> @@ -149,6 +152,7 @@ void irq_work_run(void)
>>                             next_flags(NULL, IRQ_WORK_BUSY),
>>                             NULL);
>>       }
>> +     trace_irq_work_run_exit(0);
>>  }
>>  EXPORT_SYMBOL_GPL(irq_work_run);
>>
>> --
>> 1.7.3.1
>>
>



Vaibhav Nagarnaik

[PATCH 4/6] trace: Add tracepoints to reschedule interrupt handler

[Vaibhav Nagarnaik]

This is a part of overall effort to trace all the interrupts happening
in a system to figure out what time is spent in kernel space versus user
space.

Signed-off-by: Vaibhav Nagarnaik <vnagarnaik@google.com>
---
 include/trace/events/irq.h |   45 ++++++++++++++++++++++++++++++++++++++++++++
 kernel/sched.c             |    4 +++
 2 files changed, 49 insertions(+), 0 deletions(-)

diff --git a/include/trace/events/irq.h b/include/trace/events/irq.h
index d8fab89..a2a0a49 100644
--- a/include/trace/events/irq.h
+++ b/include/trace/events/irq.h
@@ -339,6 +339,51 @@ DEFINE_EVENT(irq_work, irq_work_run_exit,
 	TP_ARGS(ignore)
 );
 
+DECLARE_EVENT_CLASS(reschedule_interrupt,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore),
+
+	TP_STRUCT__entry(
+		__field(	unsigned int,	ignore	)
+	),
+
+	TP_fast_assign(
+		__entry->ignore = ignore;
+	),
+
+	TP_printk("%u", __entry->ignore)
+);
+
+/**
+ * reschedule_interrupt_entry - called immediately after entering the
+ * reschedule interrupt handler
+ *
+ * When used in combination with the reschedule_interrupt_exit tracepoint
+ * we can determine the reschedule interrupt handler runtime.
+ */
+DEFINE_EVENT(reschedule_interrupt, reschedule_interrupt_entry,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
+/**
+ * reschedule_interrupt_exit - called just before the reschedule interrupt
+ * handler returns
+ *
+ * When used in combination with the reschedule_interrupt_entry tracepoint
+ * we can determine the reschedule interrupt handler runtime.
+ */
+DEFINE_EVENT(reschedule_interrupt, reschedule_interrupt_exit,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
 #endif /*  _TRACE_IRQ_H */
 
 /* This part must be outside protection */
diff --git a/kernel/sched.c b/kernel/sched.c
index 9769c75..605c938 100644
--- a/kernel/sched.c
+++ b/kernel/sched.c
@@ -79,6 +79,8 @@
 #include "sched_cpupri.h"
 #include "workqueue_sched.h"
 #include "sched_autogroup.h"
+#include <trace/events/irq.h>
+
 
 #define CREATE_TRACE_POINTS
 #include <trace/events/sched.h>
@@ -2565,7 +2567,9 @@ static void sched_ttwu_pending(void)
 
 void scheduler_ipi(void)
 {
+	trace_reschedule_interrupt_entry(0);
 	sched_ttwu_pending();
+	trace_reschedule_interrupt_exit(0);
 }
 
 static void ttwu_queue_remote(struct task_struct *p, int cpu)
-- 
1.7.3.1

Re: [PATCH 4/6] trace: Add tracepoints to reschedule interrupt handler

[Frederic Weisbecker]

Looks good to me. But I'm adding Peter in Cc.

On Thu, Jul 14, 2011 at 02:38:13PM -0700, Vaibhav Nagarnaik wrote:
> This is a part of overall effort to trace all the interrupts happening
> in a system to figure out what time is spent in kernel space versus user
> space.
> 
> Signed-off-by: Vaibhav Nagarnaik <vnagarnaik@google.com>
> ---
>  include/trace/events/irq.h |   45 ++++++++++++++++++++++++++++++++++++++++++++
>  kernel/sched.c             |    4 +++
>  2 files changed, 49 insertions(+), 0 deletions(-)
> 
> diff --git a/include/trace/events/irq.h b/include/trace/events/irq.h
> index d8fab89..a2a0a49 100644
> --- a/include/trace/events/irq.h
> +++ b/include/trace/events/irq.h
> @@ -339,6 +339,51 @@ DEFINE_EVENT(irq_work, irq_work_run_exit,
>  	TP_ARGS(ignore)
>  );
>  
> +DECLARE_EVENT_CLASS(reschedule_interrupt,
> +
> +	TP_PROTO(unsigned int ignore),
> +
> +	TP_ARGS(ignore),
> +
> +	TP_STRUCT__entry(
> +		__field(	unsigned int,	ignore	)
> +	),
> +
> +	TP_fast_assign(
> +		__entry->ignore = ignore;
> +	),
> +
> +	TP_printk("%u", __entry->ignore)
> +);
> +
> +/**
> + * reschedule_interrupt_entry - called immediately after entering the
> + * reschedule interrupt handler
> + *
> + * When used in combination with the reschedule_interrupt_exit tracepoint
> + * we can determine the reschedule interrupt handler runtime.
> + */
> +DEFINE_EVENT(reschedule_interrupt, reschedule_interrupt_entry,
> +
> +	TP_PROTO(unsigned int ignore),
> +
> +	TP_ARGS(ignore)
> +);
> +
> +/**
> + * reschedule_interrupt_exit - called just before the reschedule interrupt
> + * handler returns
> + *
> + * When used in combination with the reschedule_interrupt_entry tracepoint
> + * we can determine the reschedule interrupt handler runtime.
> + */
> +DEFINE_EVENT(reschedule_interrupt, reschedule_interrupt_exit,
> +
> +	TP_PROTO(unsigned int ignore),
> +
> +	TP_ARGS(ignore)
> +);
> +
>  #endif /*  _TRACE_IRQ_H */
>  
>  /* This part must be outside protection */
> diff --git a/kernel/sched.c b/kernel/sched.c
> index 9769c75..605c938 100644
> --- a/kernel/sched.c
> +++ b/kernel/sched.c
> @@ -79,6 +79,8 @@
>  #include "sched_cpupri.h"
>  #include "workqueue_sched.h"
>  #include "sched_autogroup.h"
> +#include <trace/events/irq.h>
> +
>  
>  #define CREATE_TRACE_POINTS
>  #include <trace/events/sched.h>
> @@ -2565,7 +2567,9 @@ static void sched_ttwu_pending(void)
>  
>  void scheduler_ipi(void)
>  {
> +	trace_reschedule_interrupt_entry(0);
>  	sched_ttwu_pending();
> +	trace_reschedule_interrupt_exit(0);
>  }
>  
>  static void ttwu_queue_remote(struct task_struct *p, int cpu)
> -- 
> 1.7.3.1
> 

Re: [PATCH 4/6] trace: Add tracepoints to reschedule interrupt handler

[Peter Zijlstra]

On Fri, 2011-07-15 at 00:02 +0200, Frederic Weisbecker wrote:
> > This is a part of overall effort to trace all the interrupts happening
> > in a system to figure out what time is spent in kernel space versus user
> > space. 

How about you enable CONFIG_IRQ_TIME_ACCOUNTING and get all that?

Re: [PATCH 4/6] trace: Add tracepoints to reschedule interrupt handler

[David Sharp]

On Fri, Jul 15, 2011 at 1:48 AM, Peter Zijlstra <a.p.zijlstra@chello.nl> wrote:
> On Fri, 2011-07-15 at 00:02 +0200, Frederic Weisbecker wrote:
>> > This is a part of overall effort to trace all the interrupts happening
>> > in a system to figure out what time is spent in kernel space versus user
>> > space.
>
> How about you enable CONFIG_IRQ_TIME_ACCOUNTING and get all that?
>

It's not just about how long, it's when, and what other events the
interrupts are interacting with.

Re: [PATCH 4/6] trace: Add tracepoints to reschedule interrupt handler

[Peter Zijlstra]

On Fri, 2011-07-15 at 10:50 -0700, David Sharp wrote:
> On Fri, Jul 15, 2011 at 1:48 AM, Peter Zijlstra <a.p.zijlstra@chello.nl> wrote:
> > On Fri, 2011-07-15 at 00:02 +0200, Frederic Weisbecker wrote:
> >> > This is a part of overall effort to trace all the interrupts happening
> >> > in a system to figure out what time is spent in kernel space versus user
> >> > space.
> >
> > How about you enable CONFIG_IRQ_TIME_ACCOUNTING and get all that?
> >
> 
> It's not just about how long, it's when, and what other events the
> interrupts are interacting with.

But that's not what the Changelog said, how am I supposed to smell that?

As to the patch in particular, I hate it, why do you need separate
tracepoints for the resched ipi and wtf is up with that ignore argument.

Re: [PATCH 4/6] trace: Add tracepoints to reschedule interrupt handler

[Vaibhav Nagarnaik]

On Thu, Jul 21, 2011 at 5:31 AM, Peter Zijlstra <a.p.zijlstra@chello.nl> wrote:
> On Fri, 2011-07-15 at 10:50 -0700, David Sharp wrote:
>> On Fri, Jul 15, 2011 at 1:48 AM, Peter Zijlstra <a.p.zijlstra@chello.nl> wrote:
>> > On Fri, 2011-07-15 at 00:02 +0200, Frederic Weisbecker wrote:
>> >> > This is a part of overall effort to trace all the interrupts happening
>> >> > in a system to figure out what time is spent in kernel space versus user
>> >> > space.
>> >
>> > How about you enable CONFIG_IRQ_TIME_ACCOUNTING and get all that?
>> >
>>
>> It's not just about how long, it's when, and what other events the
>> interrupts are interacting with.
>
> But that's not what the Changelog said, how am I supposed to smell that?

I will update the changelog to be clearer.

>
> As to the patch in particular, I hate it, why do you need separate
> tracepoints for the resched ipi and wtf is up with that ignore argument.
>

By separate tracepoints if you mean the entry and exit tracepoints, we
use it to trace the interrupts in the system and get the timing for each
interrupt to complete. When interleaved with the other system trace, we
get how it affected other tasks. It would be hard to know that by using
CONFIG_IRQ_TIME_ACCOUNTING.

The 'ignore' argument is due to the limitation of the TRACE_EVENT macro,
which requires at least 1 argument passed to it. I could not think of a
suitable data argument for the tracepoint, so I had to use a dummy
argument. If you can suggest something that can be used instead, I will
be glad to update the patch.


Vaibhav Nagarnaik

[PATCH 5/6] trace: Add tracepoints to call function interrupt handlers

[Vaibhav Nagarnaik]

Add tracepoints to call function and call function single interrupt
handlers.

This is a part of overall effort to trace all the interrupts happening
in a system to figure out what time is spent in kernel space versus user
space.

Signed-off-by: Vaibhav Nagarnaik <vnagarnaik@google.com>
---
 include/trace/events/irq.h |   73 ++++++++++++++++++++++++++++++++++++++++++++
 kernel/smp.c               |    5 +++
 2 files changed, 78 insertions(+), 0 deletions(-)

diff --git a/include/trace/events/irq.h b/include/trace/events/irq.h
index a2a0a49..40b19f4 100644
--- a/include/trace/events/irq.h
+++ b/include/trace/events/irq.h
@@ -384,6 +384,79 @@ DEFINE_EVENT(reschedule_interrupt, reschedule_interrupt_exit,
 	TP_ARGS(ignore)
 );
 
+DECLARE_EVENT_CLASS(call_function,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore),
+
+	TP_STRUCT__entry(
+		__field(	unsigned int,	ignore	)
+	),
+
+	TP_fast_assign(
+		__entry->ignore = ignore;
+	),
+
+	TP_printk("%u", __entry->ignore)
+);
+
+/**
+ * call_function_entry - called immediately after entering the
+ * call function interrupt handler
+ *
+ * When used in combination with the call_function_exit tracepoint
+ * we can determine the call function interrupt handler runtime.
+ */
+DEFINE_EVENT(call_function, call_function_entry,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
+/**
+ * call_function_exit - called just before the call function interrupt
+ * handler returns
+ *
+ * When used in combination with the call_function_entry tracepoint
+ * we can determine the call function interrupt handler runtime.
+ */
+DEFINE_EVENT(call_function, call_function_exit,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
+/**
+ * call_function_single_entry - called immediately after entering the
+ * call function single interrupt handler
+ *
+ * When used in combination with the call_function_single_exit tracepoint
+ * we can determine the call function single interrupt handler runtime.
+ */
+DEFINE_EVENT(call_function, call_function_single_entry,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
+/**
+ * call_function_single_exit - called just before the call function single
+ * interrupt handler returns
+ *
+ * When used in combination with the call_function_single_entry tracepoint
+ * we can determine the call function single interrupt handler runtime.
+ */
+DEFINE_EVENT(call_function, call_function_single_exit,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
 #endif /*  _TRACE_IRQ_H */
 
 /* This part must be outside protection */
diff --git a/kernel/smp.c b/kernel/smp.c
index fb67dfa..3c4ce30 100644
--- a/kernel/smp.c
+++ b/kernel/smp.c
@@ -12,6 +12,7 @@
 #include <linux/gfp.h>
 #include <linux/smp.h>
 #include <linux/cpu.h>
+#include <trace/events/irq.h>
 
 #ifdef CONFIG_USE_GENERIC_SMP_HELPERS
 static struct {
@@ -172,6 +173,7 @@ void generic_smp_call_function_interrupt(void)
 	struct call_function_data *data;
 	int cpu = smp_processor_id();
 
+	trace_call_function_entry(0);
 	/*
 	 * Shouldn't receive this interrupt on a cpu that is not yet online.
 	 */
@@ -240,6 +242,7 @@ void generic_smp_call_function_interrupt(void)
 		csd_unlock(&data->csd);
 	}
 
+	trace_call_function_exit(0);
 }
 
 /*
@@ -252,6 +255,7 @@ void generic_smp_call_function_single_interrupt(void)
 	unsigned int data_flags;
 	LIST_HEAD(list);
 
+	trace_call_function_single_entry(0);
 	/*
 	 * Shouldn't receive this interrupt on a cpu that is not yet online.
 	 */
@@ -282,6 +286,7 @@ void generic_smp_call_function_single_interrupt(void)
 		if (data_flags & CSD_FLAG_LOCK)
 			csd_unlock(data);
 	}
+	trace_call_function_single_exit(0);
 }
 
 static DEFINE_PER_CPU_SHARED_ALIGNED(struct call_single_data, csd_data);
-- 
1.7.3.1

Re: [PATCH 5/6] trace: Add tracepoints to call function interrupt handlers

[Frederic Weisbecker]

On Thu, Jul 14, 2011 at 02:38:14PM -0700, Vaibhav Nagarnaik wrote:
> Add tracepoints to call function and call function single interrupt
> handlers.
> 
> This is a part of overall effort to trace all the interrupts happening
> in a system to figure out what time is spent in kernel space versus user
> space.
> 
> Signed-off-by: Vaibhav Nagarnaik <vnagarnaik@google.com>
> ---
>  include/trace/events/irq.h |   73 ++++++++++++++++++++++++++++++++++++++++++++
>  kernel/smp.c               |    5 +++
>  2 files changed, 78 insertions(+), 0 deletions(-)
> 
> diff --git a/include/trace/events/irq.h b/include/trace/events/irq.h
> index a2a0a49..40b19f4 100644
> --- a/include/trace/events/irq.h
> +++ b/include/trace/events/irq.h
> @@ -384,6 +384,79 @@ DEFINE_EVENT(reschedule_interrupt, reschedule_interrupt_exit,
>  	TP_ARGS(ignore)
>  );
>  
> +DECLARE_EVENT_CLASS(call_function,
> +
> +	TP_PROTO(unsigned int ignore),
> +
> +	TP_ARGS(ignore),
> +
> +	TP_STRUCT__entry(
> +		__field(	unsigned int,	ignore	)
> +	),
> +
> +	TP_fast_assign(
> +		__entry->ignore = ignore;
> +	),
> +
> +	TP_printk("%u", __entry->ignore)
> +);
> +
> +/**
> + * call_function_entry - called immediately after entering the
> + * call function interrupt handler
> + *
> + * When used in combination with the call_function_exit tracepoint
> + * we can determine the call function interrupt handler runtime.
> + */
> +DEFINE_EVENT(call_function, call_function_entry,
> +
> +	TP_PROTO(unsigned int ignore),
> +
> +	TP_ARGS(ignore)
> +);

Looks good. But perhaps we need some disambiguation on the names, call_function is perhaps
too generic.

What about trace_irq_call_function() ? Or may be something with ipi in the name, dunno. 

Re: [PATCH 5/6] trace: Add tracepoints to call function interrupt handlers

[Vaibhav Nagarnaik]

On Thu, Jul 14, 2011 at 3:05 PM, Frederic Weisbecker <fweisbec@gmail.com> wrote:
> On Thu, Jul 14, 2011 at 02:38:14PM -0700, Vaibhav Nagarnaik wrote:
>> Add tracepoints to call function and call function single interrupt
>> handlers.
>>
>> This is a part of overall effort to trace all the interrupts happening
>> in a system to figure out what time is spent in kernel space versus user
>> space.
>>
>> Signed-off-by: Vaibhav Nagarnaik <vnagarnaik@google.com>
>> ---
>>  include/trace/events/irq.h |   73 ++++++++++++++++++++++++++++++++++++++++++++
>>  kernel/smp.c               |    5 +++
>>  2 files changed, 78 insertions(+), 0 deletions(-)
>>
>> diff --git a/include/trace/events/irq.h b/include/trace/events/irq.h
>> index a2a0a49..40b19f4 100644
>> --- a/include/trace/events/irq.h
>> +++ b/include/trace/events/irq.h
>> @@ -384,6 +384,79 @@ DEFINE_EVENT(reschedule_interrupt, reschedule_interrupt_exit,
>>       TP_ARGS(ignore)
>>  );
>>
>> +DECLARE_EVENT_CLASS(call_function,
>> +
>> +     TP_PROTO(unsigned int ignore),
>> +
>> +     TP_ARGS(ignore),
>> +
>> +     TP_STRUCT__entry(
>> +             __field(        unsigned int,   ignore  )
>> +     ),
>> +
>> +     TP_fast_assign(
>> +             __entry->ignore = ignore;
>> +     ),
>> +
>> +     TP_printk("%u", __entry->ignore)
>> +);
>> +
>> +/**
>> + * call_function_entry - called immediately after entering the
>> + * call function interrupt handler
>> + *
>> + * When used in combination with the call_function_exit tracepoint
>> + * we can determine the call function interrupt handler runtime.
>> + */
>> +DEFINE_EVENT(call_function, call_function_entry,
>> +
>> +     TP_PROTO(unsigned int ignore),
>> +
>> +     TP_ARGS(ignore)
>> +);
>
> Looks good. But perhaps we need some disambiguation on the names, call_function is perhaps
> too generic.
>
> What about trace_irq_call_function() ? Or may be something with ipi in the name, dunno.
>

How about the following?
call_function_ipi_(entry|exit) and
call_function_single_ipi_(entry|exit)


Vaibhav Nagarnaik

Re: [PATCH 5/6] trace: Add tracepoints to call function interrupt handlers

[Frederic Weisbecker]

On Thu, Jul 14, 2011 at 04:02:49PM -0700, Vaibhav Nagarnaik wrote:
> On Thu, Jul 14, 2011 at 3:05 PM, Frederic Weisbecker <fweisbec@gmail.com> wrote:
> > On Thu, Jul 14, 2011 at 02:38:14PM -0700, Vaibhav Nagarnaik wrote:
> >> Add tracepoints to call function and call function single interrupt
> >> handlers.
> >>
> >> This is a part of overall effort to trace all the interrupts happening
> >> in a system to figure out what time is spent in kernel space versus user
> >> space.
> >>
> >> Signed-off-by: Vaibhav Nagarnaik <vnagarnaik@google.com>
> >> ---
> >>  include/trace/events/irq.h |   73 ++++++++++++++++++++++++++++++++++++++++++++
> >>  kernel/smp.c               |    5 +++
> >>  2 files changed, 78 insertions(+), 0 deletions(-)
> >>
> >> diff --git a/include/trace/events/irq.h b/include/trace/events/irq.h
> >> index a2a0a49..40b19f4 100644
> >> --- a/include/trace/events/irq.h
> >> +++ b/include/trace/events/irq.h
> >> @@ -384,6 +384,79 @@ DEFINE_EVENT(reschedule_interrupt, reschedule_interrupt_exit,
> >>       TP_ARGS(ignore)
> >>  );
> >>
> >> +DECLARE_EVENT_CLASS(call_function,
> >> +
> >> +     TP_PROTO(unsigned int ignore),
> >> +
> >> +     TP_ARGS(ignore),
> >> +
> >> +     TP_STRUCT__entry(
> >> +             __field(        unsigned int,   ignore  )
> >> +     ),
> >> +
> >> +     TP_fast_assign(
> >> +             __entry->ignore = ignore;
> >> +     ),
> >> +
> >> +     TP_printk("%u", __entry->ignore)
> >> +);
> >> +
> >> +/**
> >> + * call_function_entry - called immediately after entering the
> >> + * call function interrupt handler
> >> + *
> >> + * When used in combination with the call_function_exit tracepoint
> >> + * we can determine the call function interrupt handler runtime.
> >> + */
> >> +DEFINE_EVENT(call_function, call_function_entry,
> >> +
> >> +     TP_PROTO(unsigned int ignore),
> >> +
> >> +     TP_ARGS(ignore)
> >> +);
> >
> > Looks good. But perhaps we need some disambiguation on the names, call_function is perhaps
> > too generic.
> >
> > What about trace_irq_call_function() ? Or may be something with ipi in the name, dunno.
> >
> 
> How about the following?
> call_function_ipi_(entry|exit) and
> call_function_single_ipi_(entry|exit)

Yeah sounds good!

Thanks.

[PATCH 6/6] trace,x86: Add platform_irq_vector_{entry|exit} trace events

[Vaibhav Nagarnaik]

Add tracepoints to trace platform specific IRQ vectors which do not have
equivalent generic kernel handlers. Along with the IRQ number traced,
there is a symbolic mapping to the equivalent name of the IRQ.

This patch only traces the x86 and x86_64 platform vectors but other
architectures can add the tracepoints in their equivalent files to make
use of this trace event.

This is a part of overall effort to trace all the interrupts happening
in a system to figure out what time is spent in kernel space versus user
space.

Signed-off-by: Vaibhav Nagarnaik <vnagarnaik@google.com>
---
 arch/x86/include/asm/irq_vectors.h       |   43 ++++++++++++++++++++++++
 arch/x86/kernel/apic/apic.c              |    4 ++
 arch/x86/kernel/cpu/mcheck/therm_throt.c |    2 +
 arch/x86/kernel/cpu/mcheck/threshold.c   |    2 +
 arch/x86/kernel/irq.c                    |    2 +
 arch/x86/kernel/traps.c                  |    2 +
 arch/x86/mm/tlb.c                        |    2 +
 include/trace/events/irq.h               |   52 ++++++++++++++++++++++++++++++
 8 files changed, 109 insertions(+), 0 deletions(-)

diff --git a/arch/x86/include/asm/irq_vectors.h b/arch/x86/include/asm/irq_vectors.h
index 6e976ee..e169c3c 100644
--- a/arch/x86/include/asm/irq_vectors.h
+++ b/arch/x86/include/asm/irq_vectors.h
@@ -182,4 +182,47 @@ static inline int invalid_vm86_irq(int irq)
 # define NR_IRQS			NR_IRQS_LEGACY
 #endif
 
+#define platform_irq_vector_mapping(x) { x, #x }
+#define invalidate_tlb_vector_mapping(x) \
+		{ INVALIDATE_TLB_VECTOR_START+x, "INVALIDATE_TLB_VECTOR" }
+#define platform_irq_vector_name					\
+		platform_irq_vector_mapping(SPURIOUS_APIC_VECTOR),	\
+		platform_irq_vector_mapping(ERROR_APIC_VECTOR),		\
+		platform_irq_vector_mapping(THERMAL_APIC_VECTOR),	\
+		platform_irq_vector_mapping(THRESHOLD_APIC_VECTOR),	\
+		platform_irq_vector_mapping(X86_PLATFORM_IPI_VECTOR),	\
+		platform_irq_vector_mapping(NMI_VECTOR),		\
+		invalidate_tlb_vector_mapping(0),			\
+		invalidate_tlb_vector_mapping(1),			\
+		invalidate_tlb_vector_mapping(2),			\
+		invalidate_tlb_vector_mapping(3),			\
+		invalidate_tlb_vector_mapping(4),			\
+		invalidate_tlb_vector_mapping(5),			\
+		invalidate_tlb_vector_mapping(6),			\
+		invalidate_tlb_vector_mapping(7),			\
+		invalidate_tlb_vector_mapping(8),			\
+		invalidate_tlb_vector_mapping(9),			\
+		invalidate_tlb_vector_mapping(10),			\
+		invalidate_tlb_vector_mapping(11),			\
+		invalidate_tlb_vector_mapping(12),			\
+		invalidate_tlb_vector_mapping(13),			\
+		invalidate_tlb_vector_mapping(14),			\
+		invalidate_tlb_vector_mapping(15),			\
+		invalidate_tlb_vector_mapping(16),			\
+		invalidate_tlb_vector_mapping(17),			\
+		invalidate_tlb_vector_mapping(18),			\
+		invalidate_tlb_vector_mapping(19),			\
+		invalidate_tlb_vector_mapping(20),			\
+		invalidate_tlb_vector_mapping(21),			\
+		invalidate_tlb_vector_mapping(22),			\
+		invalidate_tlb_vector_mapping(23),			\
+		invalidate_tlb_vector_mapping(24),			\
+		invalidate_tlb_vector_mapping(25),			\
+		invalidate_tlb_vector_mapping(26),			\
+		invalidate_tlb_vector_mapping(27),			\
+		invalidate_tlb_vector_mapping(28),			\
+		invalidate_tlb_vector_mapping(29),			\
+		invalidate_tlb_vector_mapping(30),			\
+		invalidate_tlb_vector_mapping(31)
+
 #endif /* _ASM_X86_IRQ_VECTORS_H */
diff --git a/arch/x86/kernel/apic/apic.c b/arch/x86/kernel/apic/apic.c
index b9338b8..6062eb3 100644
--- a/arch/x86/kernel/apic/apic.c
+++ b/arch/x86/kernel/apic/apic.c
@@ -1792,6 +1792,7 @@ void smp_spurious_interrupt(struct pt_regs *regs)
 
 	exit_idle();
 	irq_enter();
+	trace_platform_irq_vector_entry(SPURIOUS_APIC_VECTOR);
 	/*
 	 * Check if this really is a spurious interrupt and ACK it
 	 * if it is a vectored one.  Just in case...
@@ -1806,6 +1807,7 @@ void smp_spurious_interrupt(struct pt_regs *regs)
 	/* see sw-dev-man vol 3, chapter 7.4.13.5 */
 	pr_info("spurious APIC interrupt on CPU#%d, "
 		"should never happen.\n", smp_processor_id());
+	trace_platform_irq_vector_exit(SPURIOUS_APIC_VECTOR);
 	irq_exit();
 }
 
@@ -1829,6 +1831,7 @@ void smp_error_interrupt(struct pt_regs *regs)
 
 	exit_idle();
 	irq_enter();
+	trace_platform_irq_vector_entry(ERROR_APIC_VECTOR);
 	/* First tickle the hardware, only then report what went on. -- REW */
 	v0 = apic_read(APIC_ESR);
 	apic_write(APIC_ESR, 0);
@@ -1849,6 +1852,7 @@ void smp_error_interrupt(struct pt_regs *regs)
 
 	apic_printk(APIC_DEBUG, KERN_CONT "\n");
 
+	trace_platform_irq_vector_exit(ERROR_APIC_VECTOR);
 	irq_exit();
 }
 
diff --git a/arch/x86/kernel/cpu/mcheck/therm_throt.c b/arch/x86/kernel/cpu/mcheck/therm_throt.c
index 27c6251..4528f26 100644
--- a/arch/x86/kernel/cpu/mcheck/therm_throt.c
+++ b/arch/x86/kernel/cpu/mcheck/therm_throt.c
@@ -398,8 +398,10 @@ asmlinkage void smp_thermal_interrupt(struct pt_regs *regs)
 {
 	exit_idle();
 	irq_enter();
+	trace_platform_irq_vector_entry(THERMAL_APIC_VECTOR);
 	inc_irq_stat(irq_thermal_count);
 	smp_thermal_vector();
+	trace_platform_irq_vector_exit(THERMAL_APIC_VECTOR);
 	irq_exit();
 	/* Ack only at the end to avoid potential reentry */
 	ack_APIC_irq();
diff --git a/arch/x86/kernel/cpu/mcheck/threshold.c b/arch/x86/kernel/cpu/mcheck/threshold.c
index d746df2..0876815 100644
--- a/arch/x86/kernel/cpu/mcheck/threshold.c
+++ b/arch/x86/kernel/cpu/mcheck/threshold.c
@@ -21,8 +21,10 @@ asmlinkage void smp_threshold_interrupt(void)
 {
 	exit_idle();
 	irq_enter();
+	trace_platform_irq_vector_entry(THRESHOLD_APIC_VECTOR);
 	inc_irq_stat(irq_threshold_count);
 	mce_threshold_vector();
+	trace_platform_irq_vector_exit(THRESHOLD_APIC_VECTOR);
 	irq_exit();
 	/* Ack only at the end to avoid potential reentry */
 	ack_APIC_irq();
diff --git a/arch/x86/kernel/irq.c b/arch/x86/kernel/irq.c
index 6c0802e..0c730f4 100644
--- a/arch/x86/kernel/irq.c
+++ b/arch/x86/kernel/irq.c
@@ -211,12 +211,14 @@ void smp_x86_platform_ipi(struct pt_regs *regs)
 	exit_idle();
 
 	irq_enter();
+	trace_platform_irq_vector_entry(X86_PLATFORM_IPI_VECTOR);
 
 	inc_irq_stat(x86_platform_ipis);
 
 	if (x86_platform_ipi_callback)
 		x86_platform_ipi_callback();
 
+	trace_platform_irq_vector_exit(X86_PLATFORM_IPI_VECTOR);
 	irq_exit();
 
 	set_irq_regs(old_regs);
diff --git a/arch/x86/kernel/traps.c b/arch/x86/kernel/traps.c
index fda27eb..0834c84 100644
--- a/arch/x86/kernel/traps.c
+++ b/arch/x86/kernel/traps.c
@@ -447,12 +447,14 @@ dotraplinkage notrace __kprobes void
 do_nmi(struct pt_regs *regs, long error_code)
 {
 	nmi_enter();
+	trace_platform_irq_vector_entry(NMI_VECTOR);
 
 	inc_irq_stat(__nmi_count);
 
 	if (!ignore_nmis)
 		default_do_nmi(regs);
 
+	trace_platform_irq_vector_exit(NMI_VECTOR);
 	nmi_exit();
 }
 
diff --git a/arch/x86/mm/tlb.c b/arch/x86/mm/tlb.c
index d6c0418..5c9e766 100644
--- a/arch/x86/mm/tlb.c
+++ b/arch/x86/mm/tlb.c
@@ -141,6 +141,7 @@ void smp_invalidate_interrupt(struct pt_regs *regs)
 	sender = ~regs->orig_ax - INVALIDATE_TLB_VECTOR_START;
 	f = &flush_state[sender];
 
+	trace_platform_irq_vector_entry(sender + INVALIDATE_TLB_VECTOR_START);
 	if (!cpumask_test_cpu(cpu, to_cpumask(f->flush_cpumask)))
 		goto out;
 		/*
@@ -167,6 +168,7 @@ out:
 	cpumask_clear_cpu(cpu, to_cpumask(f->flush_cpumask));
 	smp_mb__after_clear_bit();
 	inc_irq_stat(irq_tlb_count);
+	trace_platform_irq_vector_exit(sender + INVALIDATE_TLB_VECTOR_START);
 }
 
 static void flush_tlb_others_ipi(const struct cpumask *cpumask,
diff --git a/include/trace/events/irq.h b/include/trace/events/irq.h
index 40b19f4..2a399e8 100644
--- a/include/trace/events/irq.h
+++ b/include/trace/events/irq.h
@@ -457,6 +457,58 @@ DEFINE_EVENT(call_function, call_function_single_exit,
 	TP_ARGS(ignore)
 );
 
+#include <asm/irq.h>
+
+#if !defined(platform_irq_vector_name)
+#define platform_irq_vector_name { NULL, NULL }
+#endif
+
+DECLARE_EVENT_CLASS(platform_irq_vector,
+
+	TP_PROTO(unsigned int vec_num),
+
+	TP_ARGS(vec_num),
+
+	TP_STRUCT__entry(
+		__field(	unsigned int,	vec_num	)
+	),
+
+	TP_fast_assign(
+		__entry->vec_num = vec_num;
+	),
+
+	TP_printk("%u: %s", __entry->vec_num,
+		__print_symbolic(__entry->vec_num, platform_irq_vector_name))
+);
+
+/**
+ * platform_irq_vector_entry - called immediately after entering the
+ * platform vector interrupt handler
+ *
+ * When used in combination with the platform_irq_vector_exit tracepoint
+ * we can determine the platform interrupt vector handler runtime.
+ */
+DEFINE_EVENT(platform_irq_vector, platform_irq_vector_entry,
+
+	TP_PROTO(unsigned int vec_num),
+
+	TP_ARGS(vec_num)
+);
+
+/**
+ * platform_irq_vector_exit - called just before the platform vector
+ * interrupt handler returns
+ *
+ * When used in combination with the platform_irq_vector_entry tracepoint
+ * we can determine the platform interrupt vector handler runtime.
+ */
+DEFINE_EVENT(platform_irq_vector, platform_irq_vector_exit,
+
+	TP_PROTO(unsigned int vec_num),
+
+	TP_ARGS(vec_num)
+);
+
 #endif /*  _TRACE_IRQ_H */
 
 /* This part must be outside protection */
-- 
1.7.3.1

[PATCH v2 0/6] Add tracepoints to trace all system IRQs

[Vaibhav Nagarnaik]

This is a patch series aiming to trace all the system IRQs. The
tracepoints make it easier to understand IRQ interaction with other
system events and find out how much time is spent in kernel space versus
user space.

Patches 1-5 add tracepoints to the generic kernel IRQ handlers to
benefit all the architectures, as suggested by Frederic. Patch#6 adds
trace events to trace all platform specific interrupt vectors which do
not have any generic handlers. This patch traces x86 IRQ vectors but can
be used by other architectures to trace their vectors too.

Changelog v2-v1:
* Fix patch#3 to trace IRQ work run vector even when the irq work list
  is empty
* Fix patch#5 to use updated trace event names,
  call_function_ipi_(entry|exit) and
  call_function_single_ipi_(entry|exit)
* Rebase to 3.0
* Update changelog

Vaibhav Nagarnaik (6):
  trace,x86: Add tracepoint to x86 timer interrupt handler
  trace: Add tracepoints to timer interrupt handlers
  trace: Add tracepoints to IRQ work run handler
  trace: Add tracepoints to reschedule interrupt handler
  trace: Add tracepoints to call function interrupt handlers
  trace,x86: Add platform_irq_vector_{entry|exit} trace events

 arch/x86/include/asm/irq_vectors.h       |   43 ++++
 arch/x86/kernel/apic/apic.c              |    4 +
 arch/x86/kernel/cpu/mcheck/therm_throt.c |    2 +
 arch/x86/kernel/cpu/mcheck/threshold.c   |    2 +
 arch/x86/kernel/irq.c                    |    2 +
 arch/x86/kernel/time.c                   |   15 +-
 arch/x86/kernel/traps.c                  |    2 +
 arch/x86/mm/tlb.c                        |    2 +
 include/trace/events/irq.h               |  370 ++++++++++++++++++++++++++++++
 kernel/hrtimer.c                         |    6 +
 kernel/irq_work.c                        |    3 +
 kernel/sched.c                           |    3 +
 kernel/smp.c                             |    6 +-
 kernel/time/tick-broadcast.c             |   16 ++-
 kernel/time/tick-common.c                |    8 +-
 kernel/time/tick-sched.c                 |    4 +
 16 files changed, 478 insertions(+), 10 deletions(-)

-- 
1.7.3.1

Re: [PATCH v2 0/6] Add tracepoints to trace all system IRQs

[Peter Zijlstra]

On Wed, 2011-07-27 at 11:57 -0700, Vaibhav Nagarnaik wrote:
> This is a patch series aiming to trace all the system IRQs. The
> tracepoints make it easier to understand IRQ interaction with other
> system events and find out how much time is spent in kernel space versus
> user space.

That doesn't cover the actual rational, you can get that information by
using CONFIG_IRQ_TIME_ACCOUNTING.

> Patches 1-5 add tracepoints to the generic kernel IRQ handlers to
> benefit all the architectures, as suggested by Frederic. Patch#6 adds
> trace events to trace all platform specific interrupt vectors which do
> not have any generic handlers. This patch traces x86 IRQ vectors but can
> be used by other architectures to trace their vectors too.
> 
> Changelog v2-v1:
> * Fix patch#3 to trace IRQ work run vector even when the irq work list
>   is empty
> * Fix patch#5 to use updated trace event names,
>   call_function_ipi_(entry|exit) and
>   call_function_single_ipi_(entry|exit)
> * Rebase to 3.0
> * Update changelog

I still completely hate how you make new events for every interrupt
source. That's a massive pollution of the event space.

Also, since you do arch specific things anyway, why not from a single
tracepoint into the arch interrupt stubs and be done with it, no need to
puke all over the rest of the code.

Re: [PATCH v2 0/6] Add tracepoints to trace all system IRQs

[Frederic Weisbecker]

On Thu, Jul 28, 2011 at 02:12:49PM +0200, Peter Zijlstra wrote:
> On Wed, 2011-07-27 at 11:57 -0700, Vaibhav Nagarnaik wrote:
> > This is a patch series aiming to trace all the system IRQs. The
> > tracepoints make it easier to understand IRQ interaction with other
> > system events and find out how much time is spent in kernel space versus
> > user space.
> 
> That doesn't cover the actual rational, you can get that information by
> using CONFIG_IRQ_TIME_ACCOUNTING.
> 
> > Patches 1-5 add tracepoints to the generic kernel IRQ handlers to
> > benefit all the architectures, as suggested by Frederic. Patch#6 adds
> > trace events to trace all platform specific interrupt vectors which do
> > not have any generic handlers. This patch traces x86 IRQ vectors but can
> > be used by other architectures to trace their vectors too.
> > 
> > Changelog v2-v1:
> > * Fix patch#3 to trace IRQ work run vector even when the irq work list
> >   is empty
> > * Fix patch#5 to use updated trace event names,
> >   call_function_ipi_(entry|exit) and
> >   call_function_single_ipi_(entry|exit)
> > * Rebase to 3.0
> > * Update changelog
> 
> I still completely hate how you make new events for every interrupt
> source. That's a massive pollution of the event space.
> 
> Also, since you do arch specific things anyway, why not from a single
> tracepoint into the arch interrupt stubs and be done with it, no need to
> puke all over the rest of the code.

Because that requires to put the tracepoints in every interrupt sources
for every archs instead of putting one in the generic space.

Re: [PATCH v2 0/6] Add tracepoints to trace all system IRQs

[Peter Zijlstra]

On Thu, 2011-07-28 at 14:31 +0200, Frederic Weisbecker wrote:
> 
> Because that requires to put the tracepoints in every interrupt sources
> for every archs instead of putting one in the generic space. 

Yeah so, he needs to touch arch code anyway.

As it stands this patch-set is an utter trainwreck and isn't going
anywhere.

Re: [PATCH v2 0/6] Add tracepoints to trace all system IRQs

[Frederic Weisbecker]

On Thu, Jul 28, 2011 at 02:53:52PM +0200, Peter Zijlstra wrote:
> On Thu, 2011-07-28 at 14:31 +0200, Frederic Weisbecker wrote:
> > 
> > Because that requires to put the tracepoints in every interrupt sources
> > for every archs instead of putting one in the generic space. 
> 
> Yeah so, he needs to touch arch code anyway.

He needs to touch arch code for pure arch interrupts or some cases
where we don't have the choice. But otherwise there are many
cases where we can put that in the generic code.

> 
> As it stands this patch-set is an utter trainwreck and isn't going
> anywhere.
> 

Re: [PATCH v2 0/6] Add tracepoints to trace all system IRQs

[Peter Zijlstra]

On Thu, 2011-07-28 at 15:09 +0200, Frederic Weisbecker wrote:
> On Thu, Jul 28, 2011 at 02:53:52PM +0200, Peter Zijlstra wrote:
> > On Thu, 2011-07-28 at 14:31 +0200, Frederic Weisbecker wrote:
> > > 
> > > Because that requires to put the tracepoints in every interrupt sources
> > > for every archs instead of putting one in the generic space. 
> > 
> > Yeah so, he needs to touch arch code anyway.
> 
> He needs to touch arch code for pure arch interrupts or some cases
> where we don't have the choice. But otherwise there are many
> cases where we can put that in the generic code.

Which I just pointed out you can't, some 'generic' handlers are in fact
multiplexed on a single arch interrupt. If you want all interrupts, use
pure arch hooks at the lowest level and stop mucking about.

Re: [PATCH v2 0/6] Add tracepoints to trace all system IRQs

[Peter Zijlstra]

On Thu, 2011-07-28 at 14:31 +0200, Frederic Weisbecker wrote:
> 
> Because that requires to put the tracepoints in every interrupt sources
> for every archs instead of putting one in the generic space. 

To sum up from IRC, yes that's exactly what you need to do, because this
patch set assumes two things:

 1) that there is a 1:1 mapping between interrupt sources and generic
handlers, and

 2) that there is a neglectable amount of arch specific code for each
generic handler.

Both are false in generic. Therefore there is no option but to
instrument each and every arch specific interrupt handler.

Also, please use a single tracepoint for all that instead of this horrid
forest of random crap. Use something like arch_interrupt_enter(line_nr),
arch_interrupt_exit(line_nr).

Re: [PATCH v2 0/6] Add tracepoints to trace all system IRQs

[Frederic Weisbecker]

On Thu, Jul 28, 2011 at 04:10:04PM +0200, Peter Zijlstra wrote:
> On Thu, 2011-07-28 at 14:31 +0200, Frederic Weisbecker wrote:
> > 
> > Because that requires to put the tracepoints in every interrupt sources
> > for every archs instead of putting one in the generic space. 
> 
> To sum up from IRC, yes that's exactly what you need to do, because this
> patch set assumes two things:
> 
>  1) that there is a 1:1 mapping between interrupt sources and generic
> handlers, and
> 
>  2) that there is a neglectable amount of arch specific code for each
> generic handler.
> 
> Both are false in generic. Therefore there is no option but to
> instrument each and every arch specific interrupt handler.
> 
> Also, please use a single tracepoint for all that instead of this horrid
> forest of random crap. Use something like arch_interrupt_enter(line_nr),
> arch_interrupt_exit(line_nr).

Right, so I guess the first iteration of the patchset was good in fact.

Re: [PATCH v2 0/6] Add tracepoints to trace all system IRQs

[Vaibhav Nagarnaik]

On Thu, Jul 28, 2011 at 7:08 AM, Frederic Weisbecker <fweisbec@gmail.com> wrote:
> On Thu, Jul 28, 2011 at 04:10:04PM +0200, Peter Zijlstra wrote:
>> On Thu, 2011-07-28 at 14:31 +0200, Frederic Weisbecker wrote:
>> >
>> > Because that requires to put the tracepoints in every interrupt sources
>> > for every archs instead of putting one in the generic space.
>>
>> To sum up from IRC, yes that's exactly what you need to do, because this
>> patch set assumes two things:
>>
>>  1) that there is a 1:1 mapping between interrupt sources and generic
>> handlers, and
>>
>>  2) that there is a neglectable amount of arch specific code for each
>> generic handler.
>>
>> Both are false in generic. Therefore there is no option but to
>> instrument each and every arch specific interrupt handler.
>>
>> Also, please use a single tracepoint for all that instead of this horrid
>> forest of random crap. Use something like arch_interrupt_enter(line_nr),
>> arch_interrupt_exit(line_nr).
>
> Right, so I guess the first iteration of the patchset was good in fact.
>

Frederic and Peter

Thanks for reviewing the patch series. I will post the first iteration
of this patch rebased to the latest HEAD.


Vaibhav Nagarnaik

[PATCH v2 1/6] trace,x86: Add tracepoint to x86 timer interrupt handler

[Vaibhav Nagarnaik]

The x86 timer interrupt handler is the only handler not traced in the
irq/irq_handler_{entry|exit} trace events.

Add tracepoints to the interrupt handler to trace it.

Signed-off-by: Vaibhav Nagarnaik <vnagarnaik@google.com>
---
 arch/x86/kernel/time.c |   15 +++++++++------
 1 files changed, 9 insertions(+), 6 deletions(-)

diff --git a/arch/x86/kernel/time.c b/arch/x86/kernel/time.c
index 5a64d05..74d2280 100644
--- a/arch/x86/kernel/time.c
+++ b/arch/x86/kernel/time.c
@@ -51,6 +51,13 @@ unsigned long profile_pc(struct pt_regs *regs)
 }
 EXPORT_SYMBOL(profile_pc);
 
+static irqreturn_t timer_interrupt(int irq, void *dev_id);
+static struct irqaction irq0  = {
+	.handler = timer_interrupt,
+	.flags = IRQF_DISABLED | IRQF_NOBALANCING | IRQF_IRQPOLL | IRQF_TIMER,
+	.name = "timer"
+};
+
 /*
  * Default timer interrupt handler for PIT/HPET
  */
@@ -59,7 +66,9 @@ static irqreturn_t timer_interrupt(int irq, void *dev_id)
 	/* Keep nmi watchdog up to date */
 	inc_irq_stat(irq0_irqs);
 
+	trace_irq_handler_entry(irq, &irq0);
 	global_clock_event->event_handler(global_clock_event);
+	trace_irq_handler_exit(irq, &irq0, 1);
 
 	/* MCA bus quirk: Acknowledge irq0 by setting bit 7 in port 0x61 */
 	if (MCA_bus)
@@ -68,12 +77,6 @@ static irqreturn_t timer_interrupt(int irq, void *dev_id)
 	return IRQ_HANDLED;
 }
 
-static struct irqaction irq0  = {
-	.handler = timer_interrupt,
-	.flags = IRQF_DISABLED | IRQF_NOBALANCING | IRQF_IRQPOLL | IRQF_TIMER,
-	.name = "timer"
-};
-
 void __init setup_default_timer_irq(void)
 {
 	setup_irq(0, &irq0);
-- 
1.7.3.1

[PATCH v2 2/6] trace: Add tracepoints to timer interrupt handlers

[Vaibhav Nagarnaik]

Add tracepoints to generic kernel timer interrupt handlers to trace the
hardware timer interrupts.

This is a part of overall effort to trace all the interrupts happening
in a system. This shows how the interrupts are interacting with other
events and what time is spent in kernel space versus user space.

Signed-off-by: Vaibhav Nagarnaik <vnagarnaik@google.com>
---
 include/trace/events/irq.h   |  156 ++++++++++++++++++++++++++++++++++++++++++
 kernel/hrtimer.c             |    6 ++
 kernel/time/tick-broadcast.c |   16 ++++-
 kernel/time/tick-common.c    |    8 ++-
 kernel/time/tick-sched.c     |    4 +
 5 files changed, 187 insertions(+), 3 deletions(-)

diff --git a/include/trace/events/irq.h b/include/trace/events/irq.h
index 4b4c7d9..e6e72e0 100644
--- a/include/trace/events/irq.h
+++ b/include/trace/events/irq.h
@@ -139,6 +139,162 @@ DEFINE_EVENT(softirq, softirq_raise,
 	TP_ARGS(vec_nr)
 );
 
+DECLARE_EVENT_CLASS(timer_interrupt,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore),
+
+	TP_STRUCT__entry(
+		__field(	unsigned int,	ignore	)
+	),
+
+	TP_fast_assign(
+		__entry->ignore = ignore;
+	),
+
+	TP_printk("%u", __entry->ignore)
+);
+
+/**
+ * hrtimer_interrupt_entry - called immediately after entering the hrtimer
+ * handler
+ *
+ * When used in combination with the hrtimer_interrupt_exit tracepoint
+ * we can determine the hrtimer handler runtime.
+ */
+DEFINE_EVENT(timer_interrupt, hrtimer_interrupt_entry,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
+/**
+ * hrtimer_interrupt_exit - called just before the hrtimer handler returns
+ *
+ * When used in combination with the hrtimer_interrupt_entry tracepoint
+ * we can determine the hrtimer handler runtime.
+ */
+DEFINE_EVENT(timer_interrupt, hrtimer_interrupt_exit,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
+/**
+ * timer_broadcast_entry - called immediately after entering the broadcast
+ * timer handler
+ *
+ * When used in combination with the timer_broadcast_exit tracepoint
+ * we can determine the broadcast timer handler runtime.
+ */
+DEFINE_EVENT(timer_interrupt, timer_broadcast_entry,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
+/**
+ * timer_broadcast_exit - called just before the broadcast timer handler
+ * returns
+ *
+ * When used in combination with the timer_broadcast_entry tracepoint
+ * we can determine the broadcast timer handler runtime.
+ */
+DEFINE_EVENT(timer_interrupt, timer_broadcast_exit,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
+/**
+ * timer_oneshot_entry - called immediately after entering the oneshot
+ * timer handler
+ *
+ * When used in combination with the timer_oneshot_exit tracepoint
+ * we can determine the oneshot timer handler runtime.
+ */
+DEFINE_EVENT(timer_interrupt, timer_oneshot_entry,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
+/**
+ * timer_oneshot_exit - called just before the oneshot timer handler
+ * returns
+ *
+ * When used in combination with the timer_oneshot_entry tracepoint
+ * we can determine the oneshot timer handler runtime.
+ */
+DEFINE_EVENT(timer_interrupt, timer_oneshot_exit,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
+/**
+ * timer_periodic_entry - called immediately after entering the periodic
+ * timer handler
+ *
+ * When used in combination with the timer_periodic_exit tracepoint
+ * we can determine the periodic timer handler runtime.
+ */
+DEFINE_EVENT(timer_interrupt, timer_periodic_entry,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
+/**
+ * timer_periodic_exit - called just before the periodic timer handler
+ * returns
+ *
+ * When used in combination with the timer_periodic_entry tracepoint
+ * we can determine the periodic timer handler runtime.
+ */
+DEFINE_EVENT(timer_interrupt, timer_periodic_exit,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
+/**
+ * timer_nohz_entry - called immediately after entering the nohz
+ * timer handler
+ *
+ * When used in combination with the timer_nohz_exit tracepoint
+ * we can determine the nohz timer handler runtime.
+ */
+DEFINE_EVENT(timer_interrupt, timer_nohz_entry,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
+/**
+ * timer_nohz_exit - called just before the nohz timer handler
+ * returns
+ *
+ * When used in combination with the timer_nohz_entry tracepoint
+ * we can determine the nohz timer handler runtime.
+ */
+DEFINE_EVENT(timer_interrupt, timer_nohz_exit,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
 #endif /*  _TRACE_IRQ_H */
 
 /* This part must be outside protection */
diff --git a/kernel/hrtimer.c b/kernel/hrtimer.c
index a9205e3..3bf83d5 100644
--- a/kernel/hrtimer.c
+++ b/kernel/hrtimer.c
@@ -48,6 +48,7 @@
 
 #include <asm/uaccess.h>
 
+#include <trace/events/irq.h>
 #include <trace/events/timer.h>
 
 /*
@@ -1244,6 +1245,8 @@ void hrtimer_interrupt(struct clock_event_device *dev)
 	ktime_t expires_next, now, entry_time, delta;
 	int i, retries = 0;
 
+	trace_hrtimer_interrupt_entry(0);
+
 	BUG_ON(!cpu_base->hres_active);
 	cpu_base->nr_events++;
 	dev->next_event.tv64 = KTIME_MAX;
@@ -1316,6 +1319,7 @@ retry:
 	if (expires_next.tv64 == KTIME_MAX ||
 	    !tick_program_event(expires_next, 0)) {
 		cpu_base->hang_detected = 0;
+		trace_hrtimer_interrupt_exit(0);
 		return;
 	}
 
@@ -1355,6 +1359,8 @@ retry:
 	tick_program_event(expires_next, 1);
 	printk_once(KERN_WARNING "hrtimer: interrupt took %llu ns\n",
 		    ktime_to_ns(delta));
+
+	trace_hrtimer_interrupt_exit(0);
 }
 
 /*
diff --git a/kernel/time/tick-broadcast.c b/kernel/time/tick-broadcast.c
index c7218d1..fc3b9d6 100644
--- a/kernel/time/tick-broadcast.c
+++ b/kernel/time/tick-broadcast.c
@@ -20,6 +20,7 @@
 #include <linux/sched.h>
 
 #include "tick-internal.h"
+#include <trace/events/irq.h>
 
 /*
  * Broadcast support for broken x86 hardware, where the local apic
@@ -176,13 +177,17 @@ static void tick_handle_periodic_broadcast(struct clock_event_device *dev)
 {
 	ktime_t next;
 
+	trace_timer_broadcast_entry(0);
+
 	tick_do_periodic_broadcast();
 
 	/*
 	 * The device is in periodic mode. No reprogramming necessary:
 	 */
-	if (dev->mode == CLOCK_EVT_MODE_PERIODIC)
+	if (dev->mode == CLOCK_EVT_MODE_PERIODIC) {
+		trace_timer_broadcast_exit(0);
 		return;
+	}
 
 	/*
 	 * Setup the next period for devices, which do not have
@@ -194,10 +199,13 @@ static void tick_handle_periodic_broadcast(struct clock_event_device *dev)
 	for (next = dev->next_event; ;) {
 		next = ktime_add(next, tick_period);
 
-		if (!clockevents_program_event(dev, next, ktime_get()))
+		if (!clockevents_program_event(dev, next, ktime_get())) {
+			trace_timer_broadcast_exit(0);
 			return;
+		}
 		tick_do_periodic_broadcast();
 	}
+	trace_timer_broadcast_exit(0);
 }
 
 /*
@@ -404,6 +412,8 @@ static void tick_handle_oneshot_broadcast(struct clock_event_device *dev)
 	ktime_t now, next_event;
 	int cpu;
 
+	trace_timer_oneshot_entry(0);
+
 	raw_spin_lock(&tick_broadcast_lock);
 again:
 	dev->next_event.tv64 = KTIME_MAX;
@@ -443,6 +453,8 @@ again:
 			goto again;
 	}
 	raw_spin_unlock(&tick_broadcast_lock);
+
+	trace_timer_oneshot_exit(0);
 }
 
 /*
diff --git a/kernel/time/tick-common.c b/kernel/time/tick-common.c
index 119528d..a7f81af 100644
--- a/kernel/time/tick-common.c
+++ b/kernel/time/tick-common.c
@@ -18,6 +18,7 @@
 #include <linux/percpu.h>
 #include <linux/profile.h>
 #include <linux/sched.h>
+#include <trace/events/irq.h>
 
 #include <asm/irq_regs.h>
 
@@ -84,6 +85,8 @@ void tick_handle_periodic(struct clock_event_device *dev)
 	int cpu = smp_processor_id();
 	ktime_t next;
 
+	trace_timer_periodic_entry(0);
+
 	tick_periodic(cpu);
 
 	if (dev->mode != CLOCK_EVT_MODE_ONESHOT)
@@ -94,8 +97,10 @@ void tick_handle_periodic(struct clock_event_device *dev)
 	 */
 	next = ktime_add(dev->next_event, tick_period);
 	for (;;) {
-		if (!clockevents_program_event(dev, next, ktime_get()))
+		if (!clockevents_program_event(dev, next, ktime_get())) {
+			trace_timer_periodic_exit(0);
 			return;
+		}
 		/*
 		 * Have to be careful here. If we're in oneshot mode,
 		 * before we call tick_periodic() in a loop, we need
@@ -109,6 +114,7 @@ void tick_handle_periodic(struct clock_event_device *dev)
 			tick_periodic(cpu);
 		next = ktime_add(next, tick_period);
 	}
+	trace_timer_periodic_exit(0);
 }
 
 /*
diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
index d5097c4..54e7b07 100644
--- a/kernel/time/tick-sched.c
+++ b/kernel/time/tick-sched.c
@@ -20,6 +20,7 @@
 #include <linux/profile.h>
 #include <linux/sched.h>
 #include <linux/module.h>
+#include <trace/events/irq.h>
 
 #include <asm/irq_regs.h>
 
@@ -568,6 +569,8 @@ static void tick_nohz_handler(struct clock_event_device *dev)
 	int cpu = smp_processor_id();
 	ktime_t now = ktime_get();
 
+	trace_timer_nohz_entry(0);
+
 	dev->next_event.tv64 = KTIME_MAX;
 
 	/*
@@ -604,6 +607,7 @@ static void tick_nohz_handler(struct clock_event_device *dev)
 		now = ktime_get();
 		tick_do_update_jiffies64(now);
 	}
+	trace_timer_nohz_exit(0);
 }
 
 /**
-- 
1.7.3.1

[PATCH v2 3/6] trace: Add tracepoints to IRQ work run handler

[Vaibhav Nagarnaik]

This is a part of overall effort to trace all the interrupts happening
in a system. This shows how the interrupts are interacting with other
events and what time is spent in kernel space versus user space.

Signed-off-by: Vaibhav Nagarnaik <vnagarnaik@google.com>
---
 include/trace/events/irq.h |   44 ++++++++++++++++++++++++++++++++++++++++++++
 kernel/irq_work.c          |    3 +++
 2 files changed, 47 insertions(+), 0 deletions(-)

diff --git a/include/trace/events/irq.h b/include/trace/events/irq.h
index e6e72e0..d8fab89 100644
--- a/include/trace/events/irq.h
+++ b/include/trace/events/irq.h
@@ -295,6 +295,50 @@ DEFINE_EVENT(timer_interrupt, timer_nohz_exit,
 	TP_ARGS(ignore)
 );
 
+DECLARE_EVENT_CLASS(irq_work,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore),
+
+	TP_STRUCT__entry(
+		__field(	unsigned int,	ignore	)
+	),
+
+	TP_fast_assign(
+		__entry->ignore = ignore;
+	),
+
+	TP_printk("%u", __entry->ignore)
+);
+
+/**
+ * irq_work_run_entry - called immediately after entering the irq work
+ * handler
+ *
+ * When used in combination with the irq_work_run_exit tracepoint
+ * we can determine the irq work handler runtime.
+ */
+DEFINE_EVENT(irq_work, irq_work_run_entry,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
+/**
+ * irq_work_run_exit - called just before the irq work handler returns
+ *
+ * When used in combination with the irq_work_run_entry tracepoint
+ * we can determine the irq work handler runtime.
+ */
+DEFINE_EVENT(irq_work, irq_work_run_exit,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
 #endif /*  _TRACE_IRQ_H */
 
 /* This part must be outside protection */
diff --git a/kernel/irq_work.c b/kernel/irq_work.c
index c58fa7d..39473b2 100644
--- a/kernel/irq_work.c
+++ b/kernel/irq_work.c
@@ -9,6 +9,7 @@
 #include <linux/module.h>
 #include <linux/irq_work.h>
 #include <linux/hardirq.h>
+#include <trace/events/irq.h>
 
 /*
  * An entry can be in one of four states:
@@ -122,6 +123,7 @@ void irq_work_run(void)
 {
 	struct irq_work *list;
 
+	trace_irq_work_run_entry(0);
 	if (this_cpu_read(irq_work_list) == NULL)
 		return;
 
@@ -149,6 +151,7 @@ void irq_work_run(void)
 			      next_flags(NULL, IRQ_WORK_BUSY),
 			      NULL);
 	}
+	trace_irq_work_run_exit(0);
 }
 EXPORT_SYMBOL_GPL(irq_work_run);
 
-- 
1.7.3.1

Re: [PATCH v2 3/6] trace: Add tracepoints to IRQ work run handler

[Peter Zijlstra]

On Wed, 2011-07-27 at 11:57 -0700, Vaibhav Nagarnaik wrote:
> @@ -122,6 +123,7 @@ void irq_work_run(void)
>  {
>         struct irq_work *list;
>  
> +       trace_irq_work_run_entry(0);
>         if (this_cpu_read(irq_work_list) == NULL)
>                 return;
>  
> @@ -149,6 +151,7 @@ void irq_work_run(void)
>                               next_flags(NULL, IRQ_WORK_BUSY),
>                               NULL);
>         }
> +       trace_irq_work_run_exit(0);
>  }
>  EXPORT_SYMBOL_GPL(irq_work_run); 

So what happens when we call irq_work_run() from the timer interrupt?

Re: [PATCH v2 3/6] trace: Add tracepoints to IRQ work run handler

[Frederic Weisbecker]

On Thu, Jul 28, 2011 at 02:12:51PM +0200, Peter Zijlstra wrote:
> On Wed, 2011-07-27 at 11:57 -0700, Vaibhav Nagarnaik wrote:
> > @@ -122,6 +123,7 @@ void irq_work_run(void)
> >  {
> >         struct irq_work *list;
> >  
> >        trace_irq_work_run_entry(0);
> >         if (this_cpu_read(irq_work_list) == NULL)
> >                 return;
> >  
> > @@ -149,6 +151,7 @@ void irq_work_run(void)
> >                               next_flags(NULL, IRQ_WORK_BUSY),
> >                               NULL);
> >         }
> > +       trace_irq_work_run_exit(0);
> >  }
> >  EXPORT_SYMBOL_GPL(irq_work_run); 
> 
> So what happens when we call irq_work_run() from the timer interrupt?
> 

We probably need something like:

void irq_work_run_interrupt(void)
{
	trace_irq_work_run_entry(0);
	irq_work_run();
	trace_irq_work_run_exit(0);
}

Re: [PATCH v2 3/6] trace: Add tracepoints to IRQ work run handler

[Peter Zijlstra]

On Thu, 2011-07-28 at 15:29 +0200, Frederic Weisbecker wrote:
> On Thu, Jul 28, 2011 at 02:12:51PM +0200, Peter Zijlstra wrote:
> > On Wed, 2011-07-27 at 11:57 -0700, Vaibhav Nagarnaik wrote:
> > > @@ -122,6 +123,7 @@ void irq_work_run(void)
> > >  {
> > >         struct irq_work *list;
> > >  
> > >        trace_irq_work_run_entry(0);
> > >         if (this_cpu_read(irq_work_list) == NULL)
> > >                 return;
> > >  
> > > @@ -149,6 +151,7 @@ void irq_work_run(void)
> > >                               next_flags(NULL, IRQ_WORK_BUSY),
> > >                               NULL);
> > >         }
> > > +       trace_irq_work_run_exit(0);
> > >  }
> > >  EXPORT_SYMBOL_GPL(irq_work_run); 
> > 
> > So what happens when we call irq_work_run() from the timer interrupt?
> > 
> 
> We probably need something like:
> 
> void irq_work_run_interrupt(void)
> {
> 	trace_irq_work_run_entry(0);
> 	irq_work_run();
> 	trace_irq_work_run_exit(0);
> }

No we don't. That lives in arch code and its up to the arch to decide
where, when and how to call that.

On PPC for example that's hooked of the timer interrupt.

See here again your 'generalization' crap breaks down.

Re: [PATCH v2 3/6] trace: Add tracepoints to IRQ work run handler

[Frederic Weisbecker]

On Thu, Jul 28, 2011 at 03:49:21PM +0200, Peter Zijlstra wrote:
> On Thu, 2011-07-28 at 15:29 +0200, Frederic Weisbecker wrote:
> > On Thu, Jul 28, 2011 at 02:12:51PM +0200, Peter Zijlstra wrote:
> > > On Wed, 2011-07-27 at 11:57 -0700, Vaibhav Nagarnaik wrote:
> > > > @@ -122,6 +123,7 @@ void irq_work_run(void)
> > > >  {
> > > >         struct irq_work *list;
> > > >  
> > > >        trace_irq_work_run_entry(0);
> > > >         if (this_cpu_read(irq_work_list) == NULL)
> > > >                 return;
> > > >  
> > > > @@ -149,6 +151,7 @@ void irq_work_run(void)
> > > >                               next_flags(NULL, IRQ_WORK_BUSY),
> > > >                               NULL);
> > > >         }
> > > > +       trace_irq_work_run_exit(0);
> > > >  }
> > > >  EXPORT_SYMBOL_GPL(irq_work_run); 
> > > 
> > > So what happens when we call irq_work_run() from the timer interrupt?
> > > 
> > 
> > We probably need something like:
> > 
> > void irq_work_run_interrupt(void)
> > {
> > 	trace_irq_work_run_entry(0);
> > 	irq_work_run();
> > 	trace_irq_work_run_exit(0);
> > }
> 
> No we don't. That lives in arch code and its up to the arch to decide
> where, when and how to call that.
> 
> On PPC for example that's hooked of the timer interrupt.
> 
> See here again your 'generalization' crap breaks down.

Yeah, you're right.

I don't know very well other archs than x86 and probably did the
mistake to generalize too much on top of its irq layout.

Probably they should revert to something closer to the first iterations of that patchset.

Now I'm going to let Vaibhav and David choose whichever weapon they want to stab me if
we meet up one day. Just not going to stay in a floor next to them with nobody
around.

[PATCH v2 4/6] trace: Add tracepoints to reschedule interrupt handler

[Vaibhav Nagarnaik]

This is a part of overall effort to trace all the interrupts happening
in a system. This shows how the interrupts are interacting with other
events and what time is spent in kernel space versus user space.

Signed-off-by: Vaibhav Nagarnaik <vnagarnaik@google.com>
---
 include/trace/events/irq.h |   45 ++++++++++++++++++++++++++++++++++++++++++++
 kernel/sched.c             |    3 ++
 2 files changed, 48 insertions(+), 0 deletions(-)

diff --git a/include/trace/events/irq.h b/include/trace/events/irq.h
index d8fab89..a2a0a49 100644
--- a/include/trace/events/irq.h
+++ b/include/trace/events/irq.h
@@ -339,6 +339,51 @@ DEFINE_EVENT(irq_work, irq_work_run_exit,
 	TP_ARGS(ignore)
 );
 
+DECLARE_EVENT_CLASS(reschedule_interrupt,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore),
+
+	TP_STRUCT__entry(
+		__field(	unsigned int,	ignore	)
+	),
+
+	TP_fast_assign(
+		__entry->ignore = ignore;
+	),
+
+	TP_printk("%u", __entry->ignore)
+);
+
+/**
+ * reschedule_interrupt_entry - called immediately after entering the
+ * reschedule interrupt handler
+ *
+ * When used in combination with the reschedule_interrupt_exit tracepoint
+ * we can determine the reschedule interrupt handler runtime.
+ */
+DEFINE_EVENT(reschedule_interrupt, reschedule_interrupt_entry,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
+/**
+ * reschedule_interrupt_exit - called just before the reschedule interrupt
+ * handler returns
+ *
+ * When used in combination with the reschedule_interrupt_entry tracepoint
+ * we can determine the reschedule interrupt handler runtime.
+ */
+DEFINE_EVENT(reschedule_interrupt, reschedule_interrupt_exit,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
 #endif /*  _TRACE_IRQ_H */
 
 /* This part must be outside protection */
diff --git a/kernel/sched.c b/kernel/sched.c
index ccacdbd..f48b5aa 100644
--- a/kernel/sched.c
+++ b/kernel/sched.c
@@ -82,6 +82,7 @@
 #include "sched_cpupri.h"
 #include "workqueue_sched.h"
 #include "sched_autogroup.h"
+#include <trace/events/irq.h>
 
 #define CREATE_TRACE_POINTS
 #include <trace/events/sched.h>
@@ -2578,6 +2579,7 @@ static void sched_ttwu_pending(void)
 	struct rq *rq = this_rq();
 	struct task_struct *list = xchg(&rq->wake_list, NULL);
 
+	trace_reschedule_interrupt_entry(0);
 	if (!list)
 		return;
 
@@ -2610,6 +2612,7 @@ void scheduler_ipi(void)
 	irq_enter();
 	sched_ttwu_do_pending(list);
 	irq_exit();
+	trace_reschedule_interrupt_exit(0);
 }
 
 static void ttwu_queue_remote(struct task_struct *p, int cpu)
-- 
1.7.3.1

Re: [PATCH v2 4/6] trace: Add tracepoints to reschedule interrupt handler

[Peter Zijlstra]

On Wed, 2011-07-27 at 11:57 -0700, Vaibhav Nagarnaik wrote:
> @@ -2578,6 +2579,7 @@ static void sched_ttwu_pending(void)
>         struct rq *rq = this_rq();
>         struct task_struct *list = xchg(&rq->wake_list, NULL);
>  
> +       trace_reschedule_interrupt_entry(0);
>         if (!list)
>                 return;
>  
> @@ -2610,6 +2612,7 @@ void scheduler_ipi(void)
>         irq_enter();
>         sched_ttwu_do_pending(list);
>         irq_exit();
> +       trace_reschedule_interrupt_exit(0);
>  } 

That's just wrong..

[PATCH v2 5/6] trace: Add tracepoints to call function interrupt handlers

[Vaibhav Nagarnaik]

Add tracepoints to call function and call function single interrupt
handlers.

This is a part of overall effort to trace all the interrupts happening
in a system. This shows how the interrupts are interacting with other
events and what time is spent in kernel space versus user space.

Signed-off-by: Vaibhav Nagarnaik <vnagarnaik@google.com>
---
 include/trace/events/irq.h |   73 ++++++++++++++++++++++++++++++++++++++++++++
 kernel/smp.c               |    6 +++-
 2 files changed, 78 insertions(+), 1 deletions(-)

diff --git a/include/trace/events/irq.h b/include/trace/events/irq.h
index a2a0a49..5e4f731 100644
--- a/include/trace/events/irq.h
+++ b/include/trace/events/irq.h
@@ -384,6 +384,79 @@ DEFINE_EVENT(reschedule_interrupt, reschedule_interrupt_exit,
 	TP_ARGS(ignore)
 );
 
+DECLARE_EVENT_CLASS(call_function_ipi,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore),
+
+	TP_STRUCT__entry(
+		__field(	unsigned int,	ignore	)
+	),
+
+	TP_fast_assign(
+		__entry->ignore = ignore;
+	),
+
+	TP_printk("%u", __entry->ignore)
+);
+
+/**
+ * call_function_ipi_entry - called immediately after entering the
+ * call function interrupt handler
+ *
+ * When used in combination with the call_function_ipi_exit tracepoint
+ * we can determine the call function interrupt handler runtime.
+ */
+DEFINE_EVENT(call_function_ipi, call_function_ipi_entry,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
+/**
+ * call_function_ipi_exit - called just before the call function interrupt
+ * handler returns
+ *
+ * When used in combination with the call_function_ipi_entry tracepoint
+ * we can determine the call function interrupt handler runtime.
+ */
+DEFINE_EVENT(call_function_ipi, call_function_ipi_exit,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
+/**
+ * call_function_single_ipi_entry - called immediately after entering the
+ * call function single interrupt handler
+ *
+ * When used in combination with the call_function_single_ipi_exit tracepoint
+ * we can determine the call function single interrupt handler runtime.
+ */
+DEFINE_EVENT(call_function_ipi, call_function_single_ipi_entry,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
+/**
+ * call_function_single_ipi_exit - called just before the call function single
+ * interrupt handler returns
+ *
+ * When used in combination with the call_function_single_ipi_entry tracepoint
+ * we can determine the call function single interrupt handler runtime.
+ */
+DEFINE_EVENT(call_function_ipi, call_function_single_ipi_exit,
+
+	TP_PROTO(unsigned int ignore),
+
+	TP_ARGS(ignore)
+);
+
 #endif /*  _TRACE_IRQ_H */
 
 /* This part must be outside protection */
diff --git a/kernel/smp.c b/kernel/smp.c
index fb67dfa..4ea6769 100644
--- a/kernel/smp.c
+++ b/kernel/smp.c
@@ -12,6 +12,7 @@
 #include <linux/gfp.h>
 #include <linux/smp.h>
 #include <linux/cpu.h>
+#include <trace/events/irq.h>
 
 #ifdef CONFIG_USE_GENERIC_SMP_HELPERS
 static struct {
@@ -172,6 +173,7 @@ void generic_smp_call_function_interrupt(void)
 	struct call_function_data *data;
 	int cpu = smp_processor_id();
 
+	trace_call_function_ipi_entry(0);
 	/*
 	 * Shouldn't receive this interrupt on a cpu that is not yet online.
 	 */
@@ -239,7 +241,7 @@ void generic_smp_call_function_interrupt(void)
 
 		csd_unlock(&data->csd);
 	}
-
+	trace_call_function_ipi_exit(0);
 }
 
 /*
@@ -252,6 +254,7 @@ void generic_smp_call_function_single_interrupt(void)
 	unsigned int data_flags;
 	LIST_HEAD(list);
 
+	trace_call_function_single_ipi_entry(0);
 	/*
 	 * Shouldn't receive this interrupt on a cpu that is not yet online.
 	 */
@@ -282,6 +285,7 @@ void generic_smp_call_function_single_interrupt(void)
 		if (data_flags & CSD_FLAG_LOCK)
 			csd_unlock(data);
 	}
+	trace_call_function_single_ipi_exit(0);
 }
 
 static DEFINE_PER_CPU_SHARED_ALIGNED(struct call_single_data, csd_data);
-- 
1.7.3.1

Re: [PATCH v2 5/6] trace: Add tracepoints to call function interrupt handlers

[Peter Zijlstra]

On Wed, 2011-07-27 at 11:57 -0700, Vaibhav Nagarnaik wrote:
> @@ -172,6 +173,7 @@ void generic_smp_call_function_interrupt(void)
>         struct call_function_data *data;
>         int cpu = smp_processor_id();
>  
> +       trace_call_function_ipi_entry(0);
>         /*
>          * Shouldn't receive this interrupt on a cpu that is not yet online.
>          */
> @@ -239,7 +241,7 @@ void generic_smp_call_function_interrupt(void)
>  
>                 csd_unlock(&data->csd);
>         }
> -
> +       trace_call_function_ipi_exit(0);
>  }
>  
>  /*
> @@ -252,6 +254,7 @@ void generic_smp_call_function_single_interrupt(void)
>         unsigned int data_flags;
>         LIST_HEAD(list);
>  
> +       trace_call_function_single_ipi_entry(0);
>         /*
>          * Shouldn't receive this interrupt on a cpu that is not yet online.
>          */
> @@ -282,6 +285,7 @@ void generic_smp_call_function_single_interrupt(void)
>                 if (data_flags & CSD_FLAG_LOCK)
>                         csd_unlock(data);
>         }
> +       trace_call_function_single_ipi_exit(0);
>  } 

The problem with this is that some archs only have a single IPI and
multiplex all IPIs on top, in that case you're either nesting interrupt
tracepoints or missing a part.

I really think you're doing this at the wrong level.

[PATCH v2 6/6] trace,x86: Add platform_irq_vector_{entry|exit} trace events

[Vaibhav Nagarnaik]

Add tracepoints to trace platform specific IRQ vectors which do not have
equivalent generic kernel handlers. Along with the IRQ number traced,
there is a symbolic mapping to the equivalent name of the IRQ.

This patch only traces the x86 and x86_64 platform vectors but other
architectures can add the tracepoints in their equivalent files to make
use of this trace event.

This is a part of overall effort to trace all the interrupts happening
in a system. This shows how the interrupts are interacting with other
events and what time is spent in kernel space versus user space.

Signed-off-by: Vaibhav Nagarnaik <vnagarnaik@google.com>
---
 arch/x86/include/asm/irq_vectors.h       |   43 ++++++++++++++++++++++++
 arch/x86/kernel/apic/apic.c              |    4 ++
 arch/x86/kernel/cpu/mcheck/therm_throt.c |    2 +
 arch/x86/kernel/cpu/mcheck/threshold.c   |    2 +
 arch/x86/kernel/irq.c                    |    2 +
 arch/x86/kernel/traps.c                  |    2 +
 arch/x86/mm/tlb.c                        |    2 +
 include/trace/events/irq.h               |   52 ++++++++++++++++++++++++++++++
 8 files changed, 109 insertions(+), 0 deletions(-)

diff --git a/arch/x86/include/asm/irq_vectors.h b/arch/x86/include/asm/irq_vectors.h
index f9a3209..ee99ce1 100644
--- a/arch/x86/include/asm/irq_vectors.h
+++ b/arch/x86/include/asm/irq_vectors.h
@@ -181,4 +181,47 @@ static inline int invalid_vm86_irq(int irq)
 # define NR_IRQS			NR_IRQS_LEGACY
 #endif
 
+#define platform_irq_vector_mapping(x) { (x), #x }
+#define invalidate_tlb_vector_mapping(x) \
+		{ (INVALIDATE_TLB_VECTOR_START+x), "INVALIDATE_TLB_VECTOR" }
+#define platform_irq_vector_name					\
+		platform_irq_vector_mapping(SPURIOUS_APIC_VECTOR),	\
+		platform_irq_vector_mapping(ERROR_APIC_VECTOR),		\
+		platform_irq_vector_mapping(THERMAL_APIC_VECTOR),	\
+		platform_irq_vector_mapping(THRESHOLD_APIC_VECTOR),	\
+		platform_irq_vector_mapping(X86_PLATFORM_IPI_VECTOR),	\
+		platform_irq_vector_mapping(NMI_VECTOR),		\
+		invalidate_tlb_vector_mapping(0),			\
+		invalidate_tlb_vector_mapping(1),			\
+		invalidate_tlb_vector_mapping(2),			\
+		invalidate_tlb_vector_mapping(3),			\
+		invalidate_tlb_vector_mapping(4),			\
+		invalidate_tlb_vector_mapping(5),			\
+		invalidate_tlb_vector_mapping(6),			\
+		invalidate_tlb_vector_mapping(7),			\
+		invalidate_tlb_vector_mapping(8),			\
+		invalidate_tlb_vector_mapping(9),			\
+		invalidate_tlb_vector_mapping(10),			\
+		invalidate_tlb_vector_mapping(11),			\
+		invalidate_tlb_vector_mapping(12),			\
+		invalidate_tlb_vector_mapping(13),			\
+		invalidate_tlb_vector_mapping(14),			\
+		invalidate_tlb_vector_mapping(15),			\
+		invalidate_tlb_vector_mapping(16),			\
+		invalidate_tlb_vector_mapping(17),			\
+		invalidate_tlb_vector_mapping(18),			\
+		invalidate_tlb_vector_mapping(19),			\
+		invalidate_tlb_vector_mapping(20),			\
+		invalidate_tlb_vector_mapping(21),			\
+		invalidate_tlb_vector_mapping(22),			\
+		invalidate_tlb_vector_mapping(23),			\
+		invalidate_tlb_vector_mapping(24),			\
+		invalidate_tlb_vector_mapping(25),			\
+		invalidate_tlb_vector_mapping(26),			\
+		invalidate_tlb_vector_mapping(27),			\
+		invalidate_tlb_vector_mapping(28),			\
+		invalidate_tlb_vector_mapping(29),			\
+		invalidate_tlb_vector_mapping(30),			\
+		invalidate_tlb_vector_mapping(31)
+
 #endif /* _ASM_X86_IRQ_VECTORS_H */
diff --git a/arch/x86/kernel/apic/apic.c b/arch/x86/kernel/apic/apic.c
index b24be38..1e3db2d 100644
--- a/arch/x86/kernel/apic/apic.c
+++ b/arch/x86/kernel/apic/apic.c
@@ -1793,6 +1793,7 @@ void smp_spurious_interrupt(struct pt_regs *regs)
 
 	exit_idle();
 	irq_enter();
+	trace_platform_irq_vector_entry(SPURIOUS_APIC_VECTOR);
 	/*
 	 * Check if this really is a spurious interrupt and ACK it
 	 * if it is a vectored one.  Just in case...
@@ -1807,6 +1808,7 @@ void smp_spurious_interrupt(struct pt_regs *regs)
 	/* see sw-dev-man vol 3, chapter 7.4.13.5 */
 	pr_info("spurious APIC interrupt on CPU#%d, "
 		"should never happen.\n", smp_processor_id());
+	trace_platform_irq_vector_exit(SPURIOUS_APIC_VECTOR);
 	irq_exit();
 }
 
@@ -1830,6 +1832,7 @@ void smp_error_interrupt(struct pt_regs *regs)
 
 	exit_idle();
 	irq_enter();
+	trace_platform_irq_vector_entry(ERROR_APIC_VECTOR);
 	/* First tickle the hardware, only then report what went on. -- REW */
 	v0 = apic_read(APIC_ESR);
 	apic_write(APIC_ESR, 0);
@@ -1850,6 +1853,7 @@ void smp_error_interrupt(struct pt_regs *regs)
 
 	apic_printk(APIC_DEBUG, KERN_CONT "\n");
 
+	trace_platform_irq_vector_exit(ERROR_APIC_VECTOR);
 	irq_exit();
 }
 
diff --git a/arch/x86/kernel/cpu/mcheck/therm_throt.c b/arch/x86/kernel/cpu/mcheck/therm_throt.c
index 27c6251..4528f26 100644
--- a/arch/x86/kernel/cpu/mcheck/therm_throt.c
+++ b/arch/x86/kernel/cpu/mcheck/therm_throt.c
@@ -398,8 +398,10 @@ asmlinkage void smp_thermal_interrupt(struct pt_regs *regs)
 {
 	exit_idle();
 	irq_enter();
+	trace_platform_irq_vector_entry(THERMAL_APIC_VECTOR);
 	inc_irq_stat(irq_thermal_count);
 	smp_thermal_vector();
+	trace_platform_irq_vector_exit(THERMAL_APIC_VECTOR);
 	irq_exit();
 	/* Ack only at the end to avoid potential reentry */
 	ack_APIC_irq();
diff --git a/arch/x86/kernel/cpu/mcheck/threshold.c b/arch/x86/kernel/cpu/mcheck/threshold.c
index d746df2..0876815 100644
--- a/arch/x86/kernel/cpu/mcheck/threshold.c
+++ b/arch/x86/kernel/cpu/mcheck/threshold.c
@@ -21,8 +21,10 @@ asmlinkage void smp_threshold_interrupt(void)
 {
 	exit_idle();
 	irq_enter();
+	trace_platform_irq_vector_entry(THRESHOLD_APIC_VECTOR);
 	inc_irq_stat(irq_threshold_count);
 	mce_threshold_vector();
+	trace_platform_irq_vector_exit(THRESHOLD_APIC_VECTOR);
 	irq_exit();
 	/* Ack only at the end to avoid potential reentry */
 	ack_APIC_irq();
diff --git a/arch/x86/kernel/irq.c b/arch/x86/kernel/irq.c
index 6c0802e..0c730f4 100644
--- a/arch/x86/kernel/irq.c
+++ b/arch/x86/kernel/irq.c
@@ -211,12 +211,14 @@ void smp_x86_platform_ipi(struct pt_regs *regs)
 	exit_idle();
 
 	irq_enter();
+	trace_platform_irq_vector_entry(X86_PLATFORM_IPI_VECTOR);
 
 	inc_irq_stat(x86_platform_ipis);
 
 	if (x86_platform_ipi_callback)
 		x86_platform_ipi_callback();
 
+	trace_platform_irq_vector_exit(X86_PLATFORM_IPI_VECTOR);
 	irq_exit();
 
 	set_irq_regs(old_regs);
diff --git a/arch/x86/kernel/traps.c b/arch/x86/kernel/traps.c
index 545eb3d..9f65f12 100644
--- a/arch/x86/kernel/traps.c
+++ b/arch/x86/kernel/traps.c
@@ -447,12 +447,14 @@ dotraplinkage notrace __kprobes void
 do_nmi(struct pt_regs *regs, long error_code)
 {
 	nmi_enter();
+	trace_platform_irq_vector_entry(NMI_VECTOR);
 
 	inc_irq_stat(__nmi_count);
 
 	if (!ignore_nmis)
 		default_do_nmi(regs);
 
+	trace_platform_irq_vector_exit(NMI_VECTOR);
 	nmi_exit();
 }
 
diff --git a/arch/x86/mm/tlb.c b/arch/x86/mm/tlb.c
index d6c0418..5c9e766 100644
--- a/arch/x86/mm/tlb.c
+++ b/arch/x86/mm/tlb.c
@@ -141,6 +141,7 @@ void smp_invalidate_interrupt(struct pt_regs *regs)
 	sender = ~regs->orig_ax - INVALIDATE_TLB_VECTOR_START;
 	f = &flush_state[sender];
 
+	trace_platform_irq_vector_entry(sender + INVALIDATE_TLB_VECTOR_START);
 	if (!cpumask_test_cpu(cpu, to_cpumask(f->flush_cpumask)))
 		goto out;
 		/*
@@ -167,6 +168,7 @@ out:
 	cpumask_clear_cpu(cpu, to_cpumask(f->flush_cpumask));
 	smp_mb__after_clear_bit();
 	inc_irq_stat(irq_tlb_count);
+	trace_platform_irq_vector_exit(sender + INVALIDATE_TLB_VECTOR_START);
 }
 
 static void flush_tlb_others_ipi(const struct cpumask *cpumask,
diff --git a/include/trace/events/irq.h b/include/trace/events/irq.h
index 5e4f731..7d2b057 100644
--- a/include/trace/events/irq.h
+++ b/include/trace/events/irq.h
@@ -457,6 +457,58 @@ DEFINE_EVENT(call_function_ipi, call_function_single_ipi_exit,
 	TP_ARGS(ignore)
 );
 
+#include <asm/irq.h>
+
+#if !defined(platform_irq_vector_name)
+#define platform_irq_vector_name { NULL, NULL }
+#endif
+
+DECLARE_EVENT_CLASS(platform_irq_vector,
+
+	TP_PROTO(unsigned int vec_num),
+
+	TP_ARGS(vec_num),
+
+	TP_STRUCT__entry(
+		__field(	unsigned int,	vec_num	)
+	),
+
+	TP_fast_assign(
+		__entry->vec_num = vec_num;
+	),
+
+	TP_printk("%u: %s", __entry->vec_num,
+		__print_symbolic(__entry->vec_num, platform_irq_vector_name))
+);
+
+/**
+ * platform_irq_vector_entry - called immediately after entering the
+ * platform vector interrupt handler
+ *
+ * When used in combination with the platform_irq_vector_exit tracepoint
+ * we can determine the platform interrupt vector handler runtime.
+ */
+DEFINE_EVENT(platform_irq_vector, platform_irq_vector_entry,
+
+	TP_PROTO(unsigned int vec_num),
+
+	TP_ARGS(vec_num)
+);
+
+/**
+ * platform_irq_vector_exit - called just before the platform vector
+ * interrupt handler returns
+ *
+ * When used in combination with the platform_irq_vector_entry tracepoint
+ * we can determine the platform interrupt vector handler runtime.
+ */
+DEFINE_EVENT(platform_irq_vector, platform_irq_vector_exit,
+
+	TP_PROTO(unsigned int vec_num),
+
+	TP_ARGS(vec_num)
+);
+
 #endif /*  _TRACE_IRQ_H */
 
 /* This part must be outside protection */
-- 
1.7.3.1