nohz: Add basic tracing

It's not obvious to find out why the full dynticks subsystem doesn't always stop the tick: whether this is due to kthreads, posix timers, perf events, etc... These new tracepoints are here to help the user diagnose the failures and test this feature. Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com> Cc: Chris Metcalf <cmetcalf@tilera.com> Cc: Christoph Lameter <cl@linux.com> Cc: Geoff Levand <geoff@infradead.org> Cc: Gilad Ben Yossef <gilad@benyossef.com> Cc: Hakan Akkan <hakanakkan@gmail.com> Cc: Ingo Molnar <mingo@kernel.org> Cc: Kevin Hilman <khilman@linaro.org> Cc: Li Zhong <zhong@linux.vnet.ibm.com> Cc: Oleg Nesterov <oleg@redhat.com> Cc: Paul E. McKenney <paulmck@linux.vnet.ibm.com> Cc: Paul Gortmaker <paul.gortmaker@windriver.com> Cc: Peter Zijlstra <peterz@infradead.org> Cc: Steven Rostedt <rostedt@goodmis.org> Cc: Thomas Gleixner <tglx@linutronix.de>

nohz: Add basic tracing
It's not obvious to find out why the full dynticks subsystem doesn't always stop the tick: whether this is due to kthreads, posix timers, perf events, etc... These new tracepoints are here to help the user diagnose the failures and test this feature. Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com> Cc: Chris Metcalf <cmetcalf@tilera.com> Cc: Christoph Lameter <cl@linux.com> Cc: Geoff Levand <geoff@infradead.org> Cc: Gilad Ben Yossef <gilad@benyossef.com> Cc: Hakan Akkan <hakanakkan@gmail.com> Cc: Ingo Molnar <mingo@kernel.org> Cc: Kevin Hilman <khilman@linaro.org> Cc: Li Zhong <zhong@linux.vnet.ibm.com> Cc: Oleg Nesterov <oleg@redhat.com> Cc: Paul E. McKenney <paulmck@linux.vnet.ibm.com> Cc: Paul Gortmaker <paul.gortmaker@windriver.com> Cc: Peter Zijlstra <peterz@infradead.org> Cc: Steven Rostedt <rostedt@goodmis.org> Cc: Thomas Gleixner <tglx@linutronix.de>
Frederic Weisbecker
1 parent 0637e02939
Showing 2 changed files with 36 additions and 4 deletions Side-by-side Diff
include/trace/events/timer.h
kernel/time/tick-sched.c
@@ -323,6 +323,27 @@
 		  (int) __entry->pid, (unsigned long long)__entry->now)
 );
  
+#ifdef CONFIG_NO_HZ_FULL
+TRACE_EVENT(tick_stop,
+
+	TP_PROTO(int success, char *error_msg),
+
+	TP_ARGS(success, error_msg),
+
+	TP_STRUCT__entry(
+		__field( int ,		success	)
+		__string( msg, 		error_msg )
+	),
+
+	TP_fast_assign(
+		__entry->success	= success;
+		__assign_str(msg, error_msg);
+	),
+
+	TP_printk("success=%s msg=%s",  __entry->success ? "yes" : "no", __get_str(msg))
+);
+#endif
+
 #endif /*  _TRACE_TIMER_H */
  
 /* This part must be outside protection */
@@ -28,6 +28,8 @@
  
 #include "tick-internal.h"
  
+#include <trace/events/timer.h>
+
 /*
  * Per cpu nohz control structure
  */
  
  
  
  
  
