[PATCH] Documentation: RCU: update the stall warning message "timer=-1" to match reality

[PATCH] Documentation: RCU: update the stall warning message "timer=-1" to match reality

[Paul Walmsley]

The CONFIG_RCU_FAST_NO_HZ stall warning messages can never emit
"timer=-1".  This is because the printf() format specifier to generate
that number is '%lu'.  So, update the documentation to use the
unsigned long equivalent instead, "timer=4294967295".  This is what
actually shows up in traces.

Signed-off-by: Paul Walmsley <paul@pwsan.com>
Cc: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
Cc: Dipankar Sarma <dipankar@in.ibm.com>
---
 Documentation/RCU/stallwarn.txt |   10 +++++-----
 1 file changed, 5 insertions(+), 5 deletions(-)

diff --git a/Documentation/RCU/stallwarn.txt b/Documentation/RCU/stallwarn.txt
index 523364e..fe3379e 100644
--- a/Documentation/RCU/stallwarn.txt
+++ b/Documentation/RCU/stallwarn.txt
@@ -99,7 +99,7 @@ In kernels with CONFIG_RCU_FAST_NO_HZ, even more information is
 printed:
 
 	INFO: rcu_preempt detected stall on CPU
-	0: (64628 ticks this GP) idle=dd5/3fffffffffffffff/0 drain=0 . timer=-1
+	0: (64628 ticks this GP) idle=dd5/3fffffffffffffff/0 drain=0 . timer=4294967295
 	   (t=65000 jiffies)
 
 The "(64628 ticks this GP)" indicates that this CPU has taken more
@@ -119,10 +119,10 @@ number (as shown above) otherwise.
 For CONFIG_RCU_FAST_NO_HZ kernels, the "drain=0" indicates that the
 CPU is not in the process of trying to force itself into dyntick-idle
 state, the "." indicates that the CPU has not given up forcing RCU
-into dyntick-idle mode (it would be "H" otherwise), and the "timer=-1"
-indicates that the CPU has not recented forced RCU into dyntick-idle
-mode (it would otherwise indicate the number of microseconds remaining
-in this forced state).
+into dyntick-idle mode (it would be "H" otherwise), and the
+"timer=4294967295" (the magic number (2^32)-1) indicates that the CPU
+has not recently forced RCU into dyntick-idle mode (it would otherwise
+indicate the number of microseconds remaining in this forced state).
 
 
 Multiple Warnings From One Stall
-- 
1.7.10.4

Re: [PATCH] Documentation: RCU: update the stall warning message "timer=-1" to match reality

[Paul E. McKenney]

On Fri, Sep 21, 2012 at 04:13:29PM +0000, Paul Walmsley wrote:
> 
> The CONFIG_RCU_FAST_NO_HZ stall warning messages can never emit
> "timer=-1".  This is because the printf() format specifier to generate
> that number is '%lu'.  So, update the documentation to use the
> unsigned long equivalent instead, "timer=4294967295".  This is what
> actually shows up in traces.
> 
> Signed-off-by: Paul Walmsley <paul@pwsan.com>
> Cc: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
> Cc: Dipankar Sarma <dipankar@in.ibm.com>

Good catch!  Even worse, it gives "timer=18446744073709551615" on
64-bit systems, which is no easier on the eyes.  I therefore changed
the code to print a nicer message in this case, patch below.

The meaning of the "timer=4294967295" was that the corresponding CPU
was either non-idle or idle with no RCU callbacks, FWIW.

							Thanx, Paul

-------------------------------------------------------------------------

rcu: Fix CONFIG_RCU_FAST_NO_HZ stall warning message

The print_cpu_stall_fast_no_hz() function attempts to print -1 when
the ->idle_gp_timer is not pending, but unsigned arithmetic causes it
to instead print ULONG_MAX, which is 4294967295 on 32-bit systems and
18446744073709551615 on 64-bit systems.  Neither of these are the most
reader-friendly values, so this commit instead causes "timer not pending"
to be printed when ->idle_gp_timer is not pending.

