[PATCH v6 1/3] ftrace: add tracepoint for timer

[PATCH v6 1/3] ftrace: add tracepoint for timer

[Xiao Guangrong]

This patch is modify from Mathieu's patch base on Ingo's suggestion, the
original patch can be found here:
	http://marc.info/?l=linux-kernel&m=123791201816247&w=2

Great thanks to Thomas for giving me so many valuable advices.

Those tracepoints are wanted and useful:
1: We can detect a timer's delay
2: We can monitor the lifecycle and behaviors of a timer

Thus they help in analysing and debuging.

Example ftrace output:
  insmod-1712  [000]   145.901459: timer_init: timer=d0ace4b4
  insmod-1712  [000]   145.901469: timer_start: timer=d0ace4b4 func=timer_fun expires=4294813629 timeout=199
  <idle>-0     [000]   146.100230: timer_cancel: timer=d0ace4b4
  <idle>-0     [000]   146.100233: timer_expire: timer=d0ace4b4 jiffies=4294813629
  <idle>-0     [000]   146.100627: timer_callback_done: func=d0ace4b4

We expect the timer expires at 4294813629, after 199 jiffies, actually the
timer expires at 4294813629, so it is delayed by 0 jiffies.
We also realize the timer's callback started at 146.100233, and it finished
at 146.100627, so it's taking 146.100627-146.100233=0.4ms.
 
Changelog:
v1->v2:
1: Add jiffies info into timer
2: Combine debugobjects and trace as Thomas's suggestion
v2->v3:
1: Remove function address from timer_expire and timer_cancel
   as Thomas's suggestion
2: Remove debug_and_trace_timer_expire() as Thomas's suggestion
3: Rename trace_timer_entry() and trace_timer_exit() to match this patch
v3->v4:
1: Rename debug_and_trace_*() to debug_*() as Peter Zijlstra's suggestion
2: Integrate Anton Blanchard's patch, which can been found at:
	http://marc.info/?l=linux-kernel&m=124331396919301&w=2
v4->v5:
Rebase the patch against latest tip tree
v5->v6:
Rename timer_expire(), timer_callback_done() to timer_expire_entry(),
timer_expire_exit() as Ingo's suggestion

Signed-off-by: Anton Blanchard <anton@samba.org>
Signed-off-by: Mathieu Desnoyers <mathieu.desnoyers@polymtl.ca>
Signed-off-by: Xiao Guangrong <xiaoguangrong@cn.fujitsu.com>
---
 include/trace/events/timer.h |  134 ++++++++++++++++++++++++++++++++++++++++++
 kernel/timer.c               |   32 +++++++++-
 2 files changed, 162 insertions(+), 4 deletions(-)
 create mode 100644 include/trace/events/timer.h

diff --git a/include/trace/events/timer.h b/include/trace/events/timer.h
new file mode 100644
index 0000000..fcf65c7
--- /dev/null
+++ b/include/trace/events/timer.h
@@ -0,0 +1,134 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM timer
+
+#if !defined(_TRACE_TIMER_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_TIMER_H
+
+#include <linux/tracepoint.h>
+#include <linux/timer.h>
+
+/**
+ * timer_init - called when the timer is initialized
+ * @timer: pointer to struct timer_list
+ **/
+TRACE_EVENT(timer_init,
+
+	TP_PROTO(struct timer_list *timer),
+
+	TP_ARGS(timer),
+
+	TP_STRUCT__entry(
+		__field( void *,	timer	)
+	),
+
+	TP_fast_assign(
+		__entry->timer	= timer;
+	),
+
+	TP_printk("timer=%p", __entry->timer)
+);
+
+/**
+ * timer_start - called when the timer is started
+ * @timer: pointer to struct timer_list
+ * @expires: the timer's expire time
+ **/
+TRACE_EVENT(timer_start,
+
+	TP_PROTO(struct timer_list *timer, unsigned long expires),
+
+	TP_ARGS(timer, expires),
+
+	TP_STRUCT__entry(
+		__field( void *,	timer		)
+		__field( void *,	function	)
+		__field( unsigned long,	expires		)
+		__field( int,		timeout		)
+	),
+
+	TP_fast_assign(
+		__entry->timer		= timer;
+		__entry->function	= timer->function;
+		__entry->expires	= expires;
+		__entry->timeout	= timer->expires - jiffies;
+	),
+
+	TP_printk("timer=%p func=%pf expires=%lu timeout=%d", __entry->timer,
+		  __entry->function, __entry->expires, __entry->timeout)
+);
+
+/**
+ * timer_expire_entry - called immediately before the timer callback
+ * @timer: pointer to struct timer_list
+ *
+ * When used in combination with the timer_expire_exit tracepoint we can
+ * determine the timer latency.
+ **/
+TRACE_EVENT(timer_expire_entry,
+
+	TP_PROTO(struct timer_list *timer),
+
+	TP_ARGS(timer),
+
+	TP_STRUCT__entry(
+		__field( void *,	timer	)
+		__field( unsigned long,	jiffies	)
+	),
+
+	TP_fast_assign(
+		__entry->timer		= timer;
+		__entry->jiffies	= jiffies;
+	),
+
+	TP_printk("timer=%p jiffies=%lu", __entry->timer, __entry->jiffies)
+);
+
+/**
+ * timer_expire_exit - called immediately after the timer callback returns
+ * @timer: pointer to struct timer_list
+ *
+ * When used in combination with the timer_expire_entry tracepoint we can
+ * determine the timer latency.
+ **/
+TRACE_EVENT(timer_expire_exit,
+
+	TP_PROTO(struct timer_list *timer),
+
+	TP_ARGS(timer),
+
+	TP_STRUCT__entry(
+		__field(void *,	timer	)
+	),
+
+	TP_fast_assign(
+		__entry->timer	= timer;
+	),
+
+	TP_printk("func=%p", __entry->timer)
+);
+
+/**
+ * timer_cancel - called when the timer is canceled
+ * @timer: pointer to struct timer_list
+ **/
+TRACE_EVENT(timer_cancel,
+
+	TP_PROTO(struct timer_list *timer),
+
+	TP_ARGS(timer),
+
+	TP_STRUCT__entry(
+		__field( void *,	timer	)
+	),
+
+	TP_fast_assign(
+		__entry->timer	= timer;
+	),
+
+	TP_printk("timer=%p", __entry->timer)
+);
+
+#endif /*  _TRACE_TIMER_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
diff --git a/kernel/timer.c b/kernel/timer.c
index 33fc9d1..22e2ada 100644
--- a/kernel/timer.c
+++ b/kernel/timer.c
@@ -46,6 +46,9 @@
 #include <asm/timex.h>
 #include <asm/io.h>
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/timer.h>
+
 u64 jiffies_64 __cacheline_aligned_in_smp = INITIAL_JIFFIES;
 
 EXPORT_SYMBOL(jiffies_64);
@@ -521,6 +524,25 @@ static inline void debug_timer_activate(struct timer_list *timer) { }
 static inline void debug_timer_deactivate(struct timer_list *timer) { }
 #endif
 
+static inline void debug_init(struct timer_list *timer)
+{
+	debug_timer_init(timer);
+	trace_timer_init(timer);
+}
+
+static inline void
+debug_activate(struct timer_list *timer, unsigned long expires)
+{
+	debug_timer_activate(timer);
+	trace_timer_start(timer, expires);
+}
+
+static inline void debug_deactivate(struct timer_list *timer)
+{
+	debug_timer_deactivate(timer);
+	trace_timer_cancel(timer);
+}
+
 static void __init_timer(struct timer_list *timer,
 			 const char *name,
 			 struct lock_class_key *key)
@@ -549,7 +571,7 @@ void init_timer_key(struct timer_list *timer,
 		    const char *name,
 		    struct lock_class_key *key)
 {
-	debug_timer_init(timer);
+	debug_init(timer);
 	__init_timer(timer, name, key);
 }
 EXPORT_SYMBOL(init_timer_key);
@@ -568,7 +590,7 @@ static inline void detach_timer(struct timer_list *timer,
 {
 	struct list_head *entry = &timer->entry;
 
-	debug_timer_deactivate(timer);
+	debug_deactivate(timer);
 
 	__list_del(entry->prev, entry->next);
 	if (clear_pending)
@@ -632,7 +654,7 @@ __mod_timer(struct timer_list *timer, unsigned long expires,
 			goto out_unlock;
 	}
 
-	debug_timer_activate(timer);
+	debug_activate(timer, expires);
 
 	new_base = __get_cpu_var(tvec_bases);
 
@@ -787,7 +809,7 @@ void add_timer_on(struct timer_list *timer, int cpu)
 	BUG_ON(timer_pending(timer) || !timer->function);
 	spin_lock_irqsave(&base->lock, flags);
 	timer_set_base(timer, base);
-	debug_timer_activate(timer);
+	debug_activate(timer, timer->expires);
 	if (time_before(timer->expires, base->next_timer) &&
 	    !tbase_get_deferrable(timer->base))
 		base->next_timer = timer->expires;
@@ -1000,7 +1022,9 @@ static inline void __run_timers(struct tvec_base *base)
 				 */
 				lock_map_acquire(&lockdep_map);
 
+				trace_timer_expire_entry(timer);
 				fn(data);
+				trace_timer_expire_exit(timer);
 
 				lock_map_release(&lockdep_map);
 
-- 
1.6.1.2

[PATCH v6 2/3] ftrace: add tracepoint for hrtimer

[Xiao Guangrong]

Those tracepoints are wanted and useful:
1: We can detect a hrtimer's delay
2: We can monitor the lifecycle and behaviors of a hrtimer

Thus they help in analysing and debuging.

Great thanks to Thomas for giving me so many valuable advices.

Example ftrace output:
  insmod-1824  [001]   606.749538: hrtimer_init: timer=d0ae04c0 clockid=CLOCK_REALTIME mode=HRTIMER_MODE_ABS
  insmod-1824  [001]   606.749614: hrtimer_start: timer=d0ae04c0 func=hrtimer_fun expires=1246707447252299435ns softexpires=1246707447252299435ns
  <idle>-0     [001]   606.754372: hrtimer_cancel: timer=d0ae04c0
  <idle>-0     [001]   606.754374: hrtimer_expire: timer=d0ae04c0 now=1246707447257141331ns
  <idle>-0     [001]   606.754430: hrtimer_callback_done: timer=d0ae04c0
 
We expect the hrtimer expires at 1246707447252299435ns, actually the
hrtimer expires at 1246707447257141331ns, so it is delayed by
1246707447257141331-1246707447252299435=4841896ns.
We also realize the hrtimer's callback started at 606.754374, and it
finished at 606.754430, so it's taking 606.754430-606.754374=0.05ms.

Changelog:
v1->v2:
1: Remove ktime_to_ns() in TP_fast_assign()
2: Combine debugobjects and trace as Thomas's suggestion
v2->v3:
1: Remove function address from hrtimer_expire and hrtimer_cancel
   as Thomas's suggestion
2: Remove debug_and_trace_hrtimer_expire() as Thomas's suggestion
3: Rename trace_hrtimer_entry() and trace_hrtimer_exit() to match this patch
v3->v4:
1: Rename debug_and_trace_*() to debug_*() as Peter Zijlstra's suggestion
2: Move trace_hrtimer_expire() to __run_hrtimer() in order to calculate
   exacts timer latency as Peter Zijlstra's suggestion
3: Integrate Anton Blanchard's patch, which can been found at:
	http://marc.info/?l=linux-kernel&m=124331396919301&w=2
v4->v5:
Rebase the patch against latest tip tree
v5->v6:
Rename hrtimer_expire(), hrtimer_callback_done() to hrtimer_expire_entry(),
hrtimer_expire_exit() as Ingo's suggestion

Signed-off-by: Anton Blanchard <anton@samba.org>
Signed-off-by: Xiao Guangrong <xiaoguangrong@cn.fujitsu.com>
---
 include/trace/events/timer.h |  133 ++++++++++++++++++++++++++++++++++++++++++
 kernel/hrtimer.c             |   34 +++++++++--
 2 files changed, 162 insertions(+), 5 deletions(-)

diff --git a/include/trace/events/timer.h b/include/trace/events/timer.h
index fcf65c7..6140f29 100644
--- a/include/trace/events/timer.h
+++ b/include/trace/events/timer.h
@@ -128,6 +128,139 @@ 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 hrtimer's clock
+ * @mode: the hrtimer's 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("timer=%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("timer=%p func=%pf expires=%lluns softexpires=%lluns",
+		  __entry->timer, __entry->function,
+		 (unsigned long long)__entry->expires,
+		 (unsigned long long)__entry->softexpires)
+);
+
+/**
+ * htimmer_expire_entry - called immediately before the hrtimer callback
+ * @timer: pointer to struct hrtimer
+ *
+ * When used in combination with the hrtimer_expire_exit tracepoint we can
+ * determine the high res timer latency.
+ **/
+TRACE_EVENT(hrtimer_expire_entry,
+
+	TP_PROTO(struct hrtimer *timer),
+
+	TP_ARGS(timer),
+
+	TP_STRUCT__entry(
+		__field( void *,	timer	)
+		__field( s64,		now	)
+	),
+
+	TP_fast_assign(
+		__entry->timer	= timer;
+		__entry->now	= timer->base->get_time().tv64;
+	),
+
+	TP_printk("timer=%p now=%lluns", __entry->timer,
+		 (unsigned long long)__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 high res timer latency.
+  **/
+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("timer=%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("timer=%p", __entry->timer)
+);
+
 #endif /*  _TRACE_TIMER_H */
 
 /* This part must be outside protection */
diff --git a/kernel/hrtimer.c b/kernel/hrtimer.c
index e2f91ec..0cfec97 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);
@@ -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);
 	restart = fn(timer);
