Recent changes to pseudofs causing panics -- leaking a vnode lock?

From: Richard Todd <rmtodd_at_ichotolot.servalan.com>
Date: Thu, 8 Jan 2009 18:48:53 -0600
I've noticed that ever since updating to a kernel after the recent changes
to the pseudofs code late last month, that I've occasionally gotten the 
following sort of panic:

System call readlink returning with the following locks held:
exclusive lockmgr pseudofs (pseudofs) r = 0 (0xffffff00ba581cc8) locked _at_ /usr/src/sys/fs/pseudofs/pseudofs_vncache.c:193
panic: witness_warn

The line in question is the one I marked by an arrow in this chunk of the 
pfs_vncache_alloc code: 
        if ((pn->pn_flags & PFS_PROCDEP) != 0)
                (*vpp)->v_vflag |= VV_PROCDEP;
        pvd->pvd_vnode = *vpp;
        VN_LOCK_AREC(*vpp);
        vn_lock(*vpp, LK_EXCLUSIVE | LK_RETRY); <==== this lock here
        error = insmntque(*vpp, mp);

So somehow, a vnode is getting locked here and not getting unlocked.
I suspect the code in the retry2: loop later, simply because that's
the code that got added in the late December commits, but I'm not
clear on how exactly.  I've tried littering the code with extra
printfs to try to clarify what's going on, but alas, I'm still not
really sure what's going on.  I do have a good coredump that I can get
info out of, if someone can suggest to me what would be useful things
to dump.  Anyway, here's the patch for the debugging printfs I added,
and the console messages produced by those printfs from the most
recent coredump/panic.  The console msgs do seem to indicate some sort
of race condition going on, though, as they seem to show two or more processes
simultaneously hitting the pseudofs code and hitting my debugging print
statements (alas, making the console log rather a confused mess.)

