On 13 Oct, John Baldwin wrote: > On Tuesday 11 October 2005 05:43 am, Don Lewis wrote: >> On 6 Oct, Kris Kennaway wrote: [ snip - attributions trimmed to much - I said:] >> >> This problem appears to be some sort of vnode lock leak. >> > >> > leaked lockmgr locks usually panic when the thread exits. >> >> There's a KASSERT to in userret() to catch this in the syscall return >> path, but that check is only enabled if the INVARIANTS kernel option is >> enabled, which is not currently true in RELENG_6, and Mikhail doesn't >> want to risk a panic on the machine in question, which is at a remote >> location. >> >> He did reproduce the problem again with DEBUG_LOCKS enabled and we got >> some more info. Here's the locked vnode in question: >> >> (kgdb) print *(struct vnode *)0xc2741ad4 >> $1 = {v_type = VDIR, v_tag = 0xc0729abe "ufs", v_op = 0xc076c5c0, >> v_data = 0xc2c03630, v_mount = 0xc1f72000, v_nmntvnodes = { >> tqe_next = 0xc2742c08, tqe_prev = 0xc2dfa880}, v_un = {vu_mount = 0x0, >> vu_socket = 0x0, vu_cdev = 0x0, vu_fifoinfo = 0x0}, v_hashlist = { >> le_next = 0xc2895604, le_prev = 0xc1f01f28}, v_hash = 218659, >> v_cache_src = {lh_first = 0x0}, v_cache_dst = {tqh_first = 0x0, >> tqh_last = 0xc2741b04}, v_dd = 0x0, v_cstart = 0, v_lasta = 0, >> v_lastw = 0, v_clen = 0, v_lock = {lk_interlock = 0xc0783b4c, >> lk_flags = 33816640, lk_sharecount = 0, lk_waitcount = 1, >> lk_exclusivecount = 1, lk_prio = 80, lk_wmesg = 0xc0729abe "ufs", >> lk_timo = 6, lk_lockholder = 0xc1fe2300, lk_newlock = 0x0, >> lk_filename = 0xc072b093 "/var/src/sys/kern/vfs_subr.c", >> lk_lockername = 0xc072aab4 "vop_stdlock", lk_lineno = 1951, >> lk_slockholder = 0xffffffff, lk_sfilename = 0xc071d296 "none", >> lk_slockername = 0xc0724a8d "never share locked", lk_slineno = 0}, >> v_interlock = {mtx_object = {lo_class = 0xc075b224, >> lo_name = 0xc072b100 "vnode interlock", >> lo_type = 0xc072b100 "vnode interlock", lo_flags = 196608, lo_list = >> { tqe_next = 0x0, tqe_prev = 0x0}, lo_witness = 0x0}, mtx_lock = 4, >> mtx_recurse = 0}, v_vnlock = 0xc2741b2c, >> filename = 0xc07382b1 "/var/src/sys/ufs/ufs/ufs_lookup.c", line = 563, >> v_holdcnt = 5, v_usecount = 4, v_iflag = 0, v_vflag = 0, v_writecount = >> 0, v_freelist = {tqe_next = 0x0, tqe_prev = 0xc29b4948}, v_bufobj = { >> bo_mtx = 0xc2741b6c, bo_clean = {bv_hd = {tqh_first = 0xcc1cbd48, tqh_last >> = 0xcc1cbd80}, bv_root = 0xcc1cbd48, bv_cnt = 1}, bo_dirty = { bv_hd = >> {tqh_first = 0x0, tqh_last = 0xc2741bcc}, bv_root = 0x0, bv_cnt = 0}, >> bo_numoutput = 0, bo_flag = 0, bo_ops = 0xc0761b04, bo_bsize = 16384, >> bo_object = 0xc30cc39c, bo_synclist = {le_next = 0x0, le_prev = 0x0}, >> bo_private = 0xc2741ad4, __bo_vnode = 0xc2741ad4}, v_pollinfo = 0x0, >> v_label = 0x0} >> i) >> >> The culprit process knows that it is holding the lock: >> >> (kgdb) print ((struct vnode *)0xc2741ad4)->v_lock->lk_lockholder->td_locks >> $3 = 1 >> >> And this is its stack trace, once again in wait4(): >> >> (kgdb) where >> #0 sched_switch (td=0xc1fe2300, newtd=0xc1e5b300, flags=1) >> at /var/src/sys/kern/sched_4bsd.c:980 >> #1 0xc1fe2300 in ?? () >> #2 0xc0526218 in mi_switch (flags=1, newtd=0x0) >> at /var/src/sys/kern/kern_synch.c:356 >> #3 0xc0545127 in sleepq_switch (wchan=0x0) >> at /var/src/sys/kern/subr_sleepqueue.c:427 >> #4 0xc0545400 in sleepq_wait_sig (wchan=0x0) >> at /var/src/sys/kern/subr_sleepqueue.c:552 >> #5 0xc0525e67 in msleep (ident=0xc1fe520c, mtx=0xc1fe5274, priority=348, >> wmesg=0x0, timo=0) at /var/src/sys/kern/kern_synch.c:225 >> #6 0xc04feaec in kern_wait (td=0xc1fe2300, pid=-1, status=0xd4922c80, >> options=0, rusage=0x0) at /var/src/sys/kern/kern_exit.c:772 >> #7 0xc04fdeed in wait4 (td=0x0, uap=0xd4922d04) >> at /var/src/sys/kern/kern_exit.c:569 >> #8 0xc06ed702 in syscall (frame= >> {tf_fs = 59, tf_es = -1078001605, tf_ds = -1078001605, tf_edi = >> 134900352, tf_esi = 9195, tf_ebp = -1077951176, tf_isp = -728617628, tf_ebx >> = 672547876, t f_edx = 0, tf_ecx = 137943616, tf_eax = 7, tf_trapno = 12, >> tf_err = 2, tf_eip = 671979599, tf_cs = 51, tf_eflags = 534, tf_esp = >> -1077951204, tf_ss = 59}) at /var/src/sys/i386/i386/trap.c:976 >> #9 0xc06d651f in Xint0x80_syscall () at >> /var/src/sys/i386/i386/exception.s:200 #10 0x00000033 in ?? () >> Previous frame inner to this frame (corrupt stack?) >> >> >> The code referenced by the vnode filename and line members is this block >> in ufs_lookup(): >> >> if (flags & ISDOTDOT) { >> VOP_UNLOCK(pdp, 0, td); /* race to get the inode */ >> error = VFS_VGET(pdp->v_mount, dp->i_ino, >> cnp->cn_lkflags, &tdp); >> --> vn_lock(pdp, LK_EXCLUSIVE | LK_RETRY, td); >> if (error) >> return (error); >> *vpp = tdp; >> } else ... >> >> >> I don't see any obvious lock leaks in the code. > > Looks like the function returns with the desired leaf vnode locked if I > grokked it correctly in my brief perusal, so the bug could be in the caller. Most likely, but the bug is only rarely triggered and is not caught by DEBUG_VFS_LOCKS. If INVARIANTS is enabled, the problem is caught by the KASSERT in userret(), which is rather too late to find the source of the problem. The problem tends to show up about a third of the way through the openoffice build, but at different places in different runs, and some builds are successful. I was not able to reproduce this problem at all until I discovered that Mikhail had the following in /etc/sysctl.conf: debug.vfscache=0 With this setting, I'm able to reproduce this problem, at least sometimes, on both my SMP box running 6.0-BETA5 and my UP box running HEAD. Earlier today I kicked off another run on the HEAD box with DEBUG_LOCKS and the KTR stuff enabled so I should at least get the call stack that grabbed the lock. The process always seems to be dmake, so I the syscall is probably stat(). I suspect that I'll have to sprinkle some more KTR calls in the code to find the problem. Because the problem doesn't seem to occur with the default debug.vfscache setting (or if it does, it is *very* rare), I don't think this is a show stopper for 6.0-RELEASE. It might be fun to run the stress tests with this sysctl setting.Received on Thu Oct 13 2005 - 18:48:48 UTC
This archive was generated by hypermail 2.4.0 : Wed May 19 2021 - 11:38:45 UTC