Bug 136944

Summary: [ffs] [lor] bufwait/snaplk (fsync)
Product: Base System Reporter: Rene Ladan <rene>
Component: kernAssignee: freebsd-bugs (Nobody) <bugs>
Status: Open ---    
Severity: Affects Only Me CC: ml
Priority: Normal    
Version: 8.0-BETA2   
Hardware: Any   
OS: Any   

Description Rene Ladan freebsd_committer freebsd_triage 2009-07-20 22:30:05 UTC
lock order reversal: 
 1st 0xffffff8029490410 bufwait (bufwait) @ /usr/src/sys/kern/vfs_bio.c:2558
 2nd 0xffffff0078f4a130 snaplk (snaplk) @ /usr/src/sys/ufs/ffs/ffs_snapshot.c:2223
KDB: stack backtrace:
db_trace_self_wrapper() at db_trace_self_wrapper+0x2a
_witness_debugger() at _witness_debugger+0x2e
witness_checkorder() at witness_checkorder+0x81e
__lockmgr_args() at __lockmgr_args+0xcf3
ffs_copyonwrite() at ffs_copyonwrite+0x189
ffs_geom_strategy() at ffs_geom_strategy+0x1b5
bufwrite() at bufwrite+0x106
ffs_update() at ffs_update+0x1bd
ffs_fsync() at ffs_fsync+0x43
fsync() at fsync+0x148
syscall() at syscall+0x1af
Xfast_syscall() at Xfast_syscall+0xe1
--- syscall (95, FreeBSD ELF64, fsync), rip = 0x80084cd0c, rsp = 0x7fffffffdcb8, rbp = 0x1 ---

How-To-Repeat: GENERIC kernel, only devfs and UFS2 filesystems mounted via /dev/ad* (/ , /var, /tmp, /usr)
Comment 1 Mark Linimon freebsd_committer freebsd_triage 2009-07-25 02:28:12 UTC
Responsible Changed
From-To: freebsd-bugs->freebsd-fs

Over to maintainer(s).
Comment 2 Olivier Certner freebsd_committer freebsd_triage 2011-01-24 15:07:54 UTC
		Hi,

	A small mail to confirm that this problem is still present on 
9.0-CURRENT-201101. Also, I reproduce other related LORs below.

	They can be triggered by performing a 'dump -L' on a UFS file system. 
The '-L' flag of 'dump' causes it to perform a snapshot of the file system to 
dump before reading data from it.

lock order reversal:
 1st 0xfffffe0019815bd8 ufs (ufs) @ /usr/src/sys/ufs/ffs/ffs_snapshot.c:423
 2nd 0xffffff80f5db1f98 bufwait (bufwait) @ /usr/src/sys/kern/vfs_bio.c:2659
 3rd 0xfffffe0003bc2db8 ufs (ufs) @ /usr/src/sys/ufs/ffs/ffs_snapshot.c:544
KDB: stack backtrace:
db_trace_self_wrapper() at db_trace_self_wrapper+0x2a
kdb_backtrace() at kdb_backtrace+0x37
_witness_debugger() at _witness_debugger+0x2e
witness_checkorder() at witness_checkorder+0x807
__lockmgr_args() at __lockmgr_args+0xd42
ffs_lock() at ffs_lock+0x8c
VOP_LOCK1_APV() at VOP_LOCK1_APV+0x9b
_vn_lock() at _vn_lock+0x47
ffs_snapshot() at ffs_snapshot+0x1c16
ffs_mount() at ffs_mount+0x5eb
vfs_donmount() at vfs_donmount+0xf6b
nmount() at nmount+0x63
syscallenter() at syscallenter+0x1aa
syscall() at syscall+0x4c
Xfast_syscall() at Xfast_syscall+0xe2
--- syscall (378, FreeBSD ELF64, nmount), rip = 0x8006a015c, rsp = 
0x7fffffffe3a8, rbp = 0x7fffffffedeb ---

lock order reversal:
 1st 0xffffff80f5c6af78 bufwait (bufwait) @ /usr/src/sys/kern/vfs_bio.c:2659
 2nd 0xfffffe0003c37d30 snaplk (snaplk) 
@ /usr/src/sys/ufs/ffs/ffs_snapshot.c:2261
KDB: stack backtrace:
db_trace_self_wrapper() at db_trace_self_wrapper+0x2a
kdb_backtrace() at kdb_backtrace+0x37
_witness_debugger() at _witness_debugger+0x2e
witness_checkorder() at witness_checkorder+0x807
__lockmgr_args() at __lockmgr_args+0xd42
ffs_copyonwrite() at ffs_copyonwrite+0x189
ffs_geom_strategy() at ffs_geom_strategy+0x1ba
bufwrite() at bufwrite+0x10c
ffs_update() at ffs_update+0x1a3
ffs_fsync() at ffs_fsync+0x43
fsync() at fsync+0x148
syscallenter() at syscallenter+0x1aa
syscall() at syscall+0x4c
Xfast_syscall() at Xfast_syscall+0xe2
--- syscall (95, FreeBSD ELF64, fsync), rip = 0x800856d5c, rsp = 
0x7fffffffe128, rbp = 0x800c8c0d0 ---

