Re: rcu_sched stall detected, but no state dump

["Paul E. McKenney" <paulmck@linux.vnet.ibm.com>]

On Thu, Dec 11, 2014 at 08:50:10AM -0800, Paul E. McKenney wrote:
> On Thu, Dec 11, 2014 at 10:35:15AM +0100, Miroslav Benes wrote:
> > On Wed, 10 Dec 2014, Paul E. McKenney wrote:
> > 
> > > On Wed, Dec 10, 2014 at 01:52:02PM +0100, Miroslav Benes wrote:
> > > > 
> > > > Hi,
> > > > 
> > > > today I came across RCU stall which was correctly detected, but there is 
> > > > no state dump. This is a bit suspicious, I think. 
> > > > 
> > > > This is the output in serial console:
> > > > 
> > > > [  105.727003] INFO: rcu_sched detected stalls on CPUs/tasks:
> > > > [  105.727003]  (detected by 0, t=21002 jiffies, g=3269, c=3268, q=138)
> > > > [  105.727003] INFO: Stall ended before state dump start
> > > > [  168.732006] INFO: rcu_sched detected stalls on CPUs/tasks:
> > > > [  168.732006]  (detected by 0, t=84007 jiffies, g=3269, c=3268, q=270)
> > > > [  168.732006] INFO: Stall ended before state dump start
> > > > [  231.737003] INFO: rcu_sched detected stalls on CPUs/tasks:
> > > > [  231.737003]  (detected by 0, t=147012 jiffies, g=3269, c=3268, q=388)
> > > > [  231.737003] INFO: Stall ended before state dump start
> > > > [  294.742003] INFO: rcu_sched detected stalls on CPUs/tasks:
> > > > [  294.742003]  (detected by 0, t=210017 jiffies, g=3269, c=3268, q=539)
> > > > [  294.742003] INFO: Stall ended before state dump start
> > > > [  357.747003] INFO: rcu_sched detected stalls on CPUs/tasks:
> > > > [  357.747003]  (detected by 0, t=273022 jiffies, g=3269, c=3268, q=693)
> > > > [  357.747003] INFO: Stall ended before state dump start
> > > > [  420.752003] INFO: rcu_sched detected stalls on CPUs/tasks:
> > > > [  420.752003]  (detected by 0, t=336027 jiffies, g=3269, c=3268, q=806)
> > > > [  420.752003] INFO: Stall ended before state dump start
> > > > ...
> > > > 
> > > > It can be reproduced by trivial code attached to this mail (infinite 
> > > > loop in kernel thread created in kernel module). I have CONFIG_PREEMPT=n. 
> > > > The kernel thread is scheduled on the same CPU which causes soft lockup 
> > > > (reliably detected when lockup detector is on). There is certainly RCU 
> > > > stall, but I would expect a state dump. Is this an expected behaviour? 
> > > > Maybe I overlooked some config option, don't know.
> > > 
> > > Definitely not expected behavior!  Unless you have only one CPU, but in
> > > that case you should be running tiny RCU, not tree RCU.
> > 
> > So indeed I messed up my configs somehow and run the code on uniprocessor 
> > with SMP=y and tree RCU. With more processors RCU stall is detected and 
> > correct state is dumped. On uniprocessor with SMP=n and tiny RCU 
> > softlockup is detected, but no RCU stall in the log (is this correct?). So 
> > I'm really sorry for the noise.
> > 
> > Anyway I still think that running SMP kernel with tree RCU on 
> > uniprocessor is possible option (albeit suboptimal and maybe improbable). 
> > Should I proceed with your patch below and bisection or am I mistaken 
> > completely and we can leave it because there is no problem?
> 
> Not a problem, there have been some interesting RCU CPU stall warnings
> recently, and your data did add some insight.
> 
> So the combination SMP=n PREEMPT=y can happen straightforwardly via
> kbuild.  The combination SMP=n PREEMPT=n can happen (somewhat less)
> straightforwardly by running an SMP=y PREEMPT=n kernel on a single-CPU
> system.  In both cases, what can happen is that RCU's grace-period
> kthreads are starved, which can result in those reports.
> 
> And these reports are confusing.  I am considering attempting to improve
> the diagnostics.  If I do, would you be willing to test the resulting
> patches?