@@ -153,14 +155,20 @@
 {
 	WARN_ON_ONCE(!irqs_disabled());
  
-	if (!sched_can_stop_tick())
+	if (!sched_can_stop_tick()) {
+		trace_tick_stop(0, "more than 1 task in runqueue\n");
 		return false;
+	}
  
-	if (!posix_cpu_timers_can_stop_tick(current))
+	if (!posix_cpu_timers_can_stop_tick(current)) {
+		trace_tick_stop(0, "posix timers running\n");
 		return false;
+	}
  
-	if (!perf_event_can_stop_tick())
+	if (!perf_event_can_stop_tick()) {
+		trace_tick_stop(0, "perf events running\n");
 		return false;
+	}
  
 	/* sched_clock_tick() needs us? */
 #ifdef CONFIG_HAVE_UNSTABLE_SCHED_CLOCK
  
@@ -168,8 +176,10 @@
 	 * TODO: kick full dynticks CPUs when
 	 * sched_clock_stable is set.
 	 */
-	if (!sched_clock_stable)
+	if (!sched_clock_stable) {
+		trace_tick_stop(0, "unstable sched clock\n");
 		return false;
+	}
 #endif
  
 	return true;
@@ -631,6 +641,7 @@
  
 			ts->last_tick = hrtimer_get_expires(&ts->sched_timer);
 			ts->tick_stopped = 1;
+			trace_tick_stop(1, " ");
 		}
  
 		/*
...	...	@@ -323,6 +323,27 @@
323	323	(int) __entry->pid, (unsigned long long)__entry->now)
324	324	);
325	325
	326	+#ifdef CONFIG_NO_HZ_FULL
	327	+TRACE_EVENT(tick_stop,
	328	+
	329	+ TP_PROTO(int success, char *error_msg),
	330	+
	331	+ TP_ARGS(success, error_msg),
	332	+
	333	+ TP_STRUCT__entry(
	334	+ __field( int , success )
	335	+ __string( msg, error_msg )
	336	+ ),
	337	+
	338	+ TP_fast_assign(
	339	+ __entry->success = success;
	340	+ __assign_str(msg, error_msg);
	341	+ ),
	342	+
	343	+ TP_printk("success=%s msg=%s", __entry->success ? "yes" : "no", __get_str(msg))
	344	+);
	345	+#endif
	346	+
326	347	#endif /* _TRACE_TIMER_H */
327	348
328	349	/* This part must be outside protection */
...	...	@@ -28,6 +28,8 @@
28	28
29	29	#include "tick-internal.h"
30	30
	31	+#include <trace/events/timer.h>
	32	+
31	33	/*
32	34	* Per cpu nohz control structure
33	35	*/
34	36
35	37
36	38
37	39
38	40
...	...	@@ -153,14 +155,20 @@
153	155	{
154	156	WARN_ON_ONCE(!irqs_disabled());
155	157
156		- if (!sched_can_stop_tick())
	158	+ if (!sched_can_stop_tick()) {
	159	+ trace_tick_stop(0, "more than 1 task in runqueue\n");
157	160	return false;
	161	+ }
158	162
159		- if (!posix_cpu_timers_can_stop_tick(current))
	163	+ if (!posix_cpu_timers_can_stop_tick(current)) {
	164	+ trace_tick_stop(0, "posix timers running\n");
160	165	return false;
	166	+ }
161	167
162		- if (!perf_event_can_stop_tick())
	168	+ if (!perf_event_can_stop_tick()) {
	169	+ trace_tick_stop(0, "perf events running\n");
163	170	return false;
	171	+ }
164	172
165	173	/* sched_clock_tick() needs us? */
166	174	#ifdef CONFIG_HAVE_UNSTABLE_SCHED_CLOCK
167	175
...	...	@@ -168,8 +176,10 @@
168	176	* TODO: kick full dynticks CPUs when
169	177	* sched_clock_stable is set.
170	178	*/
171		- if (!sched_clock_stable)
	179	+ if (!sched_clock_stable) {
	180	+ trace_tick_stop(0, "unstable sched clock\n");
172	181	return false;
	182	+ }
173	183	#endif
174	184
175	185	return true;
...	...	@@ -631,6 +641,7 @@
631	641
632	642	ts->last_tick = hrtimer_get_expires(&ts->sched_timer);
633	643	ts->tick_stopped = 1;
	644	+ trace_tick_stop(1, " ");
634	645	}
635	646
636	647	/*