Project

General

Profile

Actions

Bug #16582

open

syseventd ndi deadlock

Added by Robert Mustacchi 22 days ago.

Status:
New
Priority:
Normal
Assignee:
-
Category:
kernel
Start date:
Due date:
% Done:

0%

Estimated time:
Difficulty:
Medium
Tags:
Gerrit CR:
External Bug:

Description

While testing #16581, I found that I actually hit an entirely different deadlock:

> ::pgrep diskinfo | ::walk thread | ::stacks
THREAD           STATE    SOBJ                COUNT
fffffeb32253e020 SLEEP    CV                      1
                 swtch+0x17f
                 cv_wait+0x89
                 ndi_devi_enter+0xcd
                 di_copynode+0x56d
                 di_copytree+0xb7
                 di_snapshot+0x22d
                 di_snapshot_and_clean+0x24
                 di_ioctl+0x637
                 cdev_ioctl+0x3f
                 spec_ioctl+0x55
                 fop_ioctl+0x40
                 ioctl+0x144
                 sys_syscall32+0x20f

fffffeb3213f2880 SLEEP    CV                      1
                 swtch+0x17f
                 cv_wait+0x89
                 ndi_devi_enter+0xcd
                 di_copytree+0x7b
                 di_snapshot+0x22d
                 di_snapshot_and_clean+0x24
                 di_ioctl+0x637
                 cdev_ioctl+0x3f
                 spec_ioctl+0x55
                 fop_ioctl+0x40
                 ioctl+0x144
                 sys_syscall32+0x20f

Our diskinfo processes are hanging likely on the NVMe driver. So where is it:

> ::stacks -m nvme
THREAD           STATE    SOBJ                COUNT
fffffeb308891b80 SLEEP    CV                      2
                 swtch+0x17f
                 cv_wait+0x89
                 queue_sysevent+0x86
                 log_sysevent+0x66
                 i_log_devfs_add_devinfo+0x188
                 devi_attach_node+0xe6
                 ndi_devi_online+0xa7
                 bd_attach_handle+0x222
                 nvme_attach_ns+0x74
                 nvme_ioctl_attach+0x127
                 nvme_ioctl+0x266
                 cdev_ioctl+0x3f
                 spec_ioctl+0x55
                 fop_ioctl+0x40
                 ioctl+0x144

fffffe00f4da5c20 FREE     <NONE>                  1
                 disp_lock_exit+0x58
                 cv_signal+0xc9
                 taskq_dispatch_ent+0xf9
                 nvme_process_iocq+0x84
                 0xfffffeb30318f000
                 0x71f1b65470
                 apix_dispatch_lowlevel+0x34

This is blocked on sysevent delivery, which begs the question of where is syseventd:

> ::pgrep syseventd | ::walk thread | ::stacks
THREAD           STATE    SOBJ                COUNT
fffffeb306edf400 SLEEP    CV                     12
                 swtch+0x17f
                 cv_wait_sig_swap_core+0x181
                 cv_wait_sig_swap+0x17
                 cv_waituntil_sig+0xcd
                 lwp_park+0x13f
                 syslwp_park+0x85
                 sys_syscall32+0x20f

fffffeb3096cf7e0 SLEEP    SHUTTLE                 3
                 swtch+0x17f
                 shuttle_swtch+0x21e
                 door_return+0x244
                 doorfs32+0x1f4
                 sys_syscall32+0x20f

fffffeb30eea8bc0 SLEEP    SHUTTLE                 2
                 swtch_to+0xb8
                 shuttle_resume+0x2b1
                 door_return+0x463
                 doorfs32+0x1f4
                 sys_syscall32+0x20f

fffffeb310f99440 SLEEP    CV                      1
                 swtch+0x17f
                 cv_wait+0x89
                 ndi_devi_enter+0xcd
                 devi_config_one+0x18f
                 ndi_devi_config_one+0xd4
                 dv_find+0x25c
                 devfs_lookup+0x88
                 fop_lookup+0xaa
                 lookuppnvp+0x2c8
                 lookuppnatcred+0x133
                 lookupnameatcred+0x11b
                 lookupnameat+0x39
                 vn_openat+0x322
                 copen+0x173
                 openat32+0x2a
                 open32+0x25
                 sys_syscall32+0x20f

fffffeb310f99bc0 SLEEP    CV                      1
                 swtch+0x17f
                 cv_wait_sig_swap_core+0x181
                 cv_wait_sig_swap+0x17
                 cv_waituntil_sig+0xcd
                 sigtimedwait+0x1bb
                 sys_syscall32+0x20f

fffffeb30bd8a3c0 SLEEP    CV                      1
                 swtch+0x17f
                 cv_wait_sig_swap_core+0x181
                 cv_wait_sig_swap+0x17
                 pause+0x45
                 sys_syscall32+0x20f

And what do you know, there's a syseventd thread that's stuck trying to get an NDI lock. OK, so what is it that it's looking for:

> fffffe00f6f01a28::print struct pathname
{
    pn_buf = 0xfffffec64ee68000 "/devices/pci@76,0/pci1022,1483@1,3/pci8086,8008@0/blkdev@w5CD2E46B52180300,0:q" 
    pn_path = 0xfffffec64ee6804e "" 
    pn_pathlen = 0
    pn_bufsize = 0x400
}

