lkml.org 
[lkml]   [2012]   [Jan]   [5]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
From
SubjectRe: [PATCH v5 7/8] mm: Only IPI CPUs to drain local pages if they exist
(Adding Greg to cc to see if he recalls seeing issues with sysfs dentry
suffering from recursive locking recently)

On Thu, Jan 05, 2012 at 10:35:04AM -0800, Paul E. McKenney wrote:
> On Thu, Jan 05, 2012 at 04:35:29PM +0000, Russell King - ARM Linux wrote:
> > On Thu, Jan 05, 2012 at 04:17:39PM +0000, Mel Gorman wrote:
> > > Link please?
> >
> > Forwarded, as its still in my mailbox.
> >
> > > I'm including a patch below under development that is
> > > intended to only cope with the page allocator case under heavy memory
> > > pressure. Currently it does not pass testing because eventually RCU
> > > gets stalled with the following trace
> > >
> > > [ 1817.176001] [<ffffffff810214d7>] arch_trigger_all_cpu_backtrace+0x87/0xa0
> > > [ 1817.176001] [<ffffffff810c4779>] __rcu_pending+0x149/0x260
> > > [ 1817.176001] [<ffffffff810c48ef>] rcu_check_callbacks+0x5f/0x110
> > > [ 1817.176001] [<ffffffff81068d7f>] update_process_times+0x3f/0x80
> > > [ 1817.176001] [<ffffffff8108c4eb>] tick_sched_timer+0x5b/0xc0
> > > [ 1817.176001] [<ffffffff8107f28e>] __run_hrtimer+0xbe/0x1a0
> > > [ 1817.176001] [<ffffffff8107f581>] hrtimer_interrupt+0xc1/0x1e0
> > > [ 1817.176001] [<ffffffff81020ef3>] smp_apic_timer_interrupt+0x63/0xa0
> > > [ 1817.176001] [<ffffffff81449073>] apic_timer_interrupt+0x13/0x20
> > > [ 1817.176001] [<ffffffff8116c135>] vfsmount_lock_local_lock+0x25/0x30
> > > [ 1817.176001] [<ffffffff8115c855>] path_init+0x2d5/0x370
> > > [ 1817.176001] [<ffffffff8115eecd>] path_lookupat+0x2d/0x620
> > > [ 1817.176001] [<ffffffff8115f4ef>] do_path_lookup+0x2f/0xd0
> > > [ 1817.176001] [<ffffffff811602af>] user_path_at_empty+0x9f/0xd0
> > > [ 1817.176001] [<ffffffff81154e7b>] vfs_fstatat+0x4b/0x90
> > > [ 1817.176001] [<ffffffff81154f4f>] sys_newlstat+0x1f/0x50
> > > [ 1817.176001] [<ffffffff81448692>] system_call_fastpath+0x16/0x1b
> > >
> > > It might be a separate bug, don't know for sure.
>

I rebased the patch on top of 3.2 and tested again with a bunch of
debugging options set (PROVE_RCU, PROVE_LOCKING etc). Same results. CPU
hotplug is a lot more reliable and less likely to hang but eventually
gets into trouble.

Taking a closer look though, I don't think this is an RCU problem. It's
just the messenger.

> Do you get multiple RCU CPU stall-warning messages?

Yes, one roughly every 50000 jiffies or so (HZ=250).
[ 878.315029] INFO: rcu_sched detected stall on CPU 3 (t=16250 jiffies)
[ 878.315032] INFO: rcu_sched detected stall on CPU 6 (t=16250 jiffies)
[ 1072.878669] INFO: rcu_sched detected stall on CPU 3 (t=65030 jiffies)
[ 1072.878672] INFO: rcu_sched detected stall on CPU 6 (t=65030 jiffies)
[ 1267.442308] INFO: rcu_sched detected stall on CPU 3 (t=113810 jiffies)
[ 1267.442312] INFO: rcu_sched detected stall on CPU 6 (t=113810 jiffies)
[ 1462.005948] INFO: rcu_sched detected stall on CPU 3 (t=162590 jiffies)
[ 1462.005952] INFO: rcu_sched detected stall on CPU 6 (t=162590 jiffies)
[ 1656.569588] INFO: rcu_sched detected stall on CPU 3 (t=211370 jiffies)
[ 1656.569592] INFO: rcu_sched detected stall on CPU 6 (t=211370 jiffies)
[ 1851.133229] INFO: rcu_sched detected stall on CPU 6 (t=260150 jiffies)
[ 1851.133233] INFO: rcu_sched detected stall on CPU 3 (t=260150 jiffies)
[ 2045.696868] INFO: rcu_sched detected stall on CPU 3 (t=308930 jiffies)
[ 2045.696872] INFO: rcu_sched detected stall on CPU 6 (t=308930 jiffies)
[ 2240.260508] INFO: rcu_sched detected stall on CPU 6 (t=357710 jiffies)
[ 2240.260511] INFO: rcu_sched detected stall on CPU 3 (t=357710 jiffies)

