hrtimer: Add tracepoint for hrtimers

Add tracepoints which cover the life cycle of a hrtimer. The
tracepoints are integrated with the already existing debug_object
debug points as far as possible.

[ tglx: Fixed comments, made output conistent, easier to read and
  	parse. Fixed output for 32bit archs which do not use the
  	scalar representation of ktime_t. Hand current time to
  	trace_hrtimer_expiry_entry instead of calling get_time()
  	inside of the trace assignment. ]

Signed-off-by: Xiao Guangrong <xiaoguangrong@cn.fujitsu.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Mathieu Desnoyers <mathieu.desnoyers@polymtl.ca>
Cc: Anton Blanchard <anton@samba.org>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: KOSAKI Motohiro <kosaki.motohiro@jp.fujitsu.com>
Cc: Zhaolei <zhaolei@cn.fujitsu.com>
LKML-Reference: <4A7F8B2B.5020908@cn.fujitsu.com>
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>

2 files changed, 171 insertions, 8 deletions

diff --git a/include/trace/events/timer.h b/include/trace/events/timer.h
index 725892a93b49..df3c07fa0cb8 100644
--- a/include/trace/events/timer.h
+++ b/include/trace/events/timer.h
@@ -5,6 +5,7 @@
 #define _TRACE_TIMER_H
 
 #include <linux/tracepoint.h>
+#include <linux/hrtimer.h>
 #include <linux/timer.h>
 
 /**
@@ -131,6 +132,144 @@ TRACE_EVENT(timer_cancel,
         TP_printk("timer %p", __entry->timer)
 );
 
+/**
+ * hrtimer_init - called when the hrtimer is initialized
+ * @timer:      pointer to struct hrtimer
+ * @clockid:    the hrtimers clock
+ * @mode:       the hrtimers mode
+ */
+TRACE_EVENT(hrtimer_init,
+
+        TP_PROTO(struct hrtimer *timer, clockid_t clockid,
+                 enum hrtimer_mode mode),
+
+        TP_ARGS(timer, clockid, mode),
+
+        TP_STRUCT__entry(
+                __field( void *,                timer           )
+                __field( clockid_t,             clockid         )
+                __field( enum hrtimer_mode,     mode            )
+        ),
+
+        TP_fast_assign(
+                __entry->timer          = timer;
+                __entry->clockid        = clockid;
+                __entry->mode           = mode;
+        ),
+
+        TP_printk("hrtimer %p, clockid %s, mode %s", __entry->timer,
+                  __entry->clockid == CLOCK_REALTIME ?
+                        "CLOCK_REALTIME" : "CLOCK_MONOTONIC",
+                  __entry->mode == HRTIMER_MODE_ABS ?
+                        "HRTIMER_MODE_ABS" : "HRTIMER_MODE_REL")
+);
+
+/**
+ * hrtimer_start - called when the hrtimer is started
+ * @timer: pointer to struct hrtimer
+ */
+TRACE_EVENT(hrtimer_start,
+
+        TP_PROTO(struct hrtimer *timer),
+
+        TP_ARGS(timer),
+
+        TP_STRUCT__entry(
+                __field( void *,        timer           )
+                __field( void *,        function        )
+                __field( s64,           expires         )
+                __field( s64,           softexpires     )
+        ),
+
+        TP_fast_assign(
+                __entry->timer          = timer;
+                __entry->function       = timer->function;
+                __entry->expires        = hrtimer_get_expires(timer).tv64;
+                __entry->softexpires    = hrtimer_get_softexpires(timer).tv64;
+        ),
+
+        TP_printk("hrtimer %p, func %pf, expires %llu, softexpires %llu",
+                  __entry->timer, __entry->function,
+                  (unsigned long long)ktime_to_ns((ktime_t) {
+                                  .tv64 = __entry->expires }),
+                  (unsigned long long)ktime_to_ns((ktime_t) {
+                                  .tv64 = __entry->softexpires }))
+);
+
+/**
+ * htimmer_expire_entry - called immediately before the hrtimer callback
+ * @timer:      pointer to struct hrtimer
+ * @now:        pointer to variable which contains current time of the
+ *              timers base.
+ *
+ * Allows to determine the timer latency.
+ */
+TRACE_EVENT(hrtimer_expire_entry,
+
+        TP_PROTO(struct hrtimer *timer, ktime_t *now),
+
+        TP_ARGS(timer, now),
+
+        TP_STRUCT__entry(
+                __field( void *,        timer   )
+                __field( s64,           now     )
+        ),
+
+        TP_fast_assign(
+                __entry->timer  = timer;
+                __entry->now    = now->tv64;
+        ),
+
+        TP_printk("hrtimer %p, now %llu", __entry->timer,
+                  (unsigned long long)ktime_to_ns((ktime_t) {
+                                  .tv64 = __entry->now }))
+ );
+
+/**
+ * hrtimer_expire_exit - called immediately after the hrtimer callback returns
+ * @timer:      pointer to struct hrtimer
+ *
+ * When used in combination with the hrtimer_expire_entry tracepoint we can
+ * determine the runtime of the callback function.
+ */
+TRACE_EVENT(hrtimer_expire_exit,
+
+        TP_PROTO(struct hrtimer *timer),
+
+        TP_ARGS(timer),
+
+        TP_STRUCT__entry(
+                __field( void *,        timer   )
+        ),
+
+        TP_fast_assign(
+                __entry->timer  = timer;
+        ),
+
+        TP_printk("hrtimer %p", __entry->timer)
+);
+
+/**
+ * hrtimer_cancel - called when the hrtimer is canceled
+ * @timer:      pointer to struct hrtimer
+ */
+TRACE_EVENT(hrtimer_cancel,
+
+        TP_PROTO(struct hrtimer *timer),
+
+        TP_ARGS(timer),
+
+        TP_STRUCT__entry(
+                __field( void *,        timer   )
+        ),
+
+        TP_fast_assign(
+                __entry->timer  = timer;
+        ),
+
+        TP_printk("hrtimer %p", __entry->timer)
+);
+
 #endif /*  _TRACE_TIMER_H */
 
 /* This part must be outside protection */