Well, that's handy. That's definitely one of the blkdev nodes that we're messing with. Well then. That's awkward. I manually reconstructed the stack by doing some dumpster diving in syseventd in userland to find our mysterious thread that had called into it, because of course, it's not one of the ones in the ::stacks output below:

THREAD   STATE    SOBJ        COUNT
7        PARKED   CV              5
         libc.so.1`cond_wait_queue+0x5f
         libc.so.1`__cond_wait+0xaf
         libc.so.1`cond_wait+0x2e
         client_deliver_event_thr+0x38
         libc.so.1`_thrp_setup+0x7f
         libc.so.1`_lwp_start

5        UNPARKED <NONE>          4
         door_upcall+0x8d
         libc.so.1`__door_return+0x40

9        UNPARKED <NONE>          1

4        UNPARKED <NONE>          1
         libc.so.1`sigwait+0x2f
         libc.so.1`__posix_sigwait+0x37
         sigwait_thr+0x52
         libc.so.1`_thrp_setup+0x7f
         libc.so.1`_lwp_start

12       UNPARKED <NONE>          1
         libsysevent.so.1`cache_update_service+0x7d
         libc.so.1`__door_return+0x40

1        UNPARKED <NONE>          1
         main+0x4f5
         _start_crt+0x9a
         _start+0x1a

e        PARKED   CV              1
         libc.so.1`cond_wait_queue+0x5f
         libc.so.1`__cond_wait+0xaf
         libc.so.1`cond_wait+0x2e
         datalink_mod.so`datalink_notify_thread+0x5f
         libc.so.1`_thrp_setup+0x7f
         libc.so.1`_lwp_start

a        PARKED   CV              1
         libc.so.1`cond_wait_queue+0x5f
         libc.so.1`__cond_wait+0xaf
         libc.so.1`cond_wait+0x2e
         devfsadmd_mod.so`devfsadmd_deliver_thr+0x1bf
         libc.so.1`_thrp_setup+0x7f
         libc.so.1`_lwp_start

c        PARKED   CV              1
         libc.so.1`cond_wait_queue+0x5f
         libc.so.1`__cond_wait+0xaf
         libc.so.1`cond_wait+0x2e
         picl_slm.so`piclslm_deliver_thr+0x9d
         libc.so.1`_thrp_setup+0x7f
         libc.so.1`_lwp_start

10       PARKED   CV              1
         libc.so.1`cond_wait_queue+0x5f
         libc.so.1`__cond_wait+0xaf
         libc.so.1`cond_wait+0x2e
         sysevent_conf_mod.so`queue_flush_thr+0x40
         libc.so.1`_thrp_setup+0x7f
         libc.so.1`_lwp_start

6        PARKED   CV              1
         libc.so.1`cond_wait_queue+0x5f
         libc.so.1`__cond_wait+0xaf
         libc.so.1`cond_wait+0x2e
         sysevent_reg_mod.so`subscriber_deliver_thr+0x47
         libc.so.1`_thrp_setup+0x7f
         libc.so.1`_lwp_start

2        PARKED   CV              1
         libc.so.1`sema_wait+0x46
         dispatch_message+0x82        
         libc.so.1`_thrp_setup+0x7f
         libc.so.1`_lwp_start

3        PARKED   CV              1
         libc.so.1`sema_wait+0x46
         event_completion_thr+0x164
         libc.so.1`_thrp_setup+0x7f
         libc.so.1`_lwp_start

Note that tid 9 is missing anything, so let's manually figure it out:

> 9::tid2ulwp | ::print ulwp_t ul_stktop
ul_stktop = 0xfe0c0000
> 0xfe0c0000-1000,400/nap ! grep -i open
0xfe0bf5dc:     libc.so.1`__open+0x35
0xfe0bf5e0:     libc.so.1`__open+0x35
0xfe0bf5fc:     libc.so.1`open+0x82
> 0xfe0c0000-1000,400/nap ! less        
> 0xfe0bf5f8$C 
fe0bf618 libc.so.1`open+0x82(fe0bf630, 0)
fe0bf6e8 zfs_mod.so`devid_iter+0x7e(fe0bfb1c, fe652947, 1, fee5ba2a)
fe0bff38 zfs_mod.so`zfs_deliver_add+0x8e(80691d8, 0, fe0bff88, feed5167, 8082fa8, 0)
fe0bff88 zfs_mod.so`zfs_deliver_event+0x9e(80a8258, 0, 80694d0, 8054d1a, 0, 8068cf8)
fe0bffc8 client_deliver_event_thr+0x99(8082fa8, 0, 0, 0)
fe0bffe8 libc.so.1`_thrp_setup+0x7f(feca3a40)
fe0bfff8 libc.so.1`_lwp_start(feca3a40, 0, 0, 0, 0, 0)

Back in the kernel:

> logevent_max_q_sz/X
logevent_max_q_sz:
logevent_max_q_sz:              1388            
> log_eventq_cnt/X
log_eventq_cnt:
log_eventq_cnt: 1388
> ::walk sysevent_pend ! wc -l
    5000

It's not immediately clear how to solve this backpressure problem.

So we presumably generated enough sysevents that we have some problems.

No data to display

Actions

Also available in: Atom PDF