Re: LOR: ufs vs bufwait

On Sat, 08.05.2010 at 12:20:05 +0200, Ulrich Spörlein wrote:
> This LOR also is not yet listed on the LOR page, so I guess it's rather
> new. I do use SUJ.
> 
> lock order reversal:
>  1st 0xc48388d8 ufs (ufs) _at_ /usr/src/sys/kern/vfs_lookup.c:502
>  2nd 0xec0fe304 bufwait (bufwait) _at_ /usr/src/sys/ufs/ffs/ffs_softdep.c:11363
>  3rd 0xc49e56b8 ufs (ufs) _at_ /usr/src/sys/kern/vfs_subr.c:2091
> KDB: stack backtrace:
> db_trace_self_wrapper(c09394fe,fb817308,c062e515,c061e8ab,c093c4f1,...) at db_trace_self_wrapper+0x26
> kdb_backtrace(c061e8ab,c093c4f1,c418b168,c418ef28,fb817364,...) at kdb_backtrace+0x29
> _witness_debugger(c093c4f1,c49e56b8,c092e785,c418ef28,c094369d,...) at _witness_debugger+0x25
> witness_checkorder(c49e56b8,9,c094369d,82b,0,...) at witness_checkorder+0x839
> __lockmgr_args(c49e56b8,80100,c49e56d8,0,0,...) at __lockmgr_args+0x7f9
> ffs_lock(fb817488,c062e2bb,c0942b3f,80100,c49e5660,...) at ffs_lock+0x82
> VOP_LOCK1_APV(c09bd600,fb817488,c4827cd4,c09d62a0,c49e5660,...) at VOP_LOCK1_APV+0xb5
> _vn_lock(c49e5660,80100,c094369d,82b,4,...) at _vn_lock+0x5e
> vget(c49e5660,80100,c4827c30,50,0,...) at vget+0xb9
> vfs_hash_get(c47bea20,b803,80000,c4827c30,fb8175d8,...) at vfs_hash_get+0xe6
> ffs_vgetf(c47bea20,b803,80000,fb8175d8,1,...) at ffs_vgetf+0x49
> softdep_sync_metadata(c4838880,0,c0962957,144,0,...) at softdep_sync_metadata+0xc82
> ffs_syncvnode(c4838880,1,c4827c30,fb817698,246,...) at ffs_syncvnode+0x3e2
> ffs_truncate(c4838880,200,0,880,c41fb480,...) at ffs_truncate+0x862
> ufs_direnter(c4838880,c49e5660,fb81794c,fb817bd4,0,...) at ufs_direnter+0x8d4
> ufs_makeinode(fb817bd4,0,fb817b30,fb817a94,c08e4cf5,...) at ufs_makeinode+0x517
> ufs_create(fb817b30,fb817b48,0,0,fb817ba8,...) at ufs_create+0x30
> VOP_CREATE_APV(c09bd600,fb817b30,2,fb817ac0,0,...) at VOP_CREATE_APV+0xa5
> vn_open_cred(fb817ba8,fb817c5c,1a4,0,c41fb480,...) at vn_open_cred+0x1de
> vn_open(fb817ba8,fb817c5c,1a4,c47e2428,0,...) at vn_open+0x3b
> kern_openat(c4827c30,ffffff9c,804c5e8,0,602,...) at kern_openat+0x125
> kern_open(c4827c30,804c5e8,0,601,21b6,...) at kern_open+0x35
> open(c4827c30,fb817cf8,c0972725,c091f062,c47ea2a8,...) at open+0x30
> syscall(fb817d38) at syscall+0x220
> Xint0x80_syscall() at Xint0x80_syscall+0x20
> --- syscall (5, FreeBSD ELF32, open), eip = 0x2817bf33, esp = 0xbfbfec4c, ebp = 0xbfbfecb8 ---

And now the system is hanging again. While I can still ping and receive
dmesg updates (eg. USB ports appearing), I/O is frozen solid. This is
during portupgrade, when the configure script runs and usually takes 1-2
minutes to provoke.

This part looks supsicious to me:

db> show alllocks
Process 28014 (mkdir) thread 0xc691ac30 (100152)
exclusive lockmgr bufwait (bufwait) r = 0 (0xec2bdaf0) locked _at_ /usr/src/sys/ufs/ffs/ffs_softdep.c:10684
exclusive lockmgr ufs (ufs) r = 0 (0xc6bcd5a8) locked _at_ /usr/src/sys/kern/vfs_subr.c:2091
exclusive lockmgr bufwait (bufwait) r = 0 (0xec2983f4) locked _at_ /usr/src/sys/ufs/ffs/ffs_softdep.c:11363
exclusive lockmgr ufs (ufs) r = 0 (0xc6d976b8) locked _at_ /usr/src/sys/kern/vfs_lookup.c:502
Process 1990 (sshd) thread 0xc5462750 (100117)
exclusive sx so_rcv_sx (so_rcv_sx) r = 0 (0xc546e08c) locked _at_ /usr/src/sys/kern/uipc_sockbuf.c:148
Process 12 (intr) thread 0xc41f4750 (100004)
exclusive sleep mutex ttymtx (ttymtx) r = 0 (0xc425ae04) locked _at_ /usr/src/sys/dev/dcons/dcons_os.c:232
db> 

Uli