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

From: Joe Marcus Clarke <marcus_at_FreeBSD.org>
Date: Fri, 09 Jan 2009 17:49:02 -0500
On Thu, 2009-01-08 at 18:48 -0600, Richard Todd wrote:
> 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.)

I believe I have fixed this in HEAD.  Kib gave his review and approval,
and the fix really should prevent this hang.  Please report back if you
still see the problem.

Joe

> 
> 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# 
> 
> _______________________________________________
> freebsd-current_at_freebsd.org mailing list
> http://lists.freebsd.org/mailman/listinfo/freebsd-current
> To unsubscribe, send any mail to "freebsd-current-unsubscribe_at_freebsd.org"

-- 
Joe Marcus Clarke
FreeBSD GNOME Team      ::      gnome_at_FreeBSD.org
FreeNode / #freebsd-gnome
http://www.FreeBSD.org/gnome

Received on Fri Jan 09 2009 - 21:49:06 UTC

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