Panic upon unmounting zfs snapshot: "vput: negative ref cnt"

From: Richard Todd <rmtodd_at_ichotolot.servalan.com>
Date: Sat, 29 Nov 2008 12:16:23 -0600
I'm running -CURRENT as of this Thursday, and discovered the following panic
upon doing the fairly straightforward steps of making a snapshot, mounting
it, doing some activity reading from the snapshot, and unmounting it --
the exact sequence of commands was something like
   zfs snapshot u1_at_foosnap
   mount -r -t zfs u1_at_foosnap /mnt
   ls -lR /mnt
   umount /mnt
   
Got a crash dump, gdb info follows.  Note that the offending vp seems to be
the vnode for the mount point that the snapshot was mounted on.

Script started on Sat Nov 29 02:17:46 2008
You have mail.
blo-rakane# kgdb kernel.debug /var/crash/vmcore.10
GNU gdb 6.1.1 [FreeBSD]
Copyright 2004 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you are
welcome to change it and/or distribute copies of it under certain conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB.  Type "show warranty" for details.
This GDB was configured as "i386-marcel-freebsd"...

Unread portion of the kernel message buffer:
vput: negative ref count
0x84f70c90: tag ufs, type VDIR
    usecount 0, writecount 0, refcount 0 mountedhere 0
    flags (VI_FREE)
 VI_LOCKed     lock type ufs: EXCL by thread 0x84792b40 (pid 26659)

	ino 8070, on dev da1s1a
panic: vput: negative ref cnt
cpuid = 0
KDB: stack backtrace:
db_trace_self_wrapper(80c23a8c,a7c78bd8,808367f9,80c5728f,0,...) at db_trace_self_wrapper+0x26
kdb_backtrace(80c5728f,0,80c2e3ed,a7c78be4,0,...) at kdb_backtrace+0x29
panic(80c2e3ed,80bdfde4,80c2e3d4,886,a7c78c14,...) at panic+0x119
vput(84f70c90,0,80c2cf23,53c,0,...) at vput+0x12b
dounmount(83e12000,8000000,84792b40,482,5e402c08,...) at dounmount+0x6e0
unmount(84792b40,a7c78cf8,8,84792b40,80d07bb0,...) at unmount+0x2e0
syscall(a7c78d38) at syscall+0x2b4
Xint0x80_syscall() at Xint0x80_syscall+0x20
--- syscall (22, FreeBSD ELF32, unmount), eip = 0x200d220f, esp = 0x7fbfe02c, ebp = 0x7fbfe0f8 ---
Uptime: 5h3m41s
Physical memory: 621 MB
Dumping 221 MB: 206 190 174 158 142 126 110 94 78 62 46 30 14

Reading symbols from /boot/kernel/geom_mirror.ko...done.
Loaded symbols for /boot/kernel/geom_mirror.ko
Reading symbols from /boot/kernel/zfs.ko...done.
Loaded symbols for /boot/kernel/zfs.ko
Reading symbols from /boot/kernel/opensolaris.ko...done.
Loaded symbols for /boot/kernel/opensolaris.ko
Reading symbols from /boot/kernel/linux.ko...done.
Loaded symbols for /boot/kernel/linux.ko
Reading symbols from /boot/kernel/green_saver.ko...done.
Loaded symbols for /boot/kernel/green_saver.ko
#0  doadump () at pcpu.h:246
246		__asm __volatile("movl %%fs:0,%0" : "=r" (td));
(kgdb) bt
#0  doadump () at pcpu.h:246
#1  0x8083655e in boot (howto=260) at /usr/src/sys/kern/kern_shutdown.c:420
#2  0x80836832 in panic (fmt=Variable "fmt" is not available.
) at /usr/src/sys/kern/kern_shutdown.c:576
#3  0x808c0ebb in vput (vp=0x84f70c90) at /usr/src/sys/kern/vfs_subr.c:2199
#4  0x808b9160 in dounmount (mp=0x83e12000, flags=134217728, td=0x84792b40)
    at /usr/src/sys/kern/vfs_mount.c:1343
#5  0x808b9480 in unmount (td=0x84792b40, uap=0xa7c78cf8)
    at /usr/src/sys/kern/vfs_mount.c:1182
#6  0x80b6b214 in syscall (frame=0xa7c78d38)
    at /usr/src/sys/i386/i386/trap.c:1076
