Date: Tue, 19 Feb 2013 00:36:11 -0800 From: Alfred Perlstein <alfred@ixsystems.com> To: Konstantin Belousov <kostikbel@gmail.com> Cc: Xin Li <delphij@delphij.net>, fs@freebsd.org Subject: Re: Advisory lock crashes. Message-ID: <5123397B.8030807@ixsystems.com> In-Reply-To: <20130219082026.GY2598@kib.kiev.ua> References: <512324F2.4060707@ixsystems.com> <20130219073256.GV2598@kib.kiev.ua> <512332B3.10400@ixsystems.com> <20130219082026.GY2598@kib.kiev.ua>
next in thread | previous in thread | raw e-mail | index | archive | help
On 2/19/13 12:20 AM, Konstantin Belousov wrote:
> 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.
That would make sense. It appears as if the lockf data structures are
being free()'d out from under us.
Maybe there are some asserts we can put in place to catch this under
DEBUG_VFS? or something?
Meanwhile we'll try to catchup with zfs fixes in head.
-Alfred
>
>>> 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
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?5123397B.8030807>