nullfs: panic: vrele: negative ref cnt
pluknet
pluknet at gmail.com
Mon Mar 9 13:17:49 PDT 2009
2009/3/9 pluknet <pluknet at gmail.com>:
> 2009/3/9 Paul B. Mahol <onemda at gmail.com>:
>> Hi,
>> here is part of textdump:
>>
>> db:1:lockinfo> show locks
>> db:1:locks> show alllocks
>> Process 722 (sh) thread 0xc4134000 (100065)
>> db:1:alllocks> show lockedvnods
>> Locked vnodes
>> db:0:kdb.enter.panic> show pcpu
>> cpuid = 1
>> curthread = 0xc4134000: pid 722 "sh"
>> curpcb = 0xc3ba8d90
>> fpcurthread = 0xc4134000: pid 722 "sh"
>> idlethread = 0xc3d08d80: pid 10 "idle: cpu1"
>> APIC ID = 1
>> currentldt = 0x50
>> spin locks held:
>> db:0:kdb.enter.panic> bt
>> Tracing pid 722 tid 100065 td 0xc4134000
>> kdb_enter(c0610bfe,c0610bfe,c061db9e,c3ba8aa8,1,...) at kdb_enter+0x3a
>> panic(c061db9e,0,c061cee6,88e,4,...) at panic+0x136
>> vrele(c4326d9c,0,c433fb5f,82,c060f3c7,...) at vrele+0x111
>> null_nodeget(c3fd4780,c4326d9c,c3ba8bf4,0,c3ba8be4,...) at null_nodeget+0xa0
>> null_bypass(c3ba8be0,c3f35a78,c3ba8c28) at null_bypass+0x141
>> VOP_VPTOCNP_APV(c4340240,c3ba8be0,c061bf01,387,c3cecc00,...) at
>> VOP_VPTOCNP_APV+0xb3
>> vn_vptocnp(c3ba8c4c,c061bf01,3af,c3ba8c3c,c3f35a78,...) at vn_vptocnp+0xd9
>> vn_fullpath1(c3cecc00,c3ba8c5c,3fc,315,c3cecc00,...) at vn_fullpath1+0x29a
>> kern___getcwd(c4134000,bfbfe884,0,400,c3ba8d2c,...) at kern___getcwd+0xd0
>> __getcwd(c4134000,c3ba8cf8,8,c0617c09,c0640290,...) at __getcwd+0x29
>> syscall(c3ba8d38) at syscall+0x261
>> Xint0x80_syscall() at Xint0x80_syscall+0x20
>> --- syscall (326, FreeBSD ELF32, __getcwd), eip = 0x2814edfb, esp =
>> 0xbfbfe6cc, ebp = 0xbfbfe788 ---
>>
>>
>> panic: vrele: negative ref cnt
>> cpuid = 1
>> KDB: enter: panic
>> shared lockmgr ufs (ufs) r = 0 (0xc43c36a0) locked @
>> /usr/src/sys/kern/vfs_default.c:790
>> shared lockmgr ufs (ufs) r = 0 (0xc43c36a0) locked @
>> /usr/src/sys/kern/vfs_default.c:790
>>
>> 0xc43c3648: tag ufs, type VDIR
>> usecount 1, writecount 0, refcount 1 mountedhere 0
>> flags ()
>> lock type ufs: SHARED (count 1)
>> ino 3583142, on dev ad0s1h
>>
>> 0xc43c3430: tag null, type VDIR
>> usecount 4, writecount 0, refcount 5 mountedhere 0
>> flags ()
>> lock type ufs: SHARED (count 1)
>> vp=0xc43c3430, lowervp=0xc43c3648
>>
>>
>> How to reproduce it:
>>
>> # mount_nullfs /usr/local/src /usr/src
>> # cd /sys
>> # whereis something
>>
>>
>> It appears panic have been introduced after r189488
>>
>
> [marcus@ cc'ed]
>
> Futher debugging shows:
>
> Script started on Mon Mar 9 21:43:17 2009
> c8-vb# kgdb /boot/ke rnel/ke rnel /var/crash/vm core.1
>
> GNU gdb 6.1.1 [FreeBSD]
> Copyright 2004 Free Software Foundation, Inc.
> GDB is free software, covered by the GNU General Public License, and you are
> welcome to change it and/or distribute copies of it under certain conditions.
> Type "show copying" to see the conditions.
> There is absolutely no warranty for GDB. Type "show warranty" for details.
> This GDB was configured as "i386-marcel-freebsd"...
>
> Unread portion of the kernel message buffer:
> , FreeBSD ELF32, __getcwd), eip = 0x28154b2b, esp = 0xbfbfe71c, ebp =
> 0xbfbfe7d8 ---
> null_hashget: 0xc4451560 is not locked but should be
> KDB: enter: lock violation
> panic: mutex Giant not owned at /usr/src/sys/kern/tty_ttydisc.c:1127
> cpuid = 0
> Uptime: 43m7s
> Physical memory: 1015 MB
> Dumping 51 MB: 36 20 4
>
> Reading symbols from /boot/kernel/if_em.ko...Reading symbols from
> /boot/kernel/if_em.ko.symbols...done.
> done.
> Loaded symbols for /boot/kernel/if_em.ko
> Reading symbols from /boot/kernel/nfsclient.ko...Reading symbols from
> /boot/kernel/nfsclient.ko.symbols...done.
> done.
> Loaded symbols for /boot/kernel/nfsclient.ko
> #0 doadump () at pcpu.h:246
> 246 pcpu.h: No such file or directory.
> in pcpu.h
> (kgdb) bt
> #0 doadump () at pcpu.h:246
> #1 0xc05c458e in boot (howto=260) at /usr/src/sys/kern/kern_shutdown.c:420
> #2 0xc05c4862 in panic (fmt=Variable "fmt" is not available.
> ) at /usr/src/sys/kern/kern_shutdown.c:576
> #3 0xc05b4c77 in _mtx_assert (m=0xc08b6170, what=4,
> file=0xc0829baf "/usr/src/sys/kern/tty_ttydisc.c", line=1127)
> at /usr/src/sys/kern/kern_mutex.c:639
> #4 0xc06197dd in ttydisc_getc (tp=0xc3dbf000, buf=0xe66bc7c0, len=128)
> at /usr/src/sys/kern/tty_ttydisc.c:1127
> #5 0xc050daf4 in sctty_outwakeup (tp=0xc3dbf000)
> at /usr/src/sys/dev/syscons/syscons.c:323
> #6 0xc050e05c in scgetc (sc=0xc0a73000, flags=3)
> at /usr/src/sys/dev/syscons/syscons.c:3281
> #7 0xc050e680 in sc_cngetc (cd=0xc0863d20)
> at /usr/src/sys/dev/syscons/syscons.c:1607
> #8 0xc058cd68 in cncheckc () at /usr/src/sys/kern/kern_cons.c:377
> #9 0xc058cda6 in cngetc () at /usr/src/sys/kern/kern_cons.c:355
> #10 0xc0480435 in db_readline (lstart=0xc08a0100 "", lsize=120)
> at /usr/src/sys/ddb/db_input.c:326
> #11 0xc0480e0a in db_read_line () at /usr/src/sys/ddb/db_lex.c:56
> #12 0xc047f0b6 in db_command_loop () at /usr/src/sys/ddb/db_command.c:496
> #13 0xc0480f2d in db_trap (type=3, code=0) at /usr/src/sys/ddb/db_main.c:229
> #14 0xc05f1d86 in kdb_trap (type=3, code=0, tf=0xe66bca34)
> at /usr/src/sys/kern/subr_kdb.c:534
> #15 0xc07bc856 in trap (frame=0xe66bca34) at /usr/src/sys/i386/i386/trap.c:678
> ---Type <return> to continue, or q <return> to quit---
> #16 0xc07a15bb in calltrap () at /usr/src/sys/i386/i386/exception.s:165
> #17 0xc05f1f0a in kdb_enter (why=0xc082deeb "vfslock",
> msg=0xc082dedc "lock violation") at cpufunc.h:71
> #18 0xc064a541 in vfs_badlock (msg=0xc082df39 "is not locked but should be",
> str=0xc08173c4 "null_hashget", vp=0xc4451560)
> at /usr/src/sys/kern/vfs_subr.c:3699
> #19 0xc064ddf2 in assert_vop_locked (vp=0xc4451560,
> str=0xc08173c4 "null_hashget") at /usr/src/sys/kern/vfs_subr.c:3723
> #20 0xc055c5df in null_nodeget (mp=0xc40152cc, lowervp=0xc4451560,
> vpp=0xe66bcbf0) at /usr/src/sys/fs/nullfs/null_subr.c:110
> #21 0xc055d75a in null_bypass (ap=0xe66bcbdc)
> at /usr/src/sys/fs/nullfs/null_vnops.c:325
> #22 0xc07c86a3 in VOP_VPTOCNP_APV (vop=0xc08688a0, a=0xe66bcbdc)
> at vnode_if.c:2871
> #23 0xc063a749 in vn_vptocnp (vp=0xe66bcc24, bp=0xe66bcc28,
> buf=0xc3e15c00 'p' <repeats 200 times>..., buflen=0xe66bcc48)
> at vnode_if.h:1541
> #24 0xc063aaca in vn_fullpath1 (td=Variable "td" is not available.
> ) at /usr/src/sys/kern/vfs_cache.c:1001
> #25 0xc063ae60 in kern___getcwd (td=0xc4435000,
> buf=0xbfbfe8d4 <Address 0xbfbfe8d4 out of bounds>, bufseg=UIO_USERSPACE,
> buflen=1024) at /usr/src/sys/kern/vfs_cache.c:795
> #26 0xc063b009 in __getcwd (td=0xc4435000, uap=0xe66bccf8)
> at /usr/src/sys/kern/vfs_cache.c:769
> #27 0xc07bbfd4 in syscall (frame=0xe66bcd38)
> ---Type <return> to continue, or q <return> to quit---
> at /usr/src/sys/i386/i386/trap.c:1066
> #28 0xc07a1620 in Xint0x80_syscall ()
> at /usr/src/sys/i386/i386/exception.s:261
> #29 0x00000033 in ?? ()
> Previous frame inner to this frame (corrupt stack?)
> (kgdb) c8-vb#
>
> c8-vb# ^D exit
>
> Script done on Mon Mar 9 21:43:35 2009
>
Gahr.. another one looks a bit different.
No null_hashget assert, but now in usecount == 0 (like in Paul B. Mahol's case).
Script started on Mon Mar 9 23:00:44 2009
c8-vb# kgdb /boot/kernel/kernel /var/crash/vmcore.5
Unread portion of the kernel message buffer:
mgr_args+0xb80
#1 0xc074c9d1 at ffs_lock+0xa1
#2 0xc07ca005 at VOP_LOCK1_APV+0xb5
#3 0xc065a548 at _vn_lock+0x78
#4 0xc065b63f at vn_close+0x7f
#5 0xc063ea1d at vop_stdvptocnp+0x68d
#6 0xc07c86a6 at VOP_VPTOCNP_APV+0xd6
#7 0xc07c875b at VOP_VPTOCNP_AP+0x1b
#8 0xc055d6a9 at null_bypass+0xf9
#9 0xc07c86b3 at VOP_VPTOCNP_APV+0xe3
#10 0xc063a759 at vn_vptocnp+0xd9
#11 0xc063aada at vn_fullpath1+0x29a
#12 0xc063ae70 at kern___getcwd+0xd0
#13 0xc063b019 at __getcwd+0x29
#14 0xc07bbfe4 at syscall+0x2b4
#15 0xc07a1630 at Xint0x80_syscall+0x20
ino 70663, on dev ad0s1a
panic: vrele: negative ref cnt
cpuid = 0
KDB: enter: panic
Uptime: 1m20s
Physical memory: 1015 MB
Dumping 51 MB: 36 20 4
Reading symbols from /boot/kernel/if_em.ko...Reading symbols from
/boot/kernel/if_em.ko.symbols...done.
done.
Loaded symbols for /boot/kernel/if_em.ko
Reading symbols from /boot/kernel/nfsclient.ko...Reading symbols from
/boot/kernel/nfsclient.ko.symbols...done.
done.
Loaded symbols for /boot/kernel/nfsclient.ko
#0 doadump () at pcpu.h:246
246 pcpu.h: No such file or directory.
in pcpu.h
(kgdb) bt
#0 doadump () at pcpu.h:246
#1 0xc05c459e in boot (howto=260) at /usr/src/sys/kern/kern_shutdown.c:420
#2 0xc05c4872 in panic (fmt=Variable "fmt" is not available.
) at /usr/src/sys/kern/kern_shutdown.c:576
#3 0xc064eeb9 in vrele (vp=0xc442cac0) at /usr/src/sys/kern/vfs_subr.c:2191
#4 0xc055c6b1 in null_nodeget (mp=0xc40162cc, lowervp=0xc442cac0,
vpp=0xe66b0bf0) at /usr/src/sys/fs/nullfs/null_subr.c:204
#5 0xc055d76a in null_bypass (ap=0xe66b0bdc)
at /usr/src/sys/fs/nullfs/null_vnops.c:325
#6 0xc07c86b3 in VOP_VPTOCNP_APV (vop=0xc08688a0, a=0xe66b0bdc)
at vnode_if.c:2871
#7 0xc063a759 in vn_vptocnp (vp=0xe66b0c24, bp=0xe66b0c28,
buf=0xc3dee800 'p' <repeats 200 times>..., buflen=0xe66b0c48)
at vnode_if.h:1541
#8 0xc063aada in vn_fullpath1 (td=Variable "td" is not available.
) at /usr/src/sys/kern/vfs_cache.c:1001
#9 0xc063ae70 in kern___getcwd (td=0xc41a5460,
buf=0xbfbfe844 <Address 0xbfbfe844 out of bounds>, bufseg=UIO_USERSPACE,
buflen=1024) at /usr/src/sys/kern/vfs_cache.c:795
#10 0xc063b019 in __getcwd (td=0xc41a5460, uap=0xe66b0cf8)
at /usr/src/sys/kern/vfs_cache.c:769
#11 0xc07bbfe4 in syscall (frame=0xe66b0d38)
at /usr/src/sys/i386/i386/trap.c:1066
#12 0xc07a1630 in Xint0x80_syscall ()
at /usr/src/sys/i386/i386/exception.s:261
#13 0x00000033 in ?? ()
Previous frame inner to this frame (corrupt stack?)
(kgdb) f 4
#4 0xc055c6b1 in null_nodeget (mp=0xc40162cc, lowervp=0xc442cac0,
vpp=0xe66b0bf0) at /usr/src/sys/fs/nullfs/null_subr.c:204
204 vrele(lowervp);
(kgdb) p vlowerQuit
(kgdb) p lowervp
$1 = (struct vnode *) 0xc442cac0
(kgdb) p *lowervp
$2 = {v_type = VDIR, v_tag = 0xc081a668 "ufs", v_op = 0xc0888a00,
v_data = 0xc442e5a0, v_mount = 0xc4016b30, v_nmntvnodes = {
tqe_next = 0xc442c968, tqe_prev = 0xc443341c}, v_un = {vu_mount = 0x0,
vu_socket = 0x0, vu_cdev = 0x0, vu_fifoinfo = 0x0, vu_yield = 0},
v_hashlist = {le_next = 0x0, le_prev = 0xc3eb17b4}, v_hash = 70663,
v_cache_src = {lh_first = 0xc444c94c}, v_cache_dst = {
tqh_first = 0xc41c1880, tqh_last = 0xc41c1890}, v_dd = 0xc442c158,
v_cstart = 0, v_lasta = 0, v_lastw = 0, v_clen = 0, v_lock = {
lock_object = {lo_name = 0xc081a668 "ufs", lo_flags = 91947009,
lo_data = 0, lo_witness = 0xc3cf51c0}, lk_lock = 1, lk_timo = 1,
lk_pri = 80, lk_stack = {depth = 16, pcs = {3227181616, 3228879313,
3229392901, 3227886920, 3227891263, 3227773469, 3229386406,
3229386587, 3226850985, 3229386419, 3227756377, 3227757274,
3227758192, 3227758617, 3229335524, 3229226544, 0, 0}}},
v_interlock = {lock_object = {lo_name = 0xc0827160 "vnode interlock",
lo_flags = 16973824, lo_data = 0, lo_witness = 0xc3cef178},
mtx_lock = 4}, v_vnlock = 0xc442cb18, v_holdcnt = 5, v_usecount = 0,
v_iflag = 0, v_vflag = 0, v_writecount = 0, v_freelist = {tqe_next = 0x0,
tqe_prev = 0xc3e74244}, v_bufobj = {bo_mtx = {lock_object = {
lo_name = 0xc082ebea "bufobj interlock", lo_flags = 16973824,
lo_data = 0, lo_witness = 0xc3cf4048}, mtx_lock = 4}, bo_clean = {
bv_hd = {tqh_first = 0xd7d19d20, tqh_last = 0xd7d19d58},
bv_root = 0xd7d19d20, bv_cnt = 1}, bo_dirty = {bv_hd = {
tqh_first = 0x0, tqh_last = 0xc442cbd8}, bv_root = 0x0, bv_cnt = 0},
---Type <return> to continue, or q <return> to quit---
bo_numoutput = 0, bo_flag = 0, bo_ops = 0xc087abe0, bo_bsize = 16384,
bo_object = 0xc443526c, bo_synclist = {le_next = 0x0, le_prev = 0x0},
bo_private = 0xc442cac0, __bo_vnode = 0xc442cac0}, v_pollinfo = 0x0,
v_label = 0x0, v_lockf = 0x0}
(kgdb) p *vpp
$3 = (struct vnode *) 0xc442c560
(kgdb) p **vpp
$4 = {v_type = VDIR, v_tag = 0xc0837f79 "null", v_op = 0xc08688a0,
v_data = 0xc3e737b0, v_mount = 0xc40162cc, v_nmntvnodes = {
tqe_next = 0xc444b2b0, tqe_prev = 0xc4016300}, v_un = {vu_mount = 0x0,
vu_socket = 0x0, vu_cdev = 0x0, vu_fifoinfo = 0x0, vu_yield = 0},
v_hashlist = {le_next = 0x0, le_prev = 0x0}, v_hash = 0, v_cache_src = {
lh_first = 0x0}, v_cache_dst = {tqh_first = 0x0, tqh_last = 0xc442c590},
v_dd = 0x0, v_cstart = 0, v_lasta = 0, v_lastw = 0, v_clen = 0, v_lock = {
lock_object = {lo_name = 0xc0837f79 "null", lo_flags = 91947016,
lo_data = 0, lo_witness = 0xc3cf5840}, lk_lock = 1, lk_timo = 1,
lk_pri = 80, lk_stack = {depth = 0, pcs = {0 <repeats 18 times>}}},
v_interlock = {lock_object = {lo_name = 0xc0827160 "vnode interlock",
lo_flags = 16973824, lo_data = 0, lo_witness = 0xc3cef178},
mtx_lock = 4}, v_vnlock = 0xc442cb18, v_holdcnt = 2, v_usecount = 3,
v_iflag = 0, v_vflag = 1, v_writecount = 0, v_freelist = {tqe_next = 0x0,
tqe_prev = 0x0}, v_bufobj = {bo_mtx = {lock_object = {
lo_name = 0xc082ebea "bufobj interlock", lo_flags = 16973824,
lo_data = 0, lo_witness = 0xc3cf4048}, mtx_lock = 4}, bo_clean = {
bv_hd = {tqh_first = 0x0, tqh_last = 0xc442c668}, bv_root = 0x0,
bv_cnt = 0}, bo_dirty = {bv_hd = {tqh_first = 0x0,
tqh_last = 0xc442c678}, bv_root = 0x0, bv_cnt = 0}, bo_numoutput = 0,
bo_flag = 0, bo_ops = 0xc087abe0, bo_bsize = 0, bo_object = 0x0,
bo_synclist = {le_next = 0x0, le_prev = 0x0}, bo_private = 0xc442c560,
__bo_vnode = 0xc442c560}, v_pollinfo = 0x0, v_label = 0x0, v_lockf = 0x0}
--
wbr,
pluknet
More information about the freebsd-current
mailing list