Skip to contentSkip to conversation

ftrace: add tracepoint for timer

PATCH In review Xiao Guangrong 5 participants 16 messages Aug 10, 2009 – Oct 13, 2009

Subsystems (2)
lore
Share & tools
lore
#0 lore raw

PATCH v6 1/3 ftrace: add tracepoint for timer

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

---
 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
include/trace/events/timer.h new file +134 -0
new file mode 100644
index 0000000..fcf65c7
@@ -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>
kernel/timer.c +28 -4
index 33fc9d1..22e2ada 100644
@@ -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);
 
Signature · 1 line
1.6.1.2
#1 lore raw

PATCH v6 2/3 ftrace: add tracepoint for hrtimer

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

---
 include/trace/events/timer.h |  133 ++++++++++++++++++++++++++++++++++++++++++
 kernel/hrtimer.c             |   34 +++++++++--
 2 files changed, 162 insertions(+), 5 deletions(-)
include/trace/events/timer.h +133 -0
index fcf65c7..6140f29 100644
@@ -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 */
kernel/hrtimer.c +29 -5
index e2f91ec..0cfec97 100644
@@ -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
Signature · 1 line
1.6.1.2
#2 lore raw

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

Commit-ID:  c6a2a1770245f654f35f60e1458d4356680f9519
Gitweb:     http://git.kernel.org/tip/c6a2a1770245f654f35f60e1458d4356680f9519
Author:     Xiao Guangrong <[email protected]>
AuthorDate: Mon, 10 Aug 2009 10:51:23 +0800
Committer:  Thomas Gleixner <[email protected]>
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. ]

Cc Steven Rostedt <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Cc Mathieu Desnoyers <[email protected]>
Cc Anton Blanchard <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc KOSAKI Motohiro <[email protected]>
Cc Zhaolei <[email protected]>

LKML-Reference: <[email protected]>

---
 include/trace/events/timer.h |  139 ++++++++++++++++++++++++++++++++++++++++++
 kernel/hrtimer.c             |   40 ++++++++++---
 2 files changed, 171 insertions(+), 8 deletions(-)
include/trace/events/timer.h +139 -0
index 725892a..df3c07f 100644
@@ -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 */
kernel/hrtimer.c +32 -8
index e2f91ec..b44d1b0 100644
@@ -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
maintainer
#3 lore raw

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

Quoted 22 lines · tip-bot for Xiao Guangrong
include/trace/events/timer.h +22 -0
+/**
+ * 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;

include/trace/events/timer.h TRACE_EVENT(timer_cancel, · line 198

Quoted 10 lines
include/trace/events/timer.h +10 -0
+	),
+
+	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

#4 lore raw

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

Quoted 41 lines · Steven Rostedt
Quoted 22 lines · tip-bot for Xiao Guangrong
include/trace/events/timer.h +22 -0
+/**
+ * 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;

include/trace/events/timer.h TRACE_EVENT(timer_cancel, · line 198

Quoted 10 lines
include/trace/events/timer.h +10 -0
+	),
+
+	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)

Quoted 7 lines

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

maintainer
#5 lore raw

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

Quoted 10 lines · Ingo Molnar
Quoted 3 lines · Steven Rostedt

(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

maintainer
#6 lore raw

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

Quoted 8 lines · Steven Rostedt
Quoted 7 lines · Ingo Molnar
Quoted 3 lines · Steven Rostedt

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

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

Quoted 7 lines
Quoted 3 lines

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

#7 lore raw

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

In reply to Steven Rostedt
Quoted 8 lines · Steven Rostedt
Quoted 7 lines · Ingo Molnar
Quoted 3 lines · Steven Rostedt

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

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

Quoted 7 lines
Quoted 3 lines

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

maintainer
#8 lore raw

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

Quoted 14 lines · Ingo Molnar
Quoted 12 lines · Steven Rostedt
Quoted 10 lines · Ingo Molnar
Quoted 3 lines · Steven Rostedt

(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.

Quoted 5 lines
Quoted 3 lines

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

#9 lore raw

[RFC] Trace types registry

Quoted 24 lines · * Steven Rostedt ([email protected]) wrote:
Quoted 14 lines · Ingo Molnar
Quoted 12 lines · Steven Rostedt
Quoted 10 lines · Ingo Molnar
Quoted 3 lines · Steven Rostedt

(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.

Quoted 5 lines
Quoted 3 lines

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.

Quoted 8 lines

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

Signature · 2 lines
Mathieu Desnoyers
OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F  BA06 3F25 A8FE 3BAE 9A68
#10 lore raw

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

In reply to Steven Rostedt
Quoted 19 lines · Steven Rostedt
Quoted 18 lines · Ingo Molnar
Quoted 15 lines · Steven Rostedt
Quoted 10 lines · Ingo Molnar
Quoted 3 lines · Steven Rostedt

(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.

Quoted 8 lines
Quoted 1 line

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

maintainer
#11 lore raw

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

Quoted 7 lines · Ingo Molnar
Quoted 3 lines

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

#12 lore raw

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

In reply to Steven Rostedt
Quoted 19 lines · Steven Rostedt

include/trace/events/timer.h TRACE_EVENT(timer_cancel, · line 198

Quoted 8 lines
include/trace/events/timer.h +8 -0
+     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:

Quoted 6 lines

(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
};
#13 lore raw

PATCH v6 3/3 ftrace: add tracepoint for itimer

In reply to 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

---
 include/trace/events/timer.h |   65 ++++++++++++++++++++++++++++++++++++++++++
 kernel/itimer.c              |    5 +++
 kernel/posix-cpu-timers.c    |    3 ++
 3 files changed, 73 insertions(+), 0 deletions(-)
include/trace/events/timer.h +65 -0
index 6140f29..fbbead9 100644
@@ -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 */
kernel/itimer.c +5 -0
index 8078a32..a3ceb34 100644
@@ -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:
kernel/posix-cpu-timers.c +3 -0
index 12161f7..14798a7 100644
@@ -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);
 	}
 
