Subject: kern/10352: lfs_vunref: vnode locked
To: None <gnats-bugs@gnats.netbsd.org>
From: None <jarle@runit.no>
List: netbsd-bugs
Date: 06/13/2000 02:12:16
>Number:         10352
>Category:       kern
>Synopsis:       lfs_vunref: vnode locked
>Confidential:   no
>Severity:       serious
>Priority:       medium
>Responsible:    kern-bug-people
>State:          open
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Tue Jun 13 02:13:00 PDT 2000
>Closed-Date:
>Last-Modified:
>Originator:     Jarle Greipsland
>Release:        -current from 2000-06-07 or thereabout
>Organization:
RUNIT as
>Environment:
	
System: NetBSD honey.runit.sintef.no 1.4ZA NetBSD 1.4ZA (HONEY) #20: Wed Jun  7 18:20:32 CEST 2000     jarle@honey.runit.sintef.no:/usr/src/sys/arch/alpha/compile/HONEY alpha


>Description:
Trying to crash NetBSD with an LFS partition, I suddenly succeeded.

Prior to the crash, the following messages were logged to the console:

lfs_fastvget: ino 11 inlocked by pid 2394
lfs_markv: lfs_fastvget failed with 35 (ino 11, segment 4375)
lfs_fastvget: ino 11 inlocked by pid 2394
lfs_markv: lfs_fastvget failed with 35 (ino 11, segment 4375)
lfs_fastvget: ino 11 inlocked by pid 2394
lfs_markv: lfs_fastvget failed with 35 (ino 11, segment 3473)
lfs_fastvget: ino 11 inlocked by pid 2394
lfs_markv: lfs_fastvget failed with 35 (ino 11, segment 3548)
lfs_fastvget: ino 11 inlocked by pid 2394
lfs_markv: lfs_fastvget failed with 35 (ino 11, segment 3548)
lfs_fastvget: ino 11 inlocked by pid 2394
lfs_markv: lfs_fastvget failed with 35 (ino 11, segment 3613)
lfs_fastvget: ino 11 inlocked by pid 2394
lfs_markv: lfs_fastvget failed with 35 (ino 11, segment 3548)
lfs_fastvget: ino 11 inlocked by pid 2394
lfs_markv: lfs_fastvget failed with 35 (ino 11, segment 3548)
lfs_fastvget: ino 11 inlocked by pid 2394
lfs_markv: lfs_fastvget failed with 35 (ino 11, segment 3548)
lfs_fastvget: ino 11 inlocked by pid 2394
lfs_markv: lfs_fastvget failed with 35 (ino 11, segment 3548)
lfs_fastvget: ino 11 inlocked by pid 2394
lfs_markv: lfs_fastvget failed with 35 (ino 11, segment 3548)
lfs_fastvget: ino 11 inlocked by pid 2394
lfs_markv: lfs_fastvget failed with 35 (ino 11, segment 3548)
lfs_fastvget: ino 11 inlocked by pid 2394
lfs_markv: lfs_fastvget failed with 35 (ino 11, segment 3548)
lfs_fastvget: ino 11 inlocked by pid 2394
lfs_markv: lfs_fastvget failed with 35 (ino 11, segment 3548)
lfs_fastvget: ino 11 inlocked by pid 2394
lfs_markv: lfs_fastvget failed with 35 (ino 11, segment 3548)
lfs_fastvget: ino 11 inlocked by pid 2394
lfs_markv: lfs_fastvget failed with 35 (ino 11, segment 3548)
lfs_fastvget: ino 11 inlocked by pid 2394
lfs_markv: lfs_fastvget failed with 35 (ino 11, segment 3704)
lfs_fastvget: ino 11 inlocked by pid 2394
lfs_markv: lfs_fastvget failed with 35 (ino 11, segment 3704)
lfs_fastvget: vnode VXLOCKed for ino 74868
lfs_markv: lfs_fastvget failed with 35 (ino 74868, segment 4683)
lfs_fastvget: ino 11 inlocked by pid 2394
lfs_markv: lfs_fastvget failed with 35 (ino 11, segment 3728)
lfs_fastvget: ino 11 inlocked by pid 2394
lfs_markv: lfs_fastvget failed with 35 (ino 11, segment 3728)
lfs_fastvget: ino 11 inlocked by pid 2394
lfs_markv: lfs_fastvget failed with 35 (ino 11, segment 3728)
lfs_fastvget: ino 11 inlocked by pid 2394
lfs_markv: lfs_fastvget failed with 35 (ino 11, segment 3728)
panic: lfs_vunref: vnode locked
Stopped in lfs_cleanerd at      cpu_Debugger+0x4:       ret     zero,(ra)
db> trace
cpu_Debugger() at cpu_Debugger+0x4
panic() at panic+0xe4
lfs_vunref() at lfs_vunref+0xcc
sys_lfs_bmapv() at sys_lfs_bmapv+0x540
syscall() at syscall+0x1c8
XentSys() at XentSys+0x50
--- syscall (184, netbsd.sys_lfs_bmapv) ---
--- user mode ---
db> ps
 PID             PPID       PGRP        UID S   FLAGS          COMMAND    WAIT
 2425            2395       2395      16073 3  0x4006               rm lfs_dir
 2418             218       2418      16073 3  0x4086              top  select
 2417            2416       2416      16073 3  0x4006              tar lfs_dir
 2416             218       2416      16073 3    0x86             bash    wait
 2415            2414       2414      16073 3  0x4086           bonnie buffers
 2414             218       2414      16073 3    0x86             bash    wait
 2412            2408       2412      16073 3  0x4186           systat   ttyin
 2408            2407       2408      16073 3  0x4086             bash    wait
 2407            2404       2404      16073 3  0x4184            xterm  select
 2404            2402       2404      16073 3  0x4084              csh   pause
 2402             167        167          0 3    0x84            sshd1  select
 2400            2399       2399      16073 2  0x4006              tar
 2399             218       2399      16073 3    0x86             bash    wait
 2398            2397       2397      16073 3  0x4086           bonnie buffers
 2397             218       2397      16073 3    0x86             bash    wait
 2395             218       2395      16073 3    0x86             bash    wait
 2394            2393       2393      16073 2  0x4006           bonnie
 2393             218       2393      16073 3    0x86             bash    wait
