From owner-freebsd-current@freebsd.org Sun Nov 13 01:12:08 2016 Return-Path: Delivered-To: freebsd-current@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id 1008EC3D2AA for ; Sun, 13 Nov 2016 01:12:08 +0000 (UTC) (envelope-from truckman@FreeBSD.org) Received: from gw.catspoiler.org (unknown [IPv6:2602:304:b010:ef20::f2]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client CN "gw.catspoiler.org", Issuer "gw.catspoiler.org" (not verified)) by mx1.freebsd.org (Postfix) with ESMTPS id C55B3173C; Sun, 13 Nov 2016 01:12:07 +0000 (UTC) (envelope-from truckman@FreeBSD.org) Received: from FreeBSD.org (mousie.catspoiler.org [192.168.101.2]) by gw.catspoiler.org (8.15.2/8.15.2) with ESMTP id uAD1Bv9V081063; Sat, 12 Nov 2016 17:12:01 -0800 (PST) (envelope-from truckman@FreeBSD.org) Message-Id: <201611130112.uAD1Bv9V081063@gw.catspoiler.org> Date: Sat, 12 Nov 2016 17:11:57 -0800 (PST) From: Don Lewis Subject: Re: panic: mutex ncnegl not owned at /usr/src/sys/kern/vfs_cache.c:743 in 12.0-CURRENT r308447 To: mjguzik@gmail.com cc: freebsd-current@FreeBSD.org, mjg@FreeBSD.org In-Reply-To: <20161112175347.GA14804@dft-labs.eu> MIME-Version: 1.0 Content-Type: TEXT/plain; charset=us-ascii X-BeenThere: freebsd-current@freebsd.org X-Mailman-Version: 2.1.23 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: Sun, 13 Nov 2016 01:12:08 -0000 On 12 Nov, Mateusz Guzik wrote: > On Fri, Nov 11, 2016 at 11:29:48PM -0800, Don Lewis wrote: >> On 11 Nov, To: freebsd-current@FreeBSD.org wrote: >> > Yesterday I upgraded my ports builder box from r306349 to r308477. It >> > crashed overnight during a poudriere run. >> > >> > panic: mutex ncnegl not owned at /usr/src/sys/kern/vfs_cache.c:743 >> >> This problem is very reproduceable for me, so I added some assertions to >> the code to try to track it down: >> >> panic: Bad link elm 0xfffff802a59cb690 prev->next != elm >> #13 0xffffffff80b0d55a in cache_negative_remove (ncp=0xfffff802a59cb690, >> neg_locked=) at /usr/src/sys/kern/vfs_cache.c:747 >> #14 0xffffffff80b0d84a in cache_zap_locked (ncp=0xfffff802a59cb690, >> neg_locked=false) at /usr/src/sys/kern/vfs_cache.c:890 >> #15 0xffffffff80b0ab98 in cache_zap_rlocked_bucket (ncp=0xfffff802a59cb690, >> blp=) at /usr/src/sys/kern/vfs_cache.c:1021 >> #16 cache_lookup (dvp=, vpp=, >> cnp=, tsp=, ticksp=) >> at /usr/src/sys/kern/vfs_cache.c:1308 >> #17 0xffffffff80b0e97c in vfs_cache_lookup (ap=) >> at /usr/src/sys/kern/vfs_cache.c:2024 >> #18 0xffffffff8103fcea in VOP_LOOKUP_APV (vop=, >> a=) at vnode_if.c:127 >> #19 0xffffffff80b17ed2 in VOP_LOOKUP (vpp=0xfffffe085bfa86e8, >> cnp=0xfffffe085bfa8710, dvp=) at ./vnode_if.h:54 >> #20 lookup (ndp=) at /usr/src/sys/kern/vfs_lookup.c:830 >> #21 0xffffffff80b1748e in namei (ndp=) >> at /usr/src/sys/kern/vfs_lookup.c:397 >> #22 0xffffffff80b30bc4 in kern_renameat (td=, oldfd=10, >> old=0x28e72a59 , >> newfd=10, >> new=0x28e72601 , >> pathseg=) at /usr/src/sys/kern/vfs_syscalls.c:3515 >> #23 0xffffffff80ff98a0 in syscallenter (td=0xfffff801ebfd8500, >> sa=) >> at /usr/src/sys/amd64/ia32/../../kern/subr_syscall.c:135 >> #24 ia32_syscall (frame=0xfffffe085bfa8a40) >> at /usr/src/sys/amd64/ia32/ia32_syscall.c:187 >> #25 >> >> >> #13 0xffffffff80b0d55a in cache_negative_remove (ncp=0xfffff802a59cb690, >> neg_locked=) at /usr/src/sys/kern/vfs_cache.c:747 >> 747 TAILQ_REMOVE(&ncneg_hot.nl_list, ncp, nc_dst); >> (kgdb) list >> 742 } else { >> 743 mtx_assert(&neglist->nl_lock, MA_OWNED); >> 744 mtx_assert(&ncneg_hot.nl_lock, MA_OWNED); >> 745 } >> 746 if (ncp->nc_flag & NCF_HOTNEGATIVE) { >> 747 TAILQ_REMOVE(&ncneg_hot.nl_list, ncp, nc_dst); >> 748 } else { >> 749 TAILQ_REMOVE(&neglist->nl_list, ncp, nc_dst); >> 750 } >> 751 if (list_locked) >> >> (kgdb) print ncp >> $1 = (struct namecache *) 0xfffff802a59cb690 >> >> (kgdb) print *ncp >> $2 = {nc_hash = {le_next = 0x0, le_prev = 0xfffffe0001814178}, nc_src = { >> le_next = 0xfffff80415e22290, le_prev = 0xfffff8048e5597a8}, nc_dst = { >> tqe_next = 0xfffff80421744a10, tqe_prev = 0xfffff80421744a30}, >> nc_dvp = 0xfffff8048e559760, n_un = {nu_vp = 0x0, nu_neghits = 0}, >> nc_flag = 32 ' ', nc_nlen = 25 '\031', >> nc_name = 0xfffff802a59cb6d2 "gtk3-icon-browser.desktop"} >> (kgdb) print ncp->nc_dst->tqe_prev >> $8 = (struct namecache **) 0xfffff80421744a30 >> (kgdb) print *(ncp->nc_dst->tqe_prev) >> $9 = (struct namecache *) 0x0 >> >> >> The line number for the failed assertion doesn't make sense. The value >> of nc_flag is 32 (0x20), but NCF_HOTNEGATIVE is defined as 0x40 and >> NCF_NEGATIVE is defined as 0x20. In any case, the list seems to be >> messed up. >> > > Can you check if the problem persists after reverting r307650 and > r307685? > > I got another report of trouble with poudriere, but so far can neither > reproduce nor diagnose what happens here. > > For instance with this crash, in principle there could be a race where > the entry is demoted and loses the HOTNEGATIVE. But the demotion code > has the hot list locked and so does this code if it spots the flag. > What's more, the race is handled by re-checking the flag after the lock > was taken. > > That said, there is something seriously fishing going on here. This !neg_locked code in cache_negative_remove() looks suspicious to me: if (!neg_locked) { if (ncp->nc_flag & NCF_HOTNEGATIVE) { hot_locked = true; mtx_lock(&ncneg_hot.nl_lock); if (!(ncp->nc_flag & NCF_HOTNEGATIVE)) { list_locked = true; mtx_lock(&neglist->nl_lock); } } else { list_locked = true; mtx_lock(&neglist->nl_lock); } It looks like you handle NCF_HOTNEGATIVE going away while waiting for the ncneg_hot.nl_lock, but don't handle the possible appearance of NCF_HOTNEGATIVE while waiting for neglist->nl_lock. What protects nc_flag, the lock for the list that it resides on? I think the only safe thing to do here is to always grab both locks. My package builder is now up to 18 1/2 hours of runtime building packages with the same kernel that previously crashed in a few hours.