linux-kernel - Re: frequent lockups in 3.18rc4

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <54813C03.8040009@oracle.com>
Date:	Fri, 05 Dec 2014 00:00:51 -0500
From:	Sasha Levin <sasha.levin@...cle.com>
To:	Dave Jones <davej@...hat.com>, Chris Mason <clm@...com>,
	Linus Torvalds <torvalds@...ux-foundation.org>,
	Dâniel Fraga <fragabr@...il.com>,
	"Paul E. McKenney" <paulmck@...ux.vnet.ibm.com>,
	Linux Kernel Mailing List <linux-kernel@...r.kernel.org>
Subject: Re: frequent lockups in 3.18rc4

On 12/02/2014 06:32 PM, Sasha Levin wrote:
> On 12/02/2014 02:32 PM, Dave Jones wrote:
>> > On Mon, Dec 01, 2014 at 06:08:38PM -0500, Chris Mason wrote:
>> >  > I'm not sure if this is related, but running trinity here, I noticed it
>> >  > was stuck at 100% system time on every CPU.  perf report tells me we are
>> >  > spending all of our time in spin_lock under the sync system call.
>> >  > 
>> >  > I think it's coming from contention in the bdi_queue_work() call from
>> >  > inside sync_inodes_sb, which is spin_lock_bh(). 
>> >  > 
>> >  > I wonder if we're just spinning so hard on this one bh lock that we're
>> >  > starving the watchdog?
>> >  > 
>> >  > Dave, do you have spinlock debugging on?  
>> > 
>> > That has been a constant, yes. I can try with that disabled some time.
> Here's my side of the story: I was observing RCU lockups which went away when
> I disabled verbose printing for fault injections. It seems that printing one
> line ~10 times a second can cause that...

Just to add to this: I've enabled the simplest level of verbosity in the fault
injection options, and RCU stalls are again easy to trigger:

[ 3926.110026] INFO: rcu_preempt detected stalls on CPUs/tasks:
[ 3926.110026] INFO: rcu_sched detected stalls on CPUs/tasks:
[ 3926.110026]  0: (62 ticks this GP) idle=b63/140000000000002/0 softirq=20384/20384 last_accelerate: f772/8874, nonlazy_posted: 619783, ..
[ 3926.110026]  (detected by 2, t=30002 jiffies, g=-222, c=-223, q=0)
[ 3926.110026] Task dump for CPU 0:
[ 3926.110026] kworker/dying   R  running task    13464     7      2 0x00080008
[ 3926.110026]  ffffffff814db441 ffff88006aa3bd68 ffffffff814db441 ffffe8fff3c6c9d4
[ 3926.110026]  00000000ffffffff ffff88006aa3bd88 ffffffff814db76b ffffffff93a27440
[ 3926.110026]  dfffe90000000000 ffff88006aa26890 ffff88006aa26000 ffff88006aa3b5d8
[ 3926.110026] Call Trace:
[ 3926.110026]  [<ffffffff814db441>] ? get_parent_ip+0x11/0x50
[ 3926.110026]  [<ffffffff814db441>] ? get_parent_ip+0x11/0x50
[ 3926.110026]  [<ffffffff814db76b>] ? preempt_count_sub+0x11b/0x1d0
[ 3926.110026]  [<ffffffff81429c57>] ? do_exit+0x1687/0x3f20
[ 3926.110026]  [<ffffffff81485578>] ? worker_thread+0xa28/0x1760
[ 3926.110026]  [<ffffffff81484b50>] ? process_one_work+0x17a0/0x17a0
[ 3926.110026]  [<ffffffff8149d719>] ? kthread+0x229/0x320
[ 3926.110026]  [<ffffffff8149d4f0>] ? kthread_worker_fn+0x7d0/0x7d0
[ 3926.110026]  [<ffffffff91ffc0fc>] ? ret_from_fork+0x7c/0xb0
[ 3926.110026]  [<ffffffff8149d4f0>] ? kthread_worker_fn+0x7d0/0x7d0
[ 3926.110033]
[ 3926.110033]  0: (62 ticks this GP) idle=b63/140000000000002/0 softirq=20384/20384 last_accelerate: f772/8876, nonlazy_posted: 619783, ..
[ 3926.110033]  (detected by 10, t=30004 jiffies, g=15638, c=15637, q=63609)
[ 3926.110033] Task dump for CPU 0:
[ 3926.110033] kworker/dying   R  running task    13464     7      2 0x00080008
[ 3926.110033]  ffffffff814db441 ffff88006aa3bd68 ffffffff814db441 ffffe8fff3c6c9d4
[ 3926.110033]  00000000ffffffff ffff88006aa3bd88 ffffffff814db76b ffffffff93a27440
[ 3926.110033]  dfffe90000000000 ffff88006aa26890 ffff88006aa26000 ffff88006aa3b5d8
[ 3926.110033] Call Trace:
[ 3926.110033]  [<ffffffff814db441>] ? get_parent_ip+0x11/0x50
[ 3926.110033]  [<ffffffff814db441>] ? get_parent_ip+0x11/0x50
[ 3926.110033]  [<ffffffff814db76b>] ? preempt_count_sub+0x11b/0x1d0
[ 3926.110033]  [<ffffffff81429c57>] ? do_exit+0x1687/0x3f20
[ 3926.110033]  [<ffffffff81485578>] ? worker_thread+0xa28/0x1760
[ 3926.110033]  [<ffffffff81484b50>] ? process_one_work+0x17a0/0x17a0
[ 3926.110033]  [<ffffffff8149d719>] ? kthread+0x229/0x320
[ 3926.110033]  [<ffffffff8149d4f0>] ? kthread_worker_fn+0x7d0/0x7d0
[ 3926.110033]  [<ffffffff91ffc0fc>] ? ret_from_fork+0x7c/0xb0
[ 3926.110033]  [<ffffffff8149d4f0>] ? kthread_worker_fn+0x7d0/0x7d0


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