Re: lock order reversals w/ backtrace

From: Thomas Hoffmann <trh411_at_gmail.com>
Date: Fri, 24 Jan 2014 23:47:16 -0500
On Fri, Jan 24, 2014 at 9:52 AM, Thomas Hoffmann <trh411_at_gmail.com> wrote:

> On Thu, Jan 23, 2014 at 11:49 AM, Hans Petter Selasky <
> hans.petter.selasky_at_bitfrost.no> wrote:
>
>>  Hi,
>>
>> Can you see if you can snap some keywords of the backtraces, like usb_xxx usbdx_xxx cam scsi or something like that.
>>
>> Else I believe there are some sysctl options to prevent the final reboot somehow so that you can write down the messages.
>>
>> --HPS
>>
>>
>> -----Original message-----
>> > From:Thomas Hoffmann <trh411_at_gmail.com>
>> > Sent: Thursday 23rd January 2014 17:15
>>
>> > To: freebsd-current <freebsd-current_at_freebsd.org>
>> > Subject: lock order reversals w/ backtrace
>> >
>> > A few days ago I started running 11.0-CURRENT at r260971 for the first time.
>>
>> >
>> > The last couple of times I shutdown my system I noticed 2 or 3 short "lock
>> > order reversal" messages with accompanying backtraces scroll by. Do these
>> > messages represent a problem that I should report or can I ignore them as
>>
>> > debug in nature? If I should report them, how or where do these messages
>> > get logged? I can find no reference to them in syslog or anywhere else upon
>> > my subsequent reboot.
>> >
>> > I also had a couple of these messages pop up the other day while
>>
>> > mounting/umounting USB thumb drives. I did not think anything of them at
>> > the time as the mounts/umounts completed successfully.
>> >
>> > Please advise. Thanks.
>> >
>> > -Tom
>>
>> I managed to snap a photo of my screen during shutdown.
> Here is the full text of the first of two lock order reversals I got last
> night during system shutdown, both of which are zfs-related to (it
> appears?) unmounts. A few lines got chopped as they were out-of-frame when
> I took the photo:
>
> shutting down local daemons:
> lock order reversal:
>   1st 0xfffff801194f67c8 zfs (zfs) _at_ /usr/src/sys/kern/vfs_mount.c:1237
>   2nd 0xfffff801194f6420 syncer (syncer) _at_
> /usr/src/sys/kern/vfs_subr.c:22[..chopped...]
> KDB: stack backtrace:
> db_trace_self_wrapper() at db_trace_delf_wrapper+0x2b/frame
> 0xfffffe01ac78[...chopped...]
> kdb_backtrace() at kdb_backtrace+0x39/frame 0xfffffe01ac784650
> witness_checkorder() at witness_checkorder+0xd23/frame 0xfffffe01ac7846e0
> __lockmgr_args() __lockmgr_args+0x878/frame 0xfffffe01ac784810
> vop_stdlock() at vop_stdlock+0x3c/frame 0xfffffe01ac784830
> VOP_LOCK1_APV() at VOP_LOCK1_APV+0xf5/frame 0xfffffe01ac784860
> _vn_lock() at _vn_lock+0xab/frame 0xfffffe01ac7848d0
> vputx() at vputx+0x240/frame 0xfffffe01ac784930
> dounmount at dounmount+0x327/frame 0xfffffe01ac7849b0
> sys_unmount() at sys_unmount+0x356/frame 0xfffffe01ac784ac0
> amd64_syscall() at amd64_syscall+0x265/frame 0xfffffe01ac784bf0
> Xfast_syscall() at Xfast_syscall+0xfb/frame 0xfffffe01ac784bf0
> --- syscall (22, FreeBSD ELF64, sys_unmount, rip = 0x80191c72a,
> rsp[...chopped...]
>
> I have a zpool on an external USB HDD that I export at shutdown via
> rc.shutdown.local. Don't know if that is contributing to this or not. When
> I get a chance to bring down the system I will manually export it before
> shutdown to see if that makes any difference.
>

Was able to capture the full text of the lock order reversal I've been
experiencing at shutdown. Turns out to be associated with the export of one
of my zpools that is hosted on an external USB HDD. Normally I export the
zpool from rc.shutdown.local, but tonight I exported it manually before I
shutdown and got the following.

lock order reversal:
: 1st 0xfffff8011952b5f0 zfs (zfs) _at_ /usr/src/sys/kern/vfs_mount.c:1237
: 2nd 0xfffff8011952b068 syncer (syncer) _at_ /usr/src/sys/kern/vfs_subr.c:2212
KDB: stack backtrace:
db_trace_self_wrapper() at db_trace_self_wrapper+0x2b/frame
0xfffffe01add6e5a0
kdb_backtrace() at kdb_backtrace+0x39/frame 0xfffffe01add6e650
witness_checkorder() at witness_checkorder+0xd23/frame 0xfffffe01add6e6e0
__lockmgr_args() at __lockmgr_args+0x878/frame 0xfffffe01add6e810
vop_stdlock() at vop_stdlock+0x3c/frame 0xfffffe01add6e830
VOP_LOCK1_APV() at VOP_LOCK1_APV+0xf5/frame 0xfffffe01add6e860
_vn_lock() at _vn_lock+0xab/frame 0xfffffe01add6e8d0
vputx() at vputx+0x240/frame 0xfffffe01add6e930
dounmount() at dounmount+0x327/frame 0xfffffe01add6e9b0
sys_unmount() at sys_unmount+0x356/frame 0xfffffe01add6eae0
amd64_syscall() at amd64_syscall+0x265/frame 0xfffffe01add6ebf0
Xfast_syscall() at Xfast_syscall+0xfb/frame 0xfffffe01add6ebf0
--- syscall (22, FreeBSD ELF64, sys_unmount), rip = 0x80191c72a, rsp =
0x7fffffffc4c8, rbp = 0x7fffffffc960 ---

When imported and mounted, the zpool reports no errors and I have not
experienced any anomalies reading or writing to the zpool. Should I be
concerned?
Received on Sat Jan 25 2014 - 03:47:18 UTC

This archive was generated by hypermail 2.4.0 : Wed May 19 2021 - 11:40:46 UTC