by Ian Kent

[permalink] [raw]

Subject: Re: BUG() in shrink_dcache_for_umount_subtree on nfs4 mount

On Thu, 2011-03-31 at 12:17 -0700, Mark Moseley wrote:
> On Wed, Mar 30, 2011 at 6:37 PM, Jeff Layton <[email protected]> wrote:
> > On Wed, 30 Mar 2011 14:55:00 -0700
> > Mark Moseley <[email protected]> wrote:
> >
> >> > I'm not 100% sure it's related (but I'm going to guess it is) but on
> >> > these same boxes, they're not actually able to reboot at the end of a
> >> > graceful shutdown. After yielding that bug and continuing with the
> >> > shutdown process, it gets all the way to exec'ing:
> >> >
> >> > reboot -d -f -i
> >> >
> >> > and then just hangs forever. I'm guessing a thread is hung still
> >> > trying to unmount things. On another box, I triggered that bug with a
> >> > umount of one top-level mount that had subtrees. When I umount'd
> >> > another top-level mount with subtrees on that same box, it's blocked
> >> > and unkillable. That second umount also logged another bug to the
> >> > kernel logs.
> >> >
> >> > In both umounts described above, the entries in /proc/mounts go away
> >> > after the umount.
> >> >
> >> > Jeff, are you at liberty to do a graceful shutdown of the box you saw
> >> > that bug on? If so, does it actually reboot?
> >>
> >>
> >> A bit more info: On the same boxes, freshly booted but with all the
> >> same mounts (even the subtrees) mounted, I don't get that bug, so it
> >> seems to happen just when there's been significant usage within those
> >> mounts. These are all read-only mounts, if it makes a difference.
> >>
> >> I was however able to trigger the bug on a box that had been running
> >> (web serving) for about 15 minutes. Here's a snippet from slabinfo
> >> right before umount'ing (let me know if more of it would help):
> >>
> >
> > No, it hung. Unfortunately, I didn't collect any info that told me
> > where it was hung though.
> >
> > I believe that's fairly typical though in situations like this. The
> > problem is that we likely have a dentry refcount leak somewhere. The
> > vfsmount refcount was low enough to allow an unmount though. Often
> > these sorts of problems lurk in error handling code...
> >
> >> # grep nfs /proc/slabinfo
> >> nfsd4_delegations 0 0 360 22 2 : tunables 0 0
> >> 0 : slabdata 0 0 0
> >> nfsd4_stateids 0 0 120 34 1 : tunables 0 0
> >> 0 : slabdata 0 0 0
> >> nfsd4_files 0 0 136 30 1 : tunables 0 0
> >> 0 : slabdata 0 0 0
> >> nfsd4_stateowners 0 0 424 38 4 : tunables 0 0
> >> 0 : slabdata 0 0 0
> >> nfs_direct_cache 0 0 136 30 1 : tunables 0 0
> >> 0 : slabdata 0 0 0
> >> nfs_write_data 46 46 704 23 4 : tunables 0 0
> >> 0 : slabdata 2 2 0
> >> nfs_read_data 207 207 704 23 4 : tunables 0 0
> >> 0 : slabdata 9 9 0
> >> nfs_inode_cache 23901 23901 1056 31 8 : tunables 0 0
> >> 0 : slabdata 771 771 0
> >> nfs_page 256 256 128 32 1 : tunables 0 0
> >> 0 : slabdata 8 8 0
> >
> > slabinfo probably won't tell us much here. If we can narrow down the
> > reproducer for this though then that would definitely help.
> > Actually, /proc/self/mountstats might give us something to go on...
>
> Would turning on kmemleak and letting it run for a bit (luckily 15
> mins of regular use seems to be enough to trigger this bug) tell us
> anything? I can do that easily enough but I don't know if it tracks
> dentry entries.
>
> Also I'll grab mountstats as well before/after trying a umount.
> Anything in particular within mountstats I should pay close attention
> to?

Unfortunately, this type of problem defies attempts to work out what is
causing it.

I had a similar problem with a dentry ref count leak in autofs when the
rcu-walk and vfs-automount patches were merged concurrently in 2.6.38.
The only reason I eventually found it was thanks to the eagle eye of Al
Viro. It was actually an obvious problem but in this case (where the
problem actually occurs at some point before the BUG()) it's extremely
difficult to find a way to work out where to look and that's the kick!
All that can be done is to nail down a reproducer (which Jeff is working
on I believe) and hope we can work out a way to target the debugging
from there.

You did say you have clear evidence that autofs in 2.6.38 is not part of
the problem, yes? If you are using autofs then we need to add the 2.6.39
autofs patches to ensure we don't get more confused between the two
problems.

Ian

2011-05-26 20:20:19

by Jeff Layton

[permalink] [raw]

Subject: Re: BUG() in shrink_dcache_for_umount_subtree on nfs4 mount

On Thu, 26 May 2011 23:02:32 +0800
Ian Kent <[email protected]> wrote:

> On Thu, 2011-05-26 at 09:49 -0400, Jeff Layton wrote:
> > On Wed, 25 May 2011 16:08:15 -0400
> > Jeff Layton <[email protected]> wrote:
> >
> > > On Wed, 27 Apr 2011 16:23:07 -0700
> > > Mark Moseley <[email protected]> wrote:
> > >
> > > >
> > > > I posted this to bugzilla a while back but I figured I'd paste it here too:
> > > >
> > > > -----------------------------------------------------------------------------------------------------
> > > >
> > > > I've been getting bit by the exact same bug and been bisecting for the past
> > > > couple of weeks. It's slow going as it can sometimes take a day for the BUG()
> > > > to show up (though can also at time take 10 minutes). And I've also seen it
> > > > more than once where something was good after a day and then BUG()'d later on,
> > > > just to make things more complicated. So the upshot is that while I feel
> > > > confident enough about this latest batch of bisecting to post it here, I
> > > > wouldn't bet my life on it. I hope this isn't a case where bisecting just shows
> > > > where the bug gets exposed but not where it actually got planted :)
> > > >
> > > > Incidentally, I tried the patch from the top of this thread and it didn't seem
> > > > to make a difference. I still got bit.
> > > >
> > > > I've posted on the linux-fsdevel thread that Jeff Layton started about it,
> > > > http://www.spinics.net/lists/linux-nfs/msg20280.html if you need more details
> > > > on my setup (though I'll be happy to provide anything else you need). Though in
> > > > that thread you'll see that I'm not using autofs explicitly, the Netapp GX
> > > > cluster NFS appears to use autofs to do the implicit submounts (I'm not 100%
> > > > sure that's the correct terminology, so hopefully you know what I mean).
> > > >
> > > > Here's my bisect log, ending up at commit
> > > > e61da20a50d21725ff27571a6dff9468e4fb7146
> > > >
> > > > git bisect start 'fs'
> > > > # good: [3c0eee3fe6a3a1c745379547c7e7c904aa64f6d5] Linux 2.6.37
> > > > git bisect good 3c0eee3fe6a3a1c745379547c7e7c904aa64f6d5
> > > > # bad: [c56eb8fb6dccb83d9fe62fd4dc00c834de9bc470] Linux 2.6.38-rc1
> > > > git bisect bad c56eb8fb6dccb83d9fe62fd4dc00c834de9bc470
> > > > # good: [7c955fca3e1d8132982148267d9efcafae849bb6] Merge branch 'for_linus' of
> > > > git://git.kernel.org/pub/scm/linux/kernel/git/jack/linux-udf-2.6
> > > > git bisect good 7c955fca3e1d8132982148267d9efcafae849bb6
> > > > # good: [c32b0d4b3f19c2f5d29568f8b7b72b61693f1277] fs/mpage.c: consolidate code
> > > > git bisect good c32b0d4b3f19c2f5d29568f8b7b72b61693f1277
> > > > # bad: [f8206b925fb0eba3a11839419be118b09105d7b1] Merge branch 'for-linus' of
> > > > git://git.kernel.org/pub/scm/linux/kernel/git/viro/vfs-2.6
> > > > git bisect bad f8206b925fb0eba3a11839419be118b09105d7b1
> > > > # good: [a8f2800b4f7b76cecb7209cb6a7d2b14904fc711] nfsd4: fix callback
> > > > restarting
> > > > git bisect good a8f2800b4f7b76cecb7209cb6a7d2b14904fc711
> > > > # bad: [6651149371b842715906311b4631b8489cebf7e8] autofs4: Clean up
> > > > autofs4_free_ino()
> > > > git bisect bad 6651149371b842715906311b4631b8489cebf7e8
> > > > # good: [0ad53eeefcbb2620b6a71ffdaad4add20b450b8b] afs: add afs_wq and use it
> > > > instead of the system workqueue
> > > > git bisect good 0ad53eeefcbb2620b6a71ffdaad4add20b450b8b
> > > > # good: [01c64feac45cea1317263eabc4f7ee1b240f297f] CIFS: Use d_automount()
> > > > rather than abusing follow_link()
> > > > git bisect good 01c64feac45cea1317263eabc4f7ee1b240f297f
> > > > # good: [b5b801779d59165c4ecf1009009109545bd1f642] autofs4: Add d_manage()
> > > > dentry operation
> > > > git bisect good b5b801779d59165c4ecf1009009109545bd1f642
> > > > # bad: [e61da20a50d21725ff27571a6dff9468e4fb7146] autofs4: Clean up inode
> > > > operations
> > > > git bisect bad e61da20a50d21725ff27571a6dff9468e4fb7146
> > > > # good: [8c13a676d5a56495c350f3141824a5ef6c6b4606] autofs4: Remove unused code
> > > > git bisect good 8c13a676d5a56495c350f3141824a5ef6c6b4606
> > >
> > > I can more or less reproduce this at will now, I think even with very
> > > few NFS operations on an automounted nfsv4 mount. Here's an oops from a
> > > 2.6.39 kernel:
> > >
> > > [ 119.419789] tun0: Features changed: 0x00004800 -> 0x00004000
> > > [ 178.242917] FS-Cache: Netfs 'nfs' registered for caching
> > > [ 178.269980] SELinux: initialized (dev 0:2c, type nfs4), uses genfs_contexts
> > > [ 178.282296] SELinux: initialized (dev 0:2d, type nfs4), uses genfs_contexts
> > > [ 523.953284] BUG: Dentry ffff8801f3084180{i=2,n=} still in use (1) [unmount of nfs4 0:2c]
> > > [ 523.953306] ------------[ cut here ]------------
> > > [ 523.954013] kernel BUG at fs/dcache.c:925!
> > > [ 523.954013] invalid opcode: 0000 [#1] SMP
> > > [ 523.954013] last sysfs file: /sys/devices/virtual/bdi/0:45/uevent
> > > [ 523.954013] CPU 1
> > > [ 523.954013] Modules linked in: nfs lockd auth_rpcgss nfs_acl tun fuse ip6table_filter ip6_tables ebtable_nat ebtables sunrpc cachefiles fscache cpufreq_ondemand powernow_k8 freq_table mperf it87 adt7475 hwmon_vid xfs snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_intel raid1 snd_hda_codec snd_usb_audio snd_usbmidi_lib snd_hwdep snd_seq snd_rawmidi snd_seq_device snd_pcm snd_timer snd uvcvideo ppdev videodev soundcore media sp5100_tco v4l2_compat_ioctl32 edac_core parport_pc snd_page_alloc i2c_piix4 edac_mce_amd k10temp parport wmi r8169 microcode mii virtio_net kvm_amd kvm ipv6 ata_generic pata_acpi pata_atiixp radeon ttm drm_kms_helper drm i2c_algo_bit i2c_core [last unloaded: scsi_wait_scan]
> > > [ 523.954013]
> > > [ 523.954013] Pid: 8387, comm: umount.nfs4 Not tainted 2.6.39-1.fc16.x86_64 #1 BIOSTAR Group TA790GX 128M/TA790GX 128M
> > > [ 523.954013] RIP: 0010:[<ffffffff81131788>] [<ffffffff81131788>] shrink_dcache_for_umount_subtree+0x104/0x1c9
> > > [ 523.954013] RSP: 0018:ffff8801f2385d98 EFLAGS: 00010296
> > > [ 523.954013] RAX: 0000000000000062 RBX: ffff8801f3084180 RCX: 00000000000027a7
> > > [ 523.954013] RDX: 0000000000000000 RSI: 0000000000000046 RDI: 0000000000000246
> > > [ 523.954013] RBP: ffff8801f2385dc8 R08: 0000000000000002 R09: 0000ffff00066c0a
> > > [ 523.954013] R10: 0000ffff00066c0a R11: 0000000000000003 R12: ffff8801f3084180
> > > [ 523.954013] R13: ffff8801f31305f0 R14: ffff8801f30ec5f0 R15: 0000000000000000
> > > [ 523.954013] FS: 00007f08e468d720(0000) GS:ffff88022fc80000(0000) knlGS:00000000f770f870
> > > [ 523.954013] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > > [ 523.954013] CR2: 00007fff8fc29ff8 CR3: 00000001f7ac4000 CR4: 00000000000006e0
> > > [ 523.954013] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> > > [ 523.954013] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
> > > [ 523.954013] Process umount.nfs4 (pid: 8387, threadinfo ffff8801f2384000, task ffff8801f7a61710)
> > > [ 523.954013] Stack:
> > > [ 523.954013] ffff8801fdd74a58 0000000000000000 ffff8801fdd74800 ffff8801f3084240
> > > [ 523.954013] ffff8801f2385f28 ffff8801f30ec540 ffff8801f2385de8 ffffffff81132063
> > > [ 523.954013] ffff8801fdd74800 ffffffffa0542300 ffff8801f2385e18 ffffffff81121f15
> > > [ 523.954013] Call Trace:
> > > [ 523.954013] [<ffffffff81132063>] shrink_dcache_for_umount+0x4d/0x5f
> > > [ 523.954013] [<ffffffff81121f15>] generic_shutdown_super+0x23/0xde
> > > [ 523.954013] [<ffffffff8112204d>] kill_anon_super+0x13/0x4c
> > > [ 523.954013] [<ffffffffa051c436>] nfs4_kill_super+0x44/0x77 [nfs]
> > > [ 523.954013] [<ffffffff81122271>] deactivate_locked_super+0x26/0x4b
> > > [ 523.954013] [<ffffffff81122a83>] deactivate_super+0x37/0x3b
> > > [ 523.954013] [<ffffffff811375b3>] mntput_no_expire+0xcc/0xd1
> > > [ 523.954013] [<ffffffff811375de>] mntput+0x26/0x28
> > > [ 523.954013] [<ffffffff81137bef>] release_mounts+0x59/0x73
> > > [ 523.954013] [<ffffffff81138155>] sys_umount+0x28d/0x2da
> > > [ 523.954013] [<ffffffff814828c2>] system_call_fastpath+0x16/0x1b
> > > [ 523.954013] Code: 8b 40 28 4c 8b 08 48 8b 43 30 48 85 c0 74 07 48 8b 90 a8 00 00 00 48 89 34 24 48 c7 c7 f9 ed 7a 81 48 89 de 31 c0 e8 4e 17 34 00 <0f> 0b 4c 8b 63 18 4c 39 e3 75 11 48 8d bb 90 00 00 00 45 31 e4
> > > [ 523.954013] RIP [<ffffffff81131788>] shrink_dcache_for_umount_subtree+0x104/0x1c9
> > > [ 523.954013] RSP <ffff8801f2385d98>
> > > [ 523.954013] [drm] force priority to high
> > > [ 523.954013] [drm] force priority to high
> > > [ 524.042397] ---[ end trace ff21a3f70c461b5e ]---
> > > [ 534.621786] [drm] force priority to high
> > > [ 534.621866] [drm] force priority to high
> > >
> > > Client rpc stats:
> > > calls retrans authrefrsh
> > > 44 0 44
> > >
> > > Client nfs v4:
> > > null read write commit open open_conf
> > > 0 0% 0 0% 1 2% 0 0% 1 2% 1 2%
> > > open_noat open_dgrd close setattr fsinfo renew
> > > 0 0% 0 0% 1 2% 1 2% 4 9% 0 0%
> > > setclntid confirm lock lockt locku access
> > > 1 2% 1 2% 0 0% 0 0% 0 0% 6 13%
> > > getattr lookup lookup_root remove rename link
> > > 7 16% 5 11% 1 2% 0 0% 0 0% 0 0%
> > > symlink create pathconf statfs readlink readdir
> > > 0 0% 0 0% 3 6% 0 0% 0 0% 3 6%
> > > server_caps delegreturn getacl setacl fs_locations rel_lkowner
> > > 7 16% 0 0% 0 0% 0 0% 0 0% 0 0%
> > > exchange_id create_ses destroy_ses sequence get_lease_t reclaim_comp
> > > 0 0% 0 0% 0 0% 0 0% 0 0% 0 0%
> > > layoutget layoutcommit layoutreturn getdevlist getdevinfo ds_write
> > > 0 0% 0 0% 0 0% 0 0% 0 0% 0 0%
> > > ds_commit
> > > 0 0%
> > >
> > > That's good because I think it may help narrow down the codepaths that
> > > lead to this...
> > >
> > > All I did was save a file to the mount using claws-mail and wait for
> > > autofs to unmount it. I'm going to see if I can narrow down the
> > > reproducer somewhat and whether I can take autofs out of the picture.
> > >
> >
> > (cc'ing autofs mailing list too)
> >
> > Taking autofs out of the picture seems to make the problem go away, so
> > this seems to be related to that. Why, exactly, I'm not sure yet. It's
> > always been my understanding that autofs basically gets out of the way
> > once the fs is mounted, but I suppose it needs some way to check for
> > expiration so maybe that mechanism is causing issues.
>
> Mmmm ... with 2.6.39 ... mmm ...
>
> With the vfs-automount in place autofs doesn't quite get out of the way
> anymore but only in so much as it gets a looking during the follow while
> path walking.
>
> Your thought about the autofs expire may be a good lead. There could be
> a problem between the expire check and the ref countless rcu-walk in
> that a umount (possibly a kernel dentry expire) could occur while there
> is an elevated ref-count (by the autofs expire) perhaps. I've thought
> about this possibility the couple of times I've seen reports like this
> but don't have anything concrete.
>
> But, I thought that Mark sees a problem when autofs is not involved at
> all which of course probably means autofs may be the reproducer not the
> cause or we have two bugs. Mark, can you confirm you see this without
> autofs in use please?
>

Thanks Ian. I've gone ahead and opened a bug against Fedora for this so
that we have a place to track progress on this. I've written up some
info on my reproducer there and a bit that I've discovered so far.

https://bugzilla.redhat.com/show_bug.cgi?id=708039

Feel free to go on the cc list if you're interested...

Cheers,
--
Jeff Layton <[email protected]>