Re: frequent lockups in 3.18rc4
From: Sasha Levin
Date: Fri Dec 05 2014 - 00:01:12 EST
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@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/