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>

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>
Xiao Guangrong · Thomas Gleixner
1 parent 2b022e3d4b
Showing 2 changed files with 171 additions and 8 deletions Side-by-side Diff
include/trace/events/timer.h
kernel/hrtimer.c
@@ -5,6 +5,7 @@
 #define _TRACE_TIMER_H
  
 #include <linux/tracepoint.h>
+#include <linux/hrtimer.h>
 #include <linux/timer.h>
  
 /**
@@ -129,6 +130,144 @@
 	),
  
 	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 */
@@ -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_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 @@
 	struct hrtimer *entry;
 	int leftmost = 1;
  
-	debug_hrtimer_activate(timer);
+	debug_activate(timer);
  
 	/*
 	 * Find the right place in the rbtree:
@@ -883,7 +905,7 @@
 		 * 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 @@
 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 @@
 }
 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 @@
  
 	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 @@
 	 * 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 @@
 				break;
 			}
  
-			__run_hrtimer(timer);
+			__run_hrtimer(timer, &basenow);
 		}
 		base++;
 	}
@@ -1393,7 +1417,7 @@
 					hrtimer_get_expires_tv64(timer))
 				break;
  
-			__run_hrtimer(timer);
+			__run_hrtimer(timer, &base->softirq_time);
 		}
 		spin_unlock(&cpu_base->lock);
 	}
@@ -1569,7 +1593,7 @@
 	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
...	...	@@ -5,6 +5,7 @@
5	5	#define _TRACE_TIMER_H
6	6
7	7	#include <linux/tracepoint.h>
	8	+#include <linux/hrtimer.h>
8	9	#include <linux/timer.h>
9	10
10	11	/**
...	...	@@ -129,6 +130,144 @@
129	130	),
130	131
131	132	TP_printk("timer %p", __entry->timer)
	133	+);
	134	+
	135	+/**
	136	+ * hrtimer_init - called when the hrtimer is initialized
	137	+ * @timer: pointer to struct hrtimer
	138	+ * @clockid: the hrtimers clock
	139	+ * @mode: the hrtimers mode
	140	+ */
	141	+TRACE_EVENT(hrtimer_init,
	142	+
	143	+ TP_PROTO(struct hrtimer *timer, clockid_t clockid,
	144	+ enum hrtimer_mode mode),
	145	+
	146	+ TP_ARGS(timer, clockid, mode),
	147	+
	148	+ TP_STRUCT__entry(
	149	+ __field( void *, timer )
	150	+ __field( clockid_t, clockid )
	151	+ __field( enum hrtimer_mode, mode )
	152	+ ),
	153	+
	154	+ TP_fast_assign(
	155	+ __entry->timer = timer;
	156	+ __entry->clockid = clockid;
	157	+ __entry->mode = mode;
	158	+ ),
	159	+
	160	+ TP_printk("hrtimer %p, clockid %s, mode %s", __entry->timer,
	161	+ __entry->clockid == CLOCK_REALTIME ?
	162	+ "CLOCK_REALTIME" : "CLOCK_MONOTONIC",
	163	+ __entry->mode == HRTIMER_MODE_ABS ?
	164	+ "HRTIMER_MODE_ABS" : "HRTIMER_MODE_REL")
	165	+);
	166	+
	167	+/**
	168	+ * hrtimer_start - called when the hrtimer is started
	169	+ * @timer: pointer to struct hrtimer
	170	+ */
	171	+TRACE_EVENT(hrtimer_start,
	172	+
	173	+ TP_PROTO(struct hrtimer *timer),
	174	+
	175	+ TP_ARGS(timer),
	176	+
	177	+ TP_STRUCT__entry(
	178	+ __field( void *, timer )
	179	+ __field( void *, function )
	180	+ __field( s64, expires )
	181	+ __field( s64, softexpires )
	182	+ ),
	183	+
	184	+ TP_fast_assign(
	185	+ __entry->timer = timer;
	186	+ __entry->function = timer->function;
	187	+ __entry->expires = hrtimer_get_expires(timer).tv64;
	188	+ __entry->softexpires = hrtimer_get_softexpires(timer).tv64;
	189	+ ),
	190	+
	191	+ TP_printk("hrtimer %p, func %pf, expires %llu, softexpires %llu",
	192	+ __entry->timer, __entry->function,
	193	+ (unsigned long long)ktime_to_ns((ktime_t) {
	194	+ .tv64 = __entry->expires }),
	195	+ (unsigned long long)ktime_to_ns((ktime_t) {
	196	+ .tv64 = __entry->softexpires }))
	197	+);
	198	+
	199	+/**
	200	+ * htimmer_expire_entry - called immediately before the hrtimer callback
	201	+ * @timer: pointer to struct hrtimer
	202	+ * @now: pointer to variable which contains current time of the
	203	+ * timers base.
	204	+ *
	205	+ * Allows to determine the timer latency.
	206	+ */
	207	+TRACE_EVENT(hrtimer_expire_entry,
	208	+
	209	+ TP_PROTO(struct hrtimer timer, ktime_t now),
	210	+
	211	+ TP_ARGS(timer, now),
	212	+
	213	+ TP_STRUCT__entry(
	214	+ __field( void *, timer )
	215	+ __field( s64, now )
	216	+ ),
	217	+
	218	+ TP_fast_assign(
	219	+ __entry->timer = timer;
	220	+ __entry->now = now->tv64;
	221	+ ),
	222	+
	223	+ TP_printk("hrtimer %p, now %llu", __entry->timer,
	224	+ (unsigned long long)ktime_to_ns((ktime_t) {
	225	+ .tv64 = __entry->now }))
	226	+ );
	227	+
	228	+/**
	229	+ * hrtimer_expire_exit - called immediately after the hrtimer callback returns
	230	+ * @timer: pointer to struct hrtimer
	231	+ *
	232	+ * When used in combination with the hrtimer_expire_entry tracepoint we can
	233	+ * determine the runtime of the callback function.
	234	+ */
	235	+TRACE_EVENT(hrtimer_expire_exit,
	236	+
	237	+ TP_PROTO(struct hrtimer *timer),
	238	+
	239	+ TP_ARGS(timer),
	240	+
	241	+ TP_STRUCT__entry(
	242	+ __field( void *, timer )
	243	+ ),
	244	+
	245	+ TP_fast_assign(
	246	+ __entry->timer = timer;
	247	+ ),
	248	+
	249	+ TP_printk("hrtimer %p", __entry->timer)
	250	+);
	251	+
	252	+/**
	253	+ * hrtimer_cancel - called when the hrtimer is canceled
	254	+ * @timer: pointer to struct hrtimer
	255	+ */
	256	+TRACE_EVENT(hrtimer_cancel,
	257	+
	258	+ TP_PROTO(struct hrtimer *timer),
	259	+
	260	+ TP_ARGS(timer),
	261	+
	262	+ TP_STRUCT__entry(
	263	+ __field( void *, timer )
	264	+ ),
	265	+
	266	+ TP_fast_assign(
	267	+ __entry->timer = timer;
	268	+ ),
	269	+
	270	+ TP_printk("hrtimer %p", __entry->timer)
132	271	);
133	272
134	273	#endif /* _TRACE_TIMER_H */
...	...	@@ -48,6 +48,8 @@
48	48
49	49	#include <asm/uaccess.h>
50	50
	51	+#include <trace/events/timer.h>
	52	+
