svn commit: r207141 - in head: lib/libufs sbin/dumpfs sbin/fsck_ffs sbin/fsdb sbin/tunefs sys/kern sys/sys sys/ufs/ffs sys/ufs/ufs usr.sbin/makefs/ffs

[Dimitry Andric]

On 2010-04-24 09:05, Jeff Roberson wrote:
> Author: jeff
> Date: Sat Apr 24 07:05:35 2010
> New Revision: 207141
> URL: http://svn.freebsd.org/changeset/base/207141
> 
> Log:
>    - Merge soft-updates journaling from projects/suj/head into head.  This
>      brings in support for an optional intent log which eliminates the need
>      for background fsck on unclean shutdown.

Hi Jeff,

Sorry that I am a bit late in checking this out, but my -CURRENT box was
nice and stable, and only now did I update it.  I found out that this
specific commit has caused softupdates to become unstable for me.

That is, when running a specific set of commands (just building the bash
port), I get a few LORs involving softupdates; first this one:

lock order reversal:
 1st 0xe41e9ee4 bufwait (bufwait) @ /usr/src/sys/kern/vfs_bio.c:2581
 2nd 0xc4e59a00 dirhash (dirhash) @ /usr/src/sys/ufs/ufs/ufs_dirhash.c:283
KDB: stack backtrace:
db_trace_self_wrapper(c0cc05e4,f32287bc,c08e7c55,c08d7fcb,c0cc35be,...) at db_trace_self_wrapper+0x26
kdb_backtrace(c08d7fcb,c0cc35be,c4122fc8,c41263c8,f3228818,...) at kdb_backtrace+0x29
_witness_debugger(c0cc35be,c4e59a00,c0ce70a0,c41263c8,c0ce6d25,...) at _witness_debugger+0x25
witness_checkorder(c4e59a00,9,c0ce6d25,11b,0,...) at witness_checkorder+0x839
_sx_xlock(c4e59a00,0,c0ce6d25,11b,c4fc01d0,...) at _sx_xlock+0x85
ufsdirhash_acquire(e41e9e84,e74f4800,200,e74f4818,f32288e8,...) at ufsdirhash_acquire+0x35
ufsdirhash_add(c4fc01d0,f3228944,818,f32288d4,f32288d8,...) at ufsdirhash_add+0x13
ufs_direnter(c4fc2660,c4fdebb0,f3228944,f3228bd4,0,...) at ufs_direnter+0x6f9
ufs_makeinode(f3228bd4,0,f3228b30,f3228a8c,c0bfc9f5,...) at ufs_makeinode+0x557
ufs_create(f3228b30,f3228b48,0,0,f3228ba8,...) at ufs_create+0x30
VOP_CREATE_APV(c0dcde00,f3228b30,f3228bd4,f3228ac8,0,...) at VOP_CREATE_APV+0xa5
vn_open_cred(f3228ba8,f3228c5c,1a4,0,c4ccf900,...) at vn_open_cred+0x215
vn_open(f3228ba8,f3228c5c,1a4,c4d22188,0,...) at vn_open+0x3b
kern_openat(c4e55900,ffffff9c,28415180,0,a02,...) at kern_openat+0x125
kern_open(c4e55900,28415180,0,a01,1a4,...) at kern_open+0x35
open(c4e55900,f3228cf8,c0cf8fe1,c0cc3e0e,c4e4daa0,...) at open+0x30
syscall(f3228d38) at syscall+0x220
Xint0x80_syscall() at Xint0x80_syscall+0x20
--- syscall (5, FreeBSD ELF32, open), eip = 0x283685e3, esp = 0xbfbfe6fc, ebp = 0xbfbfe728 ---

Then the next one:

 lock order reversal:
 1st 0xc4eb3c08 ufs (ufs) @ /usr/src/sys/kern/vfs_lookup.c:502
 2nd 0xe415b130 bufwait (bufwait) @ /usr/src/sys/ufs/ffs/ffs_softdep.c:11189
 3rd 0xc50778d8 ufs (ufs) @ /usr/src/sys/kern/vfs_subr.c:2091