diff --git a/kernel/hrtimer.c b/kernel/hrtimer.c
index e2f91ecc01a8..b44d1b07377b 100644
--- a/kernel/hrtimer.c
+++ b/kernel/hrtimer.c
@@ -48,6 +48,8 @@
 
 #include <asm/uaccess.h>
 
+#include <trace/events/timer.h>
+
 /*
  * The timer bases:
  *
@@ -441,6 +443,26 @@ static inline void debug_hrtimer_activate(struct hrtimer *timer) { }
 static inline void debug_hrtimer_deactivate(struct hrtimer *timer) { }
 #endif
 
+static inline void
+debug_init(struct hrtimer *timer, clockid_t clockid,
+           enum hrtimer_mode mode)
+{
+        debug_hrtimer_init(timer);
+        trace_hrtimer_init(timer, clockid, mode);
+}
+
+static inline void debug_activate(struct hrtimer *timer)
+{
+        debug_hrtimer_activate(timer);
+        trace_hrtimer_start(timer);
+}
+
+static inline void debug_deactivate(struct hrtimer *timer)
+{
+        debug_hrtimer_deactivate(timer);
+        trace_hrtimer_cancel(timer);
+}
+
 /* High resolution timer related functions */
 #ifdef CONFIG_HIGH_RES_TIMERS
 
@@ -797,7 +819,7 @@ static int enqueue_hrtimer(struct hrtimer *timer,
         struct hrtimer *entry;
         int leftmost = 1;
 
-        debug_hrtimer_activate(timer);
+        debug_activate(timer);
 
         /*
          * Find the right place in the rbtree:
@@ -883,7 +905,7 @@ remove_hrtimer(struct hrtimer *timer, struct hrtimer_clock_base *base)
                  * reprogramming happens in the interrupt handler. This is a
                  * rare case and less expensive than a smp call.
                  */
-                debug_hrtimer_deactivate(timer);
+                debug_deactivate(timer);
                 timer_stats_hrtimer_clear_start_info(timer);
                 reprogram = base->cpu_base == &__get_cpu_var(hrtimer_bases);
                 __remove_hrtimer(timer, base, HRTIMER_STATE_INACTIVE,
@@ -1116,7 +1138,7 @@ static void __hrtimer_init(struct hrtimer *timer, clockid_t clock_id,
 void hrtimer_init(struct hrtimer *timer, clockid_t clock_id,
                   enum hrtimer_mode mode)
 {
-        debug_hrtimer_init(timer);
+        debug_init(timer, clock_id, mode);
         __hrtimer_init(timer, clock_id, mode);
 }
 EXPORT_SYMBOL_GPL(hrtimer_init);
@@ -1140,7 +1162,7 @@ int hrtimer_get_res(const clockid_t which_clock, struct timespec *tp)
 }
 EXPORT_SYMBOL_GPL(hrtimer_get_res);
 
-static void __run_hrtimer(struct hrtimer *timer)
+static void __run_hrtimer(struct hrtimer *timer, ktime_t *now)
 {
         struct hrtimer_clock_base *base = timer->base;
         struct hrtimer_cpu_base *cpu_base = base->cpu_base;
@@ -1149,7 +1171,7 @@ static void __run_hrtimer(struct hrtimer *timer)
 
         WARN_ON(!irqs_disabled());
 
-        debug_hrtimer_deactivate(timer);
+        debug_deactivate(timer);
         __remove_hrtimer(timer, base, HRTIMER_STATE_CALLBACK, 0);
         timer_stats_account_hrtimer(timer);
         fn = timer->function;
@@ -1160,7 +1182,9 @@ static void __run_hrtimer(struct hrtimer *timer)
          * the timer base.
          */
         spin_unlock(&cpu_base->lock);
+        trace_hrtimer_expire_entry(timer, now);
         restart = fn(timer);
+        trace_hrtimer_expire_exit(timer);
         spin_lock(&cpu_base->lock);
 
         /*
@@ -1271,7 +1295,7 @@ void hrtimer_interrupt(struct clock_event_device *dev)
                                 break;
                         }
 
-                        __run_hrtimer(timer);
+                        __run_hrtimer(timer, &basenow);
                 }
                 base++;
         }
@@ -1393,7 +1417,7 @@ void hrtimer_run_queues(void)
                                         hrtimer_get_expires_tv64(timer))
                                 break;
 
-                        __run_hrtimer(timer);
+                        __run_hrtimer(timer, &base->softirq_time);
                 }
                 spin_unlock(&cpu_base->lock);
         }
@@ -1569,7 +1593,7 @@ static void migrate_hrtimer_list(struct hrtimer_clock_base *old_base,
         while ((node = rb_first(&old_base->active))) {
                 timer = rb_entry(node, struct hrtimer, node);
                 BUG_ON(hrtimer_callback_running(timer));
-                debug_hrtimer_deactivate(timer);
+                debug_deactivate(timer);
 
                 /*
                  * Mark it as STATE_MIGRATE not INACTIVE otherwise the