nohz: Use enum code for tick stop failure tracing message
authorFrederic Weisbecker <fweisbec@gmail.com>
Fri, 11 Dec 2015 02:27:25 +0000 (03:27 +0100)
committerFrederic Weisbecker <fweisbec@gmail.com>
Wed, 2 Mar 2016 15:42:15 +0000 (16:42 +0100)
It makes nohz tracing more lightweight, standard and easier to parse.

Examples:

       user_loop-2904  [007] d..1   517.701126: tick_stop: success=1 dependency=NONE
       user_loop-2904  [007] dn.1   518.021181: tick_stop: success=0 dependency=SCHED
    posix_timers-6142  [007] d..1  1739.027400: tick_stop: success=0 dependency=POSIX_TIMER
       user_loop-5463  [007] dN.1  1185.931939: tick_stop: success=0 dependency=PERF_EVENTS

Suggested-by: Peter Zijlstra <peterz@infradead.org>
Reviewed-by: Chris Metcalf <cmetcalf@ezchip.com>
Cc: Christoph Lameter <cl@linux.com>
Cc: Chris Metcalf <cmetcalf@ezchip.com>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Luiz Capitulino <lcapitulino@redhat.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Rik van Riel <riel@redhat.com>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Viresh Kumar <viresh.kumar@linaro.org>
Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
include/linux/tick.h
include/trace/events/timer.h
kernel/time/tick-sched.c

index d60e5df8ec28d5a0214fcb0121926303c0b68602..96d276a923bf72f5938d2c8d0c4a7dba95c1f198 100644 (file)
@@ -104,6 +104,7 @@ enum tick_dep_bits {
        TICK_DEP_BIT_CLOCK_UNSTABLE     = 3
 };
 
+#define TICK_DEP_MASK_NONE             0
 #define TICK_DEP_MASK_POSIX_TIMER      (1 << TICK_DEP_BIT_POSIX_TIMER)
 #define TICK_DEP_MASK_PERF_EVENTS      (1 << TICK_DEP_BIT_PERF_EVENTS)
 #define TICK_DEP_MASK_SCHED            (1 << TICK_DEP_BIT_SCHED)
index 073b9ac245ba0315f31a51f5df9f21bcdf2e9115..51440131d3372feb1f09b7139362db66119f0e2a 100644 (file)
@@ -328,23 +328,49 @@ TRACE_EVENT(itimer_expire,
 );
 
 #ifdef CONFIG_NO_HZ_COMMON
+
+#define TICK_DEP_NAMES                                 \
+               tick_dep_name(NONE)                     \
+               tick_dep_name(POSIX_TIMER)              \
+               tick_dep_name(PERF_EVENTS)              \
+               tick_dep_name(SCHED)                    \
+               tick_dep_name_end(CLOCK_UNSTABLE)
+
+#undef tick_dep_name
+#undef tick_dep_name_end
+
+#define tick_dep_name(sdep) TRACE_DEFINE_ENUM(TICK_DEP_MASK_##sdep);
+#define tick_dep_name_end(sdep)  TRACE_DEFINE_ENUM(TICK_DEP_MASK_##sdep);
+
+TICK_DEP_NAMES
+
+#undef tick_dep_name
+#undef tick_dep_name_end
+
+#define tick_dep_name(sdep) { TICK_DEP_MASK_##sdep, #sdep },
+#define tick_dep_name_end(sdep) { TICK_DEP_MASK_##sdep, #sdep }
+
+#define show_tick_dep_name(val)                                \
+       __print_symbolic(val, TICK_DEP_NAMES)
+
 TRACE_EVENT(tick_stop,
 
-       TP_PROTO(int success, char *error_msg),
+       TP_PROTO(int success, int dependency),
 
-       TP_ARGS(success, error_msg),
+       TP_ARGS(success, dependency),
 
        TP_STRUCT__entry(
                __field( int ,          success )
-               __string( msg,          error_msg )
+               __field( int ,          dependency )
        ),
 
        TP_fast_assign(
                __entry->success        = success;
-               __assign_str(msg, error_msg);
+               __entry->dependency     = dependency;
        ),
 
-       TP_printk("success=%s msg=%s",  __entry->success ? "yes" : "no", __get_str(msg))
+       TP_printk("success=%d dependency=%s",  __entry->success, \
+                       show_tick_dep_name(__entry->dependency))
 );
 #endif
 
index 74ab7dbdc0231f0b291a721195f8a8d4e6a98916..47e5ac45ce6952e7ff8b6a031fff5103e670bbf2 100644 (file)
@@ -163,22 +163,22 @@ static unsigned long tick_dep_mask;
 static void trace_tick_dependency(unsigned long dep)
 {
        if (dep & TICK_DEP_MASK_POSIX_TIMER) {
-               trace_tick_stop(0, "posix timers running\n");
+               trace_tick_stop(0, TICK_DEP_MASK_POSIX_TIMER);
                return;
        }
 
        if (dep & TICK_DEP_MASK_PERF_EVENTS) {
-               trace_tick_stop(0, "perf events running\n");
+               trace_tick_stop(0, TICK_DEP_MASK_PERF_EVENTS);
                return;
        }
 
        if (dep & TICK_DEP_MASK_SCHED) {
-               trace_tick_stop(0, "more than 1 task in runqueue\n");
+               trace_tick_stop(0, TICK_DEP_MASK_SCHED);
                return;
        }
 
        if (dep & TICK_DEP_MASK_CLOCK_UNSTABLE)
-               trace_tick_stop(0, "unstable sched clock\n");
+               trace_tick_stop(0, TICK_DEP_MASK_CLOCK_UNSTABLE);
 }
 
 static bool can_stop_full_tick(struct tick_sched *ts)
@@ -206,17 +206,17 @@ static bool can_stop_full_tick(struct tick_sched *ts)
        }
 
        if (!sched_can_stop_tick()) {
-               trace_tick_stop(0, "more than 1 task in runqueue\n");
+               trace_tick_stop(0, TICK_DEP_MASK_SCHED);
                return false;
        }
 
        if (!posix_cpu_timers_can_stop_tick(current)) {
-               trace_tick_stop(0, "posix timers running\n");
+               trace_tick_stop(0, TICK_DEP_MASK_POSIX_TIMER);
                return false;
        }
 
        if (!perf_event_can_stop_tick()) {
-               trace_tick_stop(0, "perf events running\n");
+               trace_tick_stop(0, TICK_DEP_MASK_PERF_EVENTS);
                return false;
        }
 
@@ -228,7 +228,7 @@ static bool can_stop_full_tick(struct tick_sched *ts)
         * sched_clock_stable is set.
         */
        if (!sched_clock_stable()) {
-               trace_tick_stop(0, "unstable sched clock\n");
+               trace_tick_stop(0, TICK_DEP_MASK_CLOCK_UNSTABLE);
                /*
                 * Don't allow the user to think they can get
                 * full NO_HZ with this machine.
@@ -821,7 +821,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, " ");
+               trace_tick_stop(1, TICK_DEP_MASK_NONE);
        }
 
        /*