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

[Vaibhav Nagarnaik <vnagarnaik@google.com>]

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