fs: locks: WARNING: CPU: 16 PID: 4296 at fs/locks.c:236 locks_free_lock_context+0x10d/0x240()

fs: locks: WARNING: CPU: 16 PID: 4296 at fs/locks.c:236 locks_free_lock_context+0x10d/0x240()

[Sasha Levin]

Hey Jeff,

While fuzzing with trinity inside a KVM tools guest running the latest -next
kernel, I've stumbled on the following spew:

[  887.078606] WARNING: CPU: 16 PID: 4296 at fs/locks.c:236 locks_free_lock_context+0x10d/0x240()
[  887.079703] Modules linked in:
[  887.080288] CPU: 16 PID: 4296 Comm: trinity-c273 Not tainted 3.19.0-rc4-next-20150112-sasha-00053-g23c147e02e-dirty #1710
[  887.082229]  0000000000000000 0000000000000000 0000000000000000 ffff8804c9f4f8e8
[  887.083773]  ffffffff9154e0a6 0000000000000000 ffff8804cad98000 ffff8804c9f4f938
[  887.085280]  ffffffff8140a4d0 0000000000000001 ffffffff81bf0d2d ffff8804c9f4f988
[  887.086792] Call Trace:
[  887.087320] dump_stack (lib/dump_stack.c:52)
[  887.088247] warn_slowpath_common (kernel/panic.c:447)
[  887.089342] ? locks_free_lock_context (fs/locks.c:236 (discriminator 3))
[  887.090514] warn_slowpath_null (kernel/panic.c:481)
[  887.091629] locks_free_lock_context (fs/locks.c:236 (discriminator 3))
[  887.092782] __destroy_inode (fs/inode.c:243)
[  887.093817] destroy_inode (fs/inode.c:268)
[  887.094833] evict (fs/inode.c:574)
[  887.095808] iput (fs/inode.c:1503)
[  887.096687] __dentry_kill (fs/dcache.c:323 fs/dcache.c:508)
[  887.097683] ? _raw_spin_trylock (kernel/locking/spinlock.c:136)
[  887.098733] ? dput (fs/dcache.c:545 fs/dcache.c:648)
[  887.099672] dput (fs/dcache.c:649)
[  887.100552] __fput (fs/file_table.c:227)
[  887.101437] ____fput (fs/file_table.c:245)
[  887.102317] task_work_run (kernel/task_work.c:125 (discriminator 1))
[  887.103356] ? _raw_spin_unlock (./arch/x86/include/asm/preempt.h:95 include/linux/spinlock_api_smp.h:154 kernel/locking/spinlock.c:183)
[  887.104390] do_exit (kernel/exit.c:746)
[  887.105338] ? task_numa_work (kernel/sched/fair.c:2218)
[  887.106384] ? get_signal (kernel/signal.c:2207)
[  887.107492] ? _raw_spin_unlock_irq (./arch/x86/include/asm/paravirt.h:819 include/linux/spinlock_api_smp.h:170 kernel/locking/spinlock.c:199)
[  887.108610] do_group_exit (include/linux/sched.h:775 kernel/exit.c:858)
[  887.109613] get_signal (kernel/signal.c:2358)
[  887.110578] ? trace_hardirqs_off (kernel/locking/lockdep.c:2671)
[  887.111672] do_signal (arch/x86/kernel/signal.c:703)
[  887.112604] ? acct_account_cputime (kernel/tsacct.c:168)
[  887.113722] ? context_tracking_user_exit (./arch/x86/include/asm/paravirt.h:809 (discriminator 2) kernel/context_tracking.c:144 (discriminator 2))
[  887.114937] ? trace_hardirqs_on_caller (kernel/locking/lockdep.c:2578 kernel/locking/lockdep.c:2625)
[  887.116128] ? trace_hardirqs_on (kernel/locking/lockdep.c:2633)
[  887.117160] do_notify_resume (arch/x86/kernel/signal.c:750)
[  887.118167] int_signal (arch/x86/kernel/entry_64.S:587)


Thanks,
Sasha

Re: fs: locks: WARNING: CPU: 16 PID: 4296 at fs/locks.c:236 locks_free_lock_context+0x10d/0x240()

[Jeff Layton]

On Tue, 13 Jan 2015 00:11:37 -0500
Sasha Levin <sasha.levin@oracle.com> wrote:

> Hey Jeff,
> 
> While fuzzing with trinity inside a KVM tools guest running the latest -next
> kernel, I've stumbled on the following spew:
> 
> [  887.078606] WARNING: CPU: 16 PID: 4296 at fs/locks.c:236 locks_free_lock_context+0x10d/0x240()
> [  887.079703] Modules linked in:
> [  887.080288] CPU: 16 PID: 4296 Comm: trinity-c273 Not tainted 3.19.0-rc4-next-20150112-sasha-00053-g23c147e02e-dirty #1710
> [  887.082229]  0000000000000000 0000000000000000 0000000000000000 ffff8804c9f4f8e8
> [  887.083773]  ffffffff9154e0a6 0000000000000000 ffff8804cad98000 ffff8804c9f4f938
> [  887.085280]  ffffffff8140a4d0 0000000000000001 ffffffff81bf0d2d ffff8804c9f4f988
> [  887.086792] Call Trace:
> [  887.087320] dump_stack (lib/dump_stack.c:52)
> [  887.088247] warn_slowpath_common (kernel/panic.c:447)
> [  887.089342] ? locks_free_lock_context (fs/locks.c:236 (discriminator 3))
> [  887.090514] warn_slowpath_null (kernel/panic.c:481)
> [  887.091629] locks_free_lock_context (fs/locks.c:236 (discriminator 3))
> [  887.092782] __destroy_inode (fs/inode.c:243)
> [  887.093817] destroy_inode (fs/inode.c:268)
> [  887.094833] evict (fs/inode.c:574)
> [  887.095808] iput (fs/inode.c:1503)
> [  887.096687] __dentry_kill (fs/dcache.c:323 fs/dcache.c:508)
> [  887.097683] ? _raw_spin_trylock (kernel/locking/spinlock.c:136)
> [  887.098733] ? dput (fs/dcache.c:545 fs/dcache.c:648)
> [  887.099672] dput (fs/dcache.c:649)
> [  887.100552] __fput (fs/file_table.c:227)
> [  887.101437] ____fput (fs/file_table.c:245)
> [  887.102317] task_work_run (kernel/task_work.c:125 (discriminator 1))
> [  887.103356] ? _raw_spin_unlock (./arch/x86/include/asm/preempt.h:95 include/linux/spinlock_api_smp.h:154 kernel/locking/spinlock.c:183)
> [  887.104390] do_exit (kernel/exit.c:746)
> [  887.105338] ? task_numa_work (kernel/sched/fair.c:2218)
> [  887.106384] ? get_signal (kernel/signal.c:2207)
> [  887.107492] ? _raw_spin_unlock_irq (./arch/x86/include/asm/paravirt.h:819 include/linux/spinlock_api_smp.h:170 kernel/locking/spinlock.c:199)
> [  887.108610] do_group_exit (include/linux/sched.h:775 kernel/exit.c:858)
> [  887.109613] get_signal (kernel/signal.c:2358)
> [  887.110578] ? trace_hardirqs_off (kernel/locking/lockdep.c:2671)
> [  887.111672] do_signal (arch/x86/kernel/signal.c:703)
> [  887.112604] ? acct_account_cputime (kernel/tsacct.c:168)
> [  887.113722] ? context_tracking_user_exit (./arch/x86/include/asm/paravirt.h:809 (discriminator 2) kernel/context_tracking.c:144 (discriminator 2))
> [  887.114937] ? trace_hardirqs_on_caller (kernel/locking/lockdep.c:2578 kernel/locking/lockdep.c:2625)
> [  887.116128] ? trace_hardirqs_on (kernel/locking/lockdep.c:2633)
> [  887.117160] do_notify_resume (arch/x86/kernel/signal.c:750)
> [  887.118167] int_signal (arch/x86/kernel/entry_64.S:587)
> 
> 

Huh...

Looks like the flc_flock list wasn't empty when we went to go free the
inode. I don't see how that would happen right offhand, but I'll keep
looking at it.

Just to be clear -- were there any "exotic" filesystems involved here?
In particular any that define a ->flock inode operation (e.g. NFS) ?

Thanks for the report...
-- 
Jeff Layton <jlayton@primarydata.com>

Re: fs: locks: WARNING: CPU: 16 PID: 4296 at fs/locks.c:236 locks_free_lock_context+0x10d/0x240()

[Sasha Levin]

On 01/13/2015 08:20 AM, Jeff Layton wrote:
> On Tue, 13 Jan 2015 00:11:37 -0500
> Sasha Levin <sasha.levin@oracle.com> wrote:
> 
>> Hey Jeff,
>>
>> While fuzzing with trinity inside a KVM tools guest running the latest -next
>> kernel, I've stumbled on the following spew:
>>
>> [  887.078606] WARNING: CPU: 16 PID: 4296 at fs/locks.c:236 locks_free_lock_context+0x10d/0x240()
>> [  887.079703] Modules linked in:
>> [  887.080288] CPU: 16 PID: 4296 Comm: trinity-c273 Not tainted 3.19.0-rc4-next-20150112-sasha-00053-g23c147e02e-dirty #1710
>> [  887.082229]  0000000000000000 0000000000000000 0000000000000000 ffff8804c9f4f8e8
>> [  887.083773]  ffffffff9154e0a6 0000000000000000 ffff8804cad98000 ffff8804c9f4f938
>> [  887.085280]  ffffffff8140a4d0 0000000000000001 ffffffff81bf0d2d ffff8804c9f4f988
>> [  887.086792] Call Trace:
>> [  887.087320] dump_stack (lib/dump_stack.c:52)
>> [  887.088247] warn_slowpath_common (kernel/panic.c:447)
>> [  887.089342] ? locks_free_lock_context (fs/locks.c:236 (discriminator 3))
>> [  887.090514] warn_slowpath_null (kernel/panic.c:481)
>> [  887.091629] locks_free_lock_context (fs/locks.c:236 (discriminator 3))
>> [  887.092782] __destroy_inode (fs/inode.c:243)
>> [  887.093817] destroy_inode (fs/inode.c:268)
>> [  887.094833] evict (fs/inode.c:574)
>> [  887.095808] iput (fs/inode.c:1503)
>> [  887.096687] __dentry_kill (fs/dcache.c:323 fs/dcache.c:508)
>> [  887.097683] ? _raw_spin_trylock (kernel/locking/spinlock.c:136)
>> [  887.098733] ? dput (fs/dcache.c:545 fs/dcache.c:648)
>> [  887.099672] dput (fs/dcache.c:649)
>> [  887.100552] __fput (fs/file_table.c:227)
>> [  887.101437] ____fput (fs/file_table.c:245)
>> [  887.102317] task_work_run (kernel/task_work.c:125 (discriminator 1))
>> [  887.103356] ? _raw_spin_unlock (./arch/x86/include/asm/preempt.h:95 include/linux/spinlock_api_smp.h:154 kernel/locking/spinlock.c:183)
>> [  887.104390] do_exit (kernel/exit.c:746)
>> [  887.105338] ? task_numa_work (kernel/sched/fair.c:2218)
>> [  887.106384] ? get_signal (kernel/signal.c:2207)
>> [  887.107492] ? _raw_spin_unlock_irq (./arch/x86/include/asm/paravirt.h:819 include/linux/spinlock_api_smp.h:170 kernel/locking/spinlock.c:199)
>> [  887.108610] do_group_exit (include/linux/sched.h:775 kernel/exit.c:858)
>> [  887.109613] get_signal (kernel/signal.c:2358)
>> [  887.110578] ? trace_hardirqs_off (kernel/locking/lockdep.c:2671)
>> [  887.111672] do_signal (arch/x86/kernel/signal.c:703)
>> [  887.112604] ? acct_account_cputime (kernel/tsacct.c:168)
>> [  887.113722] ? context_tracking_user_exit (./arch/x86/include/asm/paravirt.h:809 (discriminator 2) kernel/context_tracking.c:144 (discriminator 2))
>> [  887.114937] ? trace_hardirqs_on_caller (kernel/locking/lockdep.c:2578 kernel/locking/lockdep.c:2625)
>> [  887.116128] ? trace_hardirqs_on (kernel/locking/lockdep.c:2633)
>> [  887.117160] do_notify_resume (arch/x86/kernel/signal.c:750)
>> [  887.118167] int_signal (arch/x86/kernel/entry_64.S:587)
>>
>>
> 
> Huh...
> 
> Looks like the flc_flock list wasn't empty when we went to go free the
> inode. I don't see how that would happen right offhand, but I'll keep
> looking at it.
> 
> Just to be clear -- were there any "exotic" filesystems involved here?

Probably. Part of the preparation for the fuzzer is to mount every single filesystem
we can and use it as scratch space for fuzzing.

> In particular any that define a ->flock inode operation (e.g. NFS) ?

There are a few. Since this bug is pretty reproducible I'll add in something to
dump the lock when that happens and see if we can get anything out of it.


Thanks,
Sasha

Re: fs: locks: WARNING: CPU: 16 PID: 4296 at fs/locks.c:236 locks_free_lock_context+0x10d/0x240()

[Jeff Layton]

On Tue, 13 Jan 2015 00:11:37 -0500
Sasha Levin <sasha.levin@oracle.com> wrote:

> Hey Jeff,
> 
> While fuzzing with trinity inside a KVM tools guest running the latest -next
> kernel, I've stumbled on the following spew:
> 
> [  887.078606] WARNING: CPU: 16 PID: 4296 at fs/locks.c:236 locks_free_lock_context+0x10d/0x240()
> [  887.079703] Modules linked in:
> [  887.080288] CPU: 16 PID: 4296 Comm: trinity-c273 Not tainted 3.19.0-rc4-next-20150112-sasha-00053-g23c147e02e-dirty #1710
> [  887.082229]  0000000000000000 0000000000000000 0000000000000000 ffff8804c9f4f8e8
> [  887.083773]  ffffffff9154e0a6 0000000000000000 ffff8804cad98000 ffff8804c9f4f938
> [  887.085280]  ffffffff8140a4d0 0000000000000001 ffffffff81bf0d2d ffff8804c9f4f988
> [  887.086792] Call Trace:
> [  887.087320] dump_stack (lib/dump_stack.c:52)
> [  887.088247] warn_slowpath_common (kernel/panic.c:447)
> [  887.089342] ? locks_free_lock_context (fs/locks.c:236 (discriminator 3))
> [  887.090514] warn_slowpath_null (kernel/panic.c:481)
> [  887.091629] locks_free_lock_context (fs/locks.c:236 (discriminator 3))
> [  887.092782] __destroy_inode (fs/inode.c:243)
> [  887.093817] destroy_inode (fs/inode.c:268)
> [  887.094833] evict (fs/inode.c:574)
> [  887.095808] iput (fs/inode.c:1503)
> [  887.096687] __dentry_kill (fs/dcache.c:323 fs/dcache.c:508)
> [  887.097683] ? _raw_spin_trylock (kernel/locking/spinlock.c:136)
> [  887.098733] ? dput (fs/dcache.c:545 fs/dcache.c:648)
> [  887.099672] dput (fs/dcache.c:649)
> [  887.100552] __fput (fs/file_table.c:227)

So, looking at this a bit more...

It's clear that we're at the dput in __fput at this point. Much earlier
in __fput, we call locks_remove_file to remove all of the locks that
are associated with the file description.

Evidently though, something didn't go right there. The two most likely
scenarios to my mind are:

A) a lock raced onto the list somehow after that point. That seems
unlikely since presumably the fcheck should have failed at that point.

...or...

B) the CPU that called locks_remove_file mistakenly thought that
inode->i_flctx was NULL when it really wasn't (stale cache, perhaps?).
That would make it skip trying to remove any flock locks.

B seems more likely to me, and if it's the case then that would seem to
imply that we need some memory barriers (or maybe some ACCESS_ONCE
calls) in these codepaths. I'll have to sit down and work through it to
see what makes the most sense.

If your debugging seems to jive with this, then one thing that might be
interesting would be to comment out these two lines in
locks_remove_flock:

        if (!file_inode(filp)->i_flctx)
                return;

...and see if it's still reproducible. That's obviously not a real fix
for this problem, but it might help prove whether the above suspicion
is correct.

Thanks,
-- 
Jeff Layton <jlayton@primarydata.com>

Re: fs: locks: WARNING: CPU: 16 PID: 4296 at fs/locks.c:236 locks_free_lock_context+0x10d/0x240()

[Sasha Levin]

On 01/13/2015 04:44 PM, Jeff Layton wrote:
> On Tue, 13 Jan 2015 00:11:37 -0500
> Sasha Levin <sasha.levin@oracle.com> wrote:
> 
>> Hey Jeff,
>>
>> While fuzzing with trinity inside a KVM tools guest running the latest -next
>> kernel, I've stumbled on the following spew:
>>
>> [  887.078606] WARNING: CPU: 16 PID: 4296 at fs/locks.c:236 locks_free_lock_context+0x10d/0x240()
>> [  887.079703] Modules linked in:
>> [  887.080288] CPU: 16 PID: 4296 Comm: trinity-c273 Not tainted 3.19.0-rc4-next-20150112-sasha-00053-g23c147e02e-dirty #1710
>> [  887.082229]  0000000000000000 0000000000000000 0000000000000000 ffff8804c9f4f8e8
>> [  887.083773]  ffffffff9154e0a6 0000000000000000 ffff8804cad98000 ffff8804c9f4f938
>> [  887.085280]  ffffffff8140a4d0 0000000000000001 ffffffff81bf0d2d ffff8804c9f4f988
>> [  887.086792] Call Trace:
>> [  887.087320] dump_stack (lib/dump_stack.c:52)
>> [  887.088247] warn_slowpath_common (kernel/panic.c:447)
>> [  887.089342] ? locks_free_lock_context (fs/locks.c:236 (discriminator 3))
>> [  887.090514] warn_slowpath_null (kernel/panic.c:481)
>> [  887.091629] locks_free_lock_context (fs/locks.c:236 (discriminator 3))
>> [  887.092782] __destroy_inode (fs/inode.c:243)
>> [  887.093817] destroy_inode (fs/inode.c:268)
>> [  887.094833] evict (fs/inode.c:574)
>> [  887.095808] iput (fs/inode.c:1503)
>> [  887.096687] __dentry_kill (fs/dcache.c:323 fs/dcache.c:508)
>> [  887.097683] ? _raw_spin_trylock (kernel/locking/spinlock.c:136)
>> [  887.098733] ? dput (fs/dcache.c:545 fs/dcache.c:648)
>> [  887.099672] dput (fs/dcache.c:649)
>> [  887.100552] __fput (fs/file_table.c:227)
> 
> So, looking at this a bit more...
> 
> It's clear that we're at the dput in __fput at this point. Much earlier
> in __fput, we call locks_remove_file to remove all of the locks that
> are associated with the file description.
> 
> Evidently though, something didn't go right there. The two most likely
> scenarios to my mind are:
> 
> A) a lock raced onto the list somehow after that point. That seems
> unlikely since presumably the fcheck should have failed at that point.
> 
> ...or...
> 
> B) the CPU that called locks_remove_file mistakenly thought that
> inode->i_flctx was NULL when it really wasn't (stale cache, perhaps?).
> That would make it skip trying to remove any flock locks.
> 
> B seems more likely to me, and if it's the case then that would seem to
> imply that we need some memory barriers (or maybe some ACCESS_ONCE
> calls) in these codepaths. I'll have to sit down and work through it to
> see what makes the most sense.
> 
> If your debugging seems to jive with this, then one thing that might be
> interesting would be to comment out these two lines in
> locks_remove_flock:
> 
>         if (!file_inode(filp)->i_flctx)
>                 return;
> 
> ...and see if it's still reproducible. That's obviously not a real fix
> for this problem, but it might help prove whether the above suspicion
> is correct.

Removing those two lines makes the issue go away.

I'm guessing that figuring out which filesystem we were abusing isn't
interesting anymore...


Thanks,
Sasha

Re: fs: locks: WARNING: CPU: 16 PID: 4296 at fs/locks.c:236 locks_free_lock_context+0x10d/0x240()

[Jeff Layton]

On Tue, 13 Jan 2015 17:50:45 -0500
Sasha Levin <sasha.levin@oracle.com> wrote:

> On 01/13/2015 04:44 PM, Jeff Layton wrote:
> > On Tue, 13 Jan 2015 00:11:37 -0500
> > Sasha Levin <sasha.levin@oracle.com> wrote:
> > 
> >> Hey Jeff,
> >>
> >> While fuzzing with trinity inside a KVM tools guest running the latest -next
> >> kernel, I've stumbled on the following spew:
> >>
> >> [  887.078606] WARNING: CPU: 16 PID: 4296 at fs/locks.c:236 locks_free_lock_context+0x10d/0x240()
> >> [  887.079703] Modules linked in:
> >> [  887.080288] CPU: 16 PID: 4296 Comm: trinity-c273 Not tainted 3.19.0-rc4-next-20150112-sasha-00053-g23c147e02e-dirty #1710
> >> [  887.082229]  0000000000000000 0000000000000000 0000000000000000 ffff8804c9f4f8e8
> >> [  887.083773]  ffffffff9154e0a6 0000000000000000 ffff8804cad98000 ffff8804c9f4f938
> >> [  887.085280]  ffffffff8140a4d0 0000000000000001 ffffffff81bf0d2d ffff8804c9f4f988
> >> [  887.086792] Call Trace:
> >> [  887.087320] dump_stack (lib/dump_stack.c:52)
> >> [  887.088247] warn_slowpath_common (kernel/panic.c:447)
> >> [  887.089342] ? locks_free_lock_context (fs/locks.c:236 (discriminator 3))
> >> [  887.090514] warn_slowpath_null (kernel/panic.c:481)
> >> [  887.091629] locks_free_lock_context (fs/locks.c:236 (discriminator 3))
> >> [  887.092782] __destroy_inode (fs/inode.c:243)
> >> [  887.093817] destroy_inode (fs/inode.c:268)
> >> [  887.094833] evict (fs/inode.c:574)
> >> [  887.095808] iput (fs/inode.c:1503)
> >> [  887.096687] __dentry_kill (fs/dcache.c:323 fs/dcache.c:508)
> >> [  887.097683] ? _raw_spin_trylock (kernel/locking/spinlock.c:136)
> >> [  887.098733] ? dput (fs/dcache.c:545 fs/dcache.c:648)
> >> [  887.099672] dput (fs/dcache.c:649)
> >> [  887.100552] __fput (fs/file_table.c:227)
> > 
> > So, looking at this a bit more...
> > 
> > It's clear that we're at the dput in __fput at this point. Much earlier
> > in __fput, we call locks_remove_file to remove all of the locks that
> > are associated with the file description.
> > 
> > Evidently though, something didn't go right there. The two most likely
> > scenarios to my mind are:
> > 
> > A) a lock raced onto the list somehow after that point. That seems
> > unlikely since presumably the fcheck should have failed at that point.
> > 
> > ...or...
> > 
> > B) the CPU that called locks_remove_file mistakenly thought that
> > inode->i_flctx was NULL when it really wasn't (stale cache, perhaps?).
> > That would make it skip trying to remove any flock locks.
> > 
> > B seems more likely to me, and if it's the case then that would seem to
> > imply that we need some memory barriers (or maybe some ACCESS_ONCE
> > calls) in these codepaths. I'll have to sit down and work through it to
> > see what makes the most sense.
> > 
> > If your debugging seems to jive with this, then one thing that might be
> > interesting would be to comment out these two lines in
> > locks_remove_flock:
> > 
> >         if (!file_inode(filp)->i_flctx)
> >                 return;
> > 
> > ...and see if it's still reproducible. That's obviously not a real fix
> > for this problem, but it might help prove whether the above suspicion
> > is correct.
> 
> Removing those two lines makes the issue go away.
> 

Wow, that was quick! Thanks!

I'll need to ponder how best to fix this. I wonder if we need something
like an ACCESS_ONCE there, or maybe a smp_rmb() prior to that might be
sufficient? The pointer is assigned with cmpxchg(), so that should have
an implicit mb already.

Guess I need to set up a trinity test rig of my own and see if I can
reproduce this myself.

> I'm guessing that figuring out which filesystem we were abusing isn't
> interesting anymore...
> 

Yeah, probably not. If you've already figured it out, then please do
share, but there's no need to put forth further effort if not. I'll let
you know once I've got something that I think will work.

Thanks for the help so far!
-- 
Jeff Layton <jlayton@primarydata.com>

Re: fs: locks: WARNING: CPU: 16 PID: 4296 at fs/locks.c:236 locks_free_lock_context+0x10d/0x240()

[Jeff Layton]

On Tue, 13 Jan 2015 17:50:45 -0500
Sasha Levin <sasha.levin@oracle.com> wrote:

> On 01/13/2015 04:44 PM, Jeff Layton wrote:
> > On Tue, 13 Jan 2015 00:11:37 -0500
> > Sasha Levin <sasha.levin@oracle.com> wrote:
> > 
> >> Hey Jeff,
> >>
> >> While fuzzing with trinity inside a KVM tools guest running the latest -next
> >> kernel, I've stumbled on the following spew:
> >>
> >> [  887.078606] WARNING: CPU: 16 PID: 4296 at fs/locks.c:236 locks_free_lock_context+0x10d/0x240()
> >> [  887.079703] Modules linked in:
> >> [  887.080288] CPU: 16 PID: 4296 Comm: trinity-c273 Not tainted 3.19.0-rc4-next-20150112-sasha-00053-g23c147e02e-dirty #1710
> >> [  887.082229]  0000000000000000 0000000000000000 0000000000000000 ffff8804c9f4f8e8
> >> [  887.083773]  ffffffff9154e0a6 0000000000000000 ffff8804cad98000 ffff8804c9f4f938
> >> [  887.085280]  ffffffff8140a4d0 0000000000000001 ffffffff81bf0d2d ffff8804c9f4f988
> >> [  887.086792] Call Trace:
> >> [  887.087320] dump_stack (lib/dump_stack.c:52)
> >> [  887.088247] warn_slowpath_common (kernel/panic.c:447)
> >> [  887.089342] ? locks_free_lock_context (fs/locks.c:236 (discriminator 3))
> >> [  887.090514] warn_slowpath_null (kernel/panic.c:481)
> >> [  887.091629] locks_free_lock_context (fs/locks.c:236 (discriminator 3))
> >> [  887.092782] __destroy_inode (fs/inode.c:243)
> >> [  887.093817] destroy_inode (fs/inode.c:268)
> >> [  887.094833] evict (fs/inode.c:574)
> >> [  887.095808] iput (fs/inode.c:1503)
> >> [  887.096687] __dentry_kill (fs/dcache.c:323 fs/dcache.c:508)
> >> [  887.097683] ? _raw_spin_trylock (kernel/locking/spinlock.c:136)
> >> [  887.098733] ? dput (fs/dcache.c:545 fs/dcache.c:648)
> >> [  887.099672] dput (fs/dcache.c:649)
> >> [  887.100552] __fput (fs/file_table.c:227)
> > 
> > So, looking at this a bit more...
> > 
> > It's clear that we're at the dput in __fput at this point. Much earlier
> > in __fput, we call locks_remove_file to remove all of the locks that
> > are associated with the file description.
> > 
> > Evidently though, something didn't go right there. The two most likely
> > scenarios to my mind are:
> > 
> > A) a lock raced onto the list somehow after that point. That seems
> > unlikely since presumably the fcheck should have failed at that point.
> > 
> > ...or...
> > 
> > B) the CPU that called locks_remove_file mistakenly thought that
> > inode->i_flctx was NULL when it really wasn't (stale cache, perhaps?).
> > That would make it skip trying to remove any flock locks.
> > 
> > B seems more likely to me, and if it's the case then that would seem to
> > imply that we need some memory barriers (or maybe some ACCESS_ONCE
> > calls) in these codepaths. I'll have to sit down and work through it to
> > see what makes the most sense.
> > 
> > If your debugging seems to jive with this, then one thing that might be
> > interesting would be to comment out these two lines in
> > locks_remove_flock:
> > 
> >         if (!file_inode(filp)->i_flctx)
> >                 return;
> > 
> > ...and see if it's still reproducible. That's obviously not a real fix
> > for this problem, but it might help prove whether the above suspicion
> > is correct.
> 
> Removing those two lines makes the issue go away.
> 
> I'm guessing that figuring out which filesystem we were abusing isn't
> interesting anymore...
> 

Sigh. I've been trying to reproduce this today. I've set up two
different KVM guests on two different hosts, and run trinity on both,
and I can't seem to get this warning to pop.

Could you share what trinity command-line options you're using? Any
other special setup I should be considering to reproduce it?

I was hoping to get it to reproduce so I could test out potential
memory barrier fixes...

-- 
Jeff Layton <jlayton@primarydata.com>

Re: fs: locks: WARNING: CPU: 16 PID: 4296 at fs/locks.c:236 locks_free_lock_context+0x10d/0x240()

[Sasha Levin]

On 01/14/2015 09:27 AM, Jeff Layton wrote:
> On Tue, 13 Jan 2015 17:50:45 -0500
> Sasha Levin <sasha.levin@oracle.com> wrote:
> 
>> On 01/13/2015 04:44 PM, Jeff Layton wrote:
>>> On Tue, 13 Jan 2015 00:11:37 -0500
>>> Sasha Levin <sasha.levin@oracle.com> wrote:
>>>
>>>> Hey Jeff,
>>>>
>>>> While fuzzing with trinity inside a KVM tools guest running the latest -next
>>>> kernel, I've stumbled on the following spew:
>>>>
>>>> [  887.078606] WARNING: CPU: 16 PID: 4296 at fs/locks.c:236 locks_free_lock_context+0x10d/0x240()
>>>> [  887.079703] Modules linked in:
>>>> [  887.080288] CPU: 16 PID: 4296 Comm: trinity-c273 Not tainted 3.19.0-rc4-next-20150112-sasha-00053-g23c147e02e-dirty #1710
>>>> [  887.082229]  0000000000000000 0000000000000000 0000000000000000 ffff8804c9f4f8e8
>>>> [  887.083773]  ffffffff9154e0a6 0000000000000000 ffff8804cad98000 ffff8804c9f4f938
>>>> [  887.085280]  ffffffff8140a4d0 0000000000000001 ffffffff81bf0d2d ffff8804c9f4f988
>>>> [  887.086792] Call Trace:
>>>> [  887.087320] dump_stack (lib/dump_stack.c:52)
>>>> [  887.088247] warn_slowpath_common (kernel/panic.c:447)
>>>> [  887.089342] ? locks_free_lock_context (fs/locks.c:236 (discriminator 3))
>>>> [  887.090514] warn_slowpath_null (kernel/panic.c:481)
>>>> [  887.091629] locks_free_lock_context (fs/locks.c:236 (discriminator 3))
>>>> [  887.092782] __destroy_inode (fs/inode.c:243)
>>>> [  887.093817] destroy_inode (fs/inode.c:268)
>>>> [  887.094833] evict (fs/inode.c:574)
>>>> [  887.095808] iput (fs/inode.c:1503)
>>>> [  887.096687] __dentry_kill (fs/dcache.c:323 fs/dcache.c:508)
>>>> [  887.097683] ? _raw_spin_trylock (kernel/locking/spinlock.c:136)
>>>> [  887.098733] ? dput (fs/dcache.c:545 fs/dcache.c:648)
>>>> [  887.099672] dput (fs/dcache.c:649)
>>>> [  887.100552] __fput (fs/file_table.c:227)
>>>
>>> So, looking at this a bit more...
>>>
>>> It's clear that we're at the dput in __fput at this point. Much earlier
>>> in __fput, we call locks_remove_file to remove all of the locks that
>>> are associated with the file description.
>>>
>>> Evidently though, something didn't go right there. The two most likely
>>> scenarios to my mind are:
>>>
>>> A) a lock raced onto the list somehow after that point. That seems
>>> unlikely since presumably the fcheck should have failed at that point.
>>>
>>> ...or...
>>>
>>> B) the CPU that called locks_remove_file mistakenly thought that
>>> inode->i_flctx was NULL when it really wasn't (stale cache, perhaps?).
>>> That would make it skip trying to remove any flock locks.
>>>
>>> B seems more likely to me, and if it's the case then that would seem to
>>> imply that we need some memory barriers (or maybe some ACCESS_ONCE
>>> calls) in these codepaths. I'll have to sit down and work through it to
>>> see what makes the most sense.
>>>
>>> If your debugging seems to jive with this, then one thing that might be
>>> interesting would be to comment out these two lines in
>>> locks_remove_flock:
>>>
>>>         if (!file_inode(filp)->i_flctx)
>>>                 return;
>>>
>>> ...and see if it's still reproducible. That's obviously not a real fix
>>> for this problem, but it might help prove whether the above suspicion
>>> is correct.
>>
>> Removing those two lines makes the issue go away.
>>
>> I'm guessing that figuring out which filesystem we were abusing isn't
>> interesting anymore...
>>
> 
> Sigh. I've been trying to reproduce this today. I've set up two
> different KVM guests on two different hosts, and run trinity on both,
> and I can't seem to get this warning to pop.
> 
> Could you share what trinity command-line options you're using? Any
> other special setup I should be considering to reproduce it?
> 
> I was hoping to get it to reproduce so I could test out potential
> memory barrier fixes...

