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>

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>
Xiao Guangrong · Thomas Gleixner
1 parent f71bb0ac5e
Showing 2 changed files with 165 additions and 4 deletions Side-by-side Diff
include/trace/events/timer.h
kernel/timer.c
+#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>
@@ -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_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 @@
 		    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 @@
 {
 	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 @@
 			goto out_unlock;
 	}
  
-	debug_timer_activate(timer);
+	debug_activate(timer, expires);
  
 	new_base = __get_cpu_var(tvec_bases);
  
@@ -787,7 +809,7 @@
 	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 @@
 				 */
 				lock_map_acquire(&lockdep_map);
  
+				trace_timer_expire_entry(timer);
 				fn(data);
+				trace_timer_expire_exit(timer);
  
 				lock_map_release(&lockdep_map);
	1	+#undef TRACE_SYSTEM
	2	+#define TRACE_SYSTEM timer
	3	+
	4	+#if !defined(_TRACE_TIMER_H) \|\| defined(TRACE_HEADER_MULTI_READ)
	5	+#define _TRACE_TIMER_H
	6	+
	7	+#include <linux/tracepoint.h>
	8	+#include <linux/timer.h>
	9	+
	10	+/**
	11	+ * timer_init - called when the timer is initialized
	12	+ * @timer: pointer to struct timer_list
	13	+ */
	14	+TRACE_EVENT(timer_init,
	15	+
	16	+ TP_PROTO(struct timer_list *timer),
	17	+
	18	+ TP_ARGS(timer),
	19	+
	20	+ TP_STRUCT__entry(
	21	+ __field( void *, timer )
	22	+ ),
	23	+
	24	+ TP_fast_assign(
	25	+ __entry->timer = timer;
	26	+ ),
	27	+
	28	+ TP_printk("timer %p", __entry->timer)
	29	+);
	30	+
	31	+/**
	32	+ * timer_start - called when the timer is started
	33	+ * @timer: pointer to struct timer_list
	34	+ * @expires: the timers expiry time
	35	+ */
	36	+TRACE_EVENT(timer_start,
	37	+
	38	+ TP_PROTO(struct timer_list *timer, unsigned long expires),
	39	+
	40	+ TP_ARGS(timer, expires),
	41	+
	42	+ TP_STRUCT__entry(
	43	+ __field( void *, timer )
	44	+ __field( void *, function )
	45	+ __field( unsigned long, expires )
	46	+ __field( unsigned long, now )
	47	+ ),
	48	+
	49	+ TP_fast_assign(
	50	+ __entry->timer = timer;
	51	+ __entry->function = timer->function;
	52	+ __entry->expires = expires;
	53	+ __entry->now = jiffies;
	54	+ ),
	55	+
	56	+ TP_printk("timer %p: func %pf, expires %lu, timeout %ld",
	57	+ __entry->timer, __entry->function, __entry->expires,
	58	+ (long)__entry->expires - __entry->now)
	59	+);
	60	+
	61	+/**
	62	+ * timer_expire_entry - called immediately before the timer callback
	63	+ * @timer: pointer to struct timer_list
	64	+ *
	65	+ * Allows to determine the timer latency.
	66	+ */
	67	+TRACE_EVENT(timer_expire_entry,
	68	+
	69	+ TP_PROTO(struct timer_list *timer),
	70	+
	71	+ TP_ARGS(timer),
	72	+
	73	+ TP_STRUCT__entry(
	74	+ __field( void *, timer )
	75	+ __field( unsigned long, now )
	76	+ ),
	77	+
	78	+ TP_fast_assign(
	79	+ __entry->timer = timer;
	80	+ __entry->now = jiffies;
	81	+ ),
	82	+
	83	+ TP_printk("timer %p: now %lu", __entry->timer, __entry->now)
	84	+);
	85	+
	86	+/**
	87	+ * timer_expire_exit - called immediately after the timer callback returns
	88	+ * @timer: pointer to struct timer_list
	89	+ *
	90	+ * When used in combination with the timer_expire_entry tracepoint we can
	91	+ * determine the runtime of the timer callback function.
	92	+ *
	93	+ * NOTE: Do NOT derefernce timer in TP_fast_assign. The pointer might
	94	+ * be invalid. We solely track the pointer.
	95	+ */
	96	+TRACE_EVENT(timer_expire_exit,
	97	+
	98	+ TP_PROTO(struct timer_list *timer),
	99	+
	100	+ TP_ARGS(timer),
	101	+
	102	+ TP_STRUCT__entry(
	103	+ __field(void *, timer )
	104	+ ),
	105	+
	106	+ TP_fast_assign(
	107	+ __entry->timer = timer;
	108	+ ),
	109	+
	110	+ TP_printk("timer %p", __entry->timer)
	111	+);
	112	+
	113	+/**
	114	+ * timer_cancel - called when the timer is canceled
	115	+ * @timer: pointer to struct timer_list
	116	+ */
	117	+TRACE_EVENT(timer_cancel,
	118	+
	119	+ TP_PROTO(struct timer_list *timer),
	120	+
	121	+ TP_ARGS(timer),
	122	+
	123	+ TP_STRUCT__entry(
	124	+ __field( void *, timer )
	125	+ ),
	126	+
	127	+ TP_fast_assign(
	128	+ __entry->timer = timer;
	129	+ ),
	130	+
	131	+ TP_printk("timer %p", __entry->timer)
	132	+);
	133	+
	134	+#endif /* _TRACE_TIMER_H */
	135	+
	136	+/* This part must be outside protection */
	137	+#include <trace/define_trace.h>
