[tip:timers/core] timekeeping: Add debugging checks to warn if we see delays

2015-03-13 Thread tip-bot for John Stultz
Commit-ID:  3c17ad19f0697ffe5ef7438cdafc2d2b7757d8a5
Gitweb: http://git.kernel.org/tip/3c17ad19f0697ffe5ef7438cdafc2d2b7757d8a5
Author: John Stultz 
AuthorDate: Wed, 11 Mar 2015 21:16:32 -0700
Committer:  Ingo Molnar 
CommitDate: Fri, 13 Mar 2015 08:06:58 +0100

timekeeping: Add debugging checks to warn if we see delays

Recently there's been requests for better sanity
checking in the time code, so that it's more clear
when something is going wrong, since timekeeping issues
could manifest in a large number of strange ways in
various subsystems.

Thus, this patch adds some extra infrastructure to
add a check to update_wall_time() to print two new
warnings:

 1) if we see the call delayed beyond the 'max_cycles'
overflow point,

 2) or if we see the call delayed beyond the clocksource's
'max_idle_ns' value, which is currently 50% of the
overflow point.

This extra infrastructure is conditional on
a new CONFIG_DEBUG_TIMEKEEPING option, also
added in this patch - default off.

Tested this a bit by halting qemu for specified
lengths of time to trigger the warnings.

Signed-off-by: John Stultz 
Cc: Dave Jones 
Cc: Linus Torvalds 
Cc: Peter Zijlstra 
Cc: Prarit Bhargava 
Cc: Richard Cochran 
Cc: Stephen Boyd 
Cc: Thomas Gleixner 
Link: 
http://lkml.kernel.org/r/1426133800-29329-5-git-send-email-john.stu...@linaro.org
[ Improved the changelog and the messages a bit. ]
Signed-off-by: Ingo Molnar 
---
 kernel/time/jiffies.c |  1 +
 kernel/time/timekeeping.c | 28 
 lib/Kconfig.debug | 13 +
 3 files changed, 42 insertions(+)

diff --git a/kernel/time/jiffies.c b/kernel/time/jiffies.c
index a6a5bf5..7e41390 100644
--- a/kernel/time/jiffies.c
+++ b/kernel/time/jiffies.c
@@ -71,6 +71,7 @@ static struct clocksource clocksource_jiffies = {
.mask   = 0x, /*32bits*/
.mult   = NSEC_PER_JIFFY << JIFFIES_SHIFT, /* details above */
.shift  = JIFFIES_SHIFT,
+   .max_cycles = 10,
 };
 
 __cacheline_aligned_in_smp DEFINE_SEQLOCK(jiffies_lock);
diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
index 91db941..acf0491 100644
--- a/kernel/time/timekeeping.c
+++ b/kernel/time/timekeeping.c
@@ -118,6 +118,31 @@ static inline void tk_update_sleep_time(struct timekeeper 
*tk, ktime_t delta)
tk->offs_boot = ktime_add(tk->offs_boot, delta);
 }
 