I don't think there's anything special about my setup here that can
trigger that, specially if it's not dependant on a filesystem in use.

I'm running trinity with: ./trinity -xsched_setattr -xsetpriority
-xunshare -xreboot -xshutdown -xnfsservctl -xclock_nanosleep -xuselib
-xperf_event_open -m --quiet --dangerous -C 400 -l off

If that doesn't end up helping, I'd be happy to test out fixes here,
it usually reproduces quickly.


Thanks,
Sasha

Re: fs: locks: WARNING: CPU: 16 PID: 4296 at fs/locks.c:236 locks_free_lock_context+0x10d/0x240()

[Jeff Layton]

On Wed, 14 Jan 2015 18:44:41 -0500
Sasha Levin <sasha.levin@oracle.com> wrote:

> On 01/14/2015 09:27 AM, Jeff Layton wrote:
> > On Tue, 13 Jan 2015 17:50:45 -0500
> > Sasha Levin <sasha.levin@oracle.com> wrote:
> > 
> >> On 01/13/2015 04:44 PM, Jeff Layton wrote:
> >>> On Tue, 13 Jan 2015 00:11:37 -0500
> >>> Sasha Levin <sasha.levin@oracle.com> wrote:
> >>>
> >>>> Hey Jeff,
> >>>>
> >>>> While fuzzing with trinity inside a KVM tools guest running the latest -next
> >>>> kernel, I've stumbled on the following spew:
> >>>>
> >>>> [  887.078606] WARNING: CPU: 16 PID: 4296 at fs/locks.c:236 locks_free_lock_context+0x10d/0x240()
> >>>> [  887.079703] Modules linked in:
> >>>> [  887.080288] CPU: 16 PID: 4296 Comm: trinity-c273 Not tainted 3.19.0-rc4-next-20150112-sasha-00053-g23c147e02e-dirty #1710
> >>>> [  887.082229]  0000000000000000 0000000000000000 0000000000000000 ffff8804c9f4f8e8
> >>>> [  887.083773]  ffffffff9154e0a6 0000000000000000 ffff8804cad98000 ffff8804c9f4f938
> >>>> [  887.085280]  ffffffff8140a4d0 0000000000000001 ffffffff81bf0d2d ffff8804c9f4f988
> >>>> [  887.086792] Call Trace:
> >>>> [  887.087320] dump_stack (lib/dump_stack.c:52)
> >>>> [  887.088247] warn_slowpath_common (kernel/panic.c:447)
> >>>> [  887.089342] ? locks_free_lock_context (fs/locks.c:236 (discriminator 3))
> >>>> [  887.090514] warn_slowpath_null (kernel/panic.c:481)
> >>>> [  887.091629] locks_free_lock_context (fs/locks.c:236 (discriminator 3))
> >>>> [  887.092782] __destroy_inode (fs/inode.c:243)
> >>>> [  887.093817] destroy_inode (fs/inode.c:268)
> >>>> [  887.094833] evict (fs/inode.c:574)
> >>>> [  887.095808] iput (fs/inode.c:1503)
> >>>> [  887.096687] __dentry_kill (fs/dcache.c:323 fs/dcache.c:508)
> >>>> [  887.097683] ? _raw_spin_trylock (kernel/locking/spinlock.c:136)
> >>>> [  887.098733] ? dput (fs/dcache.c:545 fs/dcache.c:648)
> >>>> [  887.099672] dput (fs/dcache.c:649)
> >>>> [  887.100552] __fput (fs/file_table.c:227)
> >>>
> >>> So, looking at this a bit more...
> >>>
> >>> It's clear that we're at the dput in __fput at this point. Much earlier
> >>> in __fput, we call locks_remove_file to remove all of the locks that
> >>> are associated with the file description.
> >>>
> >>> Evidently though, something didn't go right there. The two most likely
> >>> scenarios to my mind are:
> >>>
> >>> A) a lock raced onto the list somehow after that point. That seems
> >>> unlikely since presumably the fcheck should have failed at that point.
> >>>
> >>> ...or...
> >>>
> >>> B) the CPU that called locks_remove_file mistakenly thought that
> >>> inode->i_flctx was NULL when it really wasn't (stale cache, perhaps?).
> >>> That would make it skip trying to remove any flock locks.
> >>>
> >>> B seems more likely to me, and if it's the case then that would seem to
> >>> imply that we need some memory barriers (or maybe some ACCESS_ONCE
> >>> calls) in these codepaths. I'll have to sit down and work through it to
> >>> see what makes the most sense.
> >>>
> >>> If your debugging seems to jive with this, then one thing that might be
> >>> interesting would be to comment out these two lines in
> >>> locks_remove_flock:
> >>>
> >>>         if (!file_inode(filp)->i_flctx)
> >>>                 return;
> >>>
> >>> ...and see if it's still reproducible. That's obviously not a real fix
> >>> for this problem, but it might help prove whether the above suspicion
> >>> is correct.
> >>
> >> Removing those two lines makes the issue go away.
> >>
> >> I'm guessing that figuring out which filesystem we were abusing isn't
> >> interesting anymore...
> >>
> > 
> > Sigh. I've been trying to reproduce this today. I've set up two
> > different KVM guests on two different hosts, and run trinity on both,
> > and I can't seem to get this warning to pop.
> > 
> > Could you share what trinity command-line options you're using? Any
> > other special setup I should be considering to reproduce it?
> > 
> > I was hoping to get it to reproduce so I could test out potential
> > memory barrier fixes...
> 
> I don't think there's anything special about my setup here that can
> trigger that, specially if it's not dependant on a filesystem in use.
> 
> I'm running trinity with: ./trinity -xsched_setattr -xsetpriority
> -xunshare -xreboot -xshutdown -xnfsservctl -xclock_nanosleep -xuselib
> -xperf_event_open -m --quiet --dangerous -C 400 -l off
> 
> If that doesn't end up helping, I'd be happy to test out fixes here,
> it usually reproduces quickly.
> 
> 

Great, I'll try those options tomorrow.

I did push out a newer version of the series to linux-next, which does
a smp_rmb at the beginning of locks_remove_file. I'm not sure if that's
sufficient to fix this, but it's probably a reasonable start.

If you update the kernel you're testing to the next linux-next tree,
then it'd be interesting to know if it's still reproducible.

Thanks again!
-- 
Jeff Layton <jlayton@primarydata.com>

Re: fs: locks: WARNING: CPU: 16 PID: 4296 at fs/locks.c:236 locks_free_lock_context+0x10d/0x240()

[Jeff Layton]

On Wed, 14 Jan 2015 18:44:41 -0500
Sasha Levin <sasha.levin@oracle.com> wrote:

> On 01/14/2015 09:27 AM, Jeff Layton wrote:
> > On Tue, 13 Jan 2015 17:50:45 -0500
> > Sasha Levin <sasha.levin@oracle.com> wrote:
> > 
> >> On 01/13/2015 04:44 PM, Jeff Layton wrote:
> >>> On Tue, 13 Jan 2015 00:11:37 -0500
> >>> Sasha Levin <sasha.levin@oracle.com> wrote:
> >>>
> >>>> Hey Jeff,
> >>>>
> >>>> While fuzzing with trinity inside a KVM tools guest running the latest -next
> >>>> kernel, I've stumbled on the following spew:
> >>>>
> >>>> [  887.078606] WARNING: CPU: 16 PID: 4296 at fs/locks.c:236 locks_free_lock_context+0x10d/0x240()
> >>>> [  887.079703] Modules linked in:
> >>>> [  887.080288] CPU: 16 PID: 4296 Comm: trinity-c273 Not tainted 3.19.0-rc4-next-20150112-sasha-00053-g23c147e02e-dirty #1710
> >>>> [  887.082229]  0000000000000000 0000000000000000 0000000000000000 ffff8804c9f4f8e8
> >>>> [  887.083773]  ffffffff9154e0a6 0000000000000000 ffff8804cad98000 ffff8804c9f4f938
> >>>> [  887.085280]  ffffffff8140a4d0 0000000000000001 ffffffff81bf0d2d ffff8804c9f4f988
> >>>> [  887.086792] Call Trace:
> >>>> [  887.087320] dump_stack (lib/dump_stack.c:52)
> >>>> [  887.088247] warn_slowpath_common (kernel/panic.c:447)
> >>>> [  887.089342] ? locks_free_lock_context (fs/locks.c:236 (discriminator 3))
> >>>> [  887.090514] warn_slowpath_null (kernel/panic.c:481)
> >>>> [  887.091629] locks_free_lock_context (fs/locks.c:236 (discriminator 3))
> >>>> [  887.092782] __destroy_inode (fs/inode.c:243)
> >>>> [  887.093817] destroy_inode (fs/inode.c:268)
> >>>> [  887.094833] evict (fs/inode.c:574)
> >>>> [  887.095808] iput (fs/inode.c:1503)
> >>>> [  887.096687] __dentry_kill (fs/dcache.c:323 fs/dcache.c:508)
> >>>> [  887.097683] ? _raw_spin_trylock (kernel/locking/spinlock.c:136)
> >>>> [  887.098733] ? dput (fs/dcache.c:545 fs/dcache.c:648)
> >>>> [  887.099672] dput (fs/dcache.c:649)
> >>>> [  887.100552] __fput (fs/file_table.c:227)
> >>>
> >>> So, looking at this a bit more...
> >>>
> >>> It's clear that we're at the dput in __fput at this point. Much earlier
> >>> in __fput, we call locks_remove_file to remove all of the locks that
> >>> are associated with the file description.
> >>>
> >>> Evidently though, something didn't go right there. The two most likely
> >>> scenarios to my mind are:
> >>>
> >>> A) a lock raced onto the list somehow after that point. That seems
> >>> unlikely since presumably the fcheck should have failed at that point.
> >>>
> >>> ...or...
> >>>
> >>> B) the CPU that called locks_remove_file mistakenly thought that
> >>> inode->i_flctx was NULL when it really wasn't (stale cache, perhaps?).
> >>> That would make it skip trying to remove any flock locks.
> >>>
> >>> B seems more likely to me, and if it's the case then that would seem to
> >>> imply that we need some memory barriers (or maybe some ACCESS_ONCE
> >>> calls) in these codepaths. I'll have to sit down and work through it to
> >>> see what makes the most sense.
> >>>
> >>> If your debugging seems to jive with this, then one thing that might be
> >>> interesting would be to comment out these two lines in
> >>> locks_remove_flock:
> >>>
> >>>         if (!file_inode(filp)->i_flctx)
> >>>                 return;
> >>>
> >>> ...and see if it's still reproducible. That's obviously not a real fix
> >>> for this problem, but it might help prove whether the above suspicion
> >>> is correct.
> >>
> >> Removing those two lines makes the issue go away.
> >>
> >> I'm guessing that figuring out which filesystem we were abusing isn't
> >> interesting anymore...
> >>
> > 
> > Sigh. I've been trying to reproduce this today. I've set up two
> > different KVM guests on two different hosts, and run trinity on both,
> > and I can't seem to get this warning to pop.
> > 
> > Could you share what trinity command-line options you're using? Any
> > other special setup I should be considering to reproduce it?
> > 
> > I was hoping to get it to reproduce so I could test out potential
> > memory barrier fixes...
> 
> I don't think there's anything special about my setup here that can
> trigger that, specially if it's not dependant on a filesystem in use.
> 
> I'm running trinity with: ./trinity -xsched_setattr -xsetpriority
> -xunshare -xreboot -xshutdown -xnfsservctl -xclock_nanosleep -xuselib
> -xperf_event_open -m --quiet --dangerous -C 400 -l off
> 
> If that doesn't end up helping, I'd be happy to test out fixes here,
> it usually reproduces quickly.
> 
> 

Ok, I tried to reproduce it with that and several variations but it
still doesn't seem to do it for me. Can you try the latest linux-next
tree and see if it's still reproducible there?

Thanks,
-- 
Jeff Layton <jlayton@primarydata.com>

Re: fs: locks: WARNING: CPU: 16 PID: 4296 at fs/locks.c:236 locks_free_lock_context+0x10d/0x240()

[Sasha Levin]

On 01/15/2015 03:22 PM, Jeff Layton wrote:
> Ok, I tried to reproduce it with that and several variations but it
> still doesn't seem to do it for me. Can you try the latest linux-next
> tree and see if it's still reproducible there?

It's still not in in today's -next, could you send me a patch for testing
instead?


Thanks,
Sasha

Re: fs: locks: WARNING: CPU: 16 PID: 4296 at fs/locks.c:236 locks_free_lock_context+0x10d/0x240()

[Jeff Layton]

On Fri, 16 Jan 2015 09:31:23 -0500
Sasha Levin <sasha.levin@oracle.com> wrote:

> On 01/15/2015 03:22 PM, Jeff Layton wrote:
> > Ok, I tried to reproduce it with that and several variations but it
> > still doesn't seem to do it for me. Can you try the latest linux-next
> > tree and see if it's still reproducible there?
> 
> It's still not in in today's -next, could you send me a patch for testing
> instead?
> 

Seems to be there for me:

----------------------[snip]-----------------------
/*
 * This function is called on the last close of an open file.
 */
void locks_remove_file(struct file *filp)
{
        /* ensure that we see any assignment of i_flctx */
        smp_rmb();

        /* remove any OFD locks */
        locks_remove_posix(filp, filp);
----------------------[snip]-----------------------

That's actually the right place to put the barrier, I think. We just
need to ensure that this function sees any assignment to i_flctx that
occurred before this point. By the time we're here, we shouldn't be
getting any new locks that matter to this close since the fcheck call
should fail on any new requests.

If that works, then I'll probably make some other changes to the set
and re-post it next week.

Many thanks for helping me test this!
-- 
Jeff Layton <jlayton@primarydata.com>

Re: fs: locks: WARNING: CPU: 16 PID: 4296 at fs/locks.c:236 locks_free_lock_context+0x10d/0x240()

[Sasha Levin]

On 01/16/2015 09:40 AM, Jeff Layton wrote:
> On Fri, 16 Jan 2015 09:31:23 -0500
> Sasha Levin <sasha.levin@oracle.com> wrote:
> 
>> On 01/15/2015 03:22 PM, Jeff Layton wrote:
>>> Ok, I tried to reproduce it with that and several variations but it
>>> still doesn't seem to do it for me. Can you try the latest linux-next
>>> tree and see if it's still reproducible there?
>>
>> It's still not in in today's -next, could you send me a patch for testing
>> instead?
>>
> 
> Seems to be there for me:
> 
> ----------------------[snip]-----------------------
> /*
>  * This function is called on the last close of an open file.
>  */
> void locks_remove_file(struct file *filp)
> {
>         /* ensure that we see any assignment of i_flctx */
>         smp_rmb();
> 
>         /* remove any OFD locks */
>         locks_remove_posix(filp, filp);
> ----------------------[snip]-----------------------
> 
> That's actually the right place to put the barrier, I think. We just
> need to ensure that this function sees any assignment to i_flctx that
> occurred before this point. By the time we're here, we shouldn't be
> getting any new locks that matter to this close since the fcheck call
> should fail on any new requests.
> 
> If that works, then I'll probably make some other changes to the set
> and re-post it next week.
> 
> Many thanks for helping me test this!

You're right, I somehow missed that.

But it doesn't fix the issue, I still see it happening, but it seems
to be less frequent(?).


Thanks,
Sasha

Re: fs: locks: WARNING: CPU: 16 PID: 4296 at fs/locks.c:236 locks_free_lock_context+0x10d/0x240()

[Jeff Layton]

On Fri, 16 Jan 2015 13:10:46 -0500
Sasha Levin <sasha.levin@oracle.com> wrote:

> On 01/16/2015 09:40 AM, Jeff Layton wrote:
> > On Fri, 16 Jan 2015 09:31:23 -0500
> > Sasha Levin <sasha.levin@oracle.com> wrote:
> > 
> >> On 01/15/2015 03:22 PM, Jeff Layton wrote:
> >>> Ok, I tried to reproduce it with that and several variations but it
> >>> still doesn't seem to do it for me. Can you try the latest linux-next
> >>> tree and see if it's still reproducible there?
> >>
> >> It's still not in in today's -next, could you send me a patch for testing
> >> instead?
> >>
> > 
> > Seems to be there for me:
> > 
> > ----------------------[snip]-----------------------
> > /*
> >  * This function is called on the last close of an open file.
> >  */
> > void locks_remove_file(struct file *filp)
> > {
> >         /* ensure that we see any assignment of i_flctx */
> >         smp_rmb();
> > 
> >         /* remove any OFD locks */
> >         locks_remove_posix(filp, filp);
> > ----------------------[snip]-----------------------
> > 
> > That's actually the right place to put the barrier, I think. We just
> > need to ensure that this function sees any assignment to i_flctx that
> > occurred before this point. By the time we're here, we shouldn't be
> > getting any new locks that matter to this close since the fcheck call
> > should fail on any new requests.
> > 
> > If that works, then I'll probably make some other changes to the set
> > and re-post it next week.
> > 
> > Many thanks for helping me test this!
> 
> You're right, I somehow missed that.
> 
> But it doesn't fix the issue, I still see it happening, but it seems
> to be less frequent(?).
> 

Ok, that was my worry (and one of the reasons I really would like to
find some way to reproduce this on my own). I think what I'll do at
this point is pull the patchset from linux-next until I can consult
with someone who understands this sort of cache-coherency problem
better than I do.

Once I get it resolved, I'll push it back to my linux-next branch and
let you know and we can give it another go.

Thanks for the testing so far!
-- 
Jeff Layton <jlayton@primarydata.com>

Re: fs: locks: WARNING: CPU: 16 PID: 4296 at fs/locks.c:236 locks_free_lock_context+0x10d/0x240()

[Jeff Layton]

On Fri, 16 Jan 2015 13:53:04 -0500
Jeff Layton <jlayton@primarydata.com> wrote:

> On Fri, 16 Jan 2015 13:10:46 -0500
> Sasha Levin <sasha.levin@oracle.com> wrote:
> 
> > On 01/16/2015 09:40 AM, Jeff Layton wrote:
> > > On Fri, 16 Jan 2015 09:31:23 -0500
> > > Sasha Levin <sasha.levin@oracle.com> wrote:
> > > 
> > >> On 01/15/2015 03:22 PM, Jeff Layton wrote:
> > >>> Ok, I tried to reproduce it with that and several variations but it
> > >>> still doesn't seem to do it for me. Can you try the latest linux-next
> > >>> tree and see if it's still reproducible there?
> > >>
> > >> It's still not in in today's -next, could you send me a patch for testing
> > >> instead?
> > >>
> > > 
> > > Seems to be there for me:
> > > 
> > > ----------------------[snip]-----------------------
> > > /*
> > >  * This function is called on the last close of an open file.
> > >  */
> > > void locks_remove_file(struct file *filp)
> > > {
> > >         /* ensure that we see any assignment of i_flctx */
> > >         smp_rmb();
> > > 
> > >         /* remove any OFD locks */
> > >         locks_remove_posix(filp, filp);
> > > ----------------------[snip]-----------------------
> > > 
> > > That's actually the right place to put the barrier, I think. We just
> > > need to ensure that this function sees any assignment to i_flctx that
> > > occurred before this point. By the time we're here, we shouldn't be
> > > getting any new locks that matter to this close since the fcheck call
> > > should fail on any new requests.
> > > 
> > > If that works, then I'll probably make some other changes to the set
> > > and re-post it next week.
> > > 
> > > Many thanks for helping me test this!
> > 
> > You're right, I somehow missed that.
> > 
> > But it doesn't fix the issue, I still see it happening, but it seems
> > to be less frequent(?).
> > 
> 
> Ok, that was my worry (and one of the reasons I really would like to
> find some way to reproduce this on my own). I think what I'll do at
> this point is pull the patchset from linux-next until I can consult
> with someone who understands this sort of cache-coherency problem
> better than I do.
> 
> Once I get it resolved, I'll push it back to my linux-next branch and
> let you know and we can give it another go.
> 
> Thanks for the testing so far!

Actually, I take it back. One more try...

I dragooned David Howells into helping me look at this and he talked me
into just going back to using the i_lock to protect the i_flctx
assignment.

My hope is that will work around whatever strange effect is causing
this. Can you test tomorrow's -next tree (once it's been merged) and see
whether this is still reproducible?

If that works, then I may go back to trying to do this locklessly with
cmpxchg, but I'll probably need to corner Paul McKinney and buy him a
beverage of his choice so he can talk me through how to do it properly.

Thanks again!
-- 
Jeff Layton <jlayton@primarydata.com>

Re: fs: locks: WARNING: CPU: 16 PID: 4296 at fs/locks.c:236 locks_free_lock_context+0x10d/0x240()

[Sasha Levin]

On 01/16/2015 04:16 PM, Jeff Layton wrote:
> On Fri, 16 Jan 2015 13:53:04 -0500
> Jeff Layton <jlayton@primarydata.com> wrote:
> 
>> On Fri, 16 Jan 2015 13:10:46 -0500
>> Sasha Levin <sasha.levin@oracle.com> wrote:
>>
>>> On 01/16/2015 09:40 AM, Jeff Layton wrote:
>>>> On Fri, 16 Jan 2015 09:31:23 -0500
>>>> Sasha Levin <sasha.levin@oracle.com> wrote:
>>>>
>>>>> On 01/15/2015 03:22 PM, Jeff Layton wrote:
>>>>>> Ok, I tried to reproduce it with that and several variations but it
>>>>>> still doesn't seem to do it for me. Can you try the latest linux-next
>>>>>> tree and see if it's still reproducible there?
>>>>>
>>>>> It's still not in in today's -next, could you send me a patch for testing
>>>>> instead?
>>>>>
>>>>
>>>> Seems to be there for me:
>>>>
>>>> ----------------------[snip]-----------------------
>>>> /*
>>>>  * This function is called on the last close of an open file.
>>>>  */
>>>> void locks_remove_file(struct file *filp)
>>>> {
>>>>         /* ensure that we see any assignment of i_flctx */
>>>>         smp_rmb();
>>>>
>>>>         /* remove any OFD locks */
>>>>         locks_remove_posix(filp, filp);
>>>> ----------------------[snip]-----------------------
>>>>
>>>> That's actually the right place to put the barrier, I think. We just
>>>> need to ensure that this function sees any assignment to i_flctx that
>>>> occurred before this point. By the time we're here, we shouldn't be
>>>> getting any new locks that matter to this close since the fcheck call
>>>> should fail on any new requests.
>>>>
>>>> If that works, then I'll probably make some other changes to the set
>>>> and re-post it next week.
>>>>
>>>> Many thanks for helping me test this!
>>>
>>> You're right, I somehow missed that.
>>>
>>> But it doesn't fix the issue, I still see it happening, but it seems
>>> to be less frequent(?).
>>>
>>
>> Ok, that was my worry (and one of the reasons I really would like to
>> find some way to reproduce this on my own). I think what I'll do at
>> this point is pull the patchset from linux-next until I can consult
>> with someone who understands this sort of cache-coherency problem
>> better than I do.
>>
>> Once I get it resolved, I'll push it back to my linux-next branch and
>> let you know and we can give it another go.
>>
>> Thanks for the testing so far!
> 
> Actually, I take it back. One more try...
> 
> I dragooned David Howells into helping me look at this and he talked me
> into just going back to using the i_lock to protect the i_flctx
> assignment.
> 
> My hope is that will work around whatever strange effect is causing
> this. Can you test tomorrow's -next tree (once it's been merged) and see
> whether this is still reproducible?

Sure. You can also feel free to send patches my way to test/debug, it's
pretty easy to throw them into my test setup.


Thanks,
Sasha

Re: fs: locks: WARNING: CPU: 16 PID: 4296 at fs/locks.c:236 locks_free_lock_context+0x10d/0x240()

[Sasha Levin]

On 01/16/2015 04:16 PM, Jeff Layton wrote:
> On Fri, 16 Jan 2015 13:53:04 -0500
> Jeff Layton <jlayton@primarydata.com> wrote:
> 
>> > On Fri, 16 Jan 2015 13:10:46 -0500
>> > Sasha Levin <sasha.levin@oracle.com> wrote:
>> > 
>>> > > On 01/16/2015 09:40 AM, Jeff Layton wrote:
>>>> > > > On Fri, 16 Jan 2015 09:31:23 -0500
>>>> > > > Sasha Levin <sasha.levin@oracle.com> wrote:
>>>> > > > 
>>>>> > > >> On 01/15/2015 03:22 PM, Jeff Layton wrote:
>>>>>> > > >>> Ok, I tried to reproduce it with that and several variations but it
>>>>>> > > >>> still doesn't seem to do it for me. Can you try the latest linux-next
>>>>>> > > >>> tree and see if it's still reproducible there?
>>>>> > > >>
>>>>> > > >> It's still not in in today's -next, could you send me a patch for testing
>>>>> > > >> instead?
>>>>> > > >>
>>>> > > > 
>>>> > > > Seems to be there for me:
>>>> > > > 
>>>> > > > ----------------------[snip]-----------------------
>>>> > > > /*
>>>> > > >  * This function is called on the last close of an open file.
>>>> > > >  */
>>>> > > > void locks_remove_file(struct file *filp)
>>>> > > > {
>>>> > > >         /* ensure that we see any assignment of i_flctx */
>>>> > > >         smp_rmb();
>>>> > > > 
>>>> > > >         /* remove any OFD locks */
>>>> > > >         locks_remove_posix(filp, filp);
>>>> > > > ----------------------[snip]-----------------------
>>>> > > > 
>>>> > > > That's actually the right place to put the barrier, I think. We just
>>>> > > > need to ensure that this function sees any assignment to i_flctx that
>>>> > > > occurred before this point. By the time we're here, we shouldn't be
>>>> > > > getting any new locks that matter to this close since the fcheck call
>>>> > > > should fail on any new requests.
>>>> > > > 
>>>> > > > If that works, then I'll probably make some other changes to the set
>>>> > > > and re-post it next week.
>>>> > > > 
>>>> > > > Many thanks for helping me test this!
>>> > > 
>>> > > You're right, I somehow missed that.
>>> > > 
>>> > > But it doesn't fix the issue, I still see it happening, but it seems
>>> > > to be less frequent(?).
>>> > > 
>> > 
>> > Ok, that was my worry (and one of the reasons I really would like to
>> > find some way to reproduce this on my own). I think what I'll do at
>> > this point is pull the patchset from linux-next until I can consult
>> > with someone who understands this sort of cache-coherency problem
>> > better than I do.
>> > 
>> > Once I get it resolved, I'll push it back to my linux-next branch and
>> > let you know and we can give it another go.
>> > 
>> > Thanks for the testing so far!
> Actually, I take it back. One more try...
> 
> I dragooned David Howells into helping me look at this and he talked me
> into just going back to using the i_lock to protect the i_flctx
> assignment.
> 
> My hope is that will work around whatever strange effect is causing
> this. Can you test tomorrow's -next tree (once it's been merged) and see
> whether this is still reproducible?

I've updated and re-tested with the latest -next, and it seems that the
issue is gone.

I'll update if I end up seeing it again.


Thanks,
Sasha

Re: fs: locks: WARNING: CPU: 16 PID: 4296 at fs/locks.c:236 locks_free_lock_context+0x10d/0x240()

[Jeff Layton]

On Wed, 21 Jan 2015 08:25:02 -0500
Sasha Levin <sasha.levin@oracle.com> wrote:

> On 01/16/2015 04:16 PM, Jeff Layton wrote:
> > On Fri, 16 Jan 2015 13:53:04 -0500
> > Jeff Layton <jlayton@primarydata.com> wrote:
> > 
> >> > On Fri, 16 Jan 2015 13:10:46 -0500
> >> > Sasha Levin <sasha.levin@oracle.com> wrote:
> >> > 
> >>> > > On 01/16/2015 09:40 AM, Jeff Layton wrote:
> >>>> > > > On Fri, 16 Jan 2015 09:31:23 -0500
> >>>> > > > Sasha Levin <sasha.levin@oracle.com> wrote:
> >>>> > > > 
> >>>>> > > >> On 01/15/2015 03:22 PM, Jeff Layton wrote:
> >>>>>> > > >>> Ok, I tried to reproduce it with that and several variations but it
> >>>>>> > > >>> still doesn't seem to do it for me. Can you try the latest linux-next
> >>>>>> > > >>> tree and see if it's still reproducible there?
> >>>>> > > >>
> >>>>> > > >> It's still not in in today's -next, could you send me a patch for testing
> >>>>> > > >> instead?
> >>>>> > > >>
> >>>> > > > 
> >>>> > > > Seems to be there for me:
> >>>> > > > 
> >>>> > > > ----------------------[snip]-----------------------
> >>>> > > > /*
> >>>> > > >  * This function is called on the last close of an open file.
> >>>> > > >  */
> >>>> > > > void locks_remove_file(struct file *filp)
> >>>> > > > {
> >>>> > > >         /* ensure that we see any assignment of i_flctx */
> >>>> > > >         smp_rmb();
> >>>> > > > 
> >>>> > > >         /* remove any OFD locks */
> >>>> > > >         locks_remove_posix(filp, filp);
> >>>> > > > ----------------------[snip]-----------------------
> >>>> > > > 
> >>>> > > > That's actually the right place to put the barrier, I think. We just
> >>>> > > > need to ensure that this function sees any assignment to i_flctx that
> >>>> > > > occurred before this point. By the time we're here, we shouldn't be
> >>>> > > > getting any new locks that matter to this close since the fcheck call
> >>>> > > > should fail on any new requests.
> >>>> > > > 
> >>>> > > > If that works, then I'll probably make some other changes to the set
> >>>> > > > and re-post it next week.
> >>>> > > > 
> >>>> > > > Many thanks for helping me test this!
> >>> > > 
> >>> > > You're right, I somehow missed that.
> >>> > > 
> >>> > > But it doesn't fix the issue, I still see it happening, but it seems
> >>> > > to be less frequent(?).
> >>> > > 
> >> > 
> >> > Ok, that was my worry (and one of the reasons I really would like to
> >> > find some way to reproduce this on my own). I think what I'll do at
> >> > this point is pull the patchset from linux-next until I can consult
> >> > with someone who understands this sort of cache-coherency problem
> >> > better than I do.
> >> > 
> >> > Once I get it resolved, I'll push it back to my linux-next branch and
> >> > let you know and we can give it another go.
> >> > 
> >> > Thanks for the testing so far!
> > Actually, I take it back. One more try...
> > 
> > I dragooned David Howells into helping me look at this and he talked me
> > into just going back to using the i_lock to protect the i_flctx
> > assignment.
> > 
> > My hope is that will work around whatever strange effect is causing
> > this. Can you test tomorrow's -next tree (once it's been merged) and see
> > whether this is still reproducible?
> 
> I've updated and re-tested with the latest -next, and it seems that the
> issue is gone.
> 
> I'll update if I end up seeing it again.
> 

The change was to rely on the i_lock to protect the i_flctx pointer.
I'm not sure why a cmpxchg() wasn't quite sufficient, but I'll plan to
stick with this for now. It's unlikely to make any real difference in
performance anyway.

Many thanks for testing it, Sasha!
-- 
Jeff Layton <jlayton@primarydata.com>