Date: Fri, 05 Feb 2010 12:39:54 +0100 From: Harald Schmalzbauer <h.schmalzbauer@omnilan.de> To: freebsd-stable <freebsd-stable@freebsd.org> Subject: Reboot Loop: ffs_snapshot/bufwait LORs [Was: Re: 8.0-RELEASE hangs with lighttpd, unionfs related? Some traces included] Message-ID: <4B6C038A.9020500@omnilan.de> In-Reply-To: <4B6C01AB.5030500@omnilan.de> References: <4B6C01AB.5030500@omnilan.de>
next in thread | previous in thread | raw e-mail | index | archive | help
This is an OpenPGP/MIME signed message (RFC 2440 and 3156) --------------enig03798A21429BE8F6BCA74435 Content-Type: text/plain; charset=ISO-8859-15; format=flowed Content-Transfer-Encoding: quoted-printable Harald Schmalzbauer schrieb am 05.02.2010 12:31 (localtime): > Hello, >=20 > when I start lighttpd at boot time, the system half-locks in a way, tha= t=20 > any process, which accesses /usr/local/etc stalls. It's also impossible= =20 > to shut down. > /usr/local/etc is unionfs mounted. > I compiled a kernel with debug options. >=20 > When mounting unionfs at boot time, here's the firt LOR with trace: >=20 > lock order reversal: > 1st 0xffffff00018b47f8 unionfs (unionfs) @=20 > /usr/src/sys/fs/unionfs/union_subr.c:356 > 2nd 0xffffff00018d9d80 ufs (ufs) @ /usr/src/sys/kern/vfs_subr.c:2188 > 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 > vrele() at vrele+0x120 > unionfs_noderem() at unionfs_noderem+0x1c4 > unionfs_reclaim() at unionfs_reclaim+0x11 > vgonel() at vgonel+0xf1 > vrecycle() at vrecycle+0x58 > unionfs_inactive() at uniougen2.2: <vendor 0x1267> at usbus2 > nfs_inactive+ukbd0: 0<vendor 0x1267 product 0x0103, class 0/0, rev=20 > 1.10/1.01, addr 2> on usbus2 > x20 > vinactive() at vinactive+0x6b > vput() at vput+0x216 > kern_statatkbd1 at ukbd0 > _vnhook() at kern_statat_vnhook+0xe9 > kern_statat() at kern_statat+0x15 > stat() at stat+0x22 > syscall() at syscall+0x1af > Xfast_syscall() at Xfast_syscall+0xe1 > --- suhid0: y<vendor 0x1267 product 0x0103, class 0/0, rev 1.10/1.01,=20 > addr 2> on usbus2 > scall (188, FreeBSD ELF64, stat), rip =3D 0x8009a055c, rsp =3D=20 > 0x7fffffffe5b8, rbp =3D 0x800b312c0 --- > KDB: enter: witness_checkorder > [thread pid 27 tid 100068 ] > Stopped at kdb_enter+0x3d: movq $0,0x4c04dc(%rip) > Tracing pid 27 tid 100068 td 0xffffff00016fe720 > 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 > vrele() at vrele+0x120 > unionfs_noderem() at unionfs_noderem+0x1c4 > unionfs_reclaim() at unionfs_reclaim+0x11 > vgonel() at vgonel+0xf1 > vrecycle() at vrecycle+0x58 > unionfs_inactive() at unionfs_inactive+0x20 > vinactive() at vinactive+0x6b > vput() at vput+0x216 > kern_statat_vnhook() at kern_statat_vnhook+0xe9 > kern_statat() at kern_statat+0x15 > stat() at stat+0x22 > syscall() at syscall+0x1af > Xfast_syscall() at Xfast_syscall+0xe1 > --- syscall (188, FreeBSD ELF64, stat), rip =3D 0x8009a055c, rsp =3D=20 > 0x7fffffffe5b8, rbp =3D 0x800b312c0 - >=20 >=20 > Like mentioned, there is that strange problem with lighttpd started at = > boot time. Other /urs/local/etc/rc.d startups don't lead to a=20 > /usr/local/etc deadlock. > Unfortunately I don't get any panic or anything else when the hang happ= ens. > How can I aquire more information? > It's no problem to log in and to do everything else outside=20 > /usr/local/etc... >=20 >=20 > =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D >=20 > Here's a LOR at shutdown with trace: >=20 > lock order reversal: > 1st 0xffffff0001bc2098 ufs (ufs) @ /usr/src/sys/kern/vfs_mount.c:1200 > 2nd 0xffffff0001bc1ba8 devfs (devfs) @=20 > /usr/src/sys/ufs/ffs/ffs_vfsops.c:1194 > 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 > vop_stdlock() at vop_stdlock+0x39 > VOP_LOCK1_APV() at VOP_LOCK1_APV+0x9b > _vn_lock() at _vn_lock+0x50 > ffs_flushfiles() at ffs_flushfiles+0x93 > ffs_unmount() at ffs_unmount+0x48 > dounmount() at dounmount+0x2ac > vfs_unmountall() at vfs_unmountall+0x54 > boot() at boot+0x814 > mkdumpheader() at mkdumpheader > syscall() at syscall+0x1af > Xfast_syscall() at Xfast_syscall+0xe1 > --- syscall (55, FreeBSD ELF64, reboot), rip =3D 0x40829c, rsp =3D=20 > 0x7fffffffe738, rbp =3D 0x402290 --- > KDB: enter: witness_checkorder > [thread pid 1 tid 100002 ] > Stopped at kdb_enter+0x3d: movq $0,0x4c04dc(%rip) >=20 > Tracing pid 1 tid 100002 td 0xffffff0001310ab0 > kdb_enter() at kdb_enter+0x3d > witness_checkorder() at witness_checkorder+0x7ea > __lockmgr_args() at __lockmgr_args+0xcbd > vop_stdlock() at vop_stdlock+0x39 > VOP_LOCK1_APV() at VOP_LOCK1_APV+0x9b > _vn_lock() at _vn_lock+0x50 > ffs_flushfiles() at ffs_flushfiles+0x93 > ffs_unmount() at ffs_unmount+0x48 > dounmount() at dounmount+0x2ac > vfs_unmountall() at vfs_unmountall+0x54 > boot() at boot+0x814 > mkdumpheader() at mkdumpheader > syscall() at syscall+0x1af > Xfast_syscall() at Xfast_syscall+0xe1 > --- syscall (55, FreeBSD ELF64, reboot), rip =3D 0x40829c, rsp =3D=20 > 0x7fffffffe738, rbp =3D 0x402290 --- >=20 > Any Help highly appreciated! >=20 > Thanks, >=20 > -Harry Additional LORs while regular machine operation (background fsck) which=20 leads to reboot! I have access over the serail console, but the machine is unresponsive=20 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) @=20 /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 =3D 0x8007acfec, rsp =3D=20 0x7fffffffe988, rbp =3D 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) @=20 /usr/src/sys/ufs/ffs/ffs_snapshot.c:523 2nd 0xffffff8000422028 uhci2 (uhci2) @=20 /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 =3D 0xffffffff80381141, rsp =3D 0xffffff803e959000, rbp= =3D=20 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 =3D 0x8007acfec, rsp =3D=20 0x7fffffffe988, rbp =3D 0x800a028e- lock order reversal: 1st 0xffffff00018b4470 vnode interlock (vnode interlock) @=20 /usr/src/sys/ufs/ffs/ffs_snapshot.c:523 2nd 0xffffff0001747890 USB device mutex (USB device mutex) @=20 /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 =3D 0xffffffff80381141, rsp =3D 0xffffff803e959000, rbp= =3D=20 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 =3D 0x8007acfec, rsp =3D=20 0x7fffffffe988, rbp =3D 0x800a028e- lock order reversal: (Giant after non-sleepable) 1st 0xffffff00018b4470 vnode interlock (vnode interlock) @=20 /usr/src/sys/ufs/ffs/ffs_snapshot.c:523 2nd 0xffffffff80820780 Giant (Giant) @=20 /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 =3D 0xffffffff80381141, rsp =3D 0xffffff803e959000, rbp= =3D=20 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 =3D 0x8007acfec, rsp =3D=20 0x7fffffffe988, rbp =3D 0x800a028e- lock order reversal: 1st 0xffffff802970fc28 bufwait (bufwait) @=20 /usr/src/sys/kern/vfs_bio.c:2559 2nd 0xffffff00440ef6b0 snaplk (snaplk) @=20 /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 =3D 0x8007acfec, rsp =3D=20 0x7fffffffe988, rbp =3D 0x800a028e- KDB: enter: witness_checkorder [thread pid 947 tid 100073 ] Stopped at kdb_enter+0x3d: movq $0,0x4c04dc(%rip) Thanks for any help, -Harry --------------enig03798A21429BE8F6BCA74435 Content-Type: application/pgp-signature; name="signature.asc" Content-Description: OpenPGP digital signature Content-Disposition: attachment; filename="signature.asc" -----BEGIN PGP SIGNATURE----- Version: GnuPG v2.0.13 (FreeBSD) iEYEARECAAYFAktsA4oACgkQLDqVQ9VXb8guUgCdGFG3SthcgOQ6NtiR9pyFqtAd TAwAnRaC87hoy0vfIHOgRwEF60Im17KQ =jlMu -----END PGP SIGNATURE----- --------------enig03798A21429BE8F6BCA74435--
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?4B6C038A.9020500>