> If so, it can
> be helpful to look at how the stack frame changes over time. These
> stalls are normally caused by a loop in the kernel with preemption
> disabled, though other scenarios can also cause them.
>

The stacks are not changing much over time and start with this;

[ 878.315029] INFO: rcu_sched detected stall on CPU 3 (t=16250 jiffies)
[ 878.315032] INFO: rcu_sched detected stall on CPU 6 (t=16250 jiffies)
[ 878.315036] Pid: 4422, comm: udevd Not tainted 3.2.0-guardipi-v1r6 #2
[ 878.315037] Call Trace:
[ 878.315038] <IRQ> [<ffffffff810a8b20>] __rcu_pending+0x8e/0x36c
[ 878.315052] [<ffffffff81071b9a>] ? tick_nohz_handler+0xdc/0xdc
[ 878.315054] [<ffffffff810a8f04>] rcu_check_callbacks+0x106/0x172
[ 878.315056] [<ffffffff810528e0>] update_process_times+0x3f/0x76
[ 878.315058] [<ffffffff81071c0a>] tick_sched_timer+0x70/0x9a
[ 878.315060] [<ffffffff8106654e>] __run_hrtimer+0xc7/0x157
[ 878.315062] [<ffffffff810667ec>] hrtimer_interrupt+0xba/0x18a
[ 878.315065] [<ffffffff8134fbad>] smp_apic_timer_interrupt+0x86/0x99
[ 878.315067] [<ffffffff8134dbf3>] apic_timer_interrupt+0x73/0x80
[ 878.315068] <EOI> [<ffffffff81345f34>] ? retint_restore_args+0x13/0x13
[ 878.315072] [<ffffffff81139591>] ? __shrink_dcache_sb+0x7d/0x19f
[ 878.315075] [<ffffffff81008c6e>] ? native_read_tsc+0x1/0x16
[ 878.315077] [<ffffffff811df434>] ? delay_tsc+0x3a/0x82
[ 878.315079] [<ffffffff811df4a1>] __delay+0xf/0x11
[ 878.315081] [<ffffffff811e51e5>] do_raw_spin_lock+0xb5/0xf9
[ 878.315083] [<ffffffff81345561>] _raw_spin_lock+0x39/0x3d
[ 878.315085] [<ffffffff8113972a>] ? shrink_dcache_parent+0x77/0x28c
[ 878.315087] [<ffffffff8113972a>] shrink_dcache_parent+0x77/0x28c
[ 878.315089] [<ffffffff8113741d>] ? have_submounts+0x13e/0x1bd
[ 878.315092] [<ffffffff81185970>] sysfs_dentry_revalidate+0xaa/0xbe
[ 878.315093] [<ffffffff8112e731>] do_lookup+0x263/0x2fc
[ 878.315096] [<ffffffff8119ca13>] ? security_inode_permission+0x1e/0x20
[ 878.315098] [<ffffffff8112f33d>] link_path_walk+0x1e2/0x763
[ 878.315099] [<ffffffff8112fd66>] path_lookupat+0x5c/0x61a
[ 878.315102] [<ffffffff810f4810>] ? might_fault+0x89/0x8d
[ 878.315104] [<ffffffff810f47c7>] ? might_fault+0x40/0x8d
[ 878.315105] [<ffffffff8113034e>] do_path_lookup+0x2a/0xa8
[ 878.315107] [<ffffffff81132a51>] user_path_at_empty+0x5d/0x97
[ 878.315109] [<ffffffff8107447f>] ? trace_hardirqs_off+0xd/0xf
[ 878.315111] [<ffffffff81345c4f>] ? _raw_spin_unlock_irqrestore+0x44/0x5a
[ 878.315112] [<ffffffff81132a9c>] user_path_at+0x11/0x13
[ 878.315115] [<ffffffff81128b64>] vfs_fstatat+0x44/0x71
[ 878.315117] [<ffffffff81128bef>] vfs_lstat+0x1e/0x20
[ 878.315118] [<ffffffff81128c10>] sys_newlstat+0x1f/0x40
[ 878.315120] [<ffffffff810759a8>] ? trace_hardirqs_on_caller+0x12d/0x164
[ 878.315122] [<ffffffff811e057e>] ? trace_hardirqs_on_thunk+0x3a/0x3f
[ 878.315124] [<ffffffff8107447f>] ? trace_hardirqs_off+0xd/0xf
[ 878.315126] [<ffffffff8134d082>] system_call_fastpath+0x16/0x1b
[ 878.557790] Pid: 5704, comm: udevd Not tainted 3.2.0-guardipi-v1r6 #2
[ 878.564226] Call Trace:
[ 878.566677] <IRQ> [<ffffffff810a8b20>] __rcu_pending+0x8e/0x36c
[ 878.572783] [<ffffffff81071b9a>] ? tick_nohz_handler+0xdc/0xdc
[ 878.578702] [<ffffffff810a8f04>] rcu_check_callbacks+0x106/0x172
[ 878.584794] [<ffffffff810528e0>] update_process_times+0x3f/0x76
[ 878.590798] [<ffffffff81071c0a>] tick_sched_timer+0x70/0x9a
[ 878.596459] [<ffffffff8106654e>] __run_hrtimer+0xc7/0x157
[ 878.601944] [<ffffffff810667ec>] hrtimer_interrupt+0xba/0x18a
[ 878.607778] [<ffffffff8134fbad>] smp_apic_timer_interrupt+0x86/0x99
[ 878.614129] [<ffffffff8134dbf3>] apic_timer_interrupt+0x73/0x80
[ 878.620134] <EOI> [<ffffffff81051e66>] ? run_timer_softirq+0x49/0x32a
[ 878.626759] [<ffffffff81139591>] ? __shrink_dcache_sb+0x7d/0x19f
[ 878.632851] [<ffffffff811df402>] ? delay_tsc+0x8/0x82
[ 878.637988] [<ffffffff811df4a1>] __delay+0xf/0x11
[ 878.642778] [<ffffffff811e51e5>] do_raw_spin_lock+0xb5/0xf9
[ 878.648437] [<ffffffff81345561>] _raw_spin_lock+0x39/0x3d
[ 878.653920] [<ffffffff8113972a>] ? shrink_dcache_parent+0x77/0x28c
[ 878.660186] [<ffffffff8113972a>] shrink_dcache_parent+0x77/0x28c
[ 878.666277] [<ffffffff8113741d>] ? have_submounts+0x13e/0x1bd
[ 878.672107] [<ffffffff81185970>] sysfs_dentry_revalidate+0xaa/0xbe
[ 878.678372] [<ffffffff8112e731>] do_lookup+0x263/0x2fc
[ 878.683596] [<ffffffff8119ca13>] ? security_inode_permission+0x1e/0x20
[ 878.690207] [<ffffffff8112f33d>] link_path_walk+0x1e2/0x763
[ 878.695866] [<ffffffff8112fd66>] path_lookupat+0x5c/0x61a
[ 878.701350] [<ffffffff810f4810>] ? might_fault+0x89/0x8d
[ 878.706747] [<ffffffff810f47c7>] ? might_fault+0x40/0x8d
[ 878.712145] [<ffffffff8113034e>] do_path_lookup+0x2a/0xa8
[ 878.717630] [<ffffffff81132a51>] user_path_at_empty+0x5d/0x97
[ 878.723463] [<ffffffff8107447f>] ? trace_hardirqs_off+0xd/0xf
[ 878.729295] [<ffffffff81345c4f>] ? _raw_spin_unlock_irqrestore+0x44/0x5a
[ 878.736080] [<ffffffff81132a9c>] user_path_at+0x11/0x13
[ 878.741391] [<ffffffff81128b64>] vfs_fstatat+0x44/0x71
[ 878.746616] [<ffffffff81128bef>] vfs_lstat+0x1e/0x20
[ 878.751668] [<ffffffff81128c10>] sys_newlstat+0x1f/0x40
[ 878.756981] [<ffffffff810759a8>] ? trace_hardirqs_on_caller+0x12d/0x164
[ 878.763678] [<ffffffff811e057e>] ? trace_hardirqs_on_thunk+0x3a/0x3f
[ 878.770116] [<ffffffff8107447f>] ? trace_hardirqs_off+0xd/0xf
[ 878.775949] [<ffffffff8134d082>] system_call_fastpath+0x16/0x1b
[ 908.769486] BUG: spinlock lockup on CPU#6, udevd/4422
[ 908.774547] lock: ffff8803b4c701c8, .magic: dead4ead, .owner: udevd/5709, .owner_cpu: 4
Seeing that the owner was CPU 4, I found earlier in the log