+	trace_hrtimer_expire_exit(timer);
 	spin_lock(&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
-- 
1.6.1.2

[tip:timers/tracing] hrtimer: Add tracepoint for hrtimers

[tip-bot for Xiao Guangrong]

Commit-ID:  c6a2a1770245f654f35f60e1458d4356680f9519
Gitweb:     http://git.kernel.org/tip/c6a2a1770245f654f35f60e1458d4356680f9519
Author:     Xiao Guangrong <xiaoguangrong@cn.fujitsu.com>
AuthorDate: Mon, 10 Aug 2009 10:51:23 +0800
Committer:  Thomas Gleixner <tglx@linutronix.de>
CommitDate: Sat, 29 Aug 2009 14:10:06 +0200

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>


---
 include/trace/events/timer.h |  139 ++++++++++++++++++++++++++++++++++++++++++
 kernel/hrtimer.c             |   40 ++++++++++---
 2 files changed, 171 insertions(+), 8 deletions(-)

diff --git a/include/trace/events/timer.h b/include/trace/events/timer.h
index 725892a..df3c07f 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 e2f91ec..b44d1b0 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

Re: [tip:timers/tracing] hrtimer: Add tracepoint for hrtimers

[Steven Rostedt]

On Wed, 2009-09-02 at 12:18 +0000, tip-bot for Xiao Guangrong wrote:

> +/**
> + * 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 }))
> +);
> +

I was just fixing up the trace-cmd parser (which is also used for perf)
and came across this code. That TP_printk shows up in the format file
as:

print fmt: "hrtimer %p, func %pf, expires %llu, softexpires %llu", REC->timer, REC->function, (unsigned long long)(((ktime_t) { .tv64 = REC->expires }).tv64), (unsigned long long)(((ktime_t) { .tv64 = REC->softexpires }).tv64)

Now I'm trying to parse this with a tool so that we can have something
that can read the binary output, and be able to easily figure it out by
reading the format files. But trying to parse:

(unsigned long long)(((ktime_t) { .tv64 = REC->expires }).tv64)

Is not easy. It's basically implementing a C interpreter :-(

Is there anyway we can change that TRACE_EVENT to give us a better,
trace printk output?

-- Steve

Re: [tip:timers/tracing] hrtimer: Add tracepoint for hrtimers

[Ingo Molnar]

* Steven Rostedt <rostedt@goodmis.org> wrote:

> On Wed, 2009-09-02 at 12:18 +0000, tip-bot for Xiao Guangrong wrote:
> 
> > +/**
> > + * 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 }))
> > +);
> > +
> 
> I was just fixing up the trace-cmd parser (which is also used for perf)
> and came across this code. That TP_printk shows up in the format file
> as:
> 
> print fmt: "hrtimer %p, func %pf, expires %llu, softexpires %llu", REC->timer, REC->function, (unsigned long long)(((ktime_t) { .tv64 = REC->expires }).tv64), (unsigned long long)(((ktime_t) { .tv64 = REC->softexpires }).tv64)
> 
> Now I'm trying to parse this with a tool so that we can have something
> that can read the binary output, and be able to easily figure it out by
> reading the format files. But trying to parse:
> 
> (unsigned long long)(((ktime_t) { .tv64 = REC->expires }).tv64)
> 
> Is not easy. It's basically implementing a C interpreter :-(

Btw., what i suggested quite some time ago was that we should bind 
tracepoints by emitting C source code stubs, which tools can then build 
and link in, using gcc.

	Ingo

Re: [tip:timers/tracing] hrtimer: Add tracepoint for hrtimers

[Steven Rostedt]

On Tue, 2009-10-13 at 09:08 +0200, Ingo Molnar wrote:
> * Steven Rostedt <rostedt@goodmis.org> wrote:
> 

> > (unsigned long long)(((ktime_t) { .tv64 = REC->expires }).tv64)
> > 
> > Is not easy. It's basically implementing a C interpreter :-(
> 
> Btw., what i suggested quite some time ago was that we should bind 
> tracepoints by emitting C source code stubs, which tools can then build 
> and link in, using gcc.

Yeah, and I thought about that too. But that kills any chance of running
the trace on one box (non x86) and reading it on another (x86). And that
is one of my goals for this.

-- Steve

Re: [tip:timers/tracing] hrtimer: Add tracepoint for hrtimers

[Steven Rostedt]

On Tue, 2009-10-13 at 09:17 -0400, Steven Rostedt wrote:
> On Tue, 2009-10-13 at 09:08 +0200, Ingo Molnar wrote:
> > * Steven Rostedt <rostedt@goodmis.org> wrote:
> > 
> 
> > > (unsigned long long)(((ktime_t) { .tv64 = REC->expires }).tv64)
> > > 
> > > Is not easy. It's basically implementing a C interpreter :-(
> > 
> > Btw., what i suggested quite some time ago was that we should bind 
> > tracepoints by emitting C source code stubs, which tools can then build 
> > and link in, using gcc.
> 
> Yeah, and I thought about that too. But that kills any chance of running
> the trace on one box (non x86) and reading it on another (x86). And that
> is one of my goals for this.

I'd love to see the kernel code for having this also understand ktime_t.

-- Steve

Re: [tip:timers/tracing] hrtimer: Add tracepoint for hrtimers

[Ingo Molnar]

* Steven Rostedt <rostedt@goodmis.org> wrote:

> On Tue, 2009-10-13 at 09:08 +0200, Ingo Molnar wrote:
> > * Steven Rostedt <rostedt@goodmis.org> wrote:
> > 
> 
> > > (unsigned long long)(((ktime_t) { .tv64 = REC->expires }).tv64)
> > > 
> > > Is not easy. It's basically implementing a C interpreter :-(
> > 
> > Btw., what i suggested quite some time ago was that we should bind 
> > tracepoints by emitting C source code stubs, which tools can then build 
> > and link in, using gcc.
> 
> Yeah, and I thought about that too. But that kills any chance of 
> running the trace on one box (non x86) and reading it on another 
> (x86). And that is one of my goals for this.

Why does it kill that chance?

	Ingo

Re: [tip:timers/tracing] hrtimer: Add tracepoint for hrtimers

[Steven Rostedt]

On Tue, 2009-10-13 at 15:26 +0200, Ingo Molnar wrote:
> * Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > On Tue, 2009-10-13 at 09:08 +0200, Ingo Molnar wrote:
> > > * Steven Rostedt <rostedt@goodmis.org> wrote:
> > > 
> > 
> > > > (unsigned long long)(((ktime_t) { .tv64 = REC->expires }).tv64)
> > > > 
> > > > Is not easy. It's basically implementing a C interpreter :-(
> > > 
> > > Btw., what i suggested quite some time ago was that we should bind 
> > > tracepoints by emitting C source code stubs, which tools can then build 
> > > and link in, using gcc.
> > 
> > Yeah, and I thought about that too. But that kills any chance of 
> > running the trace on one box (non x86) and reading it on another 
> > (x86). And that is one of my goals for this.
> 
> Why does it kill that chance?

Ah, I was thinking binary libraries from the trace points. But I missed
you said C source code.

But still, we need to build a way to convert big endian to little, as
well as perhaps converting 32bit to 64 bit longs. As well as vice versa.

We also need a way to export all structures (here ktime_t) as well as
enums. Of course we need to export enums now anyway, since the tools
don't know how to convert them now.

-- Steve

[RFC] Trace types registry

[Mathieu Desnoyers]

* Steven Rostedt (rostedt@goodmis.org) wrote:
> On Tue, 2009-10-13 at 15:26 +0200, Ingo Molnar wrote:
> > * Steven Rostedt <rostedt@goodmis.org> wrote:
> > 
> > > On Tue, 2009-10-13 at 09:08 +0200, Ingo Molnar wrote:
> > > > * Steven Rostedt <rostedt@goodmis.org> wrote:
> > > > 
> > > 
> > > > > (unsigned long long)(((ktime_t) { .tv64 = REC->expires }).tv64)
> > > > > 
> > > > > Is not easy. It's basically implementing a C interpreter :-(
> > > > 
> > > > Btw., what i suggested quite some time ago was that we should bind 
> > > > tracepoints by emitting C source code stubs, which tools can then build 
> > > > and link in, using gcc.
> > > 
> > > Yeah, and I thought about that too. But that kills any chance of 
> > > running the trace on one box (non x86) and reading it on another 
> > > (x86). And that is one of my goals for this.
> > 
> > Why does it kill that chance?
> 
> Ah, I was thinking binary libraries from the trace points. But I missed
> you said C source code.
> 
> But still, we need to build a way to convert big endian to little, as
> well as perhaps converting 32bit to 64 bit longs. As well as vice versa.
> 
> We also need a way to export all structures (here ktime_t) as well as
> enums. Of course we need to export enums now anyway, since the tools
> don't know how to convert them now.
> 
> -- Steve

I fully agree with Steve here. Embedded system developers, for instance,
will typically export traces taken on small embedded devices to a
completely different architecture for analysis and visualization.

The problem I see with exporting this as C code is that it does not
represent the type size and endianness of the traced kernel.

I think I may have a solution that could deal with these compound types.
Comments are welcome.

The idea is to create a type registry, that could be expressed in either
textual or binary format. (binary format simply requires a header with
the architecture endianness and basic types sizes expressed)

The registry, which would be saved along with a trace, could look like
what follows (written in C here, but would be created dynamically). Note
that this registry is only saved once with a trace, so we do not care
about compactness. What we really do care about is to make it easy to
parse a trace coming from an alien architecture.

enum entry_type { T_SCALAR, T_COMPOUND, T_EVENT };

struct event_field {
	u32 type_id;	/* maps to a type */
	char name[MAX_FIELD_NAME];
};