The debugging additions:
Index: pseudofs_vncache.c
===================================================================
RCS file: /usr/FreeBSDCVS/src/sys/fs/pseudofs/pseudofs_vncache.c,v
retrieving revision 1.44
diff -u -r1.44 pseudofs_vncache.c
--- pseudofs_vncache.c	29 Dec 2008 13:25:58 -0000	1.44
+++ pseudofs_vncache.c	8 Jan 2009 02:22:50 -0000
_at__at_ -129,6 +129,7 _at__at_
 			mtx_unlock(&pfs_vncache_mutex);
 			if (vget(vp, LK_EXCLUSIVE | LK_INTERLOCK, curthread) == 0) {
 				++pfs_vncache_hits;
+				vprint("XXX vncache 6", vp);
 				*vpp = vp;
 				/*
 				 * Some callers cache_enter(vp) later, so
_at__at_ -191,7 +192,9 _at__at_
 	pvd->pvd_vnode = *vpp;
 	VN_LOCK_AREC(*vpp);
 	vn_lock(*vpp, LK_EXCLUSIVE | LK_RETRY);
+	printf("XXX vncache 1 *vpp=%p\n", *vpp);
 	error = insmntque(*vpp, mp);
+	printf("XXX vncache 2 *vpp=%p\n", *vpp);
 	if (error != 0) {
 		*vpp = NULLVP;
 		return (error);
_at__at_ -211,11 +214,14 _at__at_
 			mtx_unlock(&pfs_vncache_mutex);
 			if (vget(vp, LK_EXCLUSIVE | LK_INTERLOCK, curthread) == 0) {
 				++pfs_vncache_hits;
+	                        vprint("XXX vncache 3", *vpp);
 				vgone(*vpp);
+	                        vprint("XXX vncache 4", *vpp);
 				*vpp = vp;
 				cache_purge(vp);
 				return (0);
 			}
+			vprint("XXX vncache 5", *vpp);
 			goto retry2;
 		}
 	}
Index: pseudofs_vnops.c
===================================================================
RCS file: /usr/FreeBSDCVS/src/sys/fs/pseudofs/pseudofs_vnops.c,v
retrieving revision 1.72
diff -u -r1.72 pseudofs_vnops.c
--- pseudofs_vnops.c	30 Dec 2008 21:49:39 -0000	1.72
+++ pseudofs_vnops.c	6 Jan 2009 23:12:40 -0000
_at__at_ -369,6 +369,7 _at__at_
 	VOP_UNLOCK(vp, 0);
 
 	error = pfs_vncache_alloc(mp, dvp, pn, pid);
+        vprint("XXX vptocnp", *dvp);
 	if (error) {
 		vn_lock(vp, locked | LK_RETRY);
 		vfs_unbusy(mp);
_at__at_ -502,6 +503,7 _at__at_
 	}
 
 	error = pfs_vncache_alloc(vn->v_mount, vpp, pn, pid);
+        vprint("XXX lookup", *vpp);
 	if (error)
 		goto failed;
 
and the msgs from the most recent coredump:
Script started on Thu Jan  8 18:34:33 2009
You have mail.
ichotolot# kgdb kernel.debug /var/crash/vmcore.206 
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 "amd64-marcel-freebsd"...

Unread portion of the kernel message buffer:
XXX vncache 1 *vpp=0xffffff00b0173c30
XXX vncache 2 *vpp=0xffffff00b0173c30
XXX vncache 1 *vpp=0xffffff000d420270XXX vncache 1 *vp
p=0xffXfXfX fvfn0cache 2 *vp0c6886750p=0xffffff000d420270
XXX vncache 2 *vpp=0xffffff00c6886750

XXX lookup
0xffffff00c6886750: tag pseudofs, type VLNK
    usecount 1, writecount 0, refcount 1 mountedhere 0
    flags ()
     lock type pseudofs: EXCL by thread 0xffffff00c873e390 (pid 18861)
#0 0xffffffff80514c28 at __lockmgr_args+0x758
#1 0xffffffff805a4409 at vop_stdlock+0x39
#2 0xffffffff808369db at VOP_LOCK1_APV+0x9b
#3 0xffffffff805bfae7 at _vn_lock+0x57
#4 0xffffffff804ce120 at pfs_vncache_alloc+0x1f0
#5 0xffffffff804cf473 at pfs_lookup+0x273
#6 0xffffffff8083543f at VOP_CACHEDLOOKUP_APV+0xaf
#7 0xffffffff805a2220 at vfs_cache_lookup+0xf0
#8 0xffffffff808378a7 at VOP_LOOKUP_APV+0xb7
#9 0xffffffff805a83d3 at lookup+0x513
#10 0xffffffff805a928e at namei+0x53e
#11 0xffffffff805b6ffa at kern_readlinkat+0x7a
#12 0xffffffff805b7121 at kern_readlink+0x21
#13 0xffffffff807f16b7 at syscall+0x1e7
#14 0xffffffff807d41bb at Xfast_syscall+0xab

XXX vncache 3
0xffffff000d420270: tag pseudofs, type VDIR
    usecount 1, writecount 0, refcount 1 mountedhere 0
    flags (VV_ROOT)
     lock type pseudofs: EXCL by thread 0xffffff0082999390 (pid 18860)
#0 0xffffffff80514c28 at __lockmgr_args+0x758
#1 0xffffffff805a4409 at vop_stdlock+0x39
#2 0xffffffff808369db at VOP_LOCK1_APV+0x9b
#3 0xffffffff805bfae7 at _vn_lock+0x57
#4 0xffffffff804ce120 at pfs_vncache_alloc+0x1f0
#5 0xffffffff805a885f at lookup+0x99f
#6 0xffffffff805a928e at namei+0x53e
#7 0xffffffff805b6ffa at kern_readlinkat+0x7a
#8 0xffffffff805b7121 at kern_readlink+0x21
#9 0xffffffff807f16b7 at syscall+0x1e7
#10 0xffffffff807d41bb at Xfast_syscall+0xab

XXX vncache 4
0xffffff000d420270: tag none, type VBAD
    usecount 1, writecount 0, refcount 1 mountedhere 0
    flags (VV_ROOT|VI_DOOMED)
     lock type pseudofs: EXCL by thread 0xffffff0082999390 (pid 18860)
#0 0xffffffff80514c28 at __lockmgr_args+0x758
#1 0xffffffff805a4409 at vop_stdlock+0x39
#2 0xffffffff808369db at VOP_LOCK1_APV+0x9b
#3 0xffffffff805bfae7 at _vn_lock+0x57
#4 0xffffffff804ce120 at pfs_vncache_alloc+0x1f0
#5 0xffffffff805a885f at lookup+0x99f
#6 0xffffffff805a928e at namei+0x53e
#7 0xffffffff805b6ffa at kern_readlinkat+0x7a
#8 0xffffffff805b7121 at kern_readlink+0x21
#9 0xffffffff807f16b7 at syscall+0x1e7
#10 0xffffffff807d41bb at Xfast_syscall+0xab

XXX vncache 6
0xffffff00c6886750: tag pseudofs, type VLNK
    usecount 1, writecount 0, refcount 1 mountedhere 0
    flags ()
     lock type pseudofs: EXCL by thread 0xffffff0082999390 (pid 18860)
#0 0xffffffff80514c28 at __lockmgr_args+0x758
#1 0xffffffff805a4409 at vop_stdlock+0x39
#2 0xffffffff808369db at VOP_LOCK1_APV+0x9b
#3 0xffffffff805bfae7 at _vn_lock+0x57
#4 0xffffffff805b3fdb at vget+0x8b
#5 0xffffffff804cdfe8 at pfs_vncache_alloc+0xb8
#6 0xffffffff804cf473 at pfs_lookup+0x273
#7 0xffffffff8083543f at VOP_CACHEDLOOKUP_APV+0xaf
#8 0xffffffff805a2220 at vfs_cache_lookup+0xf0
#9 0xffffffff808378a7 at VOP_LOOKUP_APV+0xb7
#10 0xffffffff805a83d3 at lookup+0x513
#11 0xffffffff805a928e at namei+0x53e
#12 0xffffffff805b6ffa at kern_readlinkat+0x7a
#13 0xffffffff805b7121 at kern_readlink+0x21
#14 0xffffffff807f16b7 at syscall+0x1e7
#15 0xffffffff807d41bb at Xfast_syscall+0xab

XXX lookup
0xffffff00c6886750: tag pseudofs, type VLNK
    usecount 1, writecount 0, refcount 1 mountedhere 0
    flags ()
     lock type pseudofs: EXCL by thread 0xffffff0082999390 (pid 18860)
#0 0xffffffff80514c28 at __lockmgr_args+0x758
#1 0xffffffff805a4409 at vop_stdlock+0x39
#2 0xffffffff808369db at VOP_LOCK1_APV+0x9b
#3 0xffffffff805bfae7 at _vn_lock+0x57
#4 0xffffffff805b3fdb at vget+0x8b
#5 0xffffffff804cdfe8 at pfs_vncache_alloc+0xb8
#6 0xffffffff804cf473 at pfs_lookup+0x273
#7 0xffffffff8083543f at VOP_CACHEDLOOKUP_APV+0xaf
#8 0xffffffff805a2220 at vfs_cache_lookup+0xf0
#9 0xffffffff808378a7 at VOP_LOOKUP_APV+0xb7
#10 0xffffffff805a83d3 at lookup+0x513
#11 0xffffffff805a928e at namei+0x53e
#12 0xffffffff805b6ffa at kern_readlinkat+0x7a
#13 0xffffffff805b7121 at kern_readlink+0x21
#14 0xffffffff807f16b7 at syscall+0x1e7
#15 0xffffffff807d41bb at Xfast_syscall+0xab

XXX vncache 1 *vpp=0xffffff007af74270
XXX vncache 2 *vpp=0xffffff007af74270
XXX lookup
0xffffff007af74270: tag pseudofs, type VDIR
    usecount 1, writecount 0, refcount 1 mountedhere 0
    flags (VV_PROCDEP)
     lock type pseudofs: EXCL by thread 0xffffff00c873e390 (pid 18861)
#0 0xffffffff80514c28 at __lockmgr_args+0x758
#1 0xffffffff805a4409 at vop_stdlock+0x39
#2 0xffffffff808369db at VOP_LOCK1_APV+0x9b
#3 0xffffffff805bfae7 at _vn_lock+0x57
#4 0xffffffff804ce120 at pfs_vncache_alloc+0x1f0
#5 0xffffffff804cf473 at pfs_lookup+0x273
#6 0xffffffff8083543f at VOP_CACHEDLOOKUP_APV+0xaf
#7 0xffffffff805a2220 at vfs_cache_lookup+0xf0
#8 0xffffffff808378a7 at VOP_LOOKUP_APV+0xb7
#9 0xffffffff805a83d3 at lookup+0x513
#10 0xffffffff805a928e at namei+0x53e
#11 0xffffffff805b6ffa at kern_readlinkat+0x7a
#12 0xffffffff805b7121 at kern_readlink+0x21
#13 0xffffffff807f16b7 at syscall+0x1e7
#14 0xffffffff807d41bb at Xfast_syscall+0xab

XXX vncache 1 *vpp=0xffffff00cd4719c0
XXX vncache 2 *vpp=0xffffff00cd4719c0
XXX lookup
0xffffff00cd4719c0: tag pseudofs, type VLNK
    usecount 1, writecount 0, refcount 1 mountedhere 0
    flags (VV_PROCDEP)
     lock type pseudofs: EXCL by thread 0xffffff00c873e390 (pid 18861)
#0 0xffffffff80514c28 at __lockmgr_args+0x758
#1 0xffffffff805a4409 at vop_stdlock+0x39
#2 0xffffffff808369db at VOP_LOCK1_APV+0x9b
#3 0xffffffff805bfae7 at _vn_lock+0x57
#4 0xffffffff804ce120 at pfs_vncache_alloc+0x1f0
#5 0xffffffff804cf473 at pfs_lookup+0x273
#6 0xffffffff8083543f at VOP_CACHEDLOOKUP_APV+0xaf
#7 0xffffffff805a2220 at vfs_cache_lookup+0xf0
#8 0xffffffff808378a7 at VOP_LOOKUP_APV+0xb7
#9 0xffffffff805a83d3 at lookup+0x513
#10 0xffffffff805a928e at namei+0x53e
#11 0xffffffff805b6ffa at kern_readlinkat+0x7a
#12 0xffffffff805b7121 at kern_readlink+0x21
#13 0xffffffff807f16b7 at syscall+0x1e7
#14 0xffffffff807d41bb at Xfast_syscall+0xab

XXX vncache 6
0xffffff00b0173c30: tag pseudofs, type VDIR
    usecount 2, writecount 0, refcount 3 mountedhere 0
    flags (VV_ROOT)
     lock type pseudofs: EXCL by thread 0xffffff00c625bab0 (pid 18865)
#0 0xffffffff80514c28 at __lockmgr_args+0x758
#1 0xffffffff805a4409 at vop_stdlock+0x39
#2 0xffffffff808369db at VOP_LOCK1_APV+0x9b
#3 0xffffffff805bfae7 at _vn_lock+0x57
#4 0xffffffff805b3fdb at vget+0x8b
#5 0xffffffff804cdfe8 at pfs_vncache_alloc+0xb8
#6 0xffffffff805a885f at lookup+0x99f
#7 0xffffffff805a928e at namei+0x53e
#8 0xffffffff805b6ffa at kern_readlinkat+0x7a
#9 0xffffffff805b7121 at kern_readlink+0x21
#10 0xffffffff807f16b7 at syscall+0x1e7
#11 0xffffffff807d41bb at Xfast_syscall+0xab

XXX vncache 6
0xffffff00c6886750: tag pseudofs, type VLNK
    usecount 1, writecount 0, refcount 1 mountedhere 0
    flags ()
     lock type pseudofs: EXCL by thread 0xffffff00c625bab0 (pid 18865)
#0 0xffffffff80514c28 at __lockmgr_args+0x758
#1 0xffffffff805a4409 at vop_stdlock+0x39
#2 0xffffffff808369db at VOP_LOCK1_APV+0x9b
#3 0xffffffff805bfae7 at _vn_lock+0x57
#4 0xffffffff805b3fdb at vget+0x8b
#5 0xffffffff804cdfe8 at pfs_vncache_alloc+0xb8
#6 0xffffffff804cf473 at pfs_lookup+0x273
#7 0xffffffff8083543f at VOP_CACHEDLOOKUP_APV+0xaf
#8 0xffffffff805a2220 at vfs_cache_lookup+0xf0
#9 0xffffffff808378a7 at VOP_LOOKUP_APV+0xb7
#10 0xffffffff805a83d3 at lookup+0x513
#11 0xffffffff805a928e at namei+0x53e
#12 0xffffffff805b6ffa at kern_readlinkat+0x7a
#13 0xffffffff805b7121 at kern_readlink+0x21
#14 0xffffffff807f16b7 at syscall+0x1e7
#15 0xffffffff807d41bb at Xfast_syscall+0xab

XXX lookup
0xffffff00c6886750: tag pseudofs, type VLNK
    usecount 1, writecount 0, refcount 1 mountedhere 0
    flags ()
     lock type pseudofs: EXCL by thread 0xffffff00c625bab0 (pid 18865)
#0 0xffffffff80514c28 at __lockmgr_args+0x758
#1 0xffffffff805a4409 at vop_stdlock+0x39
#2 0xffffffff808369db at VOP_LOCK1_APV+0x9b
#3 0xffffffff805bfae7 at _vn_lock+0x57
#4 0xffffffff805b3fdb at vget+0x8b
#5 0xffffffff804cdfe8 at pfs_vncache_alloc+0xb8
#6 0xffffffff804cf473 at pfs_lookup+0x273
#7 0xffffffff8083543f at VOP_CACHEDLOOKUP_APV+0xaf
#8 0xffffffff805a2220 at vfs_cache_lookup+0xf0
#9 0xffffffff808378a7 at VOP_LOOKUP_APV+0xb7
#10 0xffffffff805a83d3 at lookup+0x513
#11 0xffffffff805a928e at namei+0x53e
#12 0xffffffff805b6ffa at kern_readlinkat+0x7a
#13 0xffffffff805b7121 at kern_readlink+0x21
#14 0xffffffff807f16b7 at syscall+0x1e7
#15 0xffffffff807d41bb at Xfast_syscall+0xab

XXX vncache 1 *vpp=0xffffff0053e7a750
XXX vncache 2 *vpp=0xffffff0053e7a750
XXX lookup
0xffffff0053e7a750: tag pseudofs, type VDIR
    usecount 1, writecount 0, refcount 1 mountedhere 0
    flags (VV_PROCDEP)
     lock type pseudofs: EXCL by thread 0xffffff0082999390 (pid 18860)
#0 0xffffffff80514c28 at __lockmgr_args+0x758
#1 0xffffffff805a4409 at vop_stdlock+0x39
#2 0xffffffff808369db at VOP_LOCK1_APV+0x9b
#3 0xffffffff805bfae7 at _vn_lock+0x57
#4 0xffffffff804ce120 at pfs_vncache_alloc+0x1f0
#5 0xffffffff804cf473 at pfs_lookup+0x273
#6 0xffffffff8083543f at VOP_CACHEDLOOKUP_APV+0xaf
#7 0xffffffff805a2220 at vfs_cache_lookup+0xf0
#8 0xffffffff808378a7 at VOP_LOOKUP_APV+0xb7
#9 0xffffffff805a83d3 at lookup+0x513
#10 0xffffffff805a928e at namei+0x53e
#11 0xffffffff805b6ffa at kern_readlinkat+0x7a
#12 0xffffffff805b7121 at kern_readlink+0x21
#13 0xffffffff807f16b7 at syscall+0x1e7
#14 0xffffffff807d41bb at Xfast_syscall+0xab

XXX vncache 1 *vpp=0xffffff00429cb4e0XXX vncache 1 *vpp=0xffffff007a92a750
XXX vncache 2 *vpp=0xffffff00429cb4e0
XXX vncache 2 *vpp=0xffffff007a92a750
XXX lookup
XXX lookup
0xffffff00429cb4e0: 
0xffffff007a92a750: tag pseudofs, type VLNKtag pseudofs, type VDIR
    usecount 1, writecount 0, refcount 1 mountedhere 0
    usecount 1, writecount 0, refcount 1 mountedhere 0
    flags (VV_PROCDEP)
    flags (VV_PROCDEP)
    
     lock type ps eudofs: EXCL by thrleoacdk  type0 pseudofs: EXCL by xftfhfrfefafd0 0829099x3f9f0 f(pid 18860)fff00c625bab0 (pid 18865)

#0 0xffffffff80514c28 at __lockmgr_args+0x758#0 
0xffffffff80514c28 at __lockmgr_args+0x758
#1 0xffffffff805a4409 at vop_stdlock+0x39
#1 0xffffffff805a4409 at vop_stdlock+0x39
#2 0xffffffff808369db at VOP_LOCK1_APV+0x9b#2 
0xffffffff808369db at VOP_LOCK1_APV+0x9b
#3 0xffffffff805bfae7 at _vn_lock+0x57
#3 0xffffffff805bfae7 at _vn_lock+0x57
#4 0xffffffff804ce120 at pfs_vncache_alloc+0x1f0
#4 0xffffffff804ce120 at pfs_vncache_alloc+0x1f0
#5 0x#f5f ffff0fxff8f0f4fcff473 at pfs_lookffufp8+004xc2f7473 at pfs_lookup+30x273

#6 0xffffffff8083543f at VOP_CACHEDLOOKUP_APV+0xaf#6 0xffffffff8083543f at VOP_CACHEDLOOKUP_APV+0xaf

#7 0xffffffff805a2220 at vfs_cache_lookup+0xf0#7 0xffffffff805a2220 at vf
s_cache_lookup+0xf0
#8 0xffffffff808378a7 at VOP_LOOKUP_APV+0xb7#8 0xffffffff808378
a7 at VOP_LOOKUP_APV+0xb7
#9 0xffffffff805a83d3 at lookup+0x513
#9 0xffffffff805a83d3 at lookup+0x513
#10 0xffffff#ff8105a928e at namei+00 x53e0xffffffff805a928e at namei+0x53e

#11 0xffffffff805b6ffa at kern_readlinkat+0x7a#11 0xffffffff805b6ffa at kern_readlinkat+0x7a

#12 0xffffffff805b7121 at kern_readlink+0x21#12 0xffffffff805b7121 at ker
n_readlink+0x21
#13 0xffffffff807f16b7 at syscall+0x1e7
#13 0xffffffff807f16b7 at syscall+0x1e7
#14 0xffffffff807d41bb at Xfast_syscall+0xab

XXX vncache 1 *vpp=0xffffff007a357750#14 0xffffffff807d41bb at Xfast_syscall+0xab
XXX vncache 2 *vpp=0xffffff007a357750

XXX looku
p
0xffffff007a357750: tag pseudofs, type VLNKSystem call readlink returning
    usecount 1, writecount 0, refcount 1 mountedhere 0 with the following
    flags (VV_PROCDEP) locks held:
exclusive lockmgr pseudofs
     lock type pseudofs: EXCL by thread 0xffffff00c625b a(b0 (ppid seu1d8865)ofs)
 r = 0 (0xffffff000d420308) locked _at_ /usr/src/sys/fs/pseudofs/pseudofs_vncache.c:194
panic: witness_warn
cpuid = 0
KDB: enter: panic
Physical memory: 4012 MB
Dumping 2401 MB: 2386 2370 2354 2338 2322 2306 2290 2274 2258 2242 2226 2210 2194 2178 2162 2146 2130 2114 2098 2082 2066 2050 2034 2018 2002 1986 1970 1954 1938 1922 1906 1890 1874 1858 1842 1826 1810 1794 1778 1762 1746 1730 1714 1698 1682 1666 1650 1634 1618 1602 1586 1570 1554 1538 1522 1506 1490 1474 1458 1442 1426 1410 1394 1378 1362 1346 1330 1314 1298 1282 1266 1250 1234 1218 1202 1186 1170 1154 1138 1122 1106 1090 1074 1058 1042 1026 1010 994 978 962 946 930 914 898 882 866 850 834 818 802 786 770 754 738 722 706 690 674 658 642 626 610 594 578 562 546 530 514 498 482 466 450 434 418 402 386 370 354 338 322 306 290 274 258 242 226 210 194 178 162 146 130 114 98 82 66 50 34 18 2

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/geom_mirror.ko...done.
Loaded symbols for /boot/kernel/geom_mirror.ko
Reading symbols from /boot/kernel/snd_hda.ko...done.
Loaded symbols for /boot/kernel/snd_hda.ko
Reading symbols from /boot/kernel/sound.ko...done.
Loaded symbols for /boot/kernel/sound.ko
Reading symbols from /boot/kernel/coretemp.ko...done.
Loaded symbols for /boot/kernel/coretemp.ko
Reading symbols from /boot/kernel/atapicam.ko...done.
Loaded symbols for /boot/kernel/atapicam.ko
Reading symbols from /boot/kernel/tmpfs.ko...done.
Loaded symbols for /boot/kernel/tmpfs.ko
Reading symbols from /boot/kernel/linux.ko...done.
Loaded symbols for /boot/kernel/linux.ko
Reading symbols from /usr/local/modules/fuse.ko...done.
Loaded symbols for /usr/local/modules/fuse.ko
Reading symbols from /boot/modules/cpu.ko...done.
Loaded symbols for /boot/modules/cpu.ko
Reading symbols from /boot/kernel/green_saver.ko...done.
Loaded symbols for /boot/kernel/green_saver.ko
Reading symbols from /boot/kernel/radeon.ko...done.
Loaded symbols for /boot/kernel/radeon.ko
Reading symbols from /boot/kernel/drm.ko...done.
Loaded symbols for /boot/kernel/drm.ko
Reading symbols from /boot/kernel/nullfs.ko...done.
Loaded symbols for /boot/kernel/nullfs.ko
Reading symbols from /boot/kernel/linprocfs.ko...done.
Loaded symbols for /boot/kernel/linprocfs.ko
#0  doadump () at pcpu.h:196
196             __asm __volatile("movq %%gs:0,%0" : "=r" (td));
(kgdb)    p    bt
#0  doadump () at pcpu.h:196
#1  0xffffffff801c752c in db_fncall (dummy1=Variable "dummy1" is not available.
)
    at /usr/src/sys/ddb/db_command.c:548
#2  0xffffffff801c7861 in db_command (last_cmdp=0xffffffff80b547a0, cmd_table=Variable "cmd_table" is not available.
)
    at /usr/src/sys/ddb/db_command.c:445
#3  0xffffffff801c7ab0 in db_command_loop ()
    at /usr/src/sys/ddb/db_command.c:498
#4  0xffffffff801c9a59 in db_trap (type=Variable "type" is not available.
) at /usr/src/sys/ddb/db_main.c:229
#5  0xffffffff80558fd5 in kdb_trap (type=3, code=0, tf=0xffffffff2d73e840)
    at /usr/src/sys/kern/subr_kdb.c:534
#6  0xffffffff807f1e14 in trap (frame=0xffffffff2d73e840)
    at /usr/src/sys/amd64/amd64/trap.c:533
#7  0xffffffff807d3fae in calltrap ()
    at /usr/src/sys/amd64/amd64/exception.S:217
#8  0xffffffff805591ad in kdb_enter (why=0xffffffff808d5179 "panic", 
    msg=0x1 <Address 0x1 out of bounds>) at cpufunc.h:63
#9  0xffffffff80529c5b in panic (fmt=Variable "fmt" is not available.
) at /usr/src/sys/kern/kern_shutdown.c:559
#10 0xffffffff8056c41e in witness_warn (flags=Variable "flags" is not available.
)
    at /usr/src/sys/kern/subr_witness.c:1655
#11 0xffffffff807f175e in syscall (frame=0xffffffff2d73ec90)
    at /usr/src/sys/amd64/amd64/trap.c:965
#12 0xffffffff807d41bb in Xfast_syscall ()
    at /usr/src/sys/amd64/amd64/exception.S:338
#13 0x0000000018c1ec1c in ?? ()
Previous frame inner to this frame (corrupt stack?)
(kgdb) fr 11
#11 0xffffffff807f175e in syscall (frame=0xffffffff2d73ec90)
    at /usr/src/sys/amd64/amd64/trap.c:965
965             WITNESS_WARN(WARN_PANIC, NULL, "System call %s returning",
(kgdb) p td
$1 = (struct thread *) 0xffffff0082999390
(kgdb) p td->td_proc
$2 = (struct proc *) 0xffffff0082ae4880
(kgdb) p td->td_proc[0]
$3 = {p_list = {le_next = 0xffffff00c82e6440, le_prev = 0xffffff007ac31000}, 
  p_threads = {tqh_first = 0xffffff0082999390, tqh_last = 0xffffff00829993a0}, 
  p_slock = {lock_object = {lo_name = 0xffffffff808d3982 "process slock", 
      lo_flags = 720896, lo_data = 0, lo_witness = 0x0}, mtx_lock = 4}, 
  p_ucred = 0xffffff0010b4ec00, p_fd = 0xffffff00bdaac400, p_fdtol = 0x0, 
  p_stats = 0xffffff0082a83c00, p_limit = 0xffffff000ef56c00, p_limco = {
    c_links = {sle = {sle_next = 0x0}, tqe = {tqe_next = 0x0, 
        tqe_prev = 0x0}}, c_time = 0, c_arg = 0x0, c_func = 0, 
    c_lock = 0xffffff0082ae4978, c_flags = 0, c_cpu = 0}, 
  p_sigacts = 0xffffff00290e1000, p_flag = 268451840, p_state = PRS_NORMAL, 
  p_pid = 18860, p_hash = {le_next = 0x0, le_prev = 0xfffffffe4023fd60}, 
  p_pglist = {le_next = 0x0, le_prev = 0xffffff007ac57948}, 
  p_pptr = 0xffffff007ac57880, p_sibling = {le_next = 0x0, 
    le_prev = 0xffffff007ac57970}, p_children = {lh_first = 0x0}, p_mtx = {
    lock_object = {lo_name = 0xffffffff808d3975 "process lock", 
      lo_flags = 21168128, lo_data = 0, lo_witness = 0xfffffffe4021a400}, 
    mtx_lock = 4}, p_ksi = 0xffffff000515e000, p_sigqueue = {sq_signals = {
      __bits = {0, 0, 0, 0}}, sq_kill = {__bits = {0, 0, 0, 0}}, sq_list = {
      tqh_first = 0x0, tqh_last = 0xffffff0082ae49c0}, 
    sq_proc = 0xffffff0082ae4880, sq_flags = 1}, p_oppid = 0, 
  p_vmspace = 0xffffff0082315d38, p_swtick = 10457673, p_realtimer = {
    it_interval = {tv_sec = 0, tv_usec = 0}, it_value = {tv_sec = 0, 
      tv_usec = 0}}, p_ru = {ru_utime = {tv_sec = 0, tv_usec = 0}, ru_stime = {
      tv_sec = 0, tv_usec = 0}, ru_maxrss = 0, ru_ixrss = 0, ru_idrss = 0, 
    ru_isrss = 0, ru_minflt = 0, ru_majflt = 0, ru_nswap = 0, ru_inblock = 0, 
    ru_oublock = 0, ru_msgsnd = 0, ru_msgrcv = 0, ru_nsignals = 0, 
    ru_nvcsw = 0, ru_nivcsw = 0}, p_rux = {rux_runtime = 0, rux_uticks = 0, 
    rux_sticks = 0, rux_iticks = 0, rux_uu = 0, rux_su = 0, rux_tu = 0}, 
  p_crux = {rux_runtime = 0, rux_uticks = 0, rux_sticks = 0, rux_iticks = 0, 
    rux_uu = 0, rux_su = 0, rux_tu = 0}, p_profthreads = 0, p_exitthreads = 0, 
  p_traceflag = 0, p_tracevp = 0x0, p_tracecred = 0x0, 
  p_textvp = 0xffffff001b02a750, p_lock = 0 '\0', p_sigiolst = {
    slh_first = 0x0}, p_sigparent = 20, p_sig = 0, p_code = 0, p_stops = 0, 
  p_stype = 0, p_step = 0 '\0', p_pfsflags = 0 '\0', p_nlminfo = 0x0, 
  p_aioinfo = 0x0, p_singlethread = 0x0, p_suspcount = 0, p_xthread = 0x0, 
  p_boundary_count = 0, p_pendingcnt = 0, p_itimers = 0x0, 
  p_magic = 3203398350, p_osrel = 800054, 
  p_comm = "perl\000l", '\0' <repeats 13 times>, p_pgrp = 0xffffff000b06ec00, 
  p_sysent = 0xffffffff80b30320, p_args = 0xffffff00bdceda80, 
  p_cpulimit = 9223372036854775807, p_nice = 0 '\0', p_fibnum = 0, 
  p_xstat = 0, p_klist = {kl_list = {slh_first = 0x0}, 
    kl_lock = 0xffffffff805008a0 <knlist_mtx_lock>, 
    kl_unlock = 0xffffffff805008c0 <knlist_mtx_unlock>, 
    kl_locked = 0xffffffff80501ba0 <knlist_mtx_locked>, 
    kl_lockarg = 0xffffff0082ae4978}, p_numthreads = 1, 
  p_md = <incomplete type>, p_itcallout = {c_links = {sle = {sle_next = 0x0}, 
      tqe = {tqe_next = 0x0, tqe_prev = 0x0}}, c_time = 0, c_arg = 0x0, 
    c_func = 0, c_lock = 0x0, c_flags = 16, c_cpu = 0}, p_acflag = 0, 
  p_peers = 0x0, p_leader = 0xffffff0082ae4880, p_emuldata = 0x0, 
  p_label = 0x0, p_sched = 0xffffff0082ae4cc0, p_ktr = {stqh_first = 0x0, 
    stqh_last = 0xffffff0082ae4c90}, p_mqnotifier = {lh_first = 0x0}, 
  p_dtrace = 0x0, p_pwait = {cv_description = 0xffffffff808d42c2 "ppwait", 
    cv_waiters = 0}}
(kgdb)   p *td
$4 = {td_lock = 0xffffffff80b91680, td_proc = 0xffffff0082ae4880, td_plist = {
    tqe_next = 0x0, tqe_prev = 0xffffff0082ae4890}, td_runq = {
    tqe_next = 0xffffff000549d720, tqe_prev = 0xffffffff80b918c8}, td_slpq = {
    tqe_next = 0x0, tqe_prev = 0xffffff000721e190}, td_lockq = {
    tqe_next = 0x0, tqe_prev = 0xffffffff2cb3f750}, 
  td_cpuset = 0xffffff000288cdc8, td_sel = 0xffffff0082f7bb00, 
  td_sleepqueue = 0xffffff000721e190, td_turnstile = 0xffffff0005469900, 
  td_umtxq = 0xffffff008284b500, td_tid = 100316, td_sigqueue = {sq_signals = {
      __bits = {0, 0, 0, 0}}, sq_kill = {__bits = {0, 0, 0, 0}}, sq_list = {
      tqh_first = 0x0, tqh_last = 0xffffff0082999430}, 
    sq_proc = 0xffffff0082ae4880, sq_flags = 1}, td_flags = 4, 
  td_inhibitors = 0, td_pflags = 0, td_dupfd = 0, td_sqqueue = 0, 
  td_wchan = 0x0, td_wmesg = 0x0, td_lastcpu = 0 '\0', td_oncpu = 0 '\0', 
  td_owepreempt = 0 '\0', td_tsqueue = 0 '\0', td_locks = 1, td_rw_rlocks = 0, 
  td_lk_slocks = 0, td_blocked = 0x0, td_lockname = 0x0, td_contested = {
    lh_first = 0x0}, td_sleeplocks = 0xffffffff80cebd40, 
  td_intr_nesting_level = 0, td_pinned = 1, td_ucred = 0xffffff0010b4ec00, 
  td_estcpu = 0, td_slptick = 0, td_ru = {ru_utime = {tv_sec = 0, 
      tv_usec = 0}, ru_stime = {tv_sec = 0, tv_usec = 0}, ru_maxrss = 2044, 
    ru_ixrss = 48, ru_idrss = 3352, ru_isrss = 512, ru_minflt = 186, 
    ru_majflt = 0, ru_nswap = 0, ru_inblock = 0, ru_oublock = 0, 
    ru_msgsnd = 0, ru_msgrcv = 0, ru_nsignals = 0, ru_nvcsw = 13, 
    ru_nivcsw = 13}, td_incruntime = 61985988, td_runtime = 61985988, 
  td_pticks = 3, td_sticks = 4, td_iticks = 0, td_uticks = 0, td_uuticks = 0, 
  td_usticks = 0, td_intrval = 0, td_oldsigmask = {__bits = {0, 0, 0, 0}}, 
  td_sigmask = {__bits = {0, 0, 0, 0}}, td_generation = 26, td_sigstk = {
    ss_sp = 0x0, ss_size = 0, ss_flags = 4}, td_xsig = 0, td_profil_addr = 0, 
  td_profil_ticks = 0, td_name = "perl\000l", '\0' <repeats 13 times>, 
  td_fpop = 0x0, td_dbgflags = 0, td_osd = {osd_nslots = 0, osd_slots = 0x0, 
    osd_next = {le_next = 0x0, le_prev = 0x0}}, td_rqindex = 32 ' ', 
  td_base_pri = 128 '\200', td_priority = 128 '\200', td_pri_class = 3 '\003', 
  td_user_pri = 129 '\201', td_base_user_pri = 129 '\201', 
  td_pcb = 0xffffffff2d73ed50, td_state = TDS_RUNNING, td_retval = {23, 1023}, 
  td_slpcallout = {c_links = {sle = {sle_next = 0x0}, tqe = {tqe_next = 0x0, 
        tqe_prev = 0xffffffff0031d340}}, c_time = 9773098, 
    c_arg = 0xffffff0082999390, c_func = 0xffffffff80561850 <sleepq_timeout>, 
    c_lock = 0x0, c_flags = 16, c_cpu = 0}, td_frame = 0xffffffff2d73ec90, 
  td_kstack_obj = 0xffffff00c83a7c80, td_kstack = 18446744070177140736, 
  td_kstack_pages = 4, td_altkstack_obj = 0x0, td_altkstack = 0, 
  td_altkstack_pages = 0, td_critnest = 1, td_md = {md_spinlock_count = 0, 
    md_saved_flags = 70}, td_sched = 0xffffff00829996f0, td_ar = 0x0, 
  td_syscalls = 1517973, td_lprof = {{lh_first = 0x0}, {lh_first = 0x0}}, 
  td_dtrace = 0x0, td_errno = 0}
(kgdb) p td  *td->td_lock
$5 = {lock_object = {lo_name = 0xffffffff80b922d8 "sched lock 0", 
    lo_flags = 720896, lo_data = 0, lo_witness = 0x0}, mtx_lock = 4}
(kgdb) q
ichotolot# 
Received on Fri Jan 09 2009 - 00:45:28 UTC

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