Date: Fri, 18 Nov 2016 14:15:51 +0100 From: Henri Hennebert <hlh@restart.be> To: Andriy Gapon <avg@FreeBSD.org>, Konstantin Belousov <kib@FreeBSD.org> Cc: freebsd-stable@FreeBSD.org Subject: Re: Freebsd 11.0 RELEASE - ZFS deadlock Message-ID: <322f5c54-8fc2-9da1-5cd2-6c12f3a7e7ae@restart.be> In-Reply-To: <7c932021-ff99-9ef9-7042-4f267fb0b955@FreeBSD.org> References: <0c223160-b76f-c635-bb15-4a068ba7efe7@restart.be> <6bc95dce-31e1-3013-bfe3-7c2dd80f9d1e@restart.be> <e4878992-a362-3f12-e743-8efa1347cabf@FreeBSD.org> <23a66749-f138-1f1a-afae-c775f906ff37@restart.be> <8e7547ef-87f7-7fab-6f45-221e8cea1989@FreeBSD.org> <6d991cea-b420-531e-12cc-001e4aeed66b@restart.be> <67f2e8bd-bff0-f808-7557-7dabe5cad78c@FreeBSD.org> <1cb09c54-5f0e-2259-a41a-fefe76b4fe8b@restart.be> <d25c8035-b710-5de9-ebe3-7990b2d0e3b1@FreeBSD.org> <9f20020b-e2f1-862b-c3fc-dc6ff94e301e@restart.be> <c1b7aa94-1f1d-7edd-8764-adb72fdc053c@FreeBSD.org> <599c5a5b-aa08-2030-34f3-23ff19d09a9b@restart.be> <32686283-948a-6faf-7ded-ed8fcd23affb@FreeBSD.org> <cf0fc1e3-b621-074e-1351-4dd89d980ddd@restart.be> <af4e0c2b-00f8-bbaa-bcb7-d97062a393b8@FreeBSD.org> <26512d69-94c2-92da-e3ea-50aebf17e3a0@restart.be> <f406ad95-bd3f-710c-5a2c-cc526d1a9812@FreeBSD.org> <80f65c86-1015-c409-1bf6-c01a5fe569c8@restart.be> <7c932021-ff99-9ef9-7042-4f267fb0b955@FreeBSD.org>
next in thread | previous in thread | raw e-mail | index | archive | help
On 11/18/2016 13:30, Andriy Gapon wrote:
> On 14/11/2016 14:00, Henri Hennebert wrote:
>> On 11/14/2016 12:45, Andriy Gapon wrote:
>>> Okay. Luckily for us, it seems that 'm' is available in frame 5. It also
>>> happens to be the first field of 'struct faultstate'. So, could you please go
>>> to frame and print '*m' and '*(struct faultstate *)m' ?
>>>
>> (kgdb) fr 4
>> #4 0xffffffff8089d1c1 in vm_page_busy_sleep (m=0xfffff800df68cd40, wmesg=<value
>> optimized out>) at /usr/src/sys/vm/vm_page.c:753
>> 753 msleep(m, vm_page_lockptr(m), PVM | PDROP, wmesg, 0);
>> (kgdb) print *m
>> $1 = {plinks = {q = {tqe_next = 0xfffff800dc5d85b0, tqe_prev =
>> 0xfffff800debf3bd0}, s = {ss = {sle_next = 0xfffff800dc5d85b0},
>> pv = 0xfffff800debf3bd0}, memguard = {p = 18446735281313646000, v =
>> 18446735281353604048}}, listq = {tqe_next = 0x0,
>> tqe_prev = 0xfffff800dc5d85c0}, object = 0xfffff800b62e9c60, pindex = 11,
>> phys_addr = 3389358080, md = {pv_list = {
>> tqh_first = 0x0, tqh_last = 0xfffff800df68cd78}, pv_gen = 426, pat_mode =
>> 6}, wire_count = 0, busy_lock = 6, hold_count = 0,
>> flags = 0, aflags = 2 '\002', oflags = 0 '\0', queue = 0 '\0', psind = 0 '\0',
>> segind = 3 '\003', order = 13 '\r',
>> pool = 0 '\0', act_count = 0 '\0', valid = 0 '\0', dirty = 0 '\0'}
>
> If I interpret this correctly the page is in the 'exclusive busy' state.
> Unfortunately, I can't tell much beyond that.
> But I am confident that this is the root cause of the lock-up.
>
>> (kgdb) print *(struct faultstate *)m
>> $2 = {m = 0xfffff800dc5d85b0, object = 0xfffff800debf3bd0, pindex = 0, first_m =
>> 0xfffff800dc5d85c0,
>> first_object = 0xfffff800b62e9c60, first_pindex = 11, map = 0xca058000, entry
>> = 0x0, lookup_still_valid = -546779784,
>> vp = 0x6000001aa}
>> (kgdb)
>
> I was wrong on this one as 'm' is actually a pointer, so the above is not
> correct. Maybe 'info reg' in frame 5 would give a clue about the value of 'fs'.
(kgdb) fr 5
#5 0xffffffff8089dd4d in vm_page_sleep_if_busy (m=0xfffff800df68cd40,
msg=0xffffffff809c51bc "vmpfw")
at /usr/src/sys/vm/vm_page.c:1086
1086 vm_page_busy_sleep(m, msg);
(kgdb) info reg
rax 0x0 0
rbx 0xfffff800b62e9c78 -8793036514184
rcx 0x0 0
rdx 0x0 0
rsi 0x0 0
rdi 0x0 0
rbp 0xfffffe0101836810 0xfffffe0101836810
rsp 0xfffffe01018367e0 0xfffffe01018367e0
r8 0x0 0
r9 0x0 0
r10 0x0 0
r11 0x0 0
r12 0xfffff800b642aa00 -8793035200000
r13 0xfffff800df68cd40 -8792344834752
r14 0xfffff800b62e9c60 -8793036514208
r15 0xffffffff809c51bc -2137239108
rip 0xffffffff8089dd4d 0xffffffff8089dd4d
<vm_page_sleep_if_busy+285>
eflags 0x0 0
cs 0x0 0
ss 0x0 0
ds 0x0 0
es 0x0 0
fs 0x0 0
gs 0x0 0
I don't know what to do from here.
>
> I am not sure how to proceed from here.
> The only thing I can think of is a lock order reversal between the vnode lock
> and the page busying quasi-lock. But examining the code I can not spot it.
> Another possibility is a leak of a busy page, but that's hard to debug.
>
> How hard is it to reproduce the problem?
After 7 days all seems normal only one copy of innd:
[root@avoriaz ~]# ps xa|grep inn
1193 - Is 0:01.40 /usr/local/news/bin/innd -r
13498 - IN 0:00.01 /usr/local/news/bin/innfeed
1194 v0- IW 0:00.00 /bin/sh /usr/local/news/bin/innwatch -i 60
I will try to stop and restart innd.
All continue to look good:
[root@avoriaz ~]# ps xa|grep inn
31673 - Ss 0:00.02 /usr/local/news/bin/innd
31694 - SN 0:00.01 /usr/local/news/bin/innfeed
31674 0 S 0:00.01 /bin/sh /usr/local/news/bin/innwatch -i 60
I think to reproduce is just waiting it occurs by itself...
One thing here: The deadlock occurs at least 5 times since 10.0R. And
always with the directory /usr/local/news/bin
>
> Maybe Konstantin would have some ideas or suggestions.
>
Henri
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?322f5c54-8fc2-9da1-5cd2-6c12f3a7e7ae>