Reported-by: Paul Walmsley <paul@pwsan.com>
Signed-off-by: Paul E. McKenney <paul.mckenney@linaro.org>
Signed-off-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>

diff --git a/Documentation/RCU/stallwarn.txt b/Documentation/RCU/stallwarn.txt
index 523364e..1927151 100644
--- a/Documentation/RCU/stallwarn.txt
+++ b/Documentation/RCU/stallwarn.txt
@@ -99,7 +99,7 @@ In kernels with CONFIG_RCU_FAST_NO_HZ, even more information is
 printed:
 
 	INFO: rcu_preempt detected stall on CPU
-	0: (64628 ticks this GP) idle=dd5/3fffffffffffffff/0 drain=0 . timer=-1
+	0: (64628 ticks this GP) idle=dd5/3fffffffffffffff/0 drain=0 . timer not pending
 	   (t=65000 jiffies)
 
 The "(64628 ticks this GP)" indicates that this CPU has taken more
@@ -116,13 +116,13 @@ number between the two "/"s is the value of the nesting, which will
 be a small positive number if in the idle loop and a very large positive
 number (as shown above) otherwise.
 
-For CONFIG_RCU_FAST_NO_HZ kernels, the "drain=0" indicates that the
-CPU is not in the process of trying to force itself into dyntick-idle
-state, the "." indicates that the CPU has not given up forcing RCU
-into dyntick-idle mode (it would be "H" otherwise), and the "timer=-1"
-indicates that the CPU has not recented forced RCU into dyntick-idle
-mode (it would otherwise indicate the number of microseconds remaining
-in this forced state).
+For CONFIG_RCU_FAST_NO_HZ kernels, the "drain=0" indicates that the CPU is
+not in the process of trying to force itself into dyntick-idle state, the
+"." indicates that the CPU has not given up forcing RCU into dyntick-idle
+mode (it would be "H" otherwise), and the "timer not pending" indicates
+that the CPU has not recently forced RCU into dyntick-idle mode (it
+would otherwise indicate the number of microseconds remaining in this
+forced state).
 
 
 Multiple Warnings From One Stall
diff --git a/kernel/rcutree_plugin.h b/kernel/rcutree_plugin.h
index 3b1a11e..be822f0 100644
--- a/kernel/rcutree_plugin.h
+++ b/kernel/rcutree_plugin.h
@@ -2245,11 +2245,15 @@ static void print_cpu_stall_fast_no_hz(char *cp, int cpu)
 {
 	struct rcu_dynticks *rdtp = &per_cpu(rcu_dynticks, cpu);
 	struct timer_list *tltp = &rdtp->idle_gp_timer;
+	char c;
 
-	sprintf(cp, "drain=%d %c timer=%lu",
-		rdtp->dyntick_drain,
-		rdtp->dyntick_holdoff == jiffies ? 'H' : '.',
-		timer_pending(tltp) ? tltp->expires - jiffies : -1);
+	c = rdtp->dyntick_holdoff == jiffies ? 'H' : '.';
+	if (timer_pending(tltp))
+		sprintf(cp, "drain=%d %c timer=%lu",
+			rdtp->dyntick_drain, c, tltp->expires - jiffies);
+	else
+		sprintf(cp, "drain=%d %c timer not pending",
+			rdtp->dyntick_drain, c);
 }
 
 #else /* #ifdef CONFIG_RCU_FAST_NO_HZ */

Re: [PATCH] Documentation: RCU: update the stall warning message "timer=-1" to match reality

[Paul Walmsley]

On Fri, 21 Sep 2012, Paul E. McKenney wrote:

> Good catch!  Even worse, it gives "timer=18446744073709551615" on
> 64-bit systems, which is no easier on the eyes.  I therefore changed
> the code to print a nicer message in this case, patch below.

Looks better, thanks.

- Paul