From owner-freebsd-stable@freebsd.org Mon Mar 4 20:36:00 2019 Return-Path: Delivered-To: freebsd-stable@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2610:1c1:1:606c::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id B42BC152207C for ; Mon, 4 Mar 2019 20:35:59 +0000 (UTC) (envelope-from ncrogers@gmail.com) Received: from mail-yw1-xc2f.google.com (mail-yw1-xc2f.google.com [IPv6:2607:f8b0:4864:20::c2f]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (Client CN "smtp.gmail.com", Issuer "GTS CA 1O1" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 94C6986B18; Mon, 4 Mar 2019 20:35:58 +0000 (UTC) (envelope-from ncrogers@gmail.com) Received: by mail-yw1-xc2f.google.com with SMTP id s204so5155596ywg.2; Mon, 04 Mar 2019 12:35:58 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=mime-version:references:in-reply-to:from:date:message-id:subject:to :cc; bh=4nxFbCL6huT1huaHApl18cArCBTD1iZQZMQmmw0Sw5E=; b=feLxYtfuqyp4NFEJ0acQiJwaQEaZHRJ4bAHuHb4EzSxBeYhVhuYGRpm/7GOd+I+5RY Gf4philSqBYhr3Kd0sCvnSbZxluXQmoi8ovPSBNqH7/0ZhGF5ew1kEIkA4YJujXtvK0z WRori1DfBgPamsIZua5tw9fpUIKXZp1dZSFjnviYv2NOuX0TJFnprjHQCWEv4APjJQKV Cy4+4vsIZShGJpCPFyBLGXy2D4tQf8pBpQNkKpqRVe6bNpGiYhqXHhEf1rOX2foP8jHv xiimgfXB9ny3DRrZcqav2RAJXRnej35AAG0+DpCJKmS0fWa/d2jwEQfzXoLcGB9l0RWd Zd9Q== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:references:in-reply-to:from:date :message-id:subject:to:cc; bh=4nxFbCL6huT1huaHApl18cArCBTD1iZQZMQmmw0Sw5E=; b=uDlhfq/g8OWjxSQDXjPb4G+OpvaVnV2pt1shRtyeLC1w1p4k5FwQ0NiQG18y4h8te/ bgzSRn64HyzsTYKtNEP5Olh7H9/zb/cuYNDXRa0yFRy2SOIwZwJIKXDkBBO02eq17oV9 qkQ9sRkZvmbLLc2ibjieA64oFx0CFkkrEkw9Z/KPVbexexKD8W2HxulkCfflJgi5FH5N XzPhzARDdlD+zthgmnGacQv7OeyexIB0g+s7zwHGacQY9eQ69/98PVwBWWh7CslKPS+3 NAW5kVKX7dYQN8LXWM6oLxr0ve8Laf9iZqsTYfFrope1nYLdVJuiQduBAOYkc93de22m 9JDg== X-Gm-Message-State: APjAAAWJ6ml5thef8ZK0971JK0fsEYHBZnXiTS5mKH7TGsruNoZUzYMj QO+PoU3kFfbKWwTLOj3GtcwJ2WZ/rOfId2dpnER92zyB X-Google-Smtp-Source: APXvYqyn21eIu2mE0Y05sXj5nmTuBCiL3ZWM/I5Ocy9sAyrn9h9zqL26FzqSFqYJFRXqr9iL0RFSoFVYPvkjPbx9dEE= X-Received: by 2002:a81:8506:: with SMTP id v6mr15946165ywf.304.1551731757418; Mon, 04 Mar 2019 12:35:57 -0800 (PST) MIME-Version: 1.0 References: <233f3723-a78e-91db-ebe6-9e13c1c9b50d@FreeBSD.org> In-Reply-To: <233f3723-a78e-91db-ebe6-9e13c1c9b50d@FreeBSD.org> From: Nick Rogers Date: Mon, 4 Mar 2019 15:35:46 -0500 Message-ID: Subject: Re: 12.0-RELEASE zfs/vnode deadlock issue To: Andriy Gapon Cc: FreeBSD STABLE X-Rspamd-Queue-Id: 94C6986B18 X-Spamd-Bar: ------ Authentication-Results: mx1.freebsd.org; dkim=pass header.d=gmail.com header.s=20161025 header.b=feLxYtfu; dmarc=pass (policy=none) header.from=gmail.com; spf=pass (mx1.freebsd.org: domain of ncrogers@gmail.com designates 2607:f8b0:4864:20::c2f as permitted sender) smtp.mailfrom=ncrogers@gmail.com X-Spamd-Result: default: False [-6.70 / 15.00]; ARC_NA(0.00)[]; NEURAL_HAM_MEDIUM(-1.00)[-1.000,0]; R_DKIM_ALLOW(-0.20)[gmail.com:s=20161025]; FROM_HAS_DN(0.00)[]; R_SPF_ALLOW(-0.20)[+ip6:2607:f8b0:4000::/36]; FREEMAIL_FROM(0.00)[gmail.com]; MIME_GOOD(-0.10)[multipart/alternative,text/plain]; TO_MATCH_ENVRCPT_ALL(0.00)[]; NEURAL_HAM_LONG(-1.00)[-1.000,0]; RCVD_TLS_LAST(0.00)[]; TO_DN_ALL(0.00)[]; DKIM_TRACE(0.00)[gmail.com:+]; RCPT_COUNT_TWO(0.00)[2]; DMARC_POLICY_ALLOW(-0.50)[gmail.com,none]; MX_GOOD(-0.01)[cached: alt3.gmail-smtp-in.l.google.com]; RCVD_IN_DNSWL_NONE(0.00)[f.2.c.0.0.0.0.0.0.0.0.0.0.0.0.0.0.2.0.0.4.6.8.4.0.b.8.f.7.0.6.2.list.dnswl.org : 127.0.5.0]; NEURAL_HAM_SHORT(-0.83)[-0.835,0]; FROM_EQ_ENVFROM(0.00)[]; MIME_TRACE(0.00)[0:+,1:+]; FREEMAIL_ENVFROM(0.00)[gmail.com]; ASN(0.00)[asn:15169, ipnet:2607:f8b0::/32, country:US]; RCVD_COUNT_TWO(0.00)[2]; IP_SCORE(-2.86)[ip: (-9.49), ipnet: 2607:f8b0::/32(-2.70), asn: 15169(-2.04), country: US(-0.07)]; DWL_DNSWL_NONE(0.00)[gmail.com.dwl.dnswl.org : 127.0.5.0] Content-Type: text/plain; charset="UTF-8" X-Content-Filtered-By: Mailman/MimeDel 2.1.29 X-BeenThere: freebsd-stable@freebsd.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: Production branch of FreeBSD source code List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Mon, 04 Mar 2019 20:36:00 -0000 On Sat, Mar 2, 2019 at 12:48 PM Andriy Gapon wrote: > On 01/03/2019 17:00, Nick Rogers wrote: > > 36704 101146 perl - mi_switch+0xe1 > > sleepq_wait+0x2c sleeplk+0x1c5 lockmgr_xlock_hard+0x19c > VOP_LOCK1_APV+0x7e > > _vn_lock+0x40 zfs_znode_alloc+0x434 zfs_mknode+0xa9d > > zfs_freebsd_create+0x512 VOP_CREATE_APV+0x78 vn_open_cred+0x2c9 > > kern_openat+0x20c amd64_syscall+0x369 fast_syscall_common+0x101 > > I suspect that this thread is a root cause of the problem. > In this place, the vnode should be freshly created and not visible to > anything > but the current thread. So, vn_lock() should always immediately succeed. > I > cannot understand how the vnode lock could be held by another thread. > It happened again. I tried to get a backtrace from the offending thread and one of the others waiting for it. At the moment I have access to this particular system in its bad state and can leave it like this for as long as possible, so let me know if there's something else useful I can get out of the debugger. courtland# procstat -kka | grep zfs 0 100140 kernel zfsvfs mi_switch+0xe1 sleepq_wait+0x2c _sleep+0x237 taskqueue_thread_loop+0xf1 fork_exit+0x83 fork_trampoline+0xe 0 100424 kernel zfs_vn_rele_taskq mi_switch+0xe1 sleepq_wait+0x2c _sleep+0x237 taskqueue_thread_loop+0xf1 fork_exit+0x83 fork_trampoline+0xe 23 100119 zfskern arc_reclaim_thread mi_switch+0xe1 sleepq_timedwait+0x2f _cv_timedwait_sbt+0x17a arc_reclaim_thread+0x146 fork_exit+0x83 fork_trampoline+0xe 23 100120 zfskern arc_dnlc_evicts_thr mi_switch+0xe1 sleepq_wait+0x2c _cv_wait+0x152 arc_dnlc_evicts_thread+0x16f fork_exit+0x83 fork_trampoline+0xe 23 100122 zfskern dbuf_evict_thread mi_switch+0xe1 sleepq_timedwait+0x2f _cv_timedwait_sbt+0x17a dbuf_evict_thread+0x1c8 fork_exit+0x83 fork_trampoline+0xe 23 100139 zfskern l2arc_feed_thread mi_switch+0xe1 sleepq_timedwait+0x2f _cv_timedwait_sbt+0x17a l2arc_feed_thread+0x219 fork_exit+0x83 fork_trampoline+0xe 23 100405 zfskern trim zroot mi_switch+0xe1 sleepq_timedwait+0x2f _cv_timedwait_sbt+0x17a trim_thread+0x11f fork_exit+0x83 fork_trampoline+0xe 23 100441 zfskern txg_thread_enter mi_switch+0xe1 sleepq_wait+0x2c _cv_wait+0x152 txg_quiesce+0x21b txg_quiesce_thread+0x11b fork_exit+0x83 fork_trampoline+0xe 23 100442 zfskern txg_thread_enter mi_switch+0xe1 sleepq_wait+0x2c _cv_wait+0x152 txg_sync_thread+0x13b fork_exit+0x83 fork_trampoline+0xe 23 100443 zfskern solthread 0xfffffff mi_switch+0xe1 sleepq_wait+0x2c _cv_wait+0x152 zthr_procedure+0xcc fork_exit+0x83 fork_trampoline+0xe 23 100444 zfskern solthread 0xfffffff mi_switch+0xe1 sleepq_wait+0x2c _cv_wait+0x152 zthr_procedure+0xcc fork_exit+0x83 fork_trampoline+0xe 7476 100751 postgres - mi_switch+0xe1 sleepq_wait+0x2c _cv_wait+0x152 dmu_tx_wait+0x2eb dmu_tx_assign+0x48 zfs_freebsd_create+0x4c8 VOP_CREATE_APV+0x78 vn_open_cred+0x2c9 kern_openat+0x20c amd64_syscall+0x369 fast_syscall_common+0x101 7480 100527 postgres - mi_switch+0xe1 sleepq_wait+0x2c sleeplk+0x1c5 lockmgr_xlock_hard+0x19c VOP_LOCK1_APV+0x7e _vn_lock+0x40 zfs_znode_alloc+0x434 zfs_mknode+0xa9d zfs_freebsd_create+0x512 VOP_CREATE_APV+0x78 vn_open_cred+0x2c9 kern_openat+0x20c amd64_syscall+0x369 fast_syscall_common+0x101 46101 100471 postgres - mi_switch+0xe1 sleepq_wait+0x2c _cv_wait+0x152 dmu_tx_wait+0x2eb dmu_tx_assign+0x48 zfs_freebsd_create+0x4c8 VOP_CREATE_APV+0x78 vn_open_cred+0x2c9 kern_openat+0x20c amd64_syscall+0x369 fast_syscall_common+0x101 52625 100488 perl - mi_switch+0xe1 sleepq_wait+0x2c sleeplk+0x1c5 lockmgr_slock_hard+0x2c5 VOP_LOCK1_APV+0x7e _vn_lock+0x40 zfs_root+0x6d lookup+0x933 namei+0x44b kern_statat+0x77 sys_fstatat+0x2f amd64_syscall+0x369 fast_syscall_common+0x101 52675 100643 csh - mi_switch+0xe1 sleepq_wait+0x2c sleeplk+0x1c5 lockmgr_slock_hard+0x2c5 VOP_LOCK1_APV+0x7e _vn_lock+0x40 zfs_root+0x6d lookup+0x933 namei+0x44b kern_statat+0x77 sys_fstatat+0x2f amd64_syscall+0x369 fast_syscall_common+0x101 52826 100562 ls - mi_switch+0xe1 sleepq_wait+0x2c sleeplk+0x1c5 lockmgr_slock_hard+0x2c5 VOP_LOCK1_APV+0x7e _vn_lock+0x40 zfs_root+0x6d lookup+0x933 namei+0x44b kern_statat+0x77 sys_fstatat+0x2f amd64_syscall+0x369 fast_syscall_common+0x101 52889 100641 bash - mi_switch+0xe1 sleepq_wait+0x2c sleeplk+0x1c5 lockmgr_slock_hard+0x2c5 VOP_LOCK1_APV+0x7e _vn_lock+0x40 zfs_root+0x6d lookup+0x933 namei+0x44b kern_statat+0x77 sys_fstatat+0x2f amd64_syscall+0x369 fast_syscall_common+0x101 courtland# kgdb GNU gdb (GDB) 8.2.1 [GDB v8.2.1 for FreeBSD] Copyright (C) 2018 Free Software Foundation, Inc. License GPLv3+: GNU GPL version 3 or later This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law. Type "show copying" and "show warranty" for details. This GDB was configured as "x86_64-portbld-freebsd12.0". Type "show configuration" for configuration details. For bug reporting instructions, please see: . Find the GDB manual and other documentation resources online at: . For help, type "help". Type "apropos word" to search for commands related to "word"... Reading symbols from /boot/kernel/kernel...Reading symbols from /usr/lib/debug//boot/kernel/kernel.debug...done. done. (kgdb) tid 100471 (kgdb) bt #0 sched_switch (td=0xfffff8001196c580, newtd=0xfffff8000354f580, flags=) at /usr/src/sys/kern/sched_ule.c:2112 #1 0xffffffff80d0e0a1 in mi_switch (flags=, newtd=0x0) at /usr/src/sys/kern/kern_synch.c:439 #2 0xffffffff80d5c80c in sleepq_wait (wchan=, pri=) at /usr/src/sys/kern/subr_sleepqueue.c:692 #3 0xffffffff80c9ca52 in _cv_wait (cvp=0xfffff80011354d28, lock=0xfffff80011354c50) at /usr/src/sys/kern/kern_condvar.c:146 #4 0xffffffff80403dfb in dmu_tx_wait (tx=0xfffff8037afd1c00) at /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/dmu_tx.c:1090 #5 0xffffffff80403748 in dmu_tx_assign (tx=0xfffff8037afd1c00, txg_how=1) at /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/dmu_tx.c:1032 #6 0xffffffff804a4ce8 in zfs_create (excl=0, mode=0, dvp=, name=, vap=, vpp=, cr=, td=) at /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vnops.c:1875 #7 zfs_freebsd_create (ap=0xfffffe008e25a790) at /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vnops.c:4996 #8 0xffffffff813aaa68 in VOP_CREATE_APV (vop=, a=0xfffffe008e25a790) at vnode_if.c:263 #9 0xffffffff80de20f9 in VOP_CREATE (dvp=, vpp=0xfffffe008e25a888, cnp=, vap=0x18000000001) at ./vnode_if.h:109 #10 vn_open_cred (ndp=0xfffffe008e25a828, flagp=0xfffffe008e25a954, cmode=, vn_open_flags=, cred=0xfffff8002b529b00, fp=0xfffff80359185aa0) at /usr/src/sys/kern/vfs_vnops.c:243 #11 0xffffffff80dda74c in kern_openat (td=0xfffff8001196c580, fd=-100, path=0x88d3a0f70 , pathseg=UIO_USERSPACE, flags=2563, mode=) at /usr/src/sys/kern/vfs_syscalls.c:1082 #12 0xffffffff81222449 in syscallenter (td=) at /usr/src/sys/amd64/amd64/../../kern/subr_syscall.c:135 #13 amd64_syscall (td=0xfffff8001196c580, traced=0) at /usr/src/sys/amd64/amd64/trap.c:1076 #14 #15 0x000000080131e82a in ?? () Backtrace stopped: Cannot access memory at address 0x7fffffffb4c8 (kgdb) tid 100527 (kgdb) bt #0 sched_switch (td=0xfffff8026af9d580, newtd=0xfffff80003551000, flags=) at /usr/src/sys/kern/sched_ule.c:2112 #1 0xffffffff80d0e0a1 in mi_switch (flags=, newtd=0x0) at /usr/src/sys/kern/kern_synch.c:439 #2 0xffffffff80d5c80c in sleepq_wait (wchan=, pri=) at /usr/src/sys/kern/subr_sleepqueue.c:692 #3 0xffffffff80cd9105 in sleeplk (lk=0xfffff802f256c248, flags=, ilk=, wmesg=, pri=, timo=51, queue=0) at /usr/src/sys/kern/kern_lock.c:300 #4 0xffffffff80cd819c in lockmgr_xlock_hard (lk=0xfffff802f256c248, flags=525312, ilk=0xfffff802f256c278, file=, line=, lwa=) at /usr/src/sys/kern/kern_lock.c:822 #5 0xffffffff813acc5e in VOP_LOCK1_APV (vop=, a=0xfffffe008e36b280) at vnode_if.c:2087 #6 0xffffffff80de2820 in VOP_LOCK1 (vp=0xfffff802f256c1e0, flags=525312, file=0xffffffff813c47d0 "/usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_znode.c", line=730) at ./vnode_if.h:859 #7 _vn_lock (vp=0xfffff802f256c1e0, flags=525312, file=0xffffffff813c47d0 "/usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_znode.c", line=730) at /usr/src/sys/kern/vfs_vnops.c:1533 #8 0xffffffff804ae1f4 in zfs_znode_alloc (zfsvfs=, db=, blksz=0, obj_type=, hdl=) at /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_znode.c:730 #9 0xffffffff804adc0d in zfs_mknode (dzp=0xfffff802f461f440, vap=0xfffffe008e36b6e0, tx=, cr=0xfffff8002b529b00, flag=, zpp=0xfffffe008e36b638, acl_ids=0xfffffe008e36b5f8) at /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_znode.c:988 #10 0xffffffff804a4d32 in zfs_create (excl=0, mode=0, dvp=, name=, vap=, vpp=, cr=, td=) at /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vnops.c:1883 #11 zfs_freebsd_create (ap=0xfffffe008e36b790) at /usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vnops.c:4996 #12 0xffffffff813aaa68 in VOP_CREATE_APV (vop=, a=0xfffffe008e36b790) at vnode_if.c:263 #13 0xffffffff80de20f9 in VOP_CREATE (dvp=, vpp=0xfffffe008e36b888, cnp=, vap=0x18000000001) at ./vnode_if.h:109 #14 vn_open_cred (ndp=0xfffffe008e36b828, flagp=0xfffffe008e36b954, cmode=, vn_open_flags=, cred=0xfffff8002b529b00, fp=0xfffff8026d933d70) at /usr/src/sys/kern/vfs_vnops.c:243 #15 0xffffffff80dda74c in kern_openat (td=0xfffff8026af9d580, fd=-100, path=0x7fffffffc630 , pathseg=UIO_USERSPACE, flags=1538, mode=) at /usr/src/sys/kern/vfs_syscalls.c:1082 #16 0xffffffff81222449 in syscallenter (td=) at /usr/src/sys/amd64/amd64/../../kern/subr_syscall.c:135 #17 amd64_syscall (td=0xfffff8026af9d580, traced=0) at /usr/src/sys/amd64/amd64/trap.c:1076 #18 #19 0x000000080138b4fa in ?? () Backtrace stopped: Cannot access memory at address 0x7fffffffc138 (kgdb) fr 7 #7 _vn_lock (vp=0xfffff802f256c1e0, flags=525312, file=0xffffffff813c47d0 "/usr/src/sys/cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_znode.c", line=730) at /usr/src/sys/kern/vfs_vnops.c:1533 warning: Source file is more recent than executable. 1533 error = VOP_LOCK1(vp, flags, file, line); (kgdb) print *vp $1 = {v_tag = 0xffffffff8144af45 "zfs", v_op = 0xffffffff81c64fd0 , v_data = 0xfffff802608c3440, v_mount = 0x0, v_nmntvnodes = {tqe_next = 0xfffff8037a047000, tqe_prev = 0xfffff802f23feb60}, {v_mountedhere = 0x0, v_unpcb = 0x0, v_rdev = 0x0, v_fifoinfo = 0x0}, v_hashlist = {le_next = 0x0, le_prev = 0x0}, v_cache_src = { lh_first = 0x0}, v_cache_dst = {tqh_first = 0x0, tqh_last = 0xfffff802f256c230}, v_cache_dd = 0x0, v_lock = {lock_object = {lo_name = 0xffffffff8144af45 "zfs", lo_flags = 117112840, lo_data = 0, lo_witness = 0x0}, lk_lock = 18446744073709551605, lk_exslpfail = 0, lk_timo = 51, lk_pri = 96}, v_interlock = {lock_object = { lo_name = 0xffffffff814e4508 "vnode interlock", lo_flags = 16973824, lo_data = 0, lo_witness = 0x0}, mtx_lock = 0}, v_vnlock = 0xfffff802f256c248, v_actfreelist = {tqe_next = 0xfffff8037a047000, tqe_prev = 0xfffff80011333a38}, v_bufobj = {bo_lock = {lock_object = {lo_name = 0xffffffff814a9e5f "bufobj interlock", lo_flags = 86179840, lo_data = 0, lo_witness = 0x0}, rw_lock = 1}, bo_ops = 0xffffffff81d38600 , bo_object = 0x0, bo_synclist = {le_next = 0x0, le_prev = 0x0}, bo_private = 0xfffff802f256c1e0, bo_clean = {bv_hd = {tqh_first = 0x0, tqh_last = 0xfffff802f256c2f8}, bv_root = {pt_root = 0}, bv_cnt = 0}, bo_dirty = {bv_hd = {tqh_first = 0x0, tqh_last = 0xfffff802f256c318}, bv_root = {pt_root = 0}, bv_cnt = 0}, bo_numoutput = 0, bo_flag = 0, bo_domain = 1, bo_bsize = 16384}, v_pollinfo = 0x0, v_label = 0x0, v_lockf = 0x0, v_rl = {rl_waiters = {tqh_first = 0x0, tqh_last = 0xfffff802f256c368}, rl_currdep = 0x0}, v_cstart = 0, v_lasta = 0, v_lastw = 0, v_clen = 0, v_holdcnt = 1, v_usecount = 1, v_iflag = 0, v_vflag = 0, v_mflag = 0, v_writecount = 0, v_hash = 49436353, v_type = VREG} (kgdb) > -- > Andriy Gapon >