From owner-freebsd-current@FreeBSD.ORG Tue Feb 5 00:02:22 2013 Return-Path: Delivered-To: freebsd-current@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by hub.freebsd.org (Postfix) with ESMTP id 154926F2; Tue, 5 Feb 2013 00:02:22 +0000 (UTC) (envelope-from rmacklem@uoguelph.ca) Received: from esa-jnhn.mail.uoguelph.ca (esa-jnhn.mail.uoguelph.ca [131.104.91.44]) by mx1.freebsd.org (Postfix) with ESMTP id 868469EC; Tue, 5 Feb 2013 00:02:21 +0000 (UTC) X-IronPort-Anti-Spam-Filtered: true X-IronPort-Anti-Spam-Result: Ap8EAGtLEFGDaFvO/2dsb2JhbABFhki5EnOCHwEBBAEjBFIbDgoCAg0ZAiM2BhOHfwMJBqkaiF8NiVaBI4p6hCKBEwOIZothgViJVYFqhRKDGoIG X-IronPort-AV: E=Sophos;i="4.84,602,1355115600"; d="scan'208";a="15063763" Received: from erie.cs.uoguelph.ca (HELO zcs3.mail.uoguelph.ca) ([131.104.91.206]) by esa-jnhn.mail.uoguelph.ca with ESMTP; 04 Feb 2013 19:02:14 -0500 Received: from zcs3.mail.uoguelph.ca (localhost.localdomain [127.0.0.1]) by zcs3.mail.uoguelph.ca (Postfix) with ESMTP id 490B4B4044; Mon, 4 Feb 2013 19:02:14 -0500 (EST) Date: Mon, 4 Feb 2013 19:02:14 -0500 (EST) From: Rick Macklem To: Sergey Kandaurov Message-ID: <1077235459.2683307.1360022534263.JavaMail.root@erie.cs.uoguelph.ca> In-Reply-To: Subject: Re: panic: LK_RETRY set with incompatible flags MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit X-Originating-IP: [172.17.91.201] X-Mailer: Zimbra 6.0.10_GA_2692 (ZimbraWebClient - FF3.0 (Win)/6.0.10_GA_2692) Cc: Konstantin Belousov , FreeBSD Current , Andriy Gapon X-BeenThere: freebsd-current@freebsd.org X-Mailman-Version: 2.1.14 Precedence: list List-Id: Discussions about the use of FreeBSD-current List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Tue, 05 Feb 2013 00:02:22 -0000 Sergey Kandaurov wrote: > On 4 February 2013 16:30, Sergey Kandaurov wrote: > > On 4 February 2013 16:13, Sergey Kandaurov > > wrote: > >> On 4 February 2013 16:06, Andriy Gapon wrote: > >>> on 04/02/2013 13:49 Sergey Kandaurov said the following: > >>>> Hi, Rick! Here is the requested info regarding witness, and a bit > >>>> more. > >>>> The triggered KASSERT is now different though. > >>> > >>> It's exactly the same problem though :-) > >>> Do you have a crashdump? > >>> If yes, please print **vpp. > >> > >> Yep, but it's in a bad form :( > >> It has many bits optimized out (compiled with clang). > >> I'll rebuild the kernel with -O or so and will try again. > >> > >> #8 0xffffffff808bc4ce in kdb_enter (why=0xffffffff80e7ed99 "panic", > >> msg=) at cpufunc.h:63 > >> #9 0xffffffff80888fb7 in vpanic (fmt=, > >> ap=) at > >> /usr/src/sys/kern/kern_shutdown.c:746 > >> #10 0xffffffff80888e66 in kassert_panic (fmt=) > >> at /usr/src/sys/kern/kern_shutdown.c:641 > >> #11 0xffffffff808d2259 in witness_checkorder > >> (lock=0xfffffe00a1b44240, > >> ---Type to continue, or q to quit--- > >> flags=1, > >> file=0xffffffff81b2bb36 > >> "/usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vnops.c", > >> line=1452, > >> interlock=) at > >> /usr/src/sys/kern/subr_witness.c:1122 > >> #12 0xffffffff8086c11e in __lockmgr_args (lk=0xfffffe00a1b44240, > >> flags=, ilk=0xfffffe00a1b44270, > >> wmesg=0xffffffff81b2808d "zfs", pri=96, timo=51, > >> file=0xffffffff80e8e407 "/usr/src/sys/kern/vfs_default.c", > >> line=0) > >> at /usr/src/sys/kern/kern_lock.c:511 > >> #13 0xffffffff8091439c in vop_stdlock (ap=) > >> at lockmgr.h:97 > >> #14 0xffffffff80cb70c0 in VOP_LOCK1_APV (vop=, > >> a=) at vnode_if.c:2022 > >> #15 0xffffffff80932fbb in _vn_lock (vp=0xfffffe00a1b441d8, > >> flags=, > >> file=0xffffffff81b2bb36 > >> "/usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vnops.c", > >> line=1452) at vnode_if.h:859 > >> #16 0xffffffff81abd902 in zfs_lookup () > >> at > >> /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vnops.c:1452 > >> #17 0xffffffff81abdc1d in zfs_freebsd_lookup > >> (ap=0xffffff848e6c0270) > >> at > >> /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vnops.c:5864 > >> ---Type to continue, or q to quit--- > >> #18 0xffffffff80cb51b2 in VOP_CACHEDLOOKUP_APV (vop= >> optimized out>, > >> a=) at vnode_if.c:191 > >> #19 0xffffffff8091177f in vfs_cache_lookup (ap= >> out>) > >> at vnode_if.h:80 > >> #20 0xffffffff80cb50a2 in VOP_LOOKUP_APV (vop= >> out>, > >> a=) at vnode_if.c:125 > >> #21 0xffffffff80919658 in lookup (ndp=0xffffff848e6c05d8) at > >> vnode_if.h:54 > >> #22 0xffffffff807dffe5 in nfsvno_namei (nd=0xffffff848e6c08c8, > >> ndp=0xffffff848e6c05d8, dp=, > >> islocked=, exp=, > >> p=, retdirp=) > >> at /usr/src/sys/fs/nfsserver/nfs_nfsdport.c:413 > >> #23 0xffffffff807d8ffa in nfsrvd_lookup (nd=0xffffff848e6c08c8, > >> isdgram=, dp=0xfffffe00a1b441d8, > >> vpp=0xffffff848e6c0810, fhp=0xffffff848e6c07f4, > >> p=0xfffffe00a1198000, > >> exp=0xffffff848e6c07a0) at > >> /usr/src/sys/fs/nfsserver/nfs_nfsdserv.c:517 > >> #24 0xffffffff807cb845 in nfsrvd_dorpc (nd=0xffffff848e6c08c8, > >> isdgram=0, > >> p=0xfffffe00a1198000) at > >> /usr/src/sys/fs/nfsserver/nfs_nfsdsocket.c:823 > >> #25 0xffffffff807d7af2 in nfssvc_program (rqst=0xfffffe00a17bb000, > >> xprt=0xfffffe00a124b200) at > >> /usr/src/sys/fs/nfsserver/nfs_nfsdkrpc.c:347 > >> #26 0xffffffff80a70659 in svc_run_internal > >> (pool=0xfffffe00067db600, > >> ismaster=0) at /usr/src/sys/rpc/svc.c:895 > >> #27 0xffffffff80a7155b in svc_thread_start (arg=0xffffff848e6bfc50) > >> ---Type to continue, or q to quit--- > >> at /usr/src/sys/rpc/svc.c:1200 > >> #28 0xffffffff80858944 in fork_exit ( > >> callout=0xffffffff80a71550 , > >> arg=0xfffffe00067db600, > >> frame=0xffffff848e6c0c00) at /usr/src/sys/kern/kern_fork.c:991 > >> #29 0xffffffff80bfa86e in fork_trampoline () at exception.S:602 > >> #30 0x0000000000000080 in ?? () > >> #31 0x00007fffffffd820 in ?? () > >> #32 0x0000000000000001 in ?? () > >> #33 0x0000000000000000 in ?? () > >> Current language: auto; currently minimal > >> > >> (kgdb) p vpp > >> Cannot access memory at address 0x0 > >> (kgdb) p dvp > >> Cannot access memory at address 0x0 > >> > > > > That was from f 16. And as Andriy suggested in private (thanks > > Andriy!) > > those pointers could be reached from ap in f 17. > > On the other hand, zfs_lookup() is large, and *vpp might be > > rewritten several times there. Here it is: > > > > (kgdb) f 17 > > #17 0xffffffff81abdc1d in zfs_freebsd_lookup (ap=0xffffff848e6c0270) > > at > > /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vnops.c:5864 > > 5864 return (zfs_lookup(ap->a_dvp, nm, ap->a_vpp, cnp, > > cnp->cn_nameiop, > > (kgdb) p ap->a_vpp > > $4 = (struct vnode **) 0xffffff848e6c0618 > > (kgdb) p *ap->a_vpp > > $5 = (struct vnode *) 0xfffffe00a1b441d8 > > (kgdb) p **ap->a_vpp > > $6 = {v_tag = 0xffffffff81b2808d "zfs", v_op = 0xffffffff81b35808, > > v_data = 0xfffffe00a188f000, v_mount = 0xfffffe0015a5f000, > > v_nmntvnodes = { > > tqe_next = 0xfffffe00a1b44000, tqe_prev = 0xfffffe00a1b443d0}, > > v_un = { > > vu_mount = 0x0, vu_socket = 0x0, vu_cdev = 0x0, vu_fifoinfo = > > 0x0}, > > v_hashlist = {le_next = 0x0, le_prev = 0x0}, v_cache_src = > > {lh_first = 0x0}, > > v_cache_dst = {tqh_first = 0x0, tqh_last = 0xfffffe00a1b44228}, > > v_cache_dd = 0x0, v_lock = {lock_object = { > > lo_name = 0xffffffff81b2808d "zfs", lo_flags = 91947008, > > lo_data = 0, > > lo_witness = 0xffffff80006d2700}, lk_lock = > > 18446741877389099008, > > lk_exslpfail = 0, lk_timo = 51, lk_pri = 96}, v_interlock = { > > lock_object = {lo_name = 0xffffffff80e873f0 "vnode interlock", > > lo_flags = 16973824, lo_data = 0, lo_witness = > > 0xffffff80006c9600}, > > mtx_lock = 4}, v_vnlock = 0xfffffe00a1b44240, v_actfreelist = { > > tqe_next = 0xfffffe000bd363b0, tqe_prev = 0xfffffe0015a5f078}, > > v_bufobj = { > > bo_mtx = {lock_object = {lo_name = 0xffffffff80e8f3d5 "bufobj > > interlock", > > lo_flags = 16973824, lo_data = 0, lo_witness = > > 0xffffff80006d0580}, > > mtx_lock = 4}, bo_ops = 0xffffffff8121cc30, > > bo_object = 0xfffffe00a1872780, bo_synclist = {le_next = 0x0, > > le_prev = 0x0}, bo_private = 0xfffffe00a1b441d8, > > __bo_vnode = 0xfffffe00a1b441d8, bo_clean = {bv_hd = {tqh_first > > = 0x0, > > tqh_last = 0xfffffe00a1b442f8}, bv_root = 0x0, bv_cnt = 0}, > > bo_dirty = {bv_hd = {tqh_first = 0x0, tqh_last = > > 0xfffffe00a1b44318}, > > bv_root = 0x0, bv_cnt = 0}, bo_numoutput = 0, bo_flag = 0, > > ---Type to continue, or q to quit--- > > bo_bsize = 131072}, v_pollinfo = 0x0, v_label = 0x0, v_lockf = > > 0x0, > > v_rl = {rl_waiters = {tqh_first = 0x0, tqh_last = > > 0xfffffe00a1b44360}, > > rl_currdep = 0x0}, v_cstart = 0, v_lasta = 0, v_lastw = 0, > > v_clen = 0, > > v_holdcnt = 4, v_usecount = 4, v_iflag = 512, v_vflag = 0, > > v_writecount = 0, > > v_hash = 10597441, v_type = VDIR} > > And here is dvp, cnp. So yes, *vpp == dvp. > > (kgdb) p *ap->a_vpp > $7 = (struct vnode *) 0xfffffe00a1b441d8 > (kgdb) p ap->a_dvp > $5 = (struct vnode *) 0xfffffe00a1b441d8 > > (kgdb) p *ap->a_dvp > $8 = {v_tag = 0xffffffff81b2808d "zfs", v_op = 0xffffffff81b35808, > v_data = 0xfffffe00a188f000, v_mount = 0xfffffe0015a5f000, > v_nmntvnodes = {tqe_next = 0xfffffe00a1b44000, tqe_prev = > 0xfffffe00a1b443d0}, v_un = {vu_mount = 0x0, vu_socket = 0x0, > vu_cdev = 0x0, vu_fifoinfo = 0x0}, v_hashlist = {le_next = 0x0, > le_prev = 0x0}, v_cache_src = {lh_first = 0x0}, v_cache_dst = { > tqh_first = 0x0, tqh_last = 0xfffffe00a1b44228}, v_cache_dd = 0x0, > v_lock = {lock_object = {lo_name = 0xffffffff81b2808d "zfs", > lo_flags = 91947008, lo_data = 0, lo_witness = > 0xffffff80006d2700}, lk_lock = 18446741877389099008, lk_exslpfail = 0, > lk_timo = 51, lk_pri = 96}, v_interlock = {lock_object = {lo_name > = 0xffffffff80e873f0 "vnode interlock", lo_flags = 16973824, > lo_data = 0, lo_witness = 0xffffff80006c9600}, mtx_lock = 4}, > v_vnlock = 0xfffffe00a1b44240, v_actfreelist = { > tqe_next = 0xfffffe000bd363b0, tqe_prev = 0xfffffe0015a5f078}, > v_bufobj = {bo_mtx = {lock_object = { > lo_name = 0xffffffff80e8f3d5 "bufobj interlock", lo_flags = > 16973824, lo_data = 0, lo_witness = 0xffffff80006d0580}, > mtx_lock = 4}, bo_ops = 0xffffffff8121cc30, bo_object = > 0xfffffe00a1872780, bo_synclist = {le_next = 0x0, le_prev = 0x0}, > bo_private = 0xfffffe00a1b441d8, __bo_vnode = 0xfffffe00a1b441d8, > bo_clean = {bv_hd = {tqh_first = 0x0, > tqh_last = 0xfffffe00a1b442f8}, bv_root = 0x0, bv_cnt = 0}, > bo_dirty = {bv_hd = {tqh_first = 0x0, > tqh_last = 0xfffffe00a1b44318}, bv_root = 0x0, bv_cnt = 0}, > bo_numoutput = 0, bo_flag = 0, bo_bsize = 131072}, > v_pollinfo = 0x0, v_label = 0x0, v_lockf = 0x0, v_rl = {rl_waiters = > {tqh_first = 0x0, tqh_last = 0xfffffe00a1b44360}, > rl_currdep = 0x0}, v_cstart = 0, v_lasta = 0, v_lastw = 0, v_clen > = 0, v_holdcnt = 4, v_usecount = 4, v_iflag = 512, > v_vflag = 0, v_writecount = 0, v_hash = 10597441, v_type = VDIR} > (kgdb) p/x *ap->a_dvp > $2 = {v_tag = 0xffffffff81b2808d, v_op = 0xffffffff81b35808, v_data = > 0xfffffe00a188f000, v_mount = 0xfffffe0015a5f000, > v_nmntvnodes = {tqe_next = 0xfffffe00a1b44000, tqe_prev = > 0xfffffe00a1b443d0}, v_un = {vu_mount = 0x0, vu_socket = 0x0, > vu_cdev = 0x0, vu_fifoinfo = 0x0}, v_hashlist = {le_next = 0x0, > le_prev = 0x0}, v_cache_src = {lh_first = 0x0}, v_cache_dst = { > tqh_first = 0x0, tqh_last = 0xfffffe00a1b44228}, v_cache_dd = 0x0, > v_lock = {lock_object = {lo_name = 0xffffffff81b2808d, > lo_flags = 0x57b0000, lo_data = 0x0, lo_witness = > 0xffffff80006d2700}, lk_lock = 0xfffffe00a1198000, lk_exslpfail = 0x0, > lk_timo = 0x33, lk_pri = 0x60}, v_interlock = {lock_object = > {lo_name = 0xffffffff80e873f0, lo_flags = 0x1030000, lo_data = 0x0, > lo_witness = 0xffffff80006c9600}, mtx_lock = 0x4}, v_vnlock = > 0xfffffe00a1b44240, v_actfreelist = { > tqe_next = 0xfffffe000bd363b0, tqe_prev = 0xfffffe0015a5f078}, > v_bufobj = {bo_mtx = {lock_object = { > lo_name = 0xffffffff80e8f3d5, lo_flags = 0x1030000, lo_data = > 0x0, lo_witness = 0xffffff80006d0580}, mtx_lock = 0x4}, > bo_ops = 0xffffffff8121cc30, bo_object = 0xfffffe00a1872780, > bo_synclist = {le_next = 0x0, le_prev = 0x0}, > bo_private = 0xfffffe00a1b441d8, __bo_vnode = 0xfffffe00a1b441d8, > bo_clean = {bv_hd = {tqh_first = 0x0, > tqh_last = 0xfffffe00a1b442f8}, bv_root = 0x0, bv_cnt = 0x0}, > bo_dirty = {bv_hd = {tqh_first = 0x0, > tqh_last = 0xfffffe00a1b44318}, bv_root = 0x0, bv_cnt = 0x0}, > bo_numoutput = 0x0, bo_flag = 0x0, bo_bsize = 0x20000}, > v_pollinfo = 0x0, v_label = 0x0, v_lockf = 0x0, v_rl = {rl_waiters = > {tqh_first = 0x0, tqh_last = 0xfffffe00a1b44360}, > rl_currdep = 0x0}, v_cstart = 0x0, v_lasta = 0x0, v_lastw = 0x0, > v_clen = 0x0, v_holdcnt = 0x4, v_usecount = 0x4, > v_iflag = 0x200, v_vflag = 0x0, v_writecount = 0x0, v_hash = > 0xa1b441, v_type = 0x2} > > (kgdb) p ap->a_cnp > $9 = (struct componentname *) 0xffffff848e6c0640 > (kgdb) p *ap->a_cnp > $10 = {cn_nameiop = 0, cn_flags = 8451076, cn_thread = > 0xfffffe00a1198000, cn_cred = 0xfffffe00a167cc00, cn_lkflags = 524288, > cn_pnbuf = 0xfffffe000bdee400 "..", cn_nameptr = 0xfffffe000bdee400 > "..", cn_namelen = 2, cn_consume = 0} > (kgdb) p/x *ap->a_cnp > $4 = {cn_nameiop = 0x0, cn_flags = 0x80f404, cn_thread = > 0xfffffe00a1198000, cn_cred = 0xfffffe00a167cc00, cn_lkflags = > 0x80000, > cn_pnbuf = 0xfffffe000bdee400, cn_nameptr = 0xfffffe000bdee400, > cn_namelen = 0x2, cn_consume = 0x0} > > -- > wbr, > pluknet First off, Sergey, thanks for collecting this information. It would appear that, for this case, zfs_lookup() sets *vpp to dvp for the ".." lookup. The vnode is not flagged VV_ROOT and v_mountedhere == NULL, so I'm not sure what this means? Maybe someone familiar with ZFS can explain what these snapshots are supposed to look like: - a mount point - a directory - a regular file or ??? Does anyone know why ZFS chooses to return the same directory vnode for a lookup of ".." for this case? (The comment in the code doesn't say why, just that it does this.) Sorry, but I've never touched ZFS, rick