51	53	/*
52	54	* The timer bases:
53	55	*
...	...	@@ -441,6 +443,26 @@
441	443	static inline void debug_hrtimer_deactivate(struct hrtimer *timer) { }
442	444	#endif
443	445
	446	+static inline void
	447	+debug_init(struct hrtimer *timer, clockid_t clockid,
	448	+ enum hrtimer_mode mode)
	449	+{
	450	+ debug_hrtimer_init(timer);
	451	+ trace_hrtimer_init(timer, clockid, mode);
	452	+}
	453	+
	454	+static inline void debug_activate(struct hrtimer *timer)
	455	+{
	456	+ debug_hrtimer_activate(timer);
	457	+ trace_hrtimer_start(timer);
	458	+}
	459	+
	460	+static inline void debug_deactivate(struct hrtimer *timer)
	461	+{
	462	+ debug_hrtimer_deactivate(timer);
	463	+ trace_hrtimer_cancel(timer);
	464	+}
	465	+
444	466	/* High resolution timer related functions */
445	467	#ifdef CONFIG_HIGH_RES_TIMERS
446	468
...	...	@@ -797,7 +819,7 @@
797	819	struct hrtimer *entry;
798	820	int leftmost = 1;
799	821
800		- debug_hrtimer_activate(timer);
	822	+ debug_activate(timer);