#7  0x80b4ff10 in Xint0x80_syscall () at /usr/src/sys/i386/i386/exception.s:261
#8  0x00000033 in ?? ()
Previous frame inner to this frame (corrupt stack?)
(kgdb) fr 3
#3  0x808c0ebb in vput (vp=0x84f70c90) at /usr/src/sys/kern/vfs_subr.c:2199
2199			panic("vput: negative ref cnt");
(kgdb) p *vp
$1 = {v_type = VDIR, v_tag = 0x80c1a42c "ufs", v_op = 0x80d2c6e0, 
  v_data = 0x84e427f8, v_mount = 0x83e12c80, v_nmntvnodes = {
    tqe_next = 0x885de324, tqe_prev = 0x84f6f768}, v_un = {vu_mount = 0x0, 
    vu_socket = 0x0, vu_cdev = 0x0, vu_fifoinfo = 0x0, vu_yield = 0}, 
  v_hashlist = {le_next = 0x0, le_prev = 0x83c9f2a4}, v_hash = 8070, 
  v_cache_src = {lh_first = 0x0}, v_cache_dst = {tqh_first = 0x84f58440, 
    tqh_last = 0x84f58450}, v_dd = 0x83cfda78, v_cstart = 0, v_lasta = 0, 
  v_lastw = 0, v_clen = 0, v_lock = {lock_object = {
      lo_name = 0x80c1a42c "ufs", lo_flags = 91947009, lo_data = 0, 
      lo_witness = 0x0}, lk_lock = 2222533440, lk_timo = 16, lk_pri = 80}, 
  v_interlock = {lock_object = {lo_name = 0x80c26a32 "vnode interlock", 
      lo_flags = 16973824, lo_data = 0, lo_witness = 0x0}, 
    mtx_lock = 2222533440}, v_vnlock = 0x84f70ce8, v_holdcnt = 0, 
  v_usecount = 0, v_iflag = 256, v_vflag = 0, v_writecount = 0, v_freelist = {
    tqe_next = 0x0, tqe_prev = 0x84b242b8}, v_bufobj = {bo_mtx = {
      lock_object = {lo_name = 0x80c2e32a "bufobj interlock", 
        lo_flags = 16973824, lo_data = 0, lo_witness = 0x0}, mtx_lock = 4}, 
    bo_clean = {bv_hd = {tqh_first = 0x0, tqh_last = 0x84f70d4c}, 
      bv_root = 0x0, bv_cnt = 0}, bo_dirty = {bv_hd = {tqh_first = 0x0, 
        tqh_last = 0x84f70d5c}, bv_root = 0x0, bv_cnt = 0}, bo_numoutput = 0, 
    bo_flag = 0, bo_ops = 0x80d17100, bo_bsize = 16384, bo_object = 0x0, 
    bo_synclist = {le_next = 0x0, le_prev = 0x0}, bo_private = 0x84f70c90, 
    __bo_vnode = 0x84f70c90}, v_pollinfo = 0x0, v_label = 0x0, v_lockf = 0x0}
(kgdb) l
2194	
2195		if (vp->v_usecount != 1) {
2196	#ifdef DIAGNOSTIC
2197			vprint("vput: negative ref count", vp);
2198	#endif
2199			panic("vput: negative ref cnt");
2200		}
2201		/*
2202		 * We want to hold the vnode until the inactive finishes to
2203		 * prevent vgone() races.  We drop the use count here and the
(kgdb) p vp->v_usecount
$2 = 0
(kgdb) fr 4
#4  0x808b9160 in dounmount (mp=0x83e12000, flags=134217728, td=0x84792b40)
    at /usr/src/sys/kern/vfs_mount.c:1343
1343			vput(coveredvp);
(kgdb) p coveredvp
$3 = (struct vnode *) 0x84f70c90
(kgdb) p coveredvp[0]
$4 = {v_type = VDIR, v_tag = 0x80c1a42c "ufs", v_op = 0x80d2c6e0, 
  v_data = 0x84e427f8, v_mount = 0x83e12c80, v_nmntvnodes = {
    tqe_next = 0x885de324, tqe_prev = 0x84f6f768}, v_un = {vu_mount = 0x0, 
    vu_socket = 0x0, vu_cdev = 0x0, vu_fifoinfo = 0x0, vu_yield = 0}, 
  v_hashlist = {le_next = 0x0, le_prev = 0x83c9f2a4}, v_hash = 8070, 
  v_cache_src = {lh_first = 0x0}, v_cache_dst = {tqh_first = 0x84f58440, 
    tqh_last = 0x84f58450}, v_dd = 0x83cfda78, v_cstart = 0, v_lasta = 0, 
  v_lastw = 0, v_clen = 0, v_lock = {lock_object = {
      lo_name = 0x80c1a42c "ufs", lo_flags = 91947009, lo_data = 0, 
      lo_witness = 0x0}, lk_lock = 2222533440, lk_timo = 16, lk_pri = 80}, 
  v_interlock = {lock_object = {lo_name = 0x80c26a32 "vnode interlock", 
      lo_flags = 16973824, lo_data = 0, lo_witness = 0x0}, 
    mtx_lock = 2222533440}, v_vnlock = 0x84f70ce8, v_holdcnt = 0, 
  v_usecount = 0, v_iflag = 256, v_vflag = 0, v_writecount = 0, v_freelist = {
    tqe_next = 0x0, tqe_prev = 0x84b242b8}, v_bufobj = {bo_mtx = {
      lock_object = {lo_name = 0x80c2e32a "bufobj interlock", 
        lo_flags = 16973824, lo_data = 0, lo_witness = 0x0}, mtx_lock = 4}, 
    bo_clean = {bv_hd = {tqh_first = 0x0, tqh_last = 0x84f70d4c}, 
      bv_root = 0x0, bv_cnt = 0}, bo_dirty = {bv_hd = {tqh_first = 0x0, 
        tqh_last = 0x84f70d5c}, bv_root = 0x0, bv_cnt = 0}, bo_numoutput = 0, 
    bo_flag = 0, bo_ops = 0x80d17100, bo_bsize = 16384, bo_object = 0x0, 
    bo_synclist = {le_next = 0x0, le_prev = 0x0}, bo_private = 0x84f70c90, 
    __bo_vnode = 0x84f70c90}, v_pollinfo = 0x0, v_label = 0x0, v_lockf = 0x0}
(kgdb) l
1338		mtx_lock(&mountlist_mtx);
1339		TAILQ_REMOVE(&mountlist, mp, mnt_list);
1340		mtx_unlock(&mountlist_mtx);
1341		if (coveredvp != NULL) {
1342			coveredvp->v_mountedhere = NULL;
1343			vput(coveredvp);
1344		}
1345		vfs_event_signal(NULL, VQ_UNMOUNT, 0);
1346		vfs_mount_destroy(mp);
1347		return (0);
(kgdb) q
blo-rakane# exit
exit

Script done on Sat Nov 29 02:19:59 2008
Received on Sat Nov 29 2008 - 18:03:53 UTC

This archive was generated by hypermail 2.4.0 : Wed May 19 2021 - 11:39:38 UTC