...	...	@@ -46,6 +46,9 @@
46	46	#include <asm/timex.h>
47	47	#include <asm/io.h>
48	48
	49	+#define CREATE_TRACE_POINTS
	50	+#include <trace/events/timer.h>
	51	+
49	52	u64 jiffies_64 __cacheline_aligned_in_smp = INITIAL_JIFFIES;
50	53
51	54	EXPORT_SYMBOL(jiffies_64);
...	...	@@ -521,6 +524,25 @@
521	524	static inline void debug_timer_deactivate(struct timer_list *timer) { }
522	525	#endif
523	526
	527	+static inline void debug_init(struct timer_list *timer)
	528	+{
	529	+ debug_timer_init(timer);
	530	+ trace_timer_init(timer);
	531	+}
	532	+
	533	+static inline void
	534	+debug_activate(struct timer_list *timer, unsigned long expires)
	535	+{
	536	+ debug_timer_activate(timer);
	537	+ trace_timer_start(timer, expires);
	538	+}
	539	+
	540	+static inline void debug_deactivate(struct timer_list *timer)
	541	+{
	542	+ debug_timer_deactivate(timer);
	543	+ trace_timer_cancel(timer);
	544	+}
	545	+
524	546	static void __init_timer(struct timer_list *timer,
525	547	const char *name,
526	548	struct lock_class_key *key)
...	...	@@ -549,7 +571,7 @@
549	571	const char *name,
550	572	struct lock_class_key *key)
551	573	{
552		- debug_timer_init(timer);
	574	+ debug_init(timer);
553	575	__init_timer(timer, name, key);
554	576	}
555	577	EXPORT_SYMBOL(init_timer_key);
...	...	@@ -568,7 +590,7 @@
568	590	{
569	591	struct list_head *entry = &timer->entry;
570	592
571		- debug_timer_deactivate(timer);
	593	+ debug_deactivate(timer);
572	594
573	595	__list_del(entry->prev, entry->next);
574	596	if (clear_pending)
...	...	@@ -632,7 +654,7 @@
632	654	goto out_unlock;
633	655	}
634	656
635		- debug_timer_activate(timer);
	657	+ debug_activate(timer, expires);
636	658
637	659	new_base = __get_cpu_var(tvec_bases);
638	660
...	...	@@ -787,7 +809,7 @@
787	809	BUG_ON(timer_pending(timer) \|\| !timer->function);
788	810	spin_lock_irqsave(&base->lock, flags);
789	811	timer_set_base(timer, base);
790		- debug_timer_activate(timer);
	812	+ debug_activate(timer, timer->expires);
791	813	if (time_before(timer->expires, base->next_timer) &&
792	814	!tbase_get_deferrable(timer->base))
793	815	base->next_timer = timer->expires;
794	816
...	...	@@ -1000,7 +1022,9 @@
1000	1022	*/
1001	1023	lock_map_acquire(&lockdep_map);
1002	1024
	1025	+ trace_timer_expire_entry(timer);
1003	1026	fn(data);
	1027	+ trace_timer_expire_exit(timer);
1004	1028
1005	1029	lock_map_release(&lockdep_map);
1006	1030