Subject: kern/10196: panic: softdep_disk_write_complete: lock is held
To: None <gnats-bugs@gnats.netbsd.org>
From: None <smd@ebone.net>
List: netbsd-bugs
Date: 05/24/2000 14:35:14
>Number: 10196
>Category: kern
>Synopsis: frequent panic during make build on SOFTDEP-enabled system
>Confidential: yes
>Severity: critical
>Priority: high
>Responsible: kern-bug-people
>State: open
>Class: sw-bug
>Submitter-Id: net
>Arrival-Date: Wed May 24 14:36:01 PDT 2000
>Closed-Date:
>Last-Modified:
>Originator: Sean Doran
>Release: cvs update 2000 05 24
>Organization:
Sean Doran <smd@ebone.net>
Development Manager, Ebone Inc., Copenhagen Denmark
>Environment:
System: NetBSD sean.ebone.net 1.4Y NetBSD 1.4Y (EBONE) #6: Wed May 24 21:41:20 CEST 2000 root@:/usr/src/sys/arch/i386/compile/EBONE i386
and also many other -current -i386 kernels with SOFTDEP
>Description:
Is it interesting that lk.lkt_held is 23928 (runnable) but that
23929 is in biowait?
panic: softdep_disk_write_complete: lock is held
n mii_media_table ()
#1 0x96f6000 in ?? ()
#2 0xc01c35db in cpu_reboot (howto=260, bootstr=0x0)
at ../../../../arch/i386/i386/machdep.c:1116
#3 0xc0148541 in panic () at ../../../../kern/subr_prf.c:218
#4 0xc0219d26 in softdep_fsync_mountdev (vp=0xd9988418)
at ../../../../../gnu/sys/ufs/ffs/ffs_softdep.c:246
#5 0xc01a44d4 in ffs_fsync (v=0xd9c7cc3c)
at ../../../../ufs/ffs/ffs_vnops.c:257
#6 0xc01a340d in ffs_sync (mp=0xc07f0800, waitfor=2, cred=0xc075af80,
p=0xc02933a0) at ../../../../sys/vnode_if.h:449
#7 0xc016a20d in sys_sync (p=0xc02933a0, v=0x0, retval=0x0)
at ../../../../kern/vfs_syscalls.c:571
#8 0xc0164b39 in vfs_shutdown () at ../../../../kern/vfs_subr.c:2292
#9 0xc01c35b3 in cpu_reboot (howto=256, bootstr=0x0)
at ../../../../arch/i386/i386/machdep.c:1103
#10 0xc0148541 in panic () at ../../../../kern/subr_prf.c:218
#11 0xc02184e8 in softdep_disk_write_complete (bp=0xc5af66c0)
at ../../../../../gnu/sys/ufs/ffs/ffs_softdep.c:3069
#12 0xc015ed4f in biodone (bp=0xc5af66c0) at ../../../../kern/vfs_bio.c:954
#13 0xc01cb5de in scsipi_done (xs=0xc07a72e4)
at ../../../../dev/scsipi/scsipi_base.c:669
#14 0xc0107795 in ahc_done (ahc=0xc0788600, scb=0xc07923c0)
at ../../../../dev/ic/aic7xxx.c:3438
#15 0xc0103025 in ahc_run_qoutfifo (ahc=0xc0788600)
at ../../../../dev/ic/aic7xxx.c:575
#16 0xc0104042 in ahc_intr (arg=0xc0788600)
at ../../../../dev/ic/aic7xxx.c:1528
#17 0xc0101aa4 in Xintr15 ()
(gdb) frame 11
#11 0xc02184e8 in softdep_disk_write_complete (bp=0xc5af66c0)
at ../../../../../gnu/sys/ufs/ffs/ffs_softdep.c:3069
3069 panic("softdep_disk_write_complete: lock is held");
(gdb) list
3064 struct inodedep *inodedep;
3065 struct bmsafemap *bmsafemap;
3066
3067 #ifdef DEBUG
3068 if (lk.lkt_held != -1)
3069 panic("softdep_disk_write_complete: lock is held");
3070 lk.lkt_held = -2;
3071 #endif
3072 LIST_INIT(&reattach);
3073 while ((wk = LIST_FIRST(&bp->b_dep)) != NULL) {
(gdb) print lk
$1 = {lkt_spl = 0, lkt_held = 23928}
PID TT STAT TIME COMMAND
23928 p1 R 0:00.00 (mkdir)
sean# ps -l -p 23928 -N netbsd.2 -M netbsd.2.core
UID PID PPID CPU PRI NI VSZ RSS WCHAN STAT TT TIME COMMAND
0 23928 3 32 60 0 108 0 - R p1 0:00.00 (mkdir)
sean# ^-l^-v
ps -v -p 23928 -N netbsd.2 -M netbsd.2.core
PID STAT TIME SL RE PAGEIN VSZ RSS LIM TSIZ %CPU %MEM COMMAND
23928 R 0:00.00 0 1 0 108 0 - 60 0.0 0.0 (mkdir)
sean# ^-v^-uww
ps -uww -p 23928 -N netbsd.2 -M netbsd.2.core
USER PID %CPU %MEM VSZ RSS TT STAT STARTED TIME COMMAND
root 23928 0.0 0.0 108 0 p1 R 10:38PM 0:00.00 (mkdir)
UID PID PPID CPU PRI NI VSZ RSS WCHAN STAT TT TIME COMMAND
0 0 3 0 -18 0 0 0 schedu DLs ?? 0:00.00 swapper
0 1 3 30 10 0 324 0 wait Is ?? 0:00.01 init
0 2 3 0 -18 0 0 0 daemon DL ?? 0:00.00 pagedaemon
0 3 3 0 -18 0 0 0 reaper DL ?? 0:00.85 reaper
0 4 3 0 18 0 0 0 syncer DL ?? 0:00.70 ioflush
0 72 3 0 2 0 132 0 select Is ?? 0:00.05 syslogd
0 75 3 0 2 0 1312 0 select Ss ?? 0:00.15 named
0 90 3 0 10 0 256484 0 - Rs ?? 0:00.05 mount_mfs
0 111 3 0 10 0 236 0 nanosl Is ?? 0:00.01 cron
0 113 3 0 18 -12 688 0 pause S<s ?? 0:00.16 ntpd
0 115 3 0 2 0 128 0 select Is ?? 0:00.01 lpd
0 118 3 0 2 0 100 0 select Is ?? 0:00.00 inetd
0 150 3 0 2 0 152 0 select Is ?? 0:00.04 master
9910 152 3 0 2 0 172 0 select I ?? 0:00.02 pickup
9910 153 3 0 2 0 192 0 select I ?? 0:00.03 qmgr
9910 156 3 0 2 0 164 0 select I ?? 0:00.02 trivial-rewri
0 157 3 0 2 0 256 0 select Is ?? 0:00.33 sshd1
1113 195 3 0 2 0 156 0 select Ss ?? 0:00.01 ssh-agent1
0 197 3 6 2 0 10340 0 select S ?? 0:07.58 XFree86
0 14975 3 0 2 0 376 0 select S ?? 0:00.18 sshd1
0 22813 3 26 54 0 492 0 - Z ?? 0:00.00 junkbuster
0 22814 3 30 58 0 712 0 - Z ?? 0:00.00 junkbuster
1113 203 3 0 2 0 1060 0 select Is+ p0 0:00.75 gwm
0 248 3 0 2 0 524 0 select I+ p0 0:00.07 xterm
1113 219 3 2 10 0 460 0 wait Is p1 0:00.02 es
0 222 3 5 18 0 464 0 pause S p1 0:00.04 csh
0 22815 3 4 2 0 452 0 select S+ p1 0:00.09 make
0 22819 3 24 10 0 492 0 wait S p1 0:00.00 sh
0 22820 3 32 10 0 712 0 wait S p1 0:00.15 make
0 22823 3 24 10 0 492 0 wait S p1 0:00.00 sh
0 22825 3 32 10 0 556 0 wait S p1 0:00.11 make
0 22826 3 24 10 0 492 0 wait S p1 0:00.00 sh
0 22828 3 32 10 0 664 0 wait S p1 0:00.15 make
0 22829 3 24 10 0 492 0 wait S p1 0:00.00 sh
0 22831 3 32 10 0 1020 0 wait S p1 0:00.26 make
0 22832 3 24 10 0 492 0 wait S p1 0:00.00 sh
0 22833 3 32 10 0 2284 0 wait S p1 0:00.66 make
0 22834 3 24 10 0 492 0 wait S p1 0:00.00 sh
0 22837 3 31 10 0 2516 0 wait S p1 0:01.06 make
0 22838 3 24 10 0 492 0 wait S p1 0:00.00 sh
0 22839 3 29 10 0 376 0 wait S p1 0:00.06 make
0 22840 3 24 10 0 492 0 wait S p1 0:00.00 sh
0 22843 3 32 10 0 504 0 wait S p1 0:00.09 make
0 22844 3 24 10 0 492 0 wait S p1 0:00.00 sh
0 22847 3 29 10 0 280 0 wait S p1 0:00.03 make
0 22865 3 24 10 0 492 0 wait S p1 0:00.00 sh
0 22945 3 32 10 0 688 0 wait S p1 0:00.17 make
0 22996 3 29 10 0 488 0 wait S p1 0:00.00 sh
0 22997 3 32 10 0 420 0 wait S p1 0:00.07 make
0 23043 3 29 10 0 488 0 wait S p1 0:00.00 sh
0 23044 3 32 10 0 336 0 wait S p1 0:00.04 make
0 23135 3 31 10 0 488 0 wait S p1 0:00.00 sh
0 23138 3 32 10 0 352 0 wait S p1 0:00.05 make
0 23548 3 32 10 0 488 0 wait S p1 0:00.00 sh
0 23549 3 32 10 0 1096 0 wait S p1 0:00.32 make
0 23686 3 32 10 0 488 0 wait S p1 0:00.00 sh
0 23687 3 32 10 0 328 0 wait S p1 0:00.04 make
0 23727 3 32 10 0 488 0 wait S p1 0:00.00 sh
0 23728 3 32 10 0 496 0 wait S p1 0:00.08 make
0 23815 3 32 10 0 488 0 wait S p1 0:00.00 sh
0 23824 3 32 10 0 488 0 wait S p1 0:00.02 sh
0 23826 3 32 10 0 488 0 wait S p1 0:00.00 sh
0 23827 3 32 10 0 300 0 wait S p1 0:00.03 make
0 23828 3 32 10 0 280 0 wait S p1 0:00.02 make
0 23837 3 32 10 0 308 0 wait S p1 0:00.03 make
0 23839 3 32 10 0 488 0 wait S p1 0:00.00 sh
0 23846 3 32 10 0 308 0 wait S p1 0:00.03 make
0 23852 3 32 60 0 492 0 - R p1 0:00.02 sh
0 23866 3 32 10 0 488 0 wait S p1 0:00.00 sh
0 23867 3 32 10 0 308 0 wait S p1 0:00.03 make
0 23871 3 32 10 0 492 0 wait S p1 0:00.00 sh
0 23872 3 32 10 0 492 0 wait S p1 0:00.00 sh
0 23877 3 32 10 0 492 0 wait S p1 0:00.01 sh
0 23892 3 32 10 0 488 0 wait S p1 0:00.00 sh
0 23893 3 32 10 0 292 0 wait S p1 0:00.02 make
0 23894 3 32 10 0 488 0 wait S p1 0:00.00 sh
0 23918 3 32 60 0 144 0 - R p1 0:00.00 make
0 23922 3 32 60 0 480 0 - R p1 0:00.00 sh
0 23927 3 32 60 0 80 0 - R p1 0:00.00 mkdir
0 23928 3 32 60 0 108 0 - R p1 0:00.00 mkdir
0 23929 3 32 -5 0 108 0 biowai D p1 0:00.00 mkdir
0 23930 3 32 10 0 488 0 wait S p1 0:00.00 sh
0 23931 3 32 10 0 308 0 wait S p1 0:00.03 make
0 23932 3 32 60 0 468 0 - R p1 0:00.00 sh
0 23933 3 32 10 0 488 0 wait S p1 0:00.00 sh
0 23934 3 32 10 0 308 0 wait S p1 0:00.03 make
0 23935 3 32 10 0 488 0 wait S p1 0:00.00 sh
0 23936 3 32 60 0 488 0 - R p1 0:00.00 sh
0 23937 3 32 60 0 468 0 - R p1 0:00.00 sh
0 23938 3 32 60 0 116 0 - R p1 0:00.00 make
1113 220 3 0 10 0 460 0 wait Is p2 0:00.02 es
0 231 3 32 3 0 456 0 ttyin I+ p2 0:00.03 csh
1113 221 3 0 10 0 460 0 wait Is p3 0:00.02 es
0 224 3 2 3 0 464 0 ttyin I+ p3 0:00.03 csh
0 458 3 7 2 4 108 0 netio TN p3 0:01.77 cat
0 467 3 27 55 0 44 0 - T p3 0:08.13 tr
1113 250 3 0 3 0 460 0 ttyin Is+ p5 0:00.02 es
1113 15010 3 0 3 0 548 0 ttyin Is+ p6 0:00.03 es
0 170 3 19 10 0 500 0 wait I E0- 0:00.00 sh
0 172 3 8 76 20 632 0 - RN E0- 5:49.02 rc5des
0 178 3 30 2 0 264 0 netcon S E0- 0:00.12 junkbuster
0 180 3 0 10 0 220 0 wait Is E0 0:00.04 login
1113 185 3 2 10 0 496 0 wait I+ E0 0:00.03 es
1113 194 3 2 10 0 488 0 wait I+ E0 0:00.01 sh
1113 196 3 0 10 0 64 0 wait I+ E0 0:00.02 xinit
1113 200 3 5 10 0 488 0 wait I E0 0:00.01 sh
0 202 3 0 2 0 524 0 select I E0 0:00.09 xterm
1113 204 3 0 2 0 124 0 select I E0 0:00.04 xclock
1113 205 3 0 2 0 136 0 select S E0 0:00.05 xbiff
1113 213 3 0 2 0 584 0 select S E0 0:00.15 xwrits
1113 214 3 0 2 0 236 0 select I E0 0:00.06 xconsole
0 215 3 0 2 0 524 0 select I E0 0:00.15 xterm
0 216 3 0 2 0 524 0 select I E0 0:00.38 xterm
0 217 3 0 2 0 524 0 select S E0 0:01.33 xterm
1113 218 3 0 2 0 124 0 select S E0 0:01.50 xeyes
0 181 3 10 3 0 52 0 ttyin Is+ E1 0:00.01 getty
0 182 3 10 3 0 52 0 ttyin Is+ E2 0:00.01 getty
0 183 3 10 3 0 52 0 ttyin Is+ E3 0:00.01 getty
0 184 3 10 3 0 52 0 ttyin Is+ E4 0:00.01 getty
>How-To-Repeat:
options SOFTDEP kernel
make build
it is always this panic. the time-to-panic varies heavily,
but the panic itself is nearly reliably reproducible.
this is the best core + kernel obtained to date.
>Fix:
>Release-Note:
>Audit-Trail:
>Unformatted: