NFSroot hangs with bad unlock balance in Linux next

Hi,

Looks like Linux next with NFSroot hangs for me at some point booting into init. Then after a while it produces "BUG: bad unlock balance detected!".

This happens at least with omap5-uevm and igepv5. Not sure yet if it also happens on other boards, the ones I'm seeing it happen both have USB Ethernet controller. They usually hang after the system starts being idle some tens of seconds into booting.

I tried to bisect it down with no luck. I do have the following trace, does that provide any clues?

kworker/0:2/112 is trying to release lock (&nfsi->rmdir_sem) at:
[<c03a7f98>] nfs_async_unlink_release+0x20/0x68
but there are no more locks to release!

Very strange. We grab that rwsem at the entry into nfs_call_unlink() and then either release it there and return or call nfs_do_call_unlink(). Which arranges for eventual call of nfs_async_unlink_release() (via ->rpc_release); nfs_async_unlink_release() releases the rwsem. Nobody else releases it (on the read side, that is).

The only kinda-sorta possibility I see here is that the inode we are unlocking in that nfs_async_unlink_release() is not the one we'd locked in nfs_call_unlink() that has lead to it. That really shouldn't happen, though... Just to verify whether that's what we are hitting, could you try to reproduce that thing with the patch below on top of -next and see if it triggers any of those WARN_ON?

Quoted 6 lines · Al Viro

Very strange. We grab that rwsem at the entry into nfs_call_unlink() and then either release it there and return or call nfs_do_call_unlink(). Which arranges for eventual call of nfs_async_unlink_release() (via ->rpc_release); nfs_async_unlink_release() releases the rwsem. Nobody else releases it (on the read side, that is).

Quoted 6 lines

The only kinda-sorta possibility I see here is that the inode we are unlocking in that nfs_async_unlink_release() is not the one we'd locked in nfs_call_unlink() that has lead to it. That really shouldn't happen, though... Just to verify whether that's what we are hitting, could you try to reproduce that thing with the patch below on top of -next and see if it triggers any of those WARN_ON?

D'oh... Lockdep warnings are easy to trigger (and, AFAICS, bogus). up_read/down_read in fs/nfs/unlink.c should be replaced with up_read_non_owner/down_read_non_owner, lest the lockdep gets confused. Hangs are different - I've no idea what's triggering those. I've seen something similar on that -next, but not on work.lookups.

The joy of bisecting -next... <a couple of hours later> 9317bb69824ec8d078b0b786b6971aedb0af3d4f is the first bad commit commit 9317bb69824ec8d078b0b786b6971aedb0af3d4f

Author: Eric Dumazet <[email protected]>
Date:   Mon Apr 25 10:39:32 2016 -0700

net: SOCKWQ_ASYNC_NOSPACE optimizations

Reverting changes to sk_set_bit/sk_clear_bit gets rid of the hangs. Plain revert gives a conflict, since there had been additional change in "net: SOCKWQ_ASYNC_WAITDATA optimizations"; removing both fixed the hangs.

Note that hangs appear without any fs/nfs/unlink.c modifications being there. When the hang happens it affects NFS traffic; ssh session still works fine until it steps on a filesystem operation on NFS (i.e. you can use builtins, access procfs, etc.)

Quoted 8 lines · Al Viro

Quoted 6 lines · Al Viro

Very strange. We grab that rwsem at the entry into nfs_call_unlink() and then either release it there and return or call nfs_do_call_unlink(). Which arranges for eventual call of nfs_async_unlink_release() (via ->rpc_release); nfs_async_unlink_release() releases the rwsem. Nobody else releases it (on the read side, that is).

Quoted 6 lines

Quoted 6 lines

The only kinda-sorta possibility I see here is that the inode we are unlocking in that nfs_async_unlink_release() is not the one we'd locked in nfs_call_unlink() that has lead to it. That really shouldn't happen, though... Just to verify whether that's what we are hitting, could you try to reproduce that thing with the patch below on top of -next and see if it triggers any of those WARN_ON?

Quoted 14 lines

D'oh... Lockdep warnings are easy to trigger (and, AFAICS, bogus). up_read/down_read in fs/nfs/unlink.c should be replaced with up_read_non_owner/down_read_non_owner, lest the lockdep gets confused. Hangs are different - I've no idea what's triggering those. I've seen something similar on that -next, but not on work.lookups.

The joy of bisecting -next... <a couple of hours later> 9317bb69824ec8d078b0b786b6971aedb0af3d4f is the first bad commit commit 9317bb69824ec8d078b0b786b6971aedb0af3d4f

Author: Eric Dumazet <[email protected]>
Date:   Mon Apr 25 10:39:32 2016 -0700

net: SOCKWQ_ASYNC_NOSPACE optimizations

Quoted 8 lines

Reverting changes to sk_set_bit/sk_clear_bit gets rid of the hangs. Plain revert gives a conflict, since there had been additional change in "net: SOCKWQ_ASYNC_WAITDATA optimizations"; removing both fixed the hangs.

Note that hangs appear without any fs/nfs/unlink.c modifications being there. When the hang happens it affects NFS traffic; ssh session still works fine until it steps on a filesystem operation on NFS (i.e. you can use builtins, access procfs, etc.)

Yeah, the issue was reported last week (
http://www.spinics.net/lists/netdev/msg375777.html ), and I could not convince myself to add a new sock flag, like SOCK_FASYNC_STICKY.

(Just in case NFS would ever call sock_fasync() with an empty fasync_list, and SOCK_FASYNC would be cleared again.

Quoted 9 lines · Eric Dumazet

Quoted 8 lines · Al Viro

Quoted 6 lines · Al Viro

Very strange. We grab that rwsem at the entry into nfs_call_unlink() and then either release it there and return or call nfs_do_call_unlink(). Which arranges for eventual call of nfs_async_unlink_release() (via ->rpc_release); nfs_async_unlink_release() releases the rwsem. Nobody else releases it (on the read side, that is).

Quoted 6 lines

Quoted 6 lines

Quoted 6 lines

The only kinda-sorta possibility I see here is that the inode we are unlocking in that nfs_async_unlink_release() is not the one we'd locked in nfs_call_unlink() that has lead to it. That really shouldn't happen, though... Just to verify whether that's what we are hitting, could you try to reproduce that thing with the patch below on top of -next and see if it triggers any of those WARN_ON?

Thanks no warnings with that patch though.

Quoted 28 lines

Quoted 14 lines

D'oh... Lockdep warnings are easy to trigger (and, AFAICS, bogus). up_read/down_read in fs/nfs/unlink.c should be replaced with up_read_non_owner/down_read_non_owner, lest the lockdep gets confused. Hangs are different - I've no idea what's triggering those. I've seen something similar on that -next, but not on work.lookups.

The joy of bisecting -next... <a couple of hours later> 9317bb69824ec8d078b0b786b6971aedb0af3d4f is the first bad commit commit 9317bb69824ec8d078b0b786b6971aedb0af3d4f

Author: Eric Dumazet <[email protected]>
Date:   Mon Apr 25 10:39:32 2016 -0700

net: SOCKWQ_ASYNC_NOSPACE optimizations

Quoted 8 lines

Reverting changes to sk_set_bit/sk_clear_bit gets rid of the hangs. Plain revert gives a conflict, since there had been additional change in "net: SOCKWQ_ASYNC_WAITDATA optimizations"; removing both fixed the hangs.

Note that hangs appear without any fs/nfs/unlink.c modifications being there. When the hang happens it affects NFS traffic; ssh session still works fine until it steps on a filesystem operation on NFS (i.e. you can use builtins, access procfs, etc.)

Yeah, the issue was reported last week (
http://www.spinics.net/lists/netdev/msg375777.html ), and I could not convince myself to add a new sock flag, like SOCK_FASYNC_STICKY.

Quoted 2 lines

(Just in case NFS would ever call sock_fasync() with an empty fasync_list, and SOCK_FASYNC would be cleared again.

Yeah applying the test patch from the url above makes things work for me again.

Looks like with both patches applied I still also get this eventually:

=====================================
[ BUG: bad unlock balance detected! ]
4.6.0-rc7-next-20160509+ #1264 Not tainted
-------------------------------------

Quoted 6 lines · Tony Lindgren

Looks like with both patches applied I still also get this eventually:

=====================================
[ BUG: bad unlock balance detected! ]
4.6.0-rc7-next-20160509+ #1264 Not tainted
-------------------------------------

Lockdep warnings are noise. To make them STFU try the following incremental; I'll fold it into #work.lookups and #for-next. Note that it will do nothing to hangs - those are completely unrelated and you need Eric's patch to deal with them.

fs/nfs/unlink.c +4 -4

index d367b06..1868246 100644
@@ -64,7 +64,7 @@ static void nfs_async_unlink_release(void *calldata)
 	struct dentry *dentry = data->dentry;
 	struct super_block *sb = dentry->d_sb;
 
-	up_read(&NFS_I(d_inode(dentry->d_parent))->rmdir_sem);
+	up_read_non_owner(&NFS_I(d_inode(dentry->d_parent))->rmdir_sem);
 	d_lookup_done(dentry);
 	nfs_free_unlinkdata(data);
 	dput(dentry);

@@ -117,10 +117,10 @@ static int nfs_call_unlink(struct dentry *dentry, struct nfs_unlinkdata *data)
 	struct inode *dir = d_inode(dentry->d_parent);
 	struct dentry *alias;
 
-	down_read(&NFS_I(dir)->rmdir_sem);
+	down_read_non_owner(&NFS_I(dir)->rmdir_sem);
 	alias = d_alloc_parallel(dentry->d_parent, &data->args.name, &data->wq);
 	if (IS_ERR(alias)) {
-		up_read(&NFS_I(dir)->rmdir_sem);
+		up_read_non_owner(&NFS_I(dir)->rmdir_sem);
 		return 0;
 	}
 	if (!d_in_lookup(alias)) {

@@ -142,7 +142,7 @@ static int nfs_call_unlink(struct dentry *dentry, struct nfs_unlinkdata *data)
 			ret = 0;
 		spin_unlock(&alias->d_lock);
 		dput(alias);
-		up_read(&NFS_I(dir)->rmdir_sem);
+		up_read_non_owner(&NFS_I(dir)->rmdir_sem);
 		/*
 		 * If we'd displaced old cached devname, free it.  At that
 		 * point dentry is definitely not a root, so we won't need