Re: rcu_sched stall detected, but no state dump

From: Miroslav Benes
Date: Mon Dec 15 2014 - 08:26:40 EST

Next message: Johannes Thumshirn: "Re: [PATCH] mcb: mcb-pci: Only remap the 1st 0x200 bytes of BAR 0"
Previous message: Theodore Ts'o: "Re: WARNING: /usr/projects/linux/linux/drivers/gpu/drm/i915/intel_pm.c:6585 intel_display_power_put+0x4b/0x116 [i915]()"
In reply to: Paul E. McKenney: "Re: rcu_sched stall detected, but no state dump"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

On Fri, 12 Dec 2014, Paul E. McKenney wrote:

> On Fri, Dec 12, 2014 at 03:06:20PM +0100, Miroslav Benes wrote:
> > On Thu, 11 Dec 2014, Paul E. McKenney wrote:
> >
> > > 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. ;-)
> >
> > Ok, with next-20141212, where this patch is included, and SMP=y PREEMPT=n
> > I get the following
> >
> > ...
> > [ 206.949003] INFO: rcu_sched detected stalls on CPUs/tasks:
> > [ 206.949003] (detected by 0, t=21002 jiffies, g=3384, c=3383, q=247)
> > [ 206.949003] All QSes seen, last rcu_sched kthread activity 4294853243/4294874245, jiffies_till_next_fqs=3
> > [ 269.954004] INFO: rcu_sched detected stalls on CPUs/tasks:
> > [ 269.954004] (detected by 0, t=84007 jiffies, g=3384, c=3383, q=449)
> > [ 269.954004] All QSes seen, last rcu_sched kthread activity 4294853243/4294937250, jiffies_till_next_fqs=3
> > [ 332.959004] INFO: rcu_sched detected stalls on CPUs/tasks:
> > [ 332.959004] (detected by 0, t=147012 jiffies, g=3384, c=3383, q=651)
> > [ 332.959004] All QSes seen, last rcu_sched kthread activity 4294853243/4295000255, jiffies_till_next_fqs=3
> > [ 395.964003] INFO: rcu_sched detected stalls on CPUs/tasks:
> > [ 395.964003] (detected by 0, t=210017 jiffies, g=3384, c=3383, q=858)
> > [ 395.964003] All QSes seen, last rcu_sched kthread activity 4294853243/4295063260, jiffies_till_next_fqs=3
> > ...
> >
> > So it seems to work and it is not confusing anymore. Would it be possible
> > to dump the stack also in this case? The stall is there, the condition is
> > correctly detected, so I guess it could be possible. It would give the
> > information what caused the stall.
>
> Ah, good point! In this case, the stall is self-detected, but RCU
> incorrectly includes that it is some other CPU's fault because RCU is
> not waiting on the current CPU. Please see below for updated patch.
>
> > In SMP=n PREEMPT=y case there is no stall with my test. I guess it is
> > because module inclusion does not disable preemption. However it is
> > possible in other cases as you wrote above.
>
> OK, that matches expected behavior.
>
> > One last thing. Is there a reason that there is not any similar INFO in
> > the console for tiny implementation? I enabled RCU_TRACE and still got
> > nothing. I have only shallow knowledge of RCU, though.
>
> It is supposed to work given CONFIG_RCU_TRACE=y, and it looks like
> it should, at least as long as scheduling-clock interrupts are being
> delivered. One thing to try for diagnosis is to have every (say) 1000th
> call to check_cpu_stall() (in kernel/rcu/tiny_plugin.h) do a printk()
> and same for rcu_check_callbacks() (in kernel/rcu/tiny.c).

Unfortunately nothing is there. I'll look into it when I have more time
later this week and let you know.

>
> > I'll test more patches if you have some...
>
> Please see below for update that should print current CPU's stack for
> the "All QSes seen" case. This replaces the earlier patch.

This gives

