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 majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