+#ifdef CONFIG_DEBUG_TIMEKEEPING
+static void timekeeping_check_update(struct timekeeper *tk, cycle_t offset)
+{
+
+   cycle_t max_cycles = tk->tkr.clock->max_cycles;
+   const char *name = tk->tkr.clock->name;
+
+   if (offset > max_cycles) {
+   printk_deferred("WARNING: timekeeping: Cycle offset (%lld) is 
larger than allowed by the '%s' clock's max_cycles value (%lld): time 
overflow\n",
+   offset, name, max_cycles);
+   printk_deferred(" timekeeping: Your kernel is sick, but 
tries to cope\n");
+   } else {
+   if (offset > (max_cycles >> 1)) {
+   printk_deferred("INFO: timekeeping: Cycle offset (%lld) 
is larger than the the '%s' clock's 50%% safety margin (%lld)\n",
+   offset, name, max_cycles >> 1);
+   printk_deferred("  timekeeping: Your kernel is 
still fine, but is feeling a bit nervous\n");
+   }
+   }
+}
+#else
+static inline void timekeeping_check_update(struct timekeeper *tk, cycle_t 
offset)
+{
+}
+#endif
+
 /**
  * tk_setup_internals - Set up internals to use clocksource clock.
  *
@@ -1630,6 +1655,9 @@ void update_wall_time(void)
if (offset < real_tk->cycle_interval)
goto out;
 
+   /* Do some additional sanity checking */
+   timekeeping_check_update(real_tk, offset);
+
/*
 * With NO_HZ we may have to accumulate many cycle_intervals
 * (think "ticks") worth of time at once. To do this efficiently,
diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index c5cefb3..36b6fa8 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -865,6 +865,19 @@ config SCHED_STACK_END_CHECK
  data corruption or a sporadic crash at a later stage once the region
  is examined. The runtime overhead introduced is minimal.
 
+config DEBUG_TIMEKEEPING
+   bool "Enable extra timekeeping sanity checking"
+   help
+ This option will enable additional timekeeping sanity checks
+ which may be helpful when diagnosing issues where timekeeping
+ problems are suspected.
+
+ This may include checks in the timekeeping hotpaths, so this
+ option may have a (very small) performance impact to some
+ workloads.
+
+ If unsure, say N.
+
 config TIMER_STATS
bool "Collect kernel timers statistics"
depends on DEBUG_KERNEL && PROC_FS
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message 

[tip:timers/core] timekeeping: Add debugging checks to warn if we see delays

2015-03-13 Thread tip-bot for John Stultz
Commit-ID:  3c17ad19f0697ffe5ef7438cdafc2d2b7757d8a5
Gitweb: http://git.kernel.org/tip/3c17ad19f0697ffe5ef7438cdafc2d2b7757d8a5
Author: John Stultz john.stu...@linaro.org
AuthorDate: Wed, 11 Mar 2015 21:16:32 -0700
Committer:  Ingo Molnar mi...@kernel.org
CommitDate: Fri, 13 Mar 2015 08:06:58 +0100

timekeeping: Add debugging checks to warn if we see delays

Recently there's been requests for better sanity
checking in the time code, so that it's more clear
when something is going wrong, since timekeeping issues
could manifest in a large number of strange ways in
various subsystems.

Thus, this patch adds some extra infrastructure to
add a check to update_wall_time() to print two new
warnings:

 1) if we see the call delayed beyond the 'max_cycles'
overflow point,

 2) or if we see the call delayed beyond the clocksource's
'max_idle_ns' value, which is currently 50% of the
overflow point.

This extra infrastructure is conditional on
a new CONFIG_DEBUG_TIMEKEEPING option, also
added in this patch - default off.

Tested this a bit by halting qemu for specified
lengths of time to trigger the warnings.

Signed-off-by: John Stultz john.stu...@linaro.org
Cc: Dave Jones da...@codemonkey.org.uk
Cc: Linus Torvalds torva...@linux-foundation.org
Cc: Peter Zijlstra pet...@infradead.org
Cc: Prarit Bhargava pra...@redhat.com
Cc: Richard Cochran richardcoch...@gmail.com
Cc: Stephen Boyd sb...@codeaurora.org
Cc: Thomas Gleixner t...@linutronix.de
Link: 
http://lkml.kernel.org/r/1426133800-29329-5-git-send-email-john.stu...@linaro.org
[ Improved the changelog and the messages a bit. ]
Signed-off-by: Ingo Molnar mi...@kernel.org
---
 kernel/time/jiffies.c |  1 +
 kernel/time/timekeeping.c | 28 
 lib/Kconfig.debug | 13 +
 3 files changed, 42 insertions(+)

diff --git a/kernel/time/jiffies.c b/kernel/time/jiffies.c
index a6a5bf5..7e41390 100644
--- a/kernel/time/jiffies.c
+++ b/kernel/time/jiffies.c
@@ -71,6 +71,7 @@ static struct clocksource clocksource_jiffies = {
.mask   = 0x, /*32bits*/
.mult   = NSEC_PER_JIFFY  JIFFIES_SHIFT, /* details above */
.shift  = JIFFIES_SHIFT,
+   .max_cycles = 10,
 };
 
 __cacheline_aligned_in_smp DEFINE_SEQLOCK(jiffies_lock);
diff --git a/kernel/time/timekeeping.c b/kernel/time/timekeeping.c
index 91db941..acf0491 100644
--- a/kernel/time/timekeeping.c
+++ b/kernel/time/timekeeping.c
@@ -118,6 +118,31 @@ static inline void tk_update_sleep_time(struct timekeeper 
*tk, ktime_t delta)
tk-offs_boot = ktime_add(tk-offs_boot, delta);
 }
 
+#ifdef CONFIG_DEBUG_TIMEKEEPING
+static void timekeeping_check_update(struct timekeeper *tk, cycle_t offset)
+{
+
+   cycle_t max_cycles = tk-tkr.clock-max_cycles;
+   const char *name = tk-tkr.clock-name;
+
+   if (offset  max_cycles) {
+   printk_deferred(WARNING: timekeeping: Cycle offset (%lld) is 
larger than allowed by the '%s' clock's max_cycles value (%lld): time 
overflow\n,
+   offset, name, max_cycles);
+   printk_deferred( timekeeping: Your kernel is sick, but 
tries to cope\n);
+   } else {
+   if (offset  (max_cycles  1)) {
+   printk_deferred(INFO: timekeeping: Cycle offset (%lld) 
is larger than the the '%s' clock's 50%% safety margin (%lld)\n,
+   offset, name, max_cycles  1);
+   printk_deferred(  timekeeping: Your kernel is 
still fine, but is feeling a bit nervous\n);
+   }
+   }
+}
+#else
+static inline void timekeeping_check_update(struct timekeeper *tk, cycle_t 
offset)
+{
+}
+#endif
+
 /**
  * tk_setup_internals - Set up internals to use clocksource clock.
  *
@@ -1630,6 +1655,9 @@ void update_wall_time(void)
if (offset  real_tk-cycle_interval)
goto out;
 
+   /* Do some additional sanity checking */
+   timekeeping_check_update(real_tk, offset);
+
/*
 * With NO_HZ we may have to accumulate many cycle_intervals
 * (think ticks) worth of time at once. To do this efficiently,
diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
index c5cefb3..36b6fa8 100644
--- a/lib/Kconfig.debug
+++ b/lib/Kconfig.debug
@@ -865,6 +865,19 @@ config SCHED_STACK_END_CHECK
  data corruption or a sporadic crash at a later stage once the region
  is examined. The runtime overhead introduced is minimal.
 
+config DEBUG_TIMEKEEPING
+   bool Enable extra timekeeping sanity checking
+   help
+ This option will enable additional timekeeping sanity checks
+ which may be helpful when diagnosing issues where timekeeping
+ problems are suspected.
+
+ This may include checks in the timekeeping hotpaths, so this
+ option may have a (very small) performance impact to some
+ workloads.
+
+ If unsure, say N.
+
 config