...
[ 149.320003] INFO: rcu_sched detected stalls on CPUs/tasks:
[ 149.320003] (detected by 0, t=21002 jiffies, g=2823, c=2822, q=209)
[ 149.320003] All QSes seen, last rcu_sched kthread activity 21002 (4294816616-4294795614), jiffies_till_next_fqs=3
[ 149.320003] test_thread R running task 14832 4015 2 0x00000008
[ 149.320003] 00000000000039f0 ffff88013fc03da8 ffffffff8107874c ffffffff810786b2
[ 149.320003] ffffffff81e391c0 000000000000520a ffff88013fdcc4a0 ffffffff81e38cc0
[ 149.320003] ffffffff81e38cc0 ffff88013fc03e28 ffffffff810b1049 0000000000000002
[ 149.320003] Call Trace:
[ 149.320003] <IRQ> [<ffffffff8107874c>] sched_show_task+0x11c/0x190
[ 149.320003] [<ffffffff810786b2>] ? sched_show_task+0x82/0x190
[ 149.320003] [<ffffffff810b1049>] rcu_check_callbacks+0x839/0x850
[ 149.320003] [<ffffffff810b627b>] update_process_times+0x4b/0x80
[ 149.320003] [<ffffffff810c6865>] ? tick_sched_do_timer+0x35/0x40
[ 149.320003] [<ffffffff810c60d6>] tick_sched_handle.isra.19+0x36/0x50
[ 149.320003] [<ffffffff810c68b5>] tick_sched_timer+0x45/0x80
[ 149.320003] [<ffffffff810b7022>] __run_hrtimer+0xb2/0x250
[ 149.320003] [<ffffffff810b73cc>] ? hrtimer_interrupt+0x7c/0x250
[ 149.320003] [<ffffffff810c6870>] ? tick_sched_do_timer+0x40/0x40
[ 149.320003] [<ffffffff810b7447>] hrtimer_interrupt+0xf7/0x250
[ 149.320003] [<ffffffffa0000000>] ? 0xffffffffa0000000
[ 149.320003] [<ffffffff810356eb>] local_apic_timer_interrupt+0x3b/0x70
[ 149.320003] [<ffffffff818a9845>] smp_apic_timer_interrupt+0x45/0x60
[ 149.320003] [<ffffffff818a7c2f>] apic_timer_interrupt+0x6f/0x80
[ 149.320003] <EOI> [<ffffffff818a7960>] ? retint_restore_args+0xe/0xe
[ 149.320003] [<ffffffff8106d004>] ? kthread_should_stop+0x24/0x30
[ 149.320003] [<ffffffffa0000015>] ? test_thread_fn+0x15/0x20 [kthread_mod]
[ 149.320003] [<ffffffff8106d460>] kthread+0xf0/0x110
[ 149.320003] [<ffffffff8106d370>] ? kthread_create_on_node+0x240/0x240
[ 149.320003] [<ffffffff818a6cec>] ret_from_fork+0x7c/0xb0
[ 149.320003] [<ffffffff8106d370>] ? kthread_create_on_node+0x240/0x240
...

So it works as expected which is great. You can add my Tested-by if you
feel it is worth it.

Thanks
Miroslav

> ------------------------------------------------------------------------
>
> 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@xxxxxxx>
> Signed-off-by: Paul E. McKenney <paulmck@xxxxxxxxxxxxxxxxxx>
>
> 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..614dfaa94dd2 100644
> --- a/kernel/rcu/tree.c
> +++ b/kernel/rcu/tree.c
> @@ -1096,11 +1096,13 @@ 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;
> unsigned long flags;
> + unsigned long gpa;
> + unsigned long j;
> int ndetected = 0;
> struct rcu_node *rnp = rcu_get_root(rsp);
> long totqlen = 0;
> @@ -1144,10 +1146,22 @@ 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 {
> + j = jiffies;
> + gpa = ACCESS_ONCE(rsp->gp_activity);
> + pr_err("All QSes seen, last %s kthread activity %ld (%ld-%ld), jiffies_till_next_fqs=%ld\n",
> + rsp->name, j - gpa, j, gpa,
> + jiffies_till_next_fqs);
> + /* In this case, the current CPU might be at fault. */
> + sched_show_task(current);
> + }
> + }
>
> /* Complain about tasks blocking the grace period. */
>
> @@ -1247,7 +1261,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 +1657,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 +1718,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 +1735,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 +1774,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 +1811,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 +1861,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 +1905,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 */
>

--
Miroslav Benes
SUSE Labs
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

Next message: Johannes Thumshirn: "Re: [PATCH] mcb: mcb-pci: Only remap the 1st 0x200 bytes of BAR 0"
Previous message: Theodore Ts'o: "Re: WARNING: /usr/projects/linux/linux/drivers/gpu/drm/i915/intel_pm.c:6585 intel_display_power_put+0x4b/0x116 [i915]()"
In reply to: Paul E. McKenney: "Re: rcu_sched stall detected, but no state dump"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]