[ 815.244051] BUG: spinlock lockup on CPU#4, udevd/5709
[ 815.249103] lock: ffff8803b4c701c8, .magic: dead4ead, .owner: udevd/5709, .owner_cpu: 4
[ 815.258430] Pid: 5709, comm: udevd Not tainted 3.2.0-guardipi-v1r6 #2
[ 815.264866] Call Trace:
[ 815.267329] [<ffffffff811e507d>] spin_dump+0x88/0x8d
[ 815.272388] [<ffffffff811e5206>] do_raw_spin_lock+0xd6/0xf9
[ 815.278062] [<ffffffff81345561>] ? _raw_spin_lock+0x39/0x3d
[ 815.283720] [<ffffffff8113972a>] ? shrink_dcache_parent+0x77/0x28c
[ 815.289986] [<ffffffff8113972a>] ? shrink_dcache_parent+0x77/0x28c
[ 815.296249] [<ffffffff8113741d>] ? have_submounts+0x13e/0x1bd
[ 815.302080] [<ffffffff81185970>] ? sysfs_dentry_revalidate+0xaa/0xbe
[ 815.308515] [<ffffffff8112e731>] ? do_lookup+0x263/0x2fc
[ 815.313915] [<ffffffff8119ca13>] ? security_inode_permission+0x1e/0x20
[ 815.320524] [<ffffffff8112f33d>] ? link_path_walk+0x1e2/0x763
[ 815.326357] [<ffffffff8112fd66>] ? path_lookupat+0x5c/0x61a
[ 815.332014] [<ffffffff810f4810>] ? might_fault+0x89/0x8d
[ 815.337410] [<ffffffff810f47c7>] ? might_fault+0x40/0x8d
[ 815.342807] [<ffffffff8113034e>] ? do_path_lookup+0x2a/0xa8
[ 815.348465] [<ffffffff81132a51>] ? user_path_at_empty+0x5d/0x97
[ 815.354474] [<ffffffff8107447f>] ? trace_hardirqs_off+0xd/0xf
[ 815.360303] [<ffffffff81345c4f>] ? _raw_spin_unlock_irqrestore+0x44/0x5a
[ 815.367085] [<ffffffff81132a9c>] ? user_path_at+0x11/0x13
[ 815.372569] [<ffffffff81128b64>] ? vfs_fstatat+0x44/0x71
[ 815.377965] [<ffffffff81128bef>] ? vfs_lstat+0x1e/0x20
[ 815.383192] [<ffffffff81128c10>] ? sys_newlstat+0x1f/0x40
[ 815.388676] [<ffffffff810759a8>] ? trace_hardirqs_on_caller+0x12d/0x164
[ 815.395373] [<ffffffff811e057e>] ? trace_hardirqs_on_thunk+0x3a/0x3f
[ 815.401811] [<ffffffff8107447f>] ? trace_hardirqs_off+0xd/0xf
[ 815.407642] [<ffffffff8134d082>] ? system_call_fastpath+0x16/0x1b
The trace is not particularly useful but it looks like it
recursively locked even though the message doesn't say that. If the
shrink_dcache_parent() entry is accurate, that corresponds to this

static int select_parent(struct dentry * parent)
{
struct dentry *this_parent;
struct list_head *next;
unsigned seq;
int found = 0;
int locked = 0;
seq = read_seqbegin(&rename_lock);
again:
this_parent = parent;
spin_lock(&this_parent->d_lock); <----- HERE
I'm not overly clear on how VFS locking is meant to work but it almost
looks as if the last reference to an inode is being dropped during a
sysfs path lookup. Is that meant to happen?

Judging by sysfs_dentry_revalidate() - possibly not. It looks like
we must have reached out_bad: and called shrink_dcache_parent() on a
dentry that was already locked by the running process. Not sure how
this could have happened - Greg, does this look familiar?

--
Mel Gorman
SUSE Labs


\
 
 \ /
  Last update: 2012-01-05 23:23    [from the cache]
©2003-2011 Jasper Spaans