lock order reversal:
 1st 0xfffffe0003c37d30 snaplk (snaplk) @ /usr/src/sys/kern/vfs_vnops.c:301
 2nd 0xfffffe0019815bd8 ufs (ufs) @ /usr/src/sys/ufs/ffs/ffs_snapshot.c:1616
KDB: stack backtrace:
db_trace_self_wrapper() at db_trace_self_wrapper+0x2a
kdb_backtrace() at kdb_backtrace+0x37
_witness_debugger() at _witness_debugger+0x2e
witness_checkorder() at witness_checkorder+0x807
__lockmgr_args() at __lockmgr_args+0xd42
ffs_snapremove() at ffs_snapremove+0xe7
ffs_truncate() at ffs_truncate+0x635
ufs_inactive() at ufs_inactive+0x243
vinactive() at vinactive+0x72
vputx() at vputx+0x386
vn_close() at vn_close+0x118
vn_closefile() at vn_closefile+0x5a
_fdrop() at _fdrop+0x23
closef() at closef+0x5b
fdfree() at fdfree+0x1b4
exit1() at exit1+0x2f5
sys_exit() at sys_exit+0xe
syscallenter() at syscallenter+0x1aa
syscall() at syscall+0x4c
Xfast_syscall() at Xfast_syscall+0xe2
--- syscall (1, FreeBSD ELF64, sys_exit), rip = 0x8006f18cc, rsp = 
0x7fffffffe1b8, rbp = 0x404ed0 ---

	Thanks,

		Olivier Certner
Comment 3 Robert Schulze 2011-02-11 10:18:46 UTC
Hi,

I can confirm that, too:

lock order reversal:
  1st 0xffffff0019291cc8 ufs (ufs) @ /usr/src/sys/ufs/ffs/ffs_snapshot.c:423
  2nd 0xffffff81ef169978 bufwait (bufwait) @ 
/usr/src/sys/kern/vfs_bio.c:2636
  3rd 0xffffff00074647e8 ufs (ufs) @ /usr/src/sys/ufs/ffs/ffs_snapshot.c:544
KDB: stack backtrace:
db_trace_self_wrapper() at db_trace_self_wrapper+0x2a
kdb_backtrace() at kdb_backtrace+0x37
_witness_debugger() at _witness_debugger+0x49
witness_checkorder() at witness_checkorder+0x7d3
__lockmgr_args() at __lockmgr_args+0xd0b
ffs_lock() at ffs_lock+0xac
VOP_LOCK1_APV() at VOP_LOCK1_APV+0x9b
_vn_lock() at _vn_lock+0x5d
ffs_snapshot() at ffs_snapshot+0x1b79
ffs_mount() at ffs_mount+0x5c5
vfs_donmount() at vfs_donmount+0xcd4
nmount() at nmount+0x74
syscallenter() at syscallenter+0xe5
syscall() at syscall+0x55
Xfast_syscall() at Xfast_syscall+0xe2
--- syscall (378, FreeBSD ELF64, nmount), rip = 0x8007acfdc, rsp = 
0x7fffffffe9a8, rbp = 0x800a04530 ---
lock order reversal:
  1st 0xffffff81ef06e6f8 bufwait (bufwait) @ 
/usr/src/sys/kern/vfs_bio.c:2636
  2nd 0xffffff0015bcc630 snaplk (snaplk) @ 
/usr/src/sys/ufs/ffs/ffs_snapshot.c:2223
KDB: stack backtrace:
db_trace_self_wrapper() at db_trace_self_wrapper+0x2a
kdb_backtrace() at kdb_backtrace+0x37
_witness_debugger() at _witness_debugger+0x49
witness_checkorder() at witness_checkorder+0x7d3
__lockmgr_args() at __lockmgr_args+0xd0b
ffs_copyonwrite() at ffs_copyonwrite+0x161
ffs_geom_strategy() at ffs_geom_strategy+0x159
bufwrite() at bufwrite+0xff
ffs_sbupdate() at ffs_sbupdate+0x94
ffs_sync() at ffs_sync+0x489
sync_fsync() at sync_fsync+0x136
VOP_FSYNC_APV() at VOP_FSYNC_APV+0xb5
sync_vnode() at sync_vnode+0x143
sched_sync() at sched_sync+0x1c6
fork_exit() at fork_exit+0x12a
fork_trampoline() at fork_trampoline+0xe
--- trap 0, rip = 0, rsp = 0xffffff8245289cf0, rbp = 0 ---
lock order reversal:
  1st 0xffffff0015bcc630 snaplk (snaplk) @ /usr/src/sys/kern/vfs_vnops.c:296
  2nd 0xffffff0019291cc8 ufs (ufs) @ 
