lkml.org 
[lkml]   [2011]   [Jul]   [14]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
Patch in this message
/
From
Subject[PATCH 2/6] trace: Add tracepoints to timer interrupt handlers
Date
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


\
 
 \ /
  Last update: 2011-07-14 23:41    [from the cache]
©2003-2011 Jasper Spaans