[RFC 2/4] ftrace: Add events for tracing tick start and stop

[Jan Blunck <jblunck@suse.de>]

Trace the starting and stopping of the scheduler tick. The traces look like
this:

<idle>-0     [000] 187573.495750: sched_tick_stop: idle=1, expires=6876704000000
<idle>-0     [000] 187573.629998: sched_tick_stop: idle=0, expires=6876704000000
<idle>-0     [000] 187573.764273: sched_tick_stop: idle=0, expires=6876704000000
<idle>-0     [000] 187573.898508: sched_tick_stop: idle=0, expires=6876704000000
<idle>-0     [000] 187574.009284: sched_tick_start: now=6876232761127

In this trace you can see how tick_nohz_stop_sched_tick() is called from
the idle thread (idle=1) and later through irq_exit() (idle=0).

Signed-off-by: Jan Blunck <jblunck@suse.de>
---
 include/trace/events/sched.h |   40 ++++++++++++++++++++++++++++++++++++++++
 kernel/time/tick-sched.c     |   21 ++++++++++++++++-----
 2 files changed, 56 insertions(+), 5 deletions(-)

diff --git a/include/trace/events/sched.h b/include/trace/events/sched.h
index b9e1dd6..36385b6 100644
--- a/include/trace/events/sched.h
+++ b/include/trace/events/sched.h
@@ -380,6 +380,46 @@ TRACE_EVENT(sched_stat_runtime,
 			(unsigned long long)__entry->vruntime)
 );
 
+TRACE_EVENT(sched_tick_start,
+
+	TP_PROTO(ktime_t *now),
+
+	TP_ARGS(now),
+
+	TP_STRUCT__entry(
+		__field(s64, tv64)
+		),
+
+	TP_fast_assign(
+		__entry->tv64 = now->tv64;
+		),
+	TP_printk("now=%ld",
+		(long)__entry->tv64)
+
+);
+
+TRACE_EVENT(sched_tick_stop,
+
+	TP_PROTO(ktime_t *expires, int idle),
+
+	TP_ARGS(expires, idle),
+
+	TP_STRUCT__entry(
+		__field(s64, tv64)
+		__field(int, idle)
+		),
+
+	TP_fast_assign(
+		__entry->tv64 = expires->tv64;
+		__entry->idle = idle;
+		),
+	TP_printk("idle=%d, expires=%ld%s",
+		__entry->idle,
+		(long)__entry->tv64,
+		(__entry->tv64 == KTIME_MAX) ? " (KTIME_MAX)" : "" )
+
+);
+
 #endif /* _TRACE_SCHED_H */
 
 /* This part must be outside protection */
diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
index 813993b..81b7398 100644
--- a/kernel/time/tick-sched.c
+++ b/kernel/time/tick-sched.c
@@ -22,6 +22,8 @@
 #include <linux/tick.h>
 #include <linux/module.h>
 
+#include <trace/events/sched.h>
+
 #include <asm/irq_regs.h>
 
 #include "tick-internal.h"
@@ -428,9 +430,11 @@ void tick_nohz_stop_sched_tick(int inidle)
 		 * If the expiration time == KTIME_MAX, then
 		 * in this case we simply stop the tick timer.
 		 */
-		 if (unlikely(expires.tv64 == KTIME_MAX)) {
-			if (ts->nohz_mode == NOHZ_MODE_HIGHRES)
+		if (unlikely(expires.tv64 == KTIME_MAX)) {
+			if (ts->nohz_mode == NOHZ_MODE_HIGHRES) {
+				trace_sched_tick_stop(&expires, inidle);
 				hrtimer_cancel(&ts->sched_timer);
+			}
 			goto out;
 		}
 
@@ -438,10 +442,15 @@ void tick_nohz_stop_sched_tick(int inidle)
 			hrtimer_start(&ts->sched_timer, expires,
 				      HRTIMER_MODE_ABS_PINNED);
 			/* Check, if the timer was already in the past */
-			if (hrtimer_active(&ts->sched_timer))
-				goto out;
-		} else if (!tick_program_event(expires, 0))
+			if (hrtimer_active(&ts->sched_timer)) {
+				trace_sched_tick_stop(&expires, inidle);
 				goto out;
+			}
+		} else if (!tick_program_event(expires, 0)) {
+			trace_sched_tick_stop(&expires, inidle);
+			goto out;
+		}
+
 		/*
 		 * We are past the event already. So we crossed a
 		 * jiffie boundary. Update jiffies and raise the
@@ -495,6 +504,8 @@ static void tick_nohz_restart(struct tick_sched *ts, ktime_t now)
 		tick_do_update_jiffies64(now);
 		now = ktime_get();
 	}
+
+	trace_sched_tick_start(&now);
 }
 
 /**
-- 
1.6.4.2