Recent VFS locking vs kqueue

Hi, Jeff and -current_at_,

With a fresh -CURRENT kernel (today's source) I got the following
messages from console and /var/log/messages on my laptop, with a "cvs -R
up -PdA 2>/dev/null" running on one console (which results in disk/fs
activities) and "tail -F /var/log/messages" (which uses kqueue events).

The kernel is built with ULE scheduler, PREEMPTION+FULL_PREEMPTION
enabled, and all debugging options, like INVARIANTS and WITESS turned
on.

BTW.  I have found something that can lead to panic: Negative nice
count, which indicates that there are some races in our code, but it
seems that the bug is not easy to exercise.  Will report more
information/patches once I got some findings.

Thanks in advance!

Jun 16 16:44:09 spirit kernel: Acquiring lockmgr lock "ufs" with the
following non-sleepable locks held:
Jun 16 16:44:09 spirit kernel: exclusive sleep mutex kqueue r = 0
(0xc1b60a00) locked _at_ /usr/src/sys/kern/kern_event.c:1524
Jun 16 16:44:09 spirit kernel: exclusive sleep mutex vnode pollinfo r =
0 (0xc2074000) locked _at_ /usr/src/sys/kern/kern_event.c:1512
Jun 16 16:44:09 spirit kernel: KDB: stack backtrace:
Jun 16 16:44:09 spirit kernel:
kdb_backtrace(2,3001,c1a8e29c,c17fdaf0,de75aa08) at kdb_backtrace+0x29
Jun 16 16:44:09 spirit kernel:
witness_warn(5,c06df974,c067daa2,c06867e6) at witness_warn+0x18e
Jun 16 16:44:09 spirit kernel:
lockmgr(c1a8e278,3001,c1a8e29c,c17fdaf0,de75aa34) at lockmgr+0x8d
Jun 16 16:44:09 spirit kernel:
vop_stdlock(de75aa78,c06c8be0,de75aa78,de75aa44,c05ee068) at vop_stdlock
+0x1e
Jun 16 16:44:09 spirit kernel:
VOP_LOCK_APV(c06c92e0,de75aa78,de75aa58,c0653697,de75aa78) at
VOP_LOCK_APV+0x87
Jun 16 16:44:09 spirit kernel:
ffs_lock(de75aa78,1001,c1a8e220,de75aa94,c0576628) at ffs_lock+0x10
Jun 16 16:44:09 spirit kernel: VOP_LOCK_APV(c06c8be0,de75aa78) at
VOP_LOCK_APV+0x87
Jun 16 16:44:09 spirit kernel: vn_lock(c1a8e220,1001,c17fdaf0) at
vn_lock+0xa8
Jun 16 16:44:09 spirit kernel: filt_vfsread(c1ae4c7c,6) at filt_vfsread
+0x3a
Jun 16 16:44:09 spirit kernel: knote(c2074030,6,0) at knote+0x90
Jun 16 16:44:09 spirit kernel: VOP_WRITE_APV(c06c8be0,de75ac40) at
VOP_WRITE_APV+0x18c
Jun 16 16:44:09 spirit kernel:
vn_write(c17c3360,c1e50580,c157bd80,0,c17fdaf0) at vn_write+0x1ea
Jun 16 16:44:09 spirit kernel:
kern_writev(c17fdaf0,9,c1e50580,c1e50580,0) at kern_writev+0x8e
Jun 16 16:44:09 spirit kernel: writev(c17fdaf0,de75ad04,3,43,246) at
writev+0x30
Jun 16 16:44:09 spirit kernel:
syscall(bfbf003b,bfbf003b,bfbf003b,8056cdb,bfbfd5d0) at syscall+0x22f
Jun 16 16:44:09 spirit kernel: Xint0x80_syscall() at Xint0x80_syscall
+0x1f
Jun 16 16:44:09 spirit kernel: --- syscall (121, FreeBSD ELF32, writev),
eip = 0x280c8d4b, esp = 0xbfbfceec, ebp = 0xbfbfd5f8 ---
Jun 16 16:44:09 spirit kernel: Acquiring lockmgr lock "ufs" with the
following non-sleepable locks held:
Jun 16 16:44:09 spirit kernel: exclusive sleep mutex kqueue r = 0
(0xc1b60a00) locked _at_ /usr/src/sys/kern/kern_event.c:1524
Jun 16 16:44:09 spirit kernel: exclusive sleep mutex vnode pollinfo r =
0 (0xc2074000) locked _at_ /usr/src/sys/kern/kern_event.c:1512
Jun 16 16:44:09 spirit kernel: KDB: stack backtrace:
Jun 16 16:44:09 spirit kernel:
kdb_backtrace(2,3001,c1a8e29c,c17fdaf0,de75aa08) at kdb_backtrace+0x29
Jun 16 16:44:09 spirit kernel:
witness_warn(5,c06df974,c067daa2,c06867e6) at witness_warn+0x18e
Jun 16 16:44:09 spirit kernel:
lockmgr(c1a8e278,3001,c1a8e29c,c17fdaf0,de75aa34) at lockmgr+0x8d
Jun 16 16:44:09 spirit kernel:
vop_stdlock(de75aa78,c06c8be0,de75aa78,de75aa44,c05ee068) at vop_stdlock
+0x1e
Jun 16 16:44:09 spirit kernel:
VOP_LOCK_APV(c06c92e0,de75aa78,de75aa58,c0653697,de75aa78) at
VOP_LOCK_APV+0x87
Jun 16 16:44:09 spirit kernel:
ffs_lock(de75aa78,1001,c1a8e220,de75aa94,c0576628) at ffs_lock+0x10
Jun 16 16:44:09 spirit kernel: VOP_LOCK_APV(c06c8be0,de75aa78) at
VOP_LOCK_APV+0x87
Jun 16 16:44:09 spirit kernel: vn_lock(c1a8e220,1001,c17fdaf0) at
vn_lock+0xa8
Jun 16 16:44:09 spirit kernel: filt_vfsread(c1ae4c7c,6) at filt_vfsread
+0x3a
Jun 16 16:44:09 spirit kernel: knote(c2074030,6,0) at knote+0x90
Jun 16 16:44:09 spirit kernel: VOP_WRITE_APV(c06c8be0,de75ac40) at
VOP_WRITE_APV+0x18c
Jun 16 16:44:09 spirit kernel:
vn_write(c17c3360,c1e51480,c157bd80,0,c17fdaf0) at vn_write+0x1ea
Jun 16 16:44:09 spirit kernel:
kern_writev(c17fdaf0,9,c1e51480,c1e51480,0) at kern_writev+0x8e
Jun 16 16:44:09 spirit kernel: writev(c17fdaf0,de75ad04,3,45,246) at
writev+0x30
Jun 16 16:44:09 spirit kernel:
syscall(bfbf003b,bfbf003b,bfbf003b,8056cdb,bfbfd5d0) at syscall+0x22f
Jun 16 16:44:09 spirit kernel: Xint0x80_syscall() at Xint0x80_syscall
+0x1f
Jun 16 16:44:09 spirit kernel: --- syscall (121, FreeBSD ELF32, writev),
eip = 0x280c8d4b, esp = 0xbfbfceec, ebp = 0xbfbfd5f8 ---
Jun 16 16:44:09 spirit kernel: Acquiring lockmgr lock "ufs" with the
following non-sleepable locks held:
Jun 16 16:44:09 spirit kernel: exclusive sleep mutex kqueue r = 0
(0xc1b60a00) locked _at_ /usr/src/sys/kern/kern_event.c:1524
Jun 16 16:44:09 spirit kernel: exclusive sleep mutex vnode pollinfo r =
0 (0xc2074000) locked _at_ /usr/src/sys/kern/kern_event.c:1512
Jun 16 16:44:09 spirit kernel: KDB: stack backtrace:
Jun 16 16:44:09 spirit kernel:
kdb_backtrace(2,3001,c1a8e29c,c17fdaf0,de75aa08) at kdb_backtrace+0x29
Jun 16 16:44:09 spirit kernel:
witness_warn(5,c06df974,c067daa2,c06867e6) at witness_warn+0x18e
Jun 16 16:44:09 spirit kernel:
lockmgr(c1a8e278,3001,c1a8e29c,c17fdaf0,de75aa34) at lockmgr+0x8d
Jun 16 16:44:09 spirit kernel:
vop_stdlock(de75aa78,c06c8be0,de75aa78,de75aa44,c05ee068) at vop_stdlock
+0x1e
Jun 16 16:44:09 spirit kernel:
VOP_LOCK_APV(c06c92e0,de75aa78,de75aa58,c0653697,de75aa78) at
VOP_LOCK_APV+0x87
Jun 16 16:44:09 spirit kernel:
ffs_lock(de75aa78,1001,c1a8e220,de75aa94,c0576628) at ffs_lock+0x10
Jun 16 16:44:09 spirit kernel: VOP_LOCK_APV(c06c8be0,de75aa78) at
VOP_LOCK_APV+0x87
Jun 16 16:44:09 spirit kernel: vn_lock(c1a8e220,1001,c17fdaf0) at
vn_lock+0xa8
Jun 16 16:44:09 spirit kernel: filt_vfsread(c1ae4c7c,6) at filt_vfsread
+0x3a
Jun 16 16:44:09 spirit kernel: knote(c2074030,6,0) at knote+0x90
Jun 16 16:44:09 spirit kernel: VOP_WRITE_APV(c06c8be0,de75ac40) at
VOP_WRITE_APV+0x18c
Jun 16 16:44:09 spirit kernel:
vn_write(c17c3360,c1bafe80,c157bd80,0,c17fdaf0) at vn_write+0x1ea
Jun 16 16:44:09 spirit kernel:
kern_writev(c17fdaf0,9,c1bafe80,c1bafe80,0) at kern_writev+0x8e
Jun 16 16:44:09 spirit kernel: writev(c17fdaf0,de75ad04,3,47,246) at
writev+0x30
Jun 16 16:44:09 spirit kernel:
syscall(bfbf003b,bfbf003b,bfbf003b,8056cdb,bfbfd5d0) at syscall+0x22f
Jun 16 16:44:09 spirit kernel: Xint0x80_syscall() at Xint0x80_syscall
+0x1f
Jun 16 16:44:09 spirit kernel: --- syscall (121, FreeBSD ELF32, writev),
eip = 0x280c8d4b, esp = 0xbfbfceec, ebp = 0xbfbfd5f8 ---

Cheers,
-- 
Xin LI <delphij delphij net>  http://www.delphij.net/