Re: [PATCH] rcu: Eliminate softirq processing from rcutree

From: Paul E. McKenney
Date: Wed Dec 25 2013 - 02:56:01 EST


On Wed, Dec 25, 2013 at 04:07:34AM +0100, Mike Galbraith wrote:
> On Tue, 2013-12-24 at 11:36 -0800, Paul E. McKenney wrote:
> > On Mon, Dec 23, 2013 at 05:38:53AM +0100, Mike Galbraith wrote:
> > > On Sun, 2013-12-22 at 09:57 +0100, Mike Galbraith wrote:
> > > > I'll let the box give
> > > > RCU something to do for a couple days. No news is good news.
> > >
> > > Ho ho hum, merry christmas, gift attached.
> >
> > Hmmm... I guess I should take a moment to work out who has been
> > naughty and nice...
> >
> > > I'll beat on virgin -rt7, see if it survives, then re-apply RCU patch
> > > and retest. This kernel had nohz_full enabled, along with Sebastian's
> > > pending -rt fix for same, so RCU patch was not only not running solo,
> > > box was running a known somewhat buggy config as well. Box was doing
> > > endless tbench 64 when it started stalling fwiw.
> >
> > [72788.040872] NMI backtrace for cpu 31
> > [72788.040874] CPU: 31 PID: 13975 Comm: tbench Tainted: G W 3.12.6-rt7-nohz #192
> > [72788.040874] Hardware name: Hewlett-Packard ProLiant DL980 G7, BIOS P66 07/07/2010
> > [72788.040875] task: ffff8802728e3db0 ti: ffff88026deb2000 task.ti: ffff88026deb2000
> > [72788.040877] RIP: 0010:[<ffffffff815e34e4>] [<ffffffff815e34e4>] _raw_spin_trylock+0x14/0x80
> > [72788.040878] RSP: 0018:ffff8802769e3e58 EFLAGS: 00000002
> > [72788.040879] RAX: ffff88026deb3fd8 RBX: ffff880273544000 RCX: 000000007bc87bc6
> > [72788.040879] RDX: 0000000000000000 RSI: ffff8802728e3db0 RDI: ffff880273544000
> > [72788.040880] RBP: ffff88026deb39f8 R08: 0000063c14effd0f R09: 0000000000000119
> > [72788.040881] R10: 0000000000000005 R11: ffff8802769f2260 R12: ffff8802728e3db0
> > [72788.040881] R13: 000000000000001f R14: ffff8802769ebcc0 R15: ffffffff810c4730
> > [72788.040883] FS: 00007f7cd380a700(0000) GS:ffff8802769e0000(0000) knlGS:0000000000000000
> > [72788.040883] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > [72788.040884] CR2: 000000000068a0e8 CR3: 0000000267ba4000 CR4: 00000000000007e0
> > [72788.040885] Stack:
> > [72788.040886] ffff88026deb39f8 ffffffff815e2aa0 0000000000000000 ffffffff8106711a
> > [72788.040887] ffff8802769ec4e0 ffff8802769ec4e0 ffff8802769e3f58 ffffffff810c44bd
> > [72788.040888] ffff88026deb39f8 ffff88026deb39f8 000015ed4f5ff89b ffffffff810c476e
> > [72788.040889] Call Trace:
> > [72788.040889] <IRQ>
> > [72788.040891] [<ffffffff815e2aa0>] ? rt_spin_lock_slowunlock_hirq+0x10/0x20
> > [72788.040893] [<ffffffff8106711a>] ? update_process_times+0x3a/0x60
> > [72788.040895] [<ffffffff810c44bd>] ? tick_sched_handle+0x2d/0x70
> > [72788.040896] [<ffffffff810c476e>] ? tick_sched_timer+0x3e/0x70
> > [72788.040898] [<ffffffff810839dd>] ? __run_hrtimer+0x13d/0x260
> > [72788.040900] [<ffffffff81083c2c>] ? hrtimer_interrupt+0x12c/0x310
> > [72788.040901] [<ffffffff8109593e>] ? vtime_account_system+0x4e/0xf0
> > [72788.040903] [<ffffffff81035656>] ? smp_apic_timer_interrupt+0x36/0x50
> > [72788.040904] [<ffffffff815ebc9d>] ? apic_timer_interrupt+0x6d/0x80
> > [72788.040905] <EOI>
> > [72788.040906] [<ffffffff815e338a>] ? _raw_spin_lock+0x2a/0x40
> > [72788.040908] [<ffffffff815e23b3>] ? rt_spin_lock_slowlock+0x33/0x2d0
> > [72788.040910] [<ffffffff8108ee44>] ? migrate_enable+0xc4/0x220
> > [72788.040911] [<ffffffff8152f888>] ? ip_finish_output+0x258/0x450
> > [72788.040913] [<ffffffff81067011>] ? lock_timer_base+0x41/0x80
> > [72788.040914] [<ffffffff81068db6>] ? mod_timer+0x66/0x290
> > [72788.040916] [<ffffffff814df02f>] ? sk_reset_timer+0xf/0x20
> > [72788.040917] [<ffffffff81547d7f>] ? tcp_write_xmit+0x1cf/0x5d0
> > [72788.040919] [<ffffffff815481e5>] ? __tcp_push_pending_frames+0x25/0x60
> > [72788.040921] [<ffffffff81539e34>] ? tcp_sendmsg+0x114/0xbb0
> > [72788.040923] [<ffffffff814dbc1f>] ? sock_sendmsg+0xaf/0xf0
> > [72788.040925] [<ffffffff811bf5e5>] ? touch_atime+0x65/0x150
> > [72788.040927] [<ffffffff814dbd78>] ? SyS_sendto+0x118/0x190
> > [72788.040929] [<ffffffff81095b66>] ? vtime_account_user+0x66/0x100
> > [72788.040930] [<ffffffff8100f36a>] ? syscall_trace_enter+0x2a/0x260
> > [72788.040932] [<ffffffff815eb249>] ? tracesys+0xdd/0xe2
> >
> > The most likely suspect is the rt_spin_lock_slowlock() that is apparently
> > being acquired by migrate_enable(). This could be due to:
> >
> > 1. Massive contention on that lock.
> >
> > 2. Someone else holding that lock for excessive time periods.
> > Evidence in favor: CPU 0 appears to be running within
> > migrate_enable(). But isn't migrate_enable() really quite
> > lightweight?
> >
> > 3. Possible looping in the networking stack -- but this seems
> > unlikely given that we appear to have caught a lock acquisition
> > in the act. (Not impossible, however, if there are lots of
> > migrate_enable() calls in the networking stack, which there
> > are due to all the per-CPU work.)
> >
> > So which code do you think deserves the big lump of coal? ;-)
>
> Sebastian's NO_HZ_FULL locking fixes. Locking is hard, and rt sure
> doesn't make it any easier, so lets give him a cookie or three to nibble
> on while he ponders that trylock stuff again instead :)

Fair enough. Does Sebastian prefer milk and cookies or the other
tradition of beer and a cigar? ;-)

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/