union compound_field {
	u32 type_id;		  /* Unnamed fields (array, sequence, string) */
	struct event_field field; /* Named fields (struct, union) */
}

/* Use "type_id" lookup to find if type is scalar or compound */
union event_type {
	struct event_type_scalar scalar;
	struct event_type_compound compound;
};

struct event_type_scalar {
	struct entry_type etype;
	u32 type_id;	/* Allocated dynamically */
	char name[MAX_TYPE_NAME];
	u32 size;
	u8 host_byte_order;
	u8 signed;
	u8 format;	/* one of 256 possible print formats */
	u8 float;	/* useful for user-space tracing */
};

/* array, sequence, struct, union, string */
struct event_type_compound {
	struct entry_type etype;
	u32 type_id;	/* Allocated dynamically */
	char name[MAX_TYPE_NAME];
	enum { T_ARRAY, T_SEQ, T_STRUCT, T_UNION, T_STRING } type;
	u32 nr_fields;
	union compound_field[nr_fields] field;
};

struct event {
	struct entry_type etype;
	/* map to the event */
	unsigned int group_id;
	unsigned int event_id;
	char group_name[MAX_GROUP_NAME];
	char event_name[MAX_EVENT_NAME];
	u32 type_id;
};

stuct trace_registry {
	struct regheader {
		u32 magic_num;	/* detect endianness */
		u8 int_size;	/* basic types */
		u8 long_size;
		u8 size_t_size;
		u8 off_t_size;
		u8 ptr_diff_t_size;
	}

	struct event_type_scalar {
		.etype = T_SCALAR,
		.type_id = lookup_or_create_type_id(char);
		.name = "char",
		.size = 1,
		.host_byte_order = 1,
		.signed = 0,
		.format = 'c',
		.float = 0,
	}

	struct event_type_compound = {
		.etype = T_COMPOUND,
		.type_id = lookup_or_create_type_id(char [TASK_COMM_LEN]),
		.name = "char [TASK_COMM_LEN]",
		.type = T_ARRAY,
		.nr_fields = TASK_COMM_LEN,
		.field[0].type_id = lookup_type_id("char");
	}

	struct event_type_scalar {
		.etype = T_SCALAR,
		.type_id = lookup_or_create_type_id(pid_t),
		.name = "pid_t",
		.size = sizeof(pid_t),
		.host_byte_order = 1,
		.signed = 0,
		.format = 'u',
		.float = 0,
	}

	struct event_type_scalar {
		.etype = T_SCALAR,
		.type_id = lookup_or_create_type_id(int),
		.name = "int",
		.size = sizeof(int),
		.host_byte_order = 1,
		.signed = 1,
		.format = 'd',
		.float = 0,
	}

	struct event_type_compound = {
		.etype = T_COMPOUND,
		.type_id = lookup_or_create_type_id(
			{
				char [TASK_COMM_LEN];
				pid_t;
				int;
				char;
				pid_t;
				int;
			});

		.name = "{
				char [TASK_COMM_LEN];
				pid_t;
				int;
				char;
				pid_t;
				int;
			}",
		.type = T_STRUCT,
		.nr_fields = 6,
		.field[0].field.type_id = lookup_type_id(char [TASK_COMM_LEN]),
		.field[0].field.name = "prev_comm",
		.field[1].field.type_id = lookup_type_id(pid_t),
		.field[1].field.name = "prev_pid",
		.field[2].field.type_id = lookup_type_id(int),
		.field[2].field.name = "prev_prio",
		.field[2].field.type_id = lookup_type_id(char [TASK_COMM_LEN]),
		.field[2].field.name = "next_comm",
		.field[2].field.type_id = lookup_type_id(pid_t),
		.field[2].field.name = "next_pid",
		.field[2].field.type_id = lookup_type_id(int),
		.field[2].field.name = "next_prio",
	}

	struct event sched_switch_event {
		.etype = T_EVENT,
		.group_id = lookup_event_group("groupname"),
		.event_id = lookup_event_id("evname"),
		.groupname = "groupname",
		.eventname = "evname",
		.type_id = lookup_type_id(
			{
				char [TASK_COMM_lEN];
				pid_t;
				int;
				char;
				pid_t;
				int;
			});

.......

	}
}