801	823
802	824	/*
803	825	* Find the right place in the rbtree:
...	...	@@ -883,7 +905,7 @@
883	905	* reprogramming happens in the interrupt handler. This is a
884	906	* rare case and less expensive than a smp call.
885	907	*/
886		- debug_hrtimer_deactivate(timer);
	908	+ debug_deactivate(timer);
887	909	timer_stats_hrtimer_clear_start_info(timer);
888	910	reprogram = base->cpu_base == &__get_cpu_var(hrtimer_bases);
889	911	__remove_hrtimer(timer, base, HRTIMER_STATE_INACTIVE,
...	...	@@ -1116,7 +1138,7 @@
1116	1138	void hrtimer_init(struct hrtimer *timer, clockid_t clock_id,
1117	1139	enum hrtimer_mode mode)
1118	1140	{
1119		- debug_hrtimer_init(timer);
	1141	+ debug_init(timer, clock_id, mode);
1120	1142	__hrtimer_init(timer, clock_id, mode);
1121	1143	}
1122	1144	EXPORT_SYMBOL_GPL(hrtimer_init);
...	...	@@ -1140,7 +1162,7 @@
1140	1162	}
1141	1163	EXPORT_SYMBOL_GPL(hrtimer_get_res);
1142	1164
1143		-static void __run_hrtimer(struct hrtimer *timer)
	1165	+static void __run_hrtimer(struct hrtimer timer, ktime_t now)
1144	1166	{
1145	1167	struct hrtimer_clock_base *base = timer->base;
1146	1168	struct hrtimer_cpu_base *cpu_base = base->cpu_base;
...	...	@@ -1149,7 +1171,7 @@
1149	1171
1150	1172	WARN_ON(!irqs_disabled());
1151	1173
1152		- debug_hrtimer_deactivate(timer);
	1174	+ debug_deactivate(timer);
1153	1175	__remove_hrtimer(timer, base, HRTIMER_STATE_CALLBACK, 0);
1154	1176	timer_stats_account_hrtimer(timer);
1155	1177	fn = timer->function;
1156	1178
...	...	@@ -1160,7 +1182,9 @@
1160	1182	* the timer base.
1161	1183	*/
1162	1184	spin_unlock(&cpu_base->lock);
	1185	+ trace_hrtimer_expire_entry(timer, now);
1163	1186	restart = fn(timer);
	1187	+ trace_hrtimer_expire_exit(timer);
1164	1188	spin_lock(&cpu_base->lock);
1165	1189
1166	1190	/*
...	...	@@ -1271,7 +1295,7 @@
1271	1295	break;
1272	1296	}
1273	1297
1274		- __run_hrtimer(timer);
	1298	+ __run_hrtimer(timer, &basenow);
1275	1299	}
1276	1300	base++;
1277	1301	}
...	...	@@ -1393,7 +1417,7 @@
1393	1417	hrtimer_get_expires_tv64(timer))
1394	1418	break;
1395	1419
1396		- __run_hrtimer(timer);
	1420	+ __run_hrtimer(timer, &base->softirq_time);
1397	1421	}
1398	1422	spin_unlock(&cpu_base->lock);
1399	1423	}
...	...	@@ -1569,7 +1593,7 @@
1569	1593	while ((node = rb_first(&old_base->active))) {
1570	1594	timer = rb_entry(node, struct hrtimer, node);
1571	1595	BUG_ON(hrtimer_callback_running(timer));
1572		- debug_hrtimer_deactivate(timer);
	1596	+ debug_deactivate(timer);
1573	1597
1574	1598	/*
1575	1599	* Mark it as STATE_MIGRATE not INACTIVE otherwise the