Reboot Loop: ffs_snapshot/bufwait LORs [Was: Re: 8.0-RELEASE hangs with lighttpd, unionfs related? Some traces included]

Harald Schmalzbauer h.schmalzbauer at omnilan.de
Fri Feb 5 11:50:02 UTC 2010


Harald Schmalzbauer schrieb am 05.02.2010 12:39 (localtime):
> Harald Schmalzbauer schrieb am 05.02.2010 12:31 (localtime):
...
> 
> Additional LORs while regular machine operation (background fsck) which 
> leads to reboot!
> I have access over the serail console, but the machine is unresponsive 
> after that. So I'm now in a endelss reboot loop with the debug kernel...
> 
> lock order reversal:
>  1st 0xffffff0001b899d0 ufs (ufs) @ /usr/src/sys/ufs/ffs/ffs_snapshot.c:423
>  2nd 0xffffff802970fc28 bufwait (bufwait) @ 
> /usr/src/sys/kern/vfs_bio.c:2559
>  3rd 0xffffff00018b4448 ufs (ufs) @ /usr/src/sys/ufs/ffs/ffs_snapshot.c:544
> KDB: stack backtrace:
> db_trace_self_wrapper() at db_trace_self_wrapper+0x2a
> _witness_debugger() at _witness_debugger+0x49
> witness_checkorder() at witness_checkorder+0x7ea
> __lockmgr_args() at __lockmgr_args+0xcbd
> ffs_lock() at ffs_lock+0x8c
> VOP_LOCK1_APV() at VOP_LOCK1_APV+0x9b
> _vn_lock() at _vn_lock+0x50
> ffs_snapshot() at ffs_snapshot+0x1b70
> ffs_mount() at ffs_mount+0x651
> vfs_donmount() at vfs_donmount+0xcd4
> nmount() at nmount+0x74
> syscall() at syscall+0x1af
> Xfast_syscall() at Xfast_syscall+0xe1
> --- syscall (378, FreeBSD ELF64, nmount), rip = 0x8007acfec, rsp = 
> 0x7fffffffe988, rbp = 0x800a028e-
> KDB: enter: witness_checkorder
> [thread pid 947 tid 100073 ]
> Stopped at      kdb_enter+0x3d: movq    $0,0x4c04dc(%rip)
> db> lock order reversal:
>  1st 0xffffff00018b4470 vnode interlock (vnode interlock) @ 
> /usr/src/sys/ufs/ffs/ffs_snapshot.c:523
>  2nd 0xffffff8000422028 uhci2 (uhci2) @ 
> /usr/src/sys/dev/usb/controller/uhci.c:1551
> KDB: stack backtrace:
> db_trace_self_wrapper() at db_trace_self_wrapper+0x2a
> _witness_debugger() at _witness_debugger+0x49
> witness_checkorder() at witness_checkorder+0x7ea
> _mtx_lock_flags() at _mtx_lock_flags+0x68
> uhci_do_poll() at uhci_do_poll+0x2e
> usbd_transfer_poll() at usbd_transfer_poll+0x18d
> ukbd_do_poll() at ukbd_do_poll+0x63
> ukbd_get_key() at ukbd_get_key+0xa8
> ukbd_read_char() at ukbd_read_char+0xaa
> scgetc() at scgetc+0x5b
> sc_cngetc() at sc_cngetc+0xf2
> cncheckc() at cncheckc+0x65
> cngetc() at cngetc+0x1c
> db_readline() at db_readline+0x79
> db_read_line() at db_read_line+0x15
> db_command_loop() at db_command_loop+0x38
> db_trap() at db_trap+0x87
> kdb_trap() at kdb_trap+0x82
> trap() at trap+0x18f
> calltrap() at calltrap+0x8
> --- trap 0x3, rip = 0xffffffff80381141, rsp = 0xffffff803e959000, rbp = 
> 0xffffff803e959020 ---
> kdb_enter() at kdb_enter+0x3d
> witness_checkorder() at witness_checkorder+0x7ea
> __lockmgr_args() at __lockmgr_args+0xcbd
> ffs_lock() at ffs_lock+0x8c
> VOP_LOCK1_APV() at VOP_LOCK1_APV+0x9b
> _vn_lock() at _vn_lock+0x50
> ffs_snapshot() at ffs_snapshot+0x1b70
> ffs_mount() at ffs_mount+0x651
> vfs_donmount() at vfs_donmount+0xcd4
> nmount() at nmount+0x74
> syscall() at syscall+0x1af
> Xfast_syscall() at Xfast_syscall+0xe1
> --- syscall (378, FreeBSD ELF64, nmount), rip = 0x8007acfec, rsp = 
> 0x7fffffffe988, rbp = 0x800a028e-
> lock order reversal:
>  1st 0xffffff00018b4470 vnode interlock (vnode interlock) @ 
> /usr/src/sys/ufs/ffs/ffs_snapshot.c:523
>  2nd 0xffffff0001747890 USB device mutex (USB device mutex) @ 
> /usr/src/sys/dev/usb/usb_device.c:1410
> KDB: stack backtrace:
> db_trace_self_wrapper() at db_trace_self_wrapper+0x2a
> _witness_debugger() at _witness_debugger+0x49
> witness_checkorder() at witness_checkorder+0x7ea
> _mtx_lock_flags() at _mtx_lock_flags+0x68
> usbd_clear_stall_proc() at usbd_clear_stall_proc+0x49
> usbd_transfer_poll() at usbd_transfer_poll+0x1c0
> ukbd_do_poll() at ukbd_do_poll+0x63
> ukbd_get_key() at ukbd_get_key+0xa8
> ukbd_read_char() at ukbd_read_char+0xaa
> scgetc() at scgetc+0x5b
> sc_cngetc() at sc_cngetc+0xf2
> cncheckc() at cncheckc+0x65
> cngetc() at cngetc+0x1c
> db_readline() at db_readline+0x79
> db_read_line() at db_read_line+0x15
> db_command_loop() at db_command_loop+0x38
> db_trap() at db_trap+0x87
> kdb_trap() at kdb_trap+0x82
> trap() at trap+0x18f
> calltrap() at calltrap+0x8
> --- trap 0x3, rip = 0xffffffff80381141, rsp = 0xffffff803e959000, rbp = 
> 0xffffff803e959020 ---
> kdb_enter() at kdb_enter+0x3d
> witness_checkorder() at witness_checkorder+0x7ea
> __lockmgr_args() at __lockmgr_args+0xcbd
> ffs_lock() at ffs_lock+0x8c
> VOP_LOCK1_APV() at VOP_LOCK1_APV+0x9b
> _vn_lock() at _vn_lock+0x50
> ffs_snapshot() at ffs_snapshot+0x1b70
> ffs_mount() at ffs_mount+0x651
> vfs_donmount() at vfs_donmount+0xcd4
> nmount() at nmount+0x74
> syscall() at syscall+0x1af
> Xfast_syscall() at Xfast_syscall+0xe1
> --- syscall (378, FreeBSD ELF64, nmount), rip = 0x8007acfec, rsp = 
> 0x7fffffffe988, rbp = 0x800a028e-
> lock order reversal: (Giant after non-sleepable)
>  1st 0xffffff00018b4470 vnode interlock (vnode interlock) @ 
> /usr/src/sys/ufs/ffs/ffs_snapshot.c:523
>  2nd 0xffffffff80820780 Giant (Giant) @ 
> /usr/src/sys/dev/usb/usb_transfer.c:1952
> KDB: stack backtrace:
> db_trace_self_wrapper() at db_trace_self_wrapper+0x2a
> _witness_debugger() at _witness_debugger+0x49
> witness_checkorder() at witness_checkorder+0x7ea
> _mtx_lock_flags() at _mtx_lock_flags+0x68
> usb_callback_proc() at usb_callback_proc+0x48
> usbd_transfer_poll() at usbd_transfer_poll+0x1e9
> ukbd_do_poll() at ukbd_do_poll+0x63
> ukbd_get_key() at ukbd_get_key+0xa8
> ukbd_read_char() at ukbd_read_char+0xaa
> scgetc() at scgetc+0x5b
> sc_cngetc() at sc_cngetc+0xf2
> cncheckc() at cncheckc+0x65
> cngetc() at cngetc+0x1c
> db_readline() at db_readline+0x79
> db_read_line() at db_read_line+0x15
> db_command_loop() at db_command_loop+0x38
> db_trap() at db_trap+0x87
> kdb_trap() at kdb_trap+0x82
> trap() at trap+0x18f
> calltrap() at calltrap+0x8
> --- trap 0x3, rip = 0xffffffff80381141, rsp = 0xffffff803e959000, rbp = 
> 0xffffff803e959020 ---
> kdb_enter() at kdb_enter+0x3d
> witness_checkorder() at witness_checkorder+0x7ea
> __lockmgr_args() at __lockmgr_args+0xcbd
> ffs_lock() at ffs_lock+0x8c
> VOP_LOCK1_APV() at VOP_LOCK1_APV+0x9b
> _vn_lock() at _vn_lock+0x50
> ffs_snapshot() at ffs_snapshot+0x1b70
> ffs_mount() at ffs_mount+0x651
> vfs_donmount() at vfs_donmount+0xcd4
> nmount() at nmount+0x74
> syscall() at syscall+0x1af
> Xfast_syscall() at Xfast_syscall+0xe1
> --- syscall (378, FreeBSD ELF64, nmount), rip = 0x8007acfec, rsp = 
> 0x7fffffffe988, rbp = 0x800a028e-
> 
> lock order reversal:
>  1st 0xffffff802970fc28 bufwait (bufwait) @ 
> /usr/src/sys/kern/vfs_bio.c:2559
>  2nd 0xffffff00440ef6b0 snaplk (snaplk) @ 
> /usr/src/sys/ufs/ffs/ffs_snapshot.c:793
> KDB: stack backtrace:
> db_trace_self_wrapper() at db_trace_self_wrapper+0x2a
> _witness_debugger() at _witness_debugger+0x49
> witness_checkorder() at witness_checkorder+0x7ea
> __lockmgr_args() at __lockmgr_args+0xcbd
> ffs_lock() at ffs_lock+0x8c
> VOP_LOCK1_APV() at VOP_LOCK1_APV+0x9b
> _vn_lock() at _vn_lock+0x50
> ffs_snapshot() at ffs_snapshot+0x17d7
> ffs_mount() at ffs_mount+0x651
> vfs_donmount() at vfs_donmount+0xcd4
> nmount() at nmount+0x74
> syscall() at syscall+0x1af
> Xfast_syscall() at Xfast_syscall+0xe1
> --- syscall (378, FreeBSD ELF64, nmount), rip = 0x8007acfec, rsp = 
> 0x7fffffffe988, rbp = 0x800a028e-
> KDB: enter: witness_checkorder
> [thread pid 947 tid 100073 ]
> Stopped at      kdb_enter+0x3d: movq    $0,0x4c04dc(%rip)

Sorry, it was my watchdog who restarted the machine.
Here's the trace I coudl get:

Tracing pid 918 tid 100072 td 0xffffff0001816390
kdb_enter() at kdb_enter+0x3d
witness_checkorder() at witness_checkorder+0x7ea
__lockmgr_args() at __lockmgr_args+0xcbd
ffs_lock() at ffs_lock+0x8c
VOP_LOCK1_APV() at VOP_LOCK1_APV+0x9b
_vn_lock() at _vn_lock+0x50
ffs_snapshot() at ffs_snapshot+0x1b70
ffs_mount() at ffs_mount+0x651
vfs_donmount() at vfs_donmount+0xcd4
nmount() at nmount+0x74
syscall() at syscall+0x1af
Xfast_syscall() at Xfast_syscall+0xe1
--- syscall (378, FreeBSD ELF64, nmount), rip = 0x8007acfec, rsp = 
0x7fffffffe988, rbp = 0x800a028e-

========================================
And another LOR after cont:

lock order reversal:
  1st 0xffffff0001e40d30 snaplk (snaplk) @ /usr/src/sys/kern/vfs_vnops.c:296
  2nd 0xffffff00018a49d0 ufs (ufs) @ 
/usr/src/sys/ufs/ffs/ffs_snapshot.c:1587
KDB: stack backtrace:
db_trace_self_wrapper() at db_trace_self_wrapper+0x2a
_witness_debugger() at _witness_debugger+0x49
witness_checkorder() at witness_checkorder+0x7ea
__lockmgr_args() at __lockmgr_args+0xcbd
ffs_snapremove() at ffs_snapremove+0xe2
softdep_releasefile() at softdep_releasefile+0x133
ufs_inactive() at ufs_inactive+0x185
vinactive() at vinactive+0x6b
vput() at vput+0x216
vn_close() at vn_close+0x10b
vn_closefile() at vn_closefile+0x51
_fdrop() at _fdrop+0x20
closef() at closef+0x58
kern_close() at kern_close+0xff
syscall() at syscall+0x1af
Xfast_syscall() at Xfast_syscall+0xe1
--- syscall (6, FreeBSD ELF64, close), rip = 0x8008435ec, rsp = 
0x7fffffffe988, rbp = 0 ---
KDB: enter: witness_checkorder
[thread pid 914 tid 100080 ]
Stopped at      kdb_enter+0x3d: movq    $0,0x4c04dc(%rip)
db> trace
Tracing pid 914 tid 100080 td 0xffffff000186dab0
kdb_enter() at kdb_enter+0x3d
witness_checkorder() at witness_checkorder+0x7ea
__lockmgr_args() at __lockmgr_args+0xcbd
ffs_snapremove() at ffs_snapremove+0xe2
softdep_releasefile() at softdep_releasefile+0x133
ufs_inactive() at ufs_inactive+0x185
vinactive() at vinactive+0x6b
vput() at vput+0x216
vn_close() at vn_close+0x10b
vn_closefile() at vn_closefile+0x51
_fdrop() at _fdrop+0x20
closef() at closef+0x58
kern_close() at kern_close+0xff
syscall() at syscall+0x1af
Xfast_syscall() at Xfast_syscall+0xe1
--- syscall (6, FreeBSD ELF64, close), rip = 0x8008435ec, rsp = 
0x7fffffffe988, rbp = 0 ---

Thanks,

-Harry

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 196 bytes
Desc: OpenPGP digital signature
Url : http://lists.freebsd.org/pipermail/freebsd-stable/attachments/20100205/5feb62e3/signature.pgp


More information about the freebsd-stable mailing list