Note: lookup_type_id() and lookup_or_create_type_id() could be a macro
that stringify their parameters.

Steve, do you think this could be created by TRACE_EVENT() automatically ?
Basically, each field and event would try to register its types at
module load time. Registration would allocate a unique ID to each type
and a unique ID to each group and event.

When "unrolling" the registry at trace analysis time, these IDs would be
used to populate a hash table, so the event, group and type lookups can
be performed.

Mathieu

-- 
Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68

Re: [tip:timers/tracing] hrtimer: Add tracepoint for hrtimers

[Ingo Molnar]

* Steven Rostedt <rostedt@goodmis.org> wrote:

> On Tue, 2009-10-13 at 15:26 +0200, Ingo Molnar wrote:
> > * Steven Rostedt <rostedt@goodmis.org> wrote:
> > 
> > > On Tue, 2009-10-13 at 09:08 +0200, Ingo Molnar wrote:
> > > > * Steven Rostedt <rostedt@goodmis.org> wrote:
> > > > 
> > > 
> > > > > (unsigned long long)(((ktime_t) { .tv64 = REC->expires }).tv64)
> > > > > 
> > > > > Is not easy. It's basically implementing a C interpreter :-(
> > > > 
> > > > Btw., what i suggested quite some time ago was that we should bind 
> > > > tracepoints by emitting C source code stubs, which tools can then build 
> > > > and link in, using gcc.
> > > 
> > > Yeah, and I thought about that too. But that kills any chance of 
> > > running the trace on one box (non x86) and reading it on another 
> > > (x86). And that is one of my goals for this.
> > 
> > Why does it kill that chance?
> 
> Ah, I was thinking binary libraries from the trace points. But I 
> missed you said C source code.
> 
> But still, we need to build a way to convert big endian to little, as 
> well as perhaps converting 32bit to 64 bit longs. As well as vice 
> versa.

Exporting the print line as C in a convenient way does not in any way 
make it more difficult to define endianness and bit size - we have to do 
that anyway. It's largely orthogonal.

	Ingo

Re: [tip:timers/tracing] hrtimer: Add tracepoint for hrtimers

[Steven Rostedt]

On Tue, 2009-10-13 at 20:41 +0200, Ingo Molnar wrote:

> > But still, we need to build a way to convert big endian to little, as 
> > well as perhaps converting 32bit to 64 bit longs. As well as vice 
> > versa.
> 
> Exporting the print line as C in a convenient way does not in any way 
> make it more difficult to define endianness and bit size - we have to do 
> that anyway. It's largely orthogonal.

The way I do it now, is basically making a C interpreter. This can
easily handle word size and endianess (I have those exported too, and
can handle differences between host and file).

But to export the "printf" as a C function, that C function will need to
know a way what size a long is, as well as how to convert endianess.

I'm not really sure how to go about doing something like this
automatically. Every event will need its own C function to convert.
Sounds more like what Mathieu was describing.

We still don't have a way to handle enums and structures (like ktime).

-- Steve

Re: [tip:timers/tracing] hrtimer: Add tracepoint for hrtimers

[Peter Zijlstra]

On Mon, 2009-10-12 at 23:25 -0400, Steven Rostedt wrote:
> > +     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 }))
> > +);
> > +
> 
> I was just fixing up the trace-cmd parser (which is also used for perf)
> and came across this code. That TP_printk shows up in the format file
> as:
> 
> print fmt: "hrtimer %p, func %pf, expires %llu, softexpires %llu", REC->timer, REC->function, (unsigned long long)(((ktime_t) { .tv64 = REC->expires }).tv64), (unsigned long long)(((ktime_t) { .tv64 = REC->softexpires }).tv64)
> 
> Now I'm trying to parse this with a tool so that we can have something
> that can read the binary output, and be able to easily figure it out by
> reading the format files. But trying to parse:
> 
> (unsigned long long)(((ktime_t) { .tv64 = REC->expires }).tv64)
> 
> Is not easy. It's basically implementing a C interpreter :-(
> 
> Is there anyway we can change that TRACE_EVENT to give us a better,
> trace printk output?

LOL

Either convince tglx that ktime_t really ought to die for good (yeah, I
know arm), or specialize the whole printout for 32 vs 64 ktime_t.

union ktime {
        s64     tv64;
#if BITS_PER_LONG != 64 && !defined(CONFIG_KTIME_SCALAR)
        struct {
# ifdef __BIG_ENDIAN
        s32     sec, nsec;
# else
        s32     nsec, sec;
# endif
        } tv;
#endif
};

[PATCH v6 3/3] ftrace: add tracepoint for itimer

[Xiao Guangrong]

Those tracepoints are wanted and useful:
1: We can detect a itimer's delay
2: We can monitor the lifecycle and behaviors of a itimer

Thus they help in analysing and debuging.

Great thanks to Thomas for giving me so many valuable advices.

There have two case: 
case 1, if we use ITIMER_REAL itimer:
Example ftrace output:
  main-1517  [000]   288.826521: hrtimer_start: timer=ce807544 func=it_real_fn expires=289327664443 ns softexpires=289327664443 ns
  main-1517  [000]   288.826524: itimer_state: which=0 expires=0 it_value=0.500 it_interval=0.0
  main-1517  [000]   288.827313: hrtimer_expire: timer=ce807544 now=289327958161 ns
  main-1517  [000]   288.827314: hrtimer_cancel: timer=ce807544
  main-1517  [000]   288.827315: itimer_expire: pid=1517 which=0 now=0
  main-1517  [000]   288.827319: hrtimer_callback_done: timer=ce807544
  main-1517  [000]   288.827463: itimer_state: which=0 expires=0 it_value=0.0 it_interval=0.0

ITIMER_REAL itime use hrtimer to calculate time, so we can cooperate with
hrtimer's tracepoint to get it's delay.

from this output information, the process set up a ITIMER_REAL
iteimr(which=0), use a hrtime which address is ce807544, we can get the
delay is 289327958161-289327664443=293718 ns

case 2, if we use ITIMER_VIRTUAL/ITIMER_PROF itimer:
Example ftrace output:
  main-5409  [001] 12763.874835: itimer_state: which=1 expires=2 it_value=0.500 it_interval=0.500
  main-5409  [001] 12763.883495: itimer_expire: pid=5409 which=1 now=2
  main-5409  [001] 12763.883712: itimer_state: which=1 expires=0 it_value=0.0 it_interval=0.0
  
from this, we can know the itimer delay is 2-2=0 jiffies.

