Re: frequent lockups in 3.18rc4

[Paul E. McKenney]

On Sun, Dec 07, 2014 at 06:28:43PM -0500, Sasha Levin wrote:
> On 12/07/2014 02:43 PM, Paul E. McKenney wrote:
> > On Sun, Dec 07, 2014 at 10:24:20AM -0800, Paul E. McKenney wrote:
> >> On Sun, Dec 07, 2014 at 09:58:14AM -0500, Sasha Levin wrote:
> >>> On 12/05/2014 01:15 PM, Linus Torvalds wrote:
> >>>> On Fri, Dec 5, 2014 at 7:03 AM, Sasha Levin <sasha.levin@xxxxxxxxxx> wrote:
> >>>>>
> >>>>> Yes, it's going to a serial line, but it's only about 100 lines/second on
> >>>>> average. I wouldn't expect it to cause anything to hang!
> >>>>
> >>>> A regular 16650 serial chip? Running at 115kbps, I assume? So that's
> >>>> about 11kB/s.
> >>>>
> >>>> And the serial console is polling, since it can't sleep or depend on interrupts.
> >>>>
> >>>> At a average line length of what, 40 characters? At less than 300
> >>>> lines/s, you'd be using up 100% of one CPU. And since the printouts
> >>>> are serialized, that would be all other CPU's too..
> >>>>
> >>>> 100 lines/s _average_ means that I can easily see it be 300lines/s for a while.
> >>>>
> >>>> So yeah. The serial console is simply not designed to handle
> >>>> continuous output. It's for the "occasional" stuff.
> >>>>
> >>>> The fact that your rcu lockups go away when you make the fault
> >>>> injection be quiet makes me really suspect this is related.
> >>>
> >>> The lockups themselves "go away", but looking closer at the log
> >>> without those extra prints, I'm seeing:
> >>>
> >>> [ 1458.700070] INFO: rcu_preempt detected stalls on CPUs/tasks:
> >>> [ 1458.700133]  (detected by 19, t=30502 jiffies, g=12293, c=12292, q=0)
> >>> [ 1458.702764] INFO: Stall ended before state dump start
> >>>
> >>> Quite often.
> >>>
> >>> Maybe the extra prints were just a catalyst?
> >>
> >> Is anything else being printed about the time that these message show
> >> up?  Or is this the only output for the 40,000 jiffies preceding this
> >> message?
> 
> There's actually nothing going on (beyond fuzzing noise) before/after:
> 
> [  756.618342] kexec-bzImage64: Not a bzImage
> [  762.381734] kexec-bzImage64: Not a bzImage
> [  765.129612] Unable to find swap-space signature
> [  771.022304] Unable to find swap-space signature
> [  793.434417] kexec-bzImage64: Not a bzImage
> [  797.978210] => alloc_cpumask_var: failed!
> [  800.253116] kexec-bzImage64: Not a bzImage
> [  818.280056] INFO: rcu_sched detected stalls on CPUs/tasks:
> [  818.280056]  (detected by 11, t=30503 jiffies, g=-295, c=-296, q=0)
> [  818.283400] INFO: Stall ended before state dump start
> [  829.523992] audit: type=1326 audit(39.680:47): auid=4294967295 uid=2385760256 gid=2214330370 ses=4294967295 pid=13307 comm="trinity-c353" exe="/trinity/trinity" sig=9 arch=c000003e syscall=96 compat=0 ip=0x7fffcb7bee47 code=0x0
> [  830.890841] audit: type=1326 audit(41.010:48): auid=4294967295 uid=310902784 gid=201841673 ses=4294967295 pid=13294 comm="trinity-c350" exe="/trinity/trinity" sig=9 arch=c000003e syscall=96 compat=0 ip=0x7fffcb7bee47 code=0x0

I have seen this caused by lost IPIs, but you have to lose two of them,
which seems less than fully likely.

> > And could you please build with CONFIG_RCU_CPU_STALL_INFO=y and try
> > this again?
> 
> I already have it set:
> 
> $ grep STALL_INFO .config
> CONFIG_RCU_CPU_STALL_INFO=y

Ah, apologies.  OK, time to make this the default, and later to remove
the option...

							Thanx, Paul

--
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/