*275              274        274          0 7     0x4     lfs_cleanerd
 274                1        274          0 3    0x84     lfs_cleanerd    wait
 219              218        219          0 4  0x5006              csh
 218              217        218      16073 3  0x4086             bash    wait
 217              214        214      16073 3  0x4184            xterm  select
 214              212        214      16073 3  0x4084              csh   pause
 212              167        167          0 3    0x84            sshd1  select
 208                1        208          0 3  0x4086            getty   ttyin
 206                1        206          0 3   0x184             cron nanosle
 202                1        202          0 3    0x84            inetd  select
 190                1        190          0 3    0x84             ntpd   pause
 167                1        167          0 3    0x84            sshd1  select
 127                1        127          0 3    0x84        mount_mfs  mfsidl
 116                1        116          0 3    0x84          rpcbind  select
 104                1        104          0 3    0x84          syslogd  select
 4                  0          0          0 3 0x20204          ioflush  syncer
 3                  0          0          0 3 0x20204           reaper  reaper
 2                  0          0          0 3 0x20204       pagedaemon daemon_
 1                  0          1          0 3  0x4084             init    wait
 0                 -1          0          0 3 0x20204          swapper schedul
db> trace/t 0t2394
trace: pid 2394 at 0xfffffe0005d535c8
mi_switch() at mi_switch+0x190
tsleep() at tsleep+0x2b8
biowait() at biowait+0x78
ufs_bmaparray() at ufs_bmaparray+0x32c
lfs_truncate() at lfs_truncate+0x5e0
ufs_inactive() at ufs_inactive+0xf0
vrele() at vrele+0x104
lfs_segunlock() at lfs_segunlock+0xfc
lfs_segwrite() at lfs_segwrite+0x56c
lfs_flush_fs() at lfs_flush_fs+0x5c
lfs_flush() at lfs_flush+0xc4
lfs_check() at lfs_check+0x194
lfs_balloc() at lfs_balloc+0x84
lfs_write() at lfs_write+0x26c
vn_write() at vn_write+0x154
dofilewrite() at dofilewrite+0xd0
sys_write() at sys_write+0xa0
syscall() at syscall+0x1c8
XentSys() at XentSys+0x50
--- syscall (4, netbsd.sys_write) ---
--- user mode ---

The crash happened after an hour or so of heavy file system activity.  The
system was running three separate instances of 'bonnie -s 1024', as well as
three instances of "tar xf store.tar; rm -rf store".  (The tar file
contains about 1.5GB of files of various sizes).  Every instance of
both bonnie and the tar/rm jobs would be repeated (independently) 5 times.

	
>How-To-Repeat:

Mount a clean LFS file-system.  Then do something similar to:
$ cd /lfs/tmp
$ mkdir tmp1 tmp2 tmp3; cd tmp1
$ for n in 1 2 3 4 5 6; do bonnie -s 1024; done >& bonnie.out&
$ for n in 1 2 3 4 5 6; do tar xf ~/store.tar; rm -rf store; done >& tar.out&
$ cd ../tmp2; sleep 300
$ for n in 1 2 3 4 5 6; do bonnie -s 1024; done >& bonnie.out&
$ for n in 1 2 3 4 5 6; do tar xf ~/store.tar; rm -rf store; done >& tar.out&
$ cd ../tmp3; sleep 300
$ for n in 1 2 3 4 5 6; do bonnie -s 1024; done >& bonnie.out&
$ for n in 1 2 3 4 5 6; do tar xf ~/store.tar; rm -rf store; done >& tar.out&

Grab a cup of coffee and wait for something to happen.

	
>Fix:
	
>Release-Note:
>Audit-Trail:
>Unformatted: