From e6e6cc22e067a6f44449aa8fd0328404079c3ba5 Mon Sep 17 00:00:00 2001 From: Frederic Weisbecker Date: Fri, 11 Dec 2015 03:27:25 +0100 Subject: [PATCH] nohz: Use enum code for tick stop failure tracing message 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 Reviewed-by: Chris Metcalf Cc: Christoph Lameter Cc: Chris Metcalf Cc: Ingo Molnar Cc: Luiz Capitulino Cc: Peter Zijlstra Cc: Rik van Riel Cc: Thomas Gleixner Cc: Viresh Kumar Signed-off-by: Frederic Weisbecker --- include/linux/tick.h | 1 + include/trace/events/timer.h | 36 +++++++++++++++++++++++++++++++----- kernel/time/tick-sched.c | 18 +++++++++--------- 3 files changed, 41 insertions(+), 14 deletions(-) diff --git a/include/linux/tick.h b/include/linux/tick.h index d60e5df8ec28..96d276a923bf 100644 --- a/include/linux/tick.h +++ b/include/linux/tick.h @@ -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) diff --git a/include/trace/events/timer.h b/include/trace/events/timer.h index 073b9ac245ba..51440131d337 100644 --- a/include/trace/events/timer.h +++ b/include/trace/events/timer.h @@ -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 diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c index 74ab7dbdc023..47e5ac45ce69 100644 --- a/kernel/time/tick-sched.c +++ b/kernel/time/tick-sched.c @@ -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); } /*