Re: kern/105229: panic in sync_fsync

On Sat, Dec 02, 2006 at 06:32:39PM +0900, Yoichi Nakayama wrote:
> At Tue, 21 Nov 2006 01:13:26 +0900,
> Yoichi Nakayama wrote:
> > 
> > At Mon, 20 Nov 2006 17:26:40 +0200,
> > Kostik Belousov wrote:
> > > > panic: mtx_lock() of spin mutex vnode interlock _at_ /usr/src/sys/kern/vfs_subr.c:2855
> > > >   ...
> > > > #13 0xc06b131f in panic (fmt=0xc0930a10 "mtx_lock() of spin mutex %s _at_ %s:%d")
> > > > ---Type <return> to continue, or q <return> to quit---
> > > >     at /usr/src/sys/kern/kern_shutdown.c:551
> > > > #14 0xc06a85c0 in _mtx_lock_flags (m=0xc58593a8, opts=0, 
> > > >     file=0xc093c091 "/usr/src/sys/kern/vfs_subr.c", line=2855)
> > > >     at /usr/src/sys/kern/kern_mutex.c:131
> > > > #15 0xc0712570 in vfs_msync (mp=0xc3d4e538, flags=2)
> > > >     at /usr/src/sys/kern/vfs_subr.c:2855
> > > Please, show the output of the "p *vp" and "p *mp" at this frame.
> > > 
> > > > #16 0xc0712d21 in sync_fsync (ap=0x0) at /usr/src/sys/kern/vfs_subr.c:3089
> > > > #17 0xc08bafde in VOP_FSYNC_APV (vop=0x0, a=0xe3c39cb4) at vnode_if.c:1007
> > > > #18 0xc071094e in sync_vnode (bo=0xc3d4b704, td=0xc3924c40) at vnode_if.h:537
> > > > #19 0xc0710bcd in sched_sync () at /usr/src/sys/kern/vfs_subr.c:1691
> > > > #20 0xc069b908 in fork_exit (callout=0xc07109dc <sched_sync>, arg=0x0, 
> > > >     frame=0xe3c39d38) at /usr/src/sys/kern/kern_fork.c:834
> > > > #21 0xc08943bc in fork_trampoline () at /usr/src/sys/i386/i386/exception.s:199
> 
> # kgdb kernel.debug /var/crash/vmcore.14
>    ...
> #11 0xc06b40f3 in panic (fmt=0xc0935c1c "mtx_lock() of spin mutex %s _at_ %s:%d")
>     at /usr/src/sys/kern/kern_shutdown.c:551
> ---Type <return> to continue, or q <return> to quit---
> #12 0xc06ab398 in _mtx_lock_flags (m=0xc6f043a8, opts=0, 
>     file=0xc09412af "/usr/src/sys/kern/vfs_subr.c", line=2855)
>     at /usr/src/sys/kern/kern_mutex.c:131
> #13 0xc071532c in vfs_msync (mp=0xc441b538, flags=2)
>     at /usr/src/sys/kern/vfs_subr.c:2855
> #14 0xc0715add in sync_fsync (ap=0x0) at /usr/src/sys/kern/vfs_subr.c:3089
> #15 0xc08bfcbe in VOP_FSYNC_APV (vop=0x12, a=0xe4306cb4) at vnode_if.c:1007
> #16 0xc07136c8 in sync_vnode (bo=0xc43a4e58, td=0xc3ff2a80) at vnode_if.h:537
> #17 0xc0713945 in sched_sync () at /usr/src/sys/kern/vfs_subr.c:1691
> #18 0xc069e6e0 in fork_exit (callout=0xc0713754 <sched_sync>, arg=0x0, 
>     frame=0xe4306d38) at /usr/src/sys/kern/kern_fork.c:834
> #19 0xc089868c in fork_trampoline () at /usr/src/sys/i386/i386/exception.s:199
> (kgdb) select 13
> (kgdb) p *vp
> $1 = {v_type = VREG, v_tag = 0xc093f146 "ufs", v_op = 0xc09f51c0, v_data = 0xc733f948, v_mount = 0xc441b538, 
>   v_nmntvnodes = {tqe_next = 0xc449fc00, tqe_prev = 0xc8028ca4}, v_un = {vu_mount = 0x0, vu_socket = 0x0, vu_cdev = 0x0, 
>     vu_fifoinfo = 0x0}, v_hashlist = {le_next = 0x0, le_prev = 0xc422b428}, v_hash = 949946, v_cache_src = {
>     lh_first = 0x0}, v_cache_dst = {tqh_first = 0x0, tqh_last = 0xc6f04354}, v_dd = 0x0, v_cstart = 0, v_lasta = 0, 
>   v_lastw = 0, v_clen = 0, v_lock = {lk_object = {lo_name = 0xc093f146 "ufs", lo_type = 0x0, lo_flags = 64, 
>       lo_witness_data = {lod_list = {stqe_next = 0x0}, lod_witness = 0x0}}, lk_interlock = 0xc0a384c8, lk_sharecount = 0, 
>     lk_waitcount = 0, lk_exclusivecount = 0, lk_prio = 80, lk_timo = 51, lk_lockholder = 0xffffffff, lk_newlock = 0x0}, 
>   v_interlock = {mtx_object = {lo_name = 0xc093b247 "vnode interlock", lo_type = 0xc093b247 "vnode interlock", 
>       lo_flags = 196608, lo_witness_data = {lod_list = {stqe_next = 0xc0a49150}, lod_witness = 0xc0a49150}}, mtx_lock = 4, 
>     mtx_recurse = 0}, v_vnlock = 0xc6f0437c, v_holdcnt = 0, v_usecount = 0, v_iflag = 256, v_vflag = 0, v_writecount = 0, 
>   v_freelist = {tqe_next = 0xc72c1c90, tqe_prev = 0xc8028d44}, v_bufobj = {bo_mtx = 0xc6f043a8, bo_clean = {bv_hd = {
>         tqh_first = 0x0, tqh_last = 0xc6f043e4}, bv_root = 0x0, bv_cnt = 0}, bo_dirty = {bv_hd = {tqh_first = 0x0, 
>         tqh_last = 0xc6f043f4}, bv_root = 0x0, bv_cnt = 0}, bo_numoutput = 0, bo_flag = 0, bo_ops = 0xc09e8b84, 
>     bo_bsize = 16384, bo_object = 0xc73b7bb8, bo_synclist = {le_next = 0x0, le_prev = 0x0}, bo_private = 0xc6f04324, 
>     __bo_vnode = 0xc6f04324}, v_pollinfo = 0x0, v_label = 0x0}
> (kgdb) p *mp
> $2 = {mnt_lock = {lk_object = {lo_name = 0xc0940b6b "vfslock", lo_type = 0x0, lo_flags = 16777216, lo_witness_data = {
>         lod_list = {stqe_next = 0x0}, lod_witness = 0x0}}, lk_interlock = 0xc0a37f58, lk_sharecount = 1, lk_waitcount = 0, 
>     lk_exclusivecount = 0, lk_prio = 80, lk_timo = 0, lk_lockholder = 0xffffffff, lk_newlock = 0x0}, mnt_mtx = {
>     mtx_object = {lo_name = 0xc0940b5a "struct mount mtx", lo_type = 0xc0940b5a "struct mount mtx", lo_flags = 16973824, 
>       lo_witness_data = {lod_list = {stqe_next = 0xc0a478c8}, lod_witness = 0xc0a478c8}}, mtx_lock = 3288279680, 
>     mtx_recurse = 0}, mnt_gen = 1, mnt_list = {tqe_next = 0xc4335a70, tqe_prev = 0xc4336048}, mnt_op = 0xc09f4e60, 
>   mnt_vfc = 0xc09f4ea0, mnt_vnodecovered = 0xc4338a78, mnt_syncer = 0xc43a4d9c, mnt_ref = 19648, mnt_nvnodelist = {
>     tqh_first = 0xc699a000, tqh_last = 0xc6fabca4}, mnt_nvnodelistsize = 19647, mnt_writeopcount = 1, 
>   mnt_kern_flag = 536870916, mnt_flag = 2101248, mnt_noasync = 2, mnt_opt = 0xc4309770, mnt_optnew = 0x0, 
>   mnt_maxsymlinklen = 120, mnt_stat = {f_version = 537068824, f_type = 5, f_flags = 2101248, f_bsize = 2048, 
>     f_iosize = 16384, f_blocks = 5073731, f_bfree = 1746472, f_bavail = 1340574, f_files = 1318910, f_ffree = 883512, 
>     f_syncwrites = 0, f_asyncwrites = 0, f_syncreads = 0, f_asyncreads = 0, f_spare = {0, 0, 0, 0, 0, 0, 0, 0, 0, 0}, 
>     f_namemax = 255, f_owner = 0, f_fsid = {val = {1157814914, -1754847891}}, f_charspare = '\0' <repeats 79 times>, 
>     f_fstypename = "ufs", '\0' <repeats 12 times>, f_mntfromname = "/dev/ad0s2e", '\0' <repeats 76 times>, 
>     f_mntonname = "/usr", '\0' <repeats 83 times>}, mnt_cred = 0xc43a5980, mnt_data = 0xc4333200, mnt_time = 0, 
>   mnt_iosize_max = 131072, mnt_export = 0x0, mnt_mntlabel = 0x0, mnt_fslabel = 0x0, mnt_hashseed = 2485092944, 
>   mnt_markercnt = 1, mnt_holdcnt = 1, mnt_holdcntwaiters = 0, mnt_secondary_writes = 0, mnt_secondary_accwrites = 221216, 
>   mnt_gjprovider = 0x0}
> (kgdb) 

The vp looks like normal VI_FREE vnode. The interlock mutex is unowned.
The only strange thing is the
vp->v_interlock.mtx_object.lo_flags = 196608 == 0x30000 ==
LO_INITIALIZED | LO_WITNESS. It misses 0x01000000 (LO_CLASSMASK bit) to
mark it as sleep mutex.

I suspected that the vnode is destroyed and somehow appeared on the mount
point list, but this is definitely not the case. Moreover, destroying lock
mutex (and lock object) would not clear the lo class bits.

Does anybody have further comments ?