Changelog:
v1->v2:
Remove ktime_to_ns() in TP_fast_assign()
v2->v3:
Below changes are all base on Thomas's suggestion:
1: Remove ITIMER_REAL's timer address and 'state' from trace_itimer_state()
2: Don't save task's name in trace_itimer_state()
3: Save task's pid instead of task's name in trace_itimer_expire()
v3->v4:
Modify other two patches in this patchset
v4->v5:
Rebase the patch against latest tip tree

Signed-off-by: Xiao Guangrong <xiaoguangrong@cn.fujitsu.com>
---
 include/trace/events/timer.h |   65 ++++++++++++++++++++++++++++++++++++++++++
 kernel/itimer.c              |    5 +++
 kernel/posix-cpu-timers.c    |    3 ++
 3 files changed, 73 insertions(+), 0 deletions(-)

diff --git a/include/trace/events/timer.h b/include/trace/events/timer.h
index 6140f29..fbbead9 100644
--- a/include/trace/events/timer.h
+++ b/include/trace/events/timer.h
@@ -261,6 +261,71 @@ TRACE_EVENT(hrtimer_cancel,
 	TP_printk("timer=%p", __entry->timer)
 );
 
+/**
+ * itimer_state - called when itimer is started or canceled
+ * @which: name of the interval timer
+ * @value: the itimer's value, itimer is canceled if value->it_value is zero,
+ * 	   otherwise is started
+ * @expires: the itimer's expire time
+ **/
+TRACE_EVENT(itimer_state,
+
+	TP_PROTO(int which, const struct itimerval *const value, cputime_t expires),
+
+	TP_ARGS(which, value, expires),
+
+	TP_STRUCT__entry(
+		__field(	int,		which		)
+		__field(	cputime_t,	expires		)
+		__field(	long,		value_sec	)
+		__field(	long,		value_usec	)
+		__field(	long,		interval_sec	)
+		__field(	long,		interval_usec	)
+	),
+
+	TP_fast_assign(
+		__entry->which		= which;
+		__entry->expires	= expires;
+		__entry->value_sec	= value->it_value.tv_sec;
+		__entry->value_usec	= value->it_value.tv_usec;
+		__entry->interval_sec	= value->it_interval.tv_sec;
+		__entry->interval_usec	= value->it_interval.tv_usec;
+	),
+
+	TP_printk("which=%d expires=%lu it_value=%lu.%lu it_interval=%lu.%lu",
+		  __entry->which, __entry->expires,
+		  __entry->value_sec, __entry->value_usec,
+		  __entry->interval_sec, __entry->interval_usec)
+);
+
+/**
+ * itimer_expire: called when itimer expires
+ * @which: name of the interval timer
+ * @pid: pid of process which owns the itimer
+ * @now: current time, used to calculate the latency of itimer
+ **/
+TRACE_EVENT(itimer_expire,
+
+	TP_PROTO(int which, struct pid *pid, cputime_t now),
+
+	TP_ARGS(which, pid, now),
+
+	TP_STRUCT__entry(
+		__field( int ,		which	)
+		__field( int,		pid	)
+		__field( cputime_t,	now	)
+	),
+
+	TP_fast_assign(
+		__entry->which	= which;
+		__entry->now	= now;
+		__entry->pid	= pid_vnr(pid);
+	),
+
+	TP_printk("pid=%d which=%d now=%lu", __entry->pid, __entry->which,
+		  __entry->now)
+);
+
 #endif /*  _TRACE_TIMER_H */
 
 /* This part must be outside protection */
diff --git a/kernel/itimer.c b/kernel/itimer.c
index 8078a32..a3ceb34 100644
--- a/kernel/itimer.c
+++ b/kernel/itimer.c
@@ -12,6 +12,7 @@
 #include <linux/time.h>
 #include <linux/posix-timers.h>
 #include <linux/hrtimer.h>
+#include <trace/events/timer.h>
 
 #include <asm/uaccess.h>
 
@@ -122,6 +123,7 @@ enum hrtimer_restart it_real_fn(struct hrtimer *timer)
 	struct signal_struct *sig =
 		container_of(timer, struct signal_struct, real_timer);
 
+	trace_itimer_expire(ITIMER_REAL, sig->leader_pid, 0);
 	kill_pid_info(SIGALRM, SEND_SIG_PRIV, sig->leader_pid);
 
 	return HRTIMER_NORESTART;
@@ -166,6 +168,8 @@ static void set_cpu_itimer(struct task_struct *tsk, unsigned int clock_id,
 	}
 	it->expires = nval;
 	it->incr = ninterval;
+	trace_itimer_state(clock_id == CPUCLOCK_VIRT ? ITIMER_VIRTUAL : ITIMER_PROF,
+			   value, nval);
 
 	spin_unlock_irq(&tsk->sighand->siglock);
 
@@ -217,6 +221,7 @@ again:
 		} else
 			tsk->signal->it_real_incr.tv64 = 0;
 
+		trace_itimer_state(ITIMER_REAL, value, 0);
 		spin_unlock_irq(&tsk->sighand->siglock);
 		break;
 	case ITIMER_VIRTUAL:
diff --git a/kernel/posix-cpu-timers.c b/kernel/posix-cpu-timers.c
index 12161f7..14798a7 100644
--- a/kernel/posix-cpu-timers.c
+++ b/kernel/posix-cpu-timers.c
@@ -8,6 +8,7 @@
 #include <linux/math64.h>
 #include <asm/uaccess.h>
 #include <linux/kernel_stat.h>