Like this one, for example.  ;-)

							Thanx, Paul

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

rcu: Improve diagnostics for spurious RCU CPU stall warnings

The current RCU CPU stall warning code will print "Stall ended before
state dump start" any time that the stall-warning code is triggered on
a CPU that has already reported a quiescent state for the current grace
period and if all quiescent states have been reported for the current
grace period.  However, a true stall can result in these symptoms, for
example, by preventing RCU's grace-period kthreads from ever running

This commit therefore checks for this condition, reporting the end of
the stall only if one of the grace-period counters has actually advanced.
Otherwise, it reports the last time that the grace-period kthread made
meaningful progress.  (In normal situations, the grace-period kthread
should make meaningful progress at least every jiffies_till_next_fqs
jiffies.)

Reported-by: Miroslav Benes <mbenes@suse.cz>
Signed-off-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>

diff --git a/Documentation/RCU/stallwarn.txt b/Documentation/RCU/stallwarn.txt
index 4f8e33952b88..8085bc133791 100644
--- a/Documentation/RCU/stallwarn.txt
+++ b/Documentation/RCU/stallwarn.txt
@@ -187,6 +187,11 @@ o	For !CONFIG_PREEMPT kernels, a CPU looping anywhere in the
 	behavior, you might need to replace some of the cond_resched()
 	calls with calls to cond_resched_rcu_qs().
 
+o	Anything that prevents RCU's grace-period kthreads from running.
+	This can result in the "All QSes seen" console-log message.
+	This message will include information on when the kthread last
+	ran and how often it should be expected to run.
+
 o	A CPU-bound real-time task in a CONFIG_PREEMPT kernel, which might
 	happen to preempt a low-priority task in the middle of an RCU
 	read-side critical section.   This is especially damaging if
diff --git a/kernel/rcu/tree.c b/kernel/rcu/tree.c
index 7497dfe6ff3f..6a43836b61b0 100644
--- a/kernel/rcu/tree.c
+++ b/kernel/rcu/tree.c
@@ -1096,7 +1096,7 @@ static void rcu_dump_cpu_stacks(struct rcu_state *rsp)
 	}
 }
 
-static void print_other_cpu_stall(struct rcu_state *rsp)
+static void print_other_cpu_stall(struct rcu_state *rsp, unsigned long gpnum)
 {
 	int cpu;
 	long delta;
@@ -1144,10 +1144,18 @@ static void print_other_cpu_stall(struct rcu_state *rsp)
 	pr_cont("(detected by %d, t=%ld jiffies, g=%ld, c=%ld, q=%lu)\n",
 	       smp_processor_id(), (long)(jiffies - rsp->gp_start),
 	       (long)rsp->gpnum, (long)rsp->completed, totqlen);
-	if (ndetected == 0)
-		pr_err("INFO: Stall ended before state dump start\n");
-	else
+	if (ndetected) {
 		rcu_dump_cpu_stacks(rsp);
+	} else {
+		if (ACCESS_ONCE(rsp->gpnum) != gpnum ||
+		    ACCESS_ONCE(rsp->completed) == gpnum)
+			pr_err("INFO: Stall ended before state dump start\n");
+		else
+			pr_err("All QSes seen, last %s kthread activity %ld/%ld, jiffies_till_next_fqs=%ld\n",
+			       rsp->name,
+			       ACCESS_ONCE(rsp->gp_activity), jiffies,
+			       jiffies_till_next_fqs);
+	}
 
 	/* Complain about tasks blocking the grace period. */
 
@@ -1247,7 +1255,7 @@ static void check_cpu_stall(struct rcu_state *rsp, struct rcu_data *rdp)
 		   ULONG_CMP_GE(j, js + RCU_STALL_RAT_DELAY)) {
 
 		/* They had a few time units to dump stack, so complain. */
-		print_other_cpu_stall(rsp);
+		print_other_cpu_stall(rsp, gpnum);
 	}
 }
 