KDB: stack backtrace:
db_trace_self_wrapper(c0cc05e4,f3225300,c08e7c55,c08d7fcb,c0cc35d7,...) at db_trace_self_wrapper+0x26
kdb_backtrace(c08d7fcb,c0cc35d7,c4122fc8,c4126360,f322535c,...) at kdb_backtrace+0x29
_witness_debugger(c0cc35d7,c50778d8,c0cb5991,c4126360,c0cca6ba,...) at _witness_debugger+0x25
witness_checkorder(c50778d8,9,c0cca6ba,82b,0,...) at witness_checkorder+0x839
__lockmgr_args(c50778d8,80100,c50778f8,0,0,...) at __lockmgr_args+0x7f9
ffs_lock(f3225480,c08e79fb,c0cc9b5f,80100,c5077880,...) at ffs_lock+0x8a
VOP_LOCK1_APV(c0dcde00,f3225480,c4e55be4,c0de87a0,c5077880,...) at VOP_LOCK1_APV+0xb5
_vn_lock(c5077880,80100,c0cca6ba,82b,4,...) at _vn_lock+0x5e
vget(c5077880,80100,c4e55b40,50,0,...) at vget+0xb9
vfs_hash_get(c4ac8ca8,1a9e03,80000,c4e55b40,f32255d0,...) at vfs_hash_get+0xe6
ffs_vgetf(c4ac8ca8,1a9e03,80000,f32255d0,1,...) at ffs_vgetf+0x49
softdep_sync_metadata(c4eb3bb0,0,c0ce68d1,147,0,...) at softdep_sync_metadata+0xc92
ffs_syncvnode(c4eb3bb0,1,c4e55b40,f3225690,246,...) at ffs_syncvnode+0x3e2
ffs_truncate(c4eb3bb0,a00,0,880,c4ccf900,...) at ffs_truncate+0x862
ufs_direnter(c4eb3bb0,c5111bb0,f3225944,f3225bd4,0,...) at ufs_direnter+0x8d4
ufs_makeinode(f3225bd4,0,f3225b30,f3225a8c,c0bfc9f5,...) at ufs_makeinode+0x557
ufs_create(f3225b30,f3225b48,0,0,f3225ba8,...) at ufs_create+0x30
VOP_CREATE_APV(c0dcde00,f3225b30,f3225bd4,f3225ac8,0,...) at VOP_CREATE_APV+0xa5
vn_open_cred(f3225ba8,f3225c5c,1a4,0,c4ccf900,...) at vn_open_cred+0x215
vn_open(f3225ba8,f3225c5c,1a4,c4d22348,28411000,...) at vn_open+0x3b
kern_openat(c4e55b40,ffffff9c,28409ad4,0,602,...) at kern_openat+0x125
kern_open(c4e55b40,28409ad4,0,601,1b6,...) at kern_open+0x35
open(c4e55b40,f3225cf8,c,c4e55b40,c4e4dd48,...) at open+0x30
syscall(f3225d38) at syscall+0x220
Xint0x80_syscall() at Xint0x80_syscall+0x20
--- syscall (5, FreeBSD ELF32, open), eip = 0x281e15e3, esp = 0xbfbfe2cc, ebp = 0xbfbfe388 ---

And soon after that second one, the system will just stop reacting to
any keyboard input, or on any ssh sessions.  It can still be ping'd,
though, so something is definitely alive, but it is totally unusable.

Is there any possibility of finding out whether there's a real deadlock
going on?  I can access ddb since it's a virtual machine.

Btw, I ended up on r207141 by bisecting; r207139 works perfectly stable,
r207141 will always hang up after a certain amount of time.  I realize
that r207141 was a merge from a project branch, so maybe I can try to
bisect in that branch, to see if I can pinpoint a specific change that
causes this breakage?