+#include <trace/events/timer.h>
 
 /*
  * Called after updating RLIMIT_CPU to set timer expiration if necessary.
@@ -1093,6 +1094,8 @@ static void check_cpu_itimer(struct task_struct *tsk, struct cpu_itimer *it,
 		} else
 			it->expires = cputime_zero;
 
+		trace_itimer_expire(signo == SIGPROF ? ITIMER_PROF : ITIMER_VIRTUAL,
+				    tsk->signal->leader_pid, cur_time);
 		__group_send_sig_info(signo, SEND_SIG_PRIV, tsk);
 	}
 
-- 
1.6.1.2

[tip:timers/tracing] itimers: Add tracepoints for itimer

[tip-bot for Xiao Guangrong]

Commit-ID:  3f0a525ebf4b8ef041a332bbe4a73aee94bb064b
Gitweb:     http://git.kernel.org/tip/3f0a525ebf4b8ef041a332bbe4a73aee94bb064b
Author:     Xiao Guangrong <xiaoguangrong@cn.fujitsu.com>
AuthorDate: Mon, 10 Aug 2009 10:52:30 +0800
Committer:  Thomas Gleixner <tglx@linutronix.de>
CommitDate: Sat, 29 Aug 2009 14:10:07 +0200

itimers: Add tracepoints for itimer

Add tracepoints for all itimer variants: ITIMER_REAL, ITIMER_VIRTUAL
and ITIMER_PROF.

[ tglx: Fixed comments and made the output more readable, parseable
  	and consistent. Replaced pid_vnr by pid_nr because the hrtimer
  	callback can happen in any namespace ]

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: <4A7F8B6E.2010109@cn.fujitsu.com>
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>


---
 include/trace/events/timer.h |   66 ++++++++++++++++++++++++++++++++++++++++++
 kernel/itimer.c              |    5 +++
 kernel/posix-cpu-timers.c    |    7 ++++-
 3 files changed, 77 insertions(+), 1 deletions(-)

diff --git a/include/trace/events/timer.h b/include/trace/events/timer.h
index df3c07f..1844c48 100644
--- a/include/trace/events/timer.h
+++ b/include/trace/events/timer.h
@@ -270,6 +270,72 @@ TRACE_EVENT(hrtimer_cancel,
 	TP_printk("hrtimer %p", __entry->timer)
 );
 
+/**
+ * itimer_state - called when itimer is started or canceled
+ * @which:	name of the interval timer
+ * @value:	the itimers value, itimer is canceled if value->it_value is
+ *		zero, otherwise it is started
+ * @expires:	the itimers expiry time
+ */
+TRACE_EVENT(itimer_state,
+
+	TP_PROTO(int which, const struct itimerval *const value,
+		 cputime_t expires),
+
+	TP_ARGS(which, value, expires),
+
+	TP_STRUCT__entry(
+		__field(	int,		which		)
+		__field(	cputime_t,	expires		)
+		__field(	long,		value_sec	)
+		__field(	long,		value_usec	)
+		__field(	long,		interval_sec	)
+		__field(	long,		interval_usec	)
+	),
+
+	TP_fast_assign(
+		__entry->which		= which;
+		__entry->expires	= expires;
+		__entry->value_sec	= value->it_value.tv_sec;
+		__entry->value_usec	= value->it_value.tv_usec;
+		__entry->interval_sec	= value->it_interval.tv_sec;
+		__entry->interval_usec	= value->it_interval.tv_usec;
+	),
+
+	TP_printk("which %d, expires %lu, it_value %lu.%lu, it_interval %lu.%lu",
+		  __entry->which, __entry->expires,
+		  __entry->value_sec, __entry->value_usec,
+		  __entry->interval_sec, __entry->interval_usec)
+);
+
+/**
+ * itimer_expire - called when itimer expires
+ * @which:	type of the interval timer
+ * @pid:	pid of the process which owns the timer
+ * @now:	current time, used to calculate the latency of itimer
+ */
+TRACE_EVENT(itimer_expire,
+
+	TP_PROTO(int which, struct pid *pid, cputime_t now),
+
+	TP_ARGS(which, pid, now),
+
+	TP_STRUCT__entry(
+		__field( int ,		which	)
+		__field( pid_t,		pid	)
+		__field( cputime_t,	now	)
+	),
+
+	TP_fast_assign(
+		__entry->which	= which;
+		__entry->now	= now;
+		__entry->pid	= pid_nr(pid);
+	),
+
+	    TP_printk("which %d, pid %d, now %lu", __entry->which,
+		      (int) __entry->pid, __entry->now)
+);
+
 #endif /*  _TRACE_TIMER_H */
 
 /* This part must be outside protection */
diff --git a/kernel/itimer.c b/kernel/itimer.c
index 8078a32..b03451e 100644
--- a/kernel/itimer.c
+++ b/kernel/itimer.c
@@ -12,6 +12,7 @@
 #include <linux/time.h>
 #include <linux/posix-timers.h>
 #include <linux/hrtimer.h>
+#include <trace/events/timer.h>
 
 #include <asm/uaccess.h>
 
@@ -122,6 +123,7 @@ enum hrtimer_restart it_real_fn(struct hrtimer *timer)
 	struct signal_struct *sig =
 		container_of(timer, struct signal_struct, real_timer);
 
+	trace_itimer_expire(ITIMER_REAL, sig->leader_pid, 0);
 	kill_pid_info(SIGALRM, SEND_SIG_PRIV, sig->leader_pid);
 
 	return HRTIMER_NORESTART;
@@ -166,6 +168,8 @@ static void set_cpu_itimer(struct task_struct *tsk, unsigned int clock_id,
 	}
 	it->expires = nval;
 	it->incr = ninterval;
+	trace_itimer_state(clock_id == CPUCLOCK_VIRT ?
+			   ITIMER_VIRTUAL : ITIMER_PROF, value, nval);
 
 	spin_unlock_irq(&tsk->sighand->siglock);
 
@@ -217,6 +221,7 @@ again:
 		} else
 			tsk->signal->it_real_incr.tv64 = 0;
 
+		trace_itimer_state(ITIMER_REAL, value, 0);
 		spin_unlock_irq(&tsk->sighand->siglock);
 		break;
 	case ITIMER_VIRTUAL:
diff --git a/kernel/posix-cpu-timers.c b/kernel/posix-cpu-timers.c
index 12161f7..5c9dc22 100644
--- a/kernel/posix-cpu-timers.c
+++ b/kernel/posix-cpu-timers.c
@@ -8,6 +8,7 @@
 #include <linux/math64.h>
 #include <asm/uaccess.h>
 #include <linux/kernel_stat.h>
+#include <trace/events/timer.h>
 
 /*
  * Called after updating RLIMIT_CPU to set timer expiration if necessary.
@@ -1090,9 +1091,13 @@ static void check_cpu_itimer(struct task_struct *tsk, struct cpu_itimer *it,
 							  cputime_one_jiffy);
 				it->error -= onecputick;
 			}
-		} else
+		} else {
 			it->expires = cputime_zero;
+		}
 
+		trace_itimer_expire(signo == SIGPROF ?
+				    ITIMER_PROF : ITIMER_VIRTUAL,
+				    tsk->signal->leader_pid, cur_time);
 		__group_send_sig_info(signo, SEND_SIG_PRIV, tsk);
 	}
 

[tip:timers/tracing] timers: Add tracepoints for timer_list timers

[tip-bot for Xiao Guangrong]

Commit-ID:  2b022e3d4bf9885f781221c59d86283a2cdfc2ed
Gitweb:     http://git.kernel.org/tip/2b022e3d4bf9885f781221c59d86283a2cdfc2ed
Author:     Xiao Guangrong <xiaoguangrong@cn.fujitsu.com>
AuthorDate: Mon, 10 Aug 2009 10:48:59 +0800
Committer:  Thomas Gleixner <tglx@linutronix.de>
CommitDate: Sat, 29 Aug 2009 14:10:06 +0200

timers: Add tracepoints for timer_list timers

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

Based on patches from 
Mathieu: http://marc.info/?l=linux-kernel&m=123791201816247&w=2
and 
Anton: http://marc.info/?l=linux-kernel&m=124331396919301&w=2

[ tglx: Fixed timeout value in timer_start tracepoint, massaged
  comments and made the printk's more readable ]

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


---
 include/trace/events/timer.h |  137 ++++++++++++++++++++++++++++++++++++++++++
 kernel/timer.c               |   32 +++++++++-
 2 files changed, 165 insertions(+), 4 deletions(-)

diff --git a/include/trace/events/timer.h b/include/trace/events/timer.h
new file mode 100644
index 0000000..725892a
--- /dev/null
+++ b/include/trace/events/timer.h
@@ -0,0 +1,137 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM timer
+
+#if !defined(_TRACE_TIMER_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_TIMER_H
+
+#include <linux/tracepoint.h>
+#include <linux/timer.h>
+
+/**
+ * timer_init - called when the timer is initialized
+ * @timer:	pointer to struct timer_list
+ */
+TRACE_EVENT(timer_init,
+
+	TP_PROTO(struct timer_list *timer),
+
+	TP_ARGS(timer),
+
+	TP_STRUCT__entry(
+		__field( void *,	timer	)
+	),
+
+	TP_fast_assign(
+		__entry->timer	= timer;
+	),
+
+	TP_printk("timer %p", __entry->timer)
+);
+
+/**
+ * timer_start - called when the timer is started
+ * @timer:	pointer to struct timer_list
+ * @expires:	the timers expiry time
+ */
+TRACE_EVENT(timer_start,
+
+	TP_PROTO(struct timer_list *timer, unsigned long expires),
+
+	TP_ARGS(timer, expires),
+
+	TP_STRUCT__entry(
+		__field( void *,	timer		)
+		__field( void *,	function	)
+		__field( unsigned long,	expires		)
+		__field( unsigned long,	now		)
+	),
+
+	TP_fast_assign(
+		__entry->timer		= timer;
+		__entry->function	= timer->function;
+		__entry->expires	= expires;
+		__entry->now		= jiffies;
+	),
+
+	TP_printk("timer %p: func %pf, expires %lu, timeout %ld",
+		  __entry->timer, __entry->function, __entry->expires,
+		  (long)__entry->expires - __entry->now)
+);
+
+/**
+ * timer_expire_entry - called immediately before the timer callback
+ * @timer:	pointer to struct timer_list
+ *
+ * Allows to determine the timer latency.
+ */
+TRACE_EVENT(timer_expire_entry,
+
+	TP_PROTO(struct timer_list *timer),
+
+	TP_ARGS(timer),
+
+	TP_STRUCT__entry(
+		__field( void *,	timer	)
+		__field( unsigned long,	now	)
+	),
+
+	TP_fast_assign(
+		__entry->timer		= timer;
+		__entry->now		= jiffies;
+	),
+
+	TP_printk("timer %p: now %lu", __entry->timer, __entry->now)
+);
+
+/**
+ * timer_expire_exit - called immediately after the timer callback returns
+ * @timer:	pointer to struct timer_list
+ *
+ * When used in combination with the timer_expire_entry tracepoint we can
+ * determine the runtime of the timer callback function.
+ *
+ * NOTE: Do NOT derefernce timer in TP_fast_assign. The pointer might
+ * be invalid. We solely track the pointer.
+ */
+TRACE_EVENT(timer_expire_exit,
+
+	TP_PROTO(struct timer_list *timer),
+
+	TP_ARGS(timer),
+
+	TP_STRUCT__entry(
+		__field(void *,	timer	)
+	),
+
+	TP_fast_assign(
+		__entry->timer	= timer;
+	),
+
+	TP_printk("timer %p", __entry->timer)
+);
+
+/**
+ * timer_cancel - called when the timer is canceled
+ * @timer:	pointer to struct timer_list
+ */
+TRACE_EVENT(timer_cancel,
+
+	TP_PROTO(struct timer_list *timer),
+
+	TP_ARGS(timer),
+
+	TP_STRUCT__entry(
+		__field( void *,	timer	)
+	),
+
+	TP_fast_assign(
+		__entry->timer	= timer;
+	),
+
+	TP_printk("timer %p", __entry->timer)
+);
+
+#endif /*  _TRACE_TIMER_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
diff --git a/kernel/timer.c b/kernel/timer.c
index 8e92be6..a7352b0 100644
--- a/kernel/timer.c
+++ b/kernel/timer.c
@@ -46,6 +46,9 @@
 #include <asm/timex.h>
 #include <asm/io.h>
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/timer.h>
+
 u64 jiffies_64 __cacheline_aligned_in_smp = INITIAL_JIFFIES;
 
 EXPORT_SYMBOL(jiffies_64);
@@ -521,6 +524,25 @@ static inline void debug_timer_activate(struct timer_list *timer) { }
 static inline void debug_timer_deactivate(struct timer_list *timer) { }
 #endif
 
+static inline void debug_init(struct timer_list *timer)
+{
+	debug_timer_init(timer);
+	trace_timer_init(timer);
+}
+
+static inline void
+debug_activate(struct timer_list *timer, unsigned long expires)
+{
+	debug_timer_activate(timer);
+	trace_timer_start(timer, expires);
+}
+
+static inline void debug_deactivate(struct timer_list *timer)
+{
+	debug_timer_deactivate(timer);
+	trace_timer_cancel(timer);
+}
+
 static void __init_timer(struct timer_list *timer,
 			 const char *name,
 			 struct lock_class_key *key)
@@ -549,7 +571,7 @@ void init_timer_key(struct timer_list *timer,
 		    const char *name,
 		    struct lock_class_key *key)
 {
-	debug_timer_init(timer);
+	debug_init(timer);
 	__init_timer(timer, name, key);
 }
 EXPORT_SYMBOL(init_timer_key);
@@ -568,7 +590,7 @@ static inline void detach_timer(struct timer_list *timer,
 {
 	struct list_head *entry = &timer->entry;
 
-	debug_timer_deactivate(timer);
+	debug_deactivate(timer);
 
 	__list_del(entry->prev, entry->next);
 	if (clear_pending)
@@ -632,7 +654,7 @@ __mod_timer(struct timer_list *timer, unsigned long expires,
 			goto out_unlock;
 	}
 
-	debug_timer_activate(timer);
+	debug_activate(timer, expires);
 
 	new_base = __get_cpu_var(tvec_bases);
 
@@ -787,7 +809,7 @@ void add_timer_on(struct timer_list *timer, int cpu)
 	BUG_ON(timer_pending(timer) || !timer->function);
 	spin_lock_irqsave(&base->lock, flags);
 	timer_set_base(timer, base);
-	debug_timer_activate(timer);
+	debug_activate(timer, timer->expires);
 	if (time_before(timer->expires, base->next_timer) &&
 	    !tbase_get_deferrable(timer->base))
 		base->next_timer = timer->expires;
@@ -1000,7 +1022,9 @@ static inline void __run_timers(struct tvec_base *base)
 				 */
 				lock_map_acquire(&lockdep_map);
 
+				trace_timer_expire_entry(timer);
 				fn(data);
+				trace_timer_expire_exit(timer);
 
 				lock_map_release(&lockdep_map);