Advisory lock crashes.

Tue Feb 19 08:20:40 UTC 2013

On Tue, Feb 19, 2013 at 12:07:15AM -0800, Alfred Perlstein wrote:
> On 2/18/13 11:32 PM, Konstantin Belousov wrote:
> > On Mon, Feb 18, 2013 at 11:08:34PM -0800, Alfred Perlstein wrote:
> >> Hello Konstantin & Doug,
> >>
> >> We're getting a few crashes in what looks to be kern_lockf.c:
> >>
> >> fault address here is 0x360 which appears to mean that the "sx" owner
> >> thread is NULL
> > What is the version of FreeBSD ?
> This is a releng 9.0 system.  (note, we have the most up to date version 
> of this file with the exception of a cosmetic diff for MALLOC defines).
My suspicion is that the issue is not in the kern_lockf.c at all,
rather it is a bug in the vnode lifetime management in the filesystem
code.  If true, the absense of the changes in the kern_lockf.c does
not matter, but the changes in ZFS do.

AFAIR, there were a lot of fixes in this area for ZFS, done by avg.

> 
> > What is the filesystem owning the file which was advlocked ?
> I'm pretty sure that is going to be ZFS.
> 
> > Show the line number for lf_advlockasync+0x5d7.
> 
> > (kgdb) list *(lf_advlockasync+0x5d7)
> > 0xffffffff80604fc7 is in lf_advlockasync (sx.h:152).
> > 147     {
> > 148             uintptr_t tid = (uintptr_t)td;
> > 149             int error = 0;
> > 150
> > 151             if (!atomic_cmpset_acq_ptr(&sx->sx_lock, 
> > SX_LOCK_UNLOCKED, tid))
> > 152                     error = _sx_xlock_hard(sx, tid, opts, file, line);
> > 153             else
> > 154 LOCKSTAT_PROFILE_OBTAIN_LOCK_SUCCESS(LS_SX_XLOCK_ACQUIRE,
> > 155                         sx, 0, 0, file, line);
> > 156
> That may not be helpful so I've included this:
> /usr/home/alfred # bc
> ibase=16
> 5D7
> 1495
> 
> (kgdb) disasse lf_advlockasync
> Dump of assembler code for function lf_advlockasync:
> 0xffffffff806049f0 <lf_advlockasync+0>: push   %rbp
> 0xffffffff806049f1 <lf_advlockasync+1>: mov    %rdx,%rcx
> > 0xffffffff80604f70 <lf_advlockasync+1408>:      mov    -0x80(%rbp),%rdi
> > 0xffffffff80604f74 <lf_advlockasync+1412>:      xor %ecx,%ecx
> > 0xffffffff80604f76 <lf_advlockasync+1414>:      xor %edx,%edx
> > 0xffffffff80604f78 <lf_advlockasync+1416>:      mov %rbx,%rsi
> > 0xffffffff80604f7b <lf_advlockasync+1419>:      callq 
> > 0xffffffff806246d0 <_sx_xunlock_hard>
> > 0xffffffff80604f80 <lf_advlockasync+1424>:      jmpq 
> > 0xffffffff80604c53 <lf_advlockasync+611>
> > 0xffffffff80604f85 <lf_advlockasync+1429>:      mov -0x58(%rbp),%rcx
> > 0xffffffff80604f89 <lf_advlockasync+1433>:      xor %r12d,%r12d
> > 0xffffffff80604f8c <lf_advlockasync+1436>:      mov 0x18(%rcx),%edi
> > 0xffffffff80604f8f <lf_advlockasync+1439>:      callq 
> > 0xffffffff80603b90 <lf_clearremotesys>
> > 0xffffffff80604f94 <lf_advlockasync+1444>:      jmpq 
> > 0xffffffff80604c70 <lf_advlockasync+640>
> > 0xffffffff80604f99 <lf_advlockasync+1449>:      lea 0xc8(%r13),%rdi
> > 0xffffffff80604fa0 <lf_advlockasync+1456>:      xor %r8d,%r8d
> > 0xffffffff80604fa3 <lf_advlockasync+1459>:      xor %ecx,%ecx
> > 0xffffffff80604fa5 <lf_advlockasync+1461>:      xor %edx,%edx
> > 0xffffffff80604fa7 <lf_advlockasync+1463>:      mov %rbx,%rsi
> > 0xffffffff80604faa <lf_advlockasync+1466>:      callq 
> > 0xffffffff8060a1f0 <_mtx_lock_sleep>
> > 0xffffffff80604faf <lf_advlockasync+1471>:      jmpq 
> > 0xffffffff80604f2e <lf_advlockasync+1342>
> > 0xffffffff80604fb4 <lf_advlockasync+1476>:      mov -0x80(%rbp),%rdi
> > 0xffffffff80604fb8 <lf_advlockasync+1480>:      xor %r8d,%r8d
> > 0xffffffff80604fbb <lf_advlockasync+1483>:      xor %ecx,%ecx
> > 0xffffffff80604fbd <lf_advlockasync+1485>:      xor %edx,%edx
> > 0xffffffff80604fbf <lf_advlockasync+1487>:      mov %rbx,%rsi
> > 0xffffffff80604fc2 <lf_advlockasync+1490>:      callq 
> > 0xffffffff80624210 <_sx_xlock_hard>
> > 0xffffffff80604fc7 <lf_advlockasync+1495>:      jmpq 
> > 0xffffffff80604f15 <lf_advlockasync+1317>
> > 0xffffffff80604fcc <lf_advlockasync+1500>:      lea 0xc8(%r13),%rdi
> > 0xffffffff80604fd3 <lf_advlockasync+1507>:      xor %ecx,%ecx
> > 0xffffffff80604fd5 <lf_advlockasync+1509>:      xor %edx,%edx
> > 0xffffffff80604fd7 <lf_advlockasync+1511>:      xor %esi,%esi
> > 0xffffffff80604fd9 <lf_advlockasync+1513>:      callq 
> > 0xffffffff8060a040 <_mtx_unlock_sleep>
> > 0xffffffff80604fde <lf_advlockasync+1518>:      jmpq 
> > 0xffffffff80604f5c <lf_advlockasync+1388>
> > 0xffffffff80604fe3 <lf_advlockasync+1523>:      mov %r15,(%rcx)
> > 0xffffffff80604fe6 <lf_advlockasync+1526>:      mov %r15,%r14
> > 0xffffffff80604fe9 <lf_advlockasync+1529>:      mov %gs:0x0,%rax
> > 0xffffffff80604ff2 <lf_advlockasync+1538>:      lock cmpxchg 
> > %rbx,0xe0(%r13)
This is not helpful too, you demonstrated the inlined part of the sx_lock().
I need to understand which sx caused the issue, state->ls_lock (and
then it is related to the vnode life), or lf_lock_states_lock.

Either the logic of the assembler should be analyzed to decipher which
lock is it, or try to list more lines around the reported address, to
see which sx_xlock() line is there.

> 
> 
> >
> > No, I never saw nothing similar in last 3 years.
> 
> Yes, I'd suspect we'd all see more things here.  We're very much capable 
> of adding instrumentation to the OS/kernel to help track this down if 
> you have ideas.
INVARIANTS, DIAGNOSTIC, DEBUG_VFS_LOCK.

What is needed is the printout of *vp involved in the panic.

> 
> -Alfred
> 
> 
> >> db>  bt
> >> Tracing pid 5099 tid 101614 td 0xfffffe005d54e8c0
> >> _sx_xlock_hard() at _sx_xlock_hard+0xb3
> >> lf_advlockasync() at lf_advlockasync+0x5d7
> >> lf_advlock() at lf_advlock+0x47
> >> vop_stdadvlock() at vop_stdadvlock+0xb3
> >> VOP_ADVLOCK_APV() at VOP_ADVLOCK_APV+0x4a
> >> closef() at closef+0x352
> >> kern_close() at kern_close+0x172
> >> amd64_syscall() at amd64_syscall+0x58a
> >> Xfast_syscall() at Xfast_syscall+0xf7
> >> --- syscall (6, FreeBSD ELF64, sys_close), rip = 0x8011651fc, rsp = 0x7fffffbfdd58, rbp = 0x807c3d6c0 ---
> >>
> >> (kgdb) list *(_sx_xlock_hard+0xb3)
> >> 0xffffffff806242c3 is in _sx_xlock_hard
> >> (/usr/home/jpaetzel/9.0.6-RELEASE-p1/FreeBSD/src/sys/kern/kern_sx.c:514).
> >> 509                     x = sx->sx_lock;
> >> 510                     if ((sx->lock_object.lo_flags & SX_NOADAPTIVE)
> >> == 0) {
> >> 511                             if ((x & SX_LOCK_SHARED) == 0) {
> >> 512                                     x = SX_OWNER(x);
> >> 513                                     owner = (struct thread *)x;
> >> 514                                     if (TD_IS_RUNNING(owner)) {
> >> 515                                             if
> >> (LOCK_LOG_TEST(&sx->lock_object, 0))
> >> 516 CTR3(KTR_LOCK,
> >> 517                                                 "%s: spinning on %p
> >> held by %p",
> >> 518 __func__, sx, owner);
> >>
> >>
> >> Another panic here, which we have less information is attached as an image.
> >>
> >> We're looking at using some INVARIANTS and WITNESS kernels, but was
> >> wondering if y'all had any other suggestions to use please?
> >>
> >> thank you,
> >> -Alfred
> >
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 834 bytes
Desc: not available
URL: <http://lists.freebsd.org/pipermail/freebsd-fs/attachments/20130219/aaf68318/attachment.sig>