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>

diff --git a/include/trace/events/timer.h b/include/trace/events/timer.h
index 425bcfe56c620211678d94f6d3923a9451305db2..f5eb53eb658fbd98a161c3a603492191a3907583 100644 (file)
--- a/include/trace/events/timer.h
+++ b/include/trace/events/timer.h
@@ -323,6 +323,27 @@ TRACE_EVENT(itimer_expire,
                  (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 */

diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
index 12a900dbb819d20ca42cac3318e0d54f6ef3ddf5..85e05ab9825388d9a5dc4dfe3c6f2a74077dce43 100644 (file)
--- a/kernel/time/tick-sched.c
+++ b/kernel/time/tick-sched.c
@@ -28,6 +28,8 @@
 
 #include "tick-internal.h"
 
+#include <trace/events/timer.h>
+
 /*
  * Per cpu nohz control structure
  */
@@ -153,14 +155,20 @@ static bool can_stop_full_tick(void)
 {
        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 @@ static bool can_stop_full_tick(void)
         * 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 @@ static ktime_t tick_nohz_stop_sched_tick(struct tick_sched *ts,
 
                        ts->last_tick = hrtimer_get_expires(&ts->sched_timer);
                        ts->tick_stopped = 1;
+                       trace_tick_stop(1, " ");
                }
 
                /*