/usr/src/sys/ufs/ffs/ffs_snapshot.c:1587
KDB: stack backtrace:
db_trace_self_wrapper() at db_trace_self_wrapper+0x2a
kdb_backtrace() at kdb_backtrace+0x37
_witness_debugger() at _witness_debugger+0x49
witness_checkorder() at witness_checkorder+0x7d3
__lockmgr_args() at __lockmgr_args+0xd0b
ffs_snapremove() at ffs_snapremove+0xe2
softdep_releasefile() at softdep_releasefile+0x133
ufs_inactive() at ufs_inactive+0x153
VOP_INACTIVE_APV() at VOP_INACTIVE_APV+0xb9
vinactive() at vinactive+0x89
vputx() at vputx+0x3c6
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
syscallenter() at syscallenter+0xe5
syscall() at syscall+0x55
Xfast_syscall() at Xfast_syscall+0xe2
--- syscall (6, FreeBSD ELF64, close), rip = 0x800844b1c, rsp = 
0x7fffffffe9a8, rbp = 0 ---

this was after hot-resetting, maybe due to a background fsck.

with kind regards,
Robert Schulze
Comment 4 Eitan Adler freebsd_committer freebsd_triage 2017-12-31 07:58:27 UTC
For bugs matching the following criteria:

Status: In Progress Changed: (is less than) 2014-06-01

Reset to default assignee and clear in-progress tags.

Mail being skipped
Comment 5 ml 2021-01-12 13:10:48 UTC
Just encountered this on a 12.2/amd64 vm while investigating #244048 (not sure wether this might be part of the cause for that).

Of course, after so many years, the stack trace is slightly different.

Jan 12 14:05:13 mksnap kernel: lock order reversal:
Jan 12 14:05:13 mksnap kernel:  1st 0xfffffe0000827230 bufwait (bufwait) @ /usr/src/sys/ufs/ffs/ffs_vnops.c:283
Jan 12 14:05:13 mksnap kernel:  2nd 0xfffff800049661b0 snaplk (snaplk) @ /usr/src/sys/ufs/ffs/ffs_snapshot.c:2314
Jan 12 14:05:13 mksnap kernel: stack backtrace:
Jan 12 14:05:13 mksnap kernel: #0 0xffffffff80604bb3 at witness_debugger+0x73
Jan 12 14:05:13 mksnap kernel: #1 0xffffffff806048fe at witness_checkorder+0xa9e
Jan 12 14:05:13 mksnap kernel: #2 0xffffffff8056c0ed at lockmgr_xlock_hard+0x6d
Jan 12 14:05:13 mksnap kernel: #3 0xffffffff8056d0d0 at __lockmgr_args+0x7a0
Jan 12 14:05:13 mksnap kernel: #4 0xffffffff807a0df6 at ffs_copyonwrite+0x176
Jan 12 14:05:13 mksnap kernel: #5 0xffffffff807c223c at ffs_geom_strategy+0x8c
Jan 12 14:05:13 mksnap kernel: #6 0xffffffff807d39c3 at ufs_strategy+0x83
Jan 12 14:05:13 mksnap kernel: #7 0xffffffff808b9911 at VOP_STRATEGY_APV+0xf1
Jan 12 14:05:13 mksnap kernel: #8 0xffffffff80647114 at bufstrategy+0x44
Jan 12 14:05:13 mksnap kernel: #9 0xffffffff80646fb0 at bufwrite+0x230
Jan 12 14:05:13 mksnap kernel: #10 0xffffffff807c406e at ffs_syncvnode+0x2be
Jan 12 14:05:13 mksnap kernel: #11 0xffffffff8079bd04 at ffs_snapshot+0x914
Jan 12 14:05:13 mksnap kernel: #12 0xffffffff807bfe5a at ffs_mount+0xb3a
Jan 12 14:05:13 mksnap kernel: #13 0xffffffff80661a54 at vfs_domount+0x8d4
Jan 12 14:05:13 mksnap kernel: #14 0xffffffff80660b27 at vfs_donmount+0x7e7
Jan 12 14:05:13 mksnap kernel: #15 0xffffffff80660312 at sys_nmount+0xf2
Jan 12 14:05:13 mksnap kernel: #16 0xffffffff808418b7 at amd64_syscall+0x2e7
Jan 12 14:05:13 mksnap kernel: #17 0xffffffff808193de at fast_syscall_common+0xf8