@@ -1643,6 +1651,7 @@ static int rcu_gp_init(struct rcu_state *rsp)
 	struct rcu_data *rdp;
 	struct rcu_node *rnp = rcu_get_root(rsp);
 
+	ACCESS_ONCE(rsp->gp_activity) = jiffies;
 	rcu_bind_gp_kthread();
 	raw_spin_lock_irq(&rnp->lock);
 	smp_mb__after_unlock_lock();
@@ -1703,6 +1712,7 @@ static int rcu_gp_init(struct rcu_state *rsp)
 					    rnp->grphi, rnp->qsmask);
 		raw_spin_unlock_irq(&rnp->lock);
 		cond_resched_rcu_qs();
+		ACCESS_ONCE(rsp->gp_activity) = jiffies;
 	}
 
 	mutex_unlock(&rsp->onoff_mutex);
@@ -1719,6 +1729,7 @@ static int rcu_gp_fqs(struct rcu_state *rsp, int fqs_state_in)
 	unsigned long maxj;
 	struct rcu_node *rnp = rcu_get_root(rsp);
 
+	ACCESS_ONCE(rsp->gp_activity) = jiffies;
 	rsp->n_force_qs++;
 	if (fqs_state == RCU_SAVE_DYNTICK) {
 		/* Collect dyntick-idle snapshots. */
@@ -1757,6 +1768,7 @@ static void rcu_gp_cleanup(struct rcu_state *rsp)
 	struct rcu_data *rdp;
 	struct rcu_node *rnp = rcu_get_root(rsp);
 
+	ACCESS_ONCE(rsp->gp_activity) = jiffies;
 	raw_spin_lock_irq(&rnp->lock);
 	smp_mb__after_unlock_lock();
 	gp_duration = jiffies - rsp->gp_start;
@@ -1793,6 +1805,7 @@ static void rcu_gp_cleanup(struct rcu_state *rsp)
 		nocb += rcu_future_gp_cleanup(rsp, rnp);
 		raw_spin_unlock_irq(&rnp->lock);
 		cond_resched_rcu_qs();
+		ACCESS_ONCE(rsp->gp_activity) = jiffies;
 	}
 	rnp = rcu_get_root(rsp);
 	raw_spin_lock_irq(&rnp->lock);
@@ -1842,6 +1855,7 @@ static int __noreturn rcu_gp_kthread(void *arg)
 			if (rcu_gp_init(rsp))
 				break;
 			cond_resched_rcu_qs();
+			ACCESS_ONCE(rsp->gp_activity) = jiffies;
 			WARN_ON(signal_pending(current));
 			trace_rcu_grace_period(rsp->name,
 					       ACCESS_ONCE(rsp->gpnum),
@@ -1885,9 +1899,11 @@ static int __noreturn rcu_gp_kthread(void *arg)
 						       ACCESS_ONCE(rsp->gpnum),
 						       TPS("fqsend"));
 				cond_resched_rcu_qs();
+				ACCESS_ONCE(rsp->gp_activity) = jiffies;
 			} else {
 				/* Deal with stray signal. */
 				cond_resched_rcu_qs();
+				ACCESS_ONCE(rsp->gp_activity) = jiffies;
 				WARN_ON(signal_pending(current));
 				trace_rcu_grace_period(rsp->name,
 						       ACCESS_ONCE(rsp->gpnum),
diff --git a/kernel/rcu/tree.h b/kernel/rcu/tree.h
index 44e9ccfe6570..856518c8dcfa 100644
--- a/kernel/rcu/tree.h
+++ b/kernel/rcu/tree.h
@@ -483,6 +483,8 @@ struct rcu_state {
 						/*  due to no GP active. */
 	unsigned long gp_start;			/* Time at which GP started, */
 						/*  but in jiffies. */
+	unsigned long gp_activity;		/* Time of last GP kthread */
+						/*  activity in jiffies. */
 	unsigned long jiffies_stall;		/* Time at which to check */
 						/*  for CPU stalls. */
 	unsigned long jiffies_resched;		/* Time at which to resched */