Signature · 1 line
1.6.1.2
#14 lore raw

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

Commit-ID:  3f0a525ebf4b8ef041a332bbe4a73aee94bb064b
Gitweb:     http://git.kernel.org/tip/3f0a525ebf4b8ef041a332bbe4a73aee94bb064b
Author:     Xiao Guangrong <[email protected]>
AuthorDate: Mon, 10 Aug 2009 10:52:30 +0800
Committer:  Thomas Gleixner <[email protected]>
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 ]

Cc Steven Rostedt <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Cc Mathieu Desnoyers <[email protected]>
Cc Anton Blanchard <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc KOSAKI Motohiro <[email protected]>
Cc Zhaolei <[email protected]>

LKML-Reference: <[email protected]>

---
 include/trace/events/timer.h |   66 ++++++++++++++++++++++++++++++++++++++++++
 kernel/itimer.c              |    5 +++
 kernel/posix-cpu-timers.c    |    7 ++++-
 3 files changed, 77 insertions(+), 1 deletions(-)
include/trace/events/timer.h +66 -0
index df3c07f..1844c48 100644
@@ -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 */
kernel/itimer.c +5 -0
index 8078a32..b03451e 100644
@@ -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:
kernel/posix-cpu-timers.c +6 -1
index 12161f7..5c9dc22 100644
@@ -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);
 	}
 
#15 lore raw

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

In reply to Xiao Guangrong
Commit-ID:  2b022e3d4bf9885f781221c59d86283a2cdfc2ed
Gitweb:     http://git.kernel.org/tip/2b022e3d4bf9885f781221c59d86283a2cdfc2ed
Author:     Xiao Guangrong <[email protected]>
AuthorDate: Mon, 10 Aug 2009 10:48:59 +0800
Committer:  Thomas Gleixner <[email protected]>
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 ]

Cc Anton Blanchard <[email protected]>
Cc Steven Rostedt <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Cc Mathieu Desnoyers <[email protected]>
Cc Peter Zijlstra <[email protected]>
Cc KOSAKI Motohiro <[email protected]>
Cc Zhaolei <[email protected]>

LKML-Reference: <[email protected]>

---
 include/trace/events/timer.h |  137 ++++++++++++++++++++++++++++++++++++++++++
 kernel/timer.c               |   32 +++++++++-
 2 files changed, 165 insertions(+), 4 deletions(-)
include/trace/events/timer.h new file +137 -0
new file mode 100644
index 0000000..725892a
@@ -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>
kernel/timer.c +28 -4
index 8e92be6..a7352b0 100644
@@ -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);