propolis-server and my VM stops responding

[leftwo]

I have a VM that, about a minute after boot, becomes non responsive over the network and on the console.

Some info from the running process:

2J80WF9K # mdb -b d3b0a12b-acf3-4564-a43f-86fc75485f7c
mdb: target stopped at:
0xfffffffffb888350:     jne    +0x2491a <0xfffffffffb8acc70>
[0]> $C
fffffe00413b3e20 0xfffffffffb888350()
fffffe00413b3e90 0xfffffffffb838e45()
fffffe00413b3f00 0xfffffffffb839157()
fffffe00413b3fa0 0xfffffffffb839b73()
fffffe00413b4020 0xfffffffffb8319e5()
fffffe00413b40a0 0xfffffffffb831bd5()
fffffe00413b4140 0xfffffffffb8b42d5()
fffffe00413b41b0 0xfffffffffb8b43fc()
fffffe00413b41e0 0xfffffffffb8b44e0()
fffffe00413b4300 0xfffffffffbb049e9()
fffffe00413b4370 0xfffffffffbb05039()
fffffe00413b43d0 0xfffffffffbb04007()
fffffe00413b4440 0xfffffffffbb050ab()
fffffe00413b44d0 0xfffffffffba17b08()
fffffe00413b4520 0xfffffffffba1812b()
fffffe00413b4570 0xfffffffffba195bb()
fffffe00413b45c0 0xfffffffffba19826()
fffffe00413b4600 0xfffffffffba19920()
fffffe00413b4630 0xfffffffffb83564a()
fffffe00413b46c0 0xfffffffffb832729()
fffffe00413b4760 0xfffffffffb838b98()
fffffe00413b47d0 0xfffffffffb838e45()
fffffe00413b4840 0xfffffffffb839157()
fffffe00413b48e0 0xfffffffffb839b73()
fffffe00413b4960 0xfffffffffb8319e5()
fffffe00413b49e0 0xfffffffffb831bd5()
fffffe00413b4a20 0xfffffffffb831c45()
fffffe00413b4b30 0xfffffffffba7c9fa()
fffffe00413b4cd0 0xfffffffffba80ad1()
fffffe00413b4da0 0xfffffffffbb0cc82()
fffffe00413b4e20 0xfffffffffb86d64d()
fffffe00413b4f00 0xfffffffffb86b4ca()
fffffe00413b4f10 0xfffffffffb8001d9()
[0]> ::status
debugging live VM 'd3b0a12b-acf3-4564-a43f-86fc75485f7c'
VM memory size: 32770 MB
vCPUs: 32
current CPU: 0 (long mode, AMD64)
default segment: DS
[0]> ::regs
%rax = 0x0000000000000000                 %r9  = 0xfffffe2d25fdebc0 
%rbx = 0x00000000000009fd                 %r10 = 0x0000000000000000 
%rcx = 0x0000000000000001                 %r11 = 0x0000000000000000 
%rdx = 0xfffffe2d25f593e0                 %r12 = 0xfffffffffbc2b5a8 
%rsi = 0x0000000000000000                 %r13 = 0xfffffe2d0e9c7028 
%rdi = 0xfffffffffbc2b5a8                 %r14 = 0xfffffe2d0e9c7028 
%r8  = 0x0001dc9e577ddd1f                 %r15 = 0x0000000000000000 

%rip = 0xfffffffffb888350 
%rbp = 0xfffffe00413b3e20
%rsp = 0xfffffe00413b3d88
%rflags = 0x00000246
  id=0 vip=0 vif=0 ac=0 vm=0 rf=0 nt=0 iopl=0x0
  status=<of,df,IF,tf,sf,ZF,af,PF,cf>

%cs = 0x0030    %ds = 0x004b    %es = 0x004b    %fs = 0x0000
%gs = 0x0000    %gsbase = 0xfffffffffbc3f000    %kgsbase = 0x0
%trapno = 0x0   %err = 0x0      %cr2 = 0x848000 %cr3 = 0x83fca4000
[0]> 

[leftwo]

Putting logs in /staff/core/propolis-1207

[iximeow]

with a bit of unholy bash i've pulled together what all the VM is doing and i think this is a manifestation of https://www.illumos.org/issues/5924, but i have no idea Why Now or anything along those lines. i also snuck illumos-cds0.toml into staff with the other debugging information in case we care to ask what the VM configuration was (32 vCPUs, 32GiB of memory, an NVMe root block device, an NVMe raw zvol, and a virtio nic.

so, what i did was roughly for i in $(seq 0 31); do echo "CPU $i" >> cpustacks; mdb -b <uuid> -e "0t$i::cpustack" >> cpustacks; done followed by taking the boot disk, copying it, booting that in a propolis-standalone, and

for line in $(cat cpustacks); do
    if echo "$line" | grep 0xff 1>/dev/null; then
        ssh -i /save/ixi/id_ed25519_tmp 192.168.100.2 \
            "mdb -ke '$(echo "$line" | cut -b -18)::dis -b -n 1' | head -n 1 | tail -n 1" >>decorated
    else
        echo "$line" >>decorated
    fi
done

(all while another mdb -b <the-vm> is making sure it's good and stopped, so we have a point-in-time image of the guest)

i'm not about to say it's good that booting a copy of the disk in another VM put the kernel and modules all at the same addresses again, but it certainly is convenient as a way to find out where things are... and so propolis-1207-vcpu-stacks has all 32 vCPUs' stacks in terms of where the guest illumos has things. for example, CPU 0 is handling a page fault:

CPU 0
fffffffffb8acd2d  mutex_vector_enter+0xbd:              movq   0x0(%r13),%r12
fffffffffb838aa8  htable_steal_active+0x58:             call   +0x4f893 <mutex_enter>
fffffffffb838e40  htable_steal+0x150:                   call   -0x3f5   <htable_steal_active>
fffffffffb839152  htable_alloc+0x182:                   call   -0x467   <htable_steal>
fffffffffb839b6e  htable_create+0x10e:                  call   -0xba3   <htable_alloc>
fffffffffb8319e0  hati_load_common+0x1b0:               call   +0x807b  <htable_create>
fffffffffb831bd0  hat_memload+0x70:                     call   -0x3a5   <hati_load_common>
fffffffffb8b42d0  segkmem_xalloc+0xb0:                  call   -0x82775 <hat_memload>
fffffffffb8b43f7  segkmem_alloc_vn+0x37:                call   -0x1dc   <segkmem_xalloc>
fffffffffb8b44db  segkmem_alloc+0x1b:                   call   -0x120   <segkmem_alloc_vn>
fffffffffbb049e4  vmem_xalloc+0x4e4:                    call   -0x27c069
fffffffffbb05034  vmem_alloc+0x134:                     call   -0xb39   <vmem_xalloc>
fffffffffbb04002  vmem_populate+0x102:                  call   +0xef9   <vmem_alloc>
fffffffffbb050a6  vmem_alloc+0x1a6:                     call   -0x11ab  <vmem_populate>
fffffffffba17b03  kmem_slab_create+0x73:                call   +0xed3f8 <vmem_alloc>
fffffffffba18126  kmem_slab_alloc+0x106:                call   -0x69b   <kmem_slab_create>
fffffffffba195b6  kmem_cache_alloc+0x156:               call   -0x159b  <kmem_slab_alloc>
fffffffffba19821  kmem_cpucache_magazine_alloc+0xa1:    call   -0x3c6   <kmem_cache_alloc>
fffffffffba1991b  kmem_cache_free+0x9b:                 call   -0x1a0   <kmem_cpucache_magazine_alloc>
fffffffffb835645  hment_free+0x65:                      call   +0x1e4236
fffffffffb832724  hat_pte_unmap+0x184:                  call   +0x2eb7  <hment_free>
fffffffffb838b93  htable_steal_active+0x143:            call   -0x65f8  <hat_pte_unmap>
fffffffffb838e40  htable_steal+0x150:                   call   -0x3f5   <htable_steal_active>
fffffffffb839152  htable_alloc+0x182:                   call   -0x467   <htable_steal>
fffffffffb839b6e  htable_create+0x10e:                  call   -0xba3   <htable_alloc>
fffffffffb8319e0  hati_load_common+0x1b0:               call   +0x807b  <htable_create>
fffffffffb831bd0  hat_memload+0x70:                     call   -0x3a5   <hati_load_common>
fffffffffb831c40  hat_memload_region+0x20:              call   -0xe5    <hat_memload>
fffffffffba7c9f5  segvn_faultpage+0x2a5:                call   -0x24adda
fffffffffba80acc  segvn_fault+0xa2c:                    call   -0x4381  <segvn_faultpage>
fffffffffbb0cc7d  as_fault+0x1ad:                       call   -0x284302
fffffffffb86d648  pagefault+0x98:                       call   +0x29f483
fffffffffb86b4c5  trap+0x1005:                          call   +0x20e6  <pagefault>
fffffffffb8001d4  cmntrap_pushed+0x37:                  call   +0x6a2e7 <trap>

CPU 1 is somewhere in the way of servicing a read:

CPU 1
fffffffffb88834b  mutex_enter+0xb:                      lock cmpxchgq %rdx,(%rdi)
fffffffffb838e40  htable_steal+0x150:                   call   -0x3f5   <htable_steal_active>
fffffffffb839152  htable_alloc+0x182:                   call   -0x467   <htable_steal>
fffffffffb839b6e  htable_create+0x10e:                  call   -0xba3   <htable_alloc>
fffffffffb8319e0  hati_load_common+0x1b0:               call   +0x807b  <htable_create>
fffffffffb831bd0  hat_memload+0x70:                     call   -0x3a5   <hati_load_common>
fffffffffb8b42d0  segkmem_xalloc+0xb0:                  call   -0x82775 <hat_memload>
fffffffffb8b43f7  segkmem_alloc_vn+0x37:                call   -0x1dc   <segkmem_xalloc>
fffffffffb8b450b  segkmem_zio_alloc+0x1b:               call   -0x150   <segkmem_alloc_vn>
fffffffffbb049e4  vmem_xalloc+0x4e4:                    call   -0x27c069
fffffffffbb05034  vmem_alloc+0x134:                     call   -0xb39   <vmem_xalloc>
fffffffffba17b03  kmem_slab_create+0x73:                call   +0xed3f8 <vmem_alloc>
fffffffffba18126  kmem_slab_alloc+0x106:                call   -0x69b   <kmem_slab_create>
fffffffffba195b6  kmem_cache_alloc+0x156:               call   -0x159b  <kmem_slab_alloc>
fffffffff39621f0  abd_alloc_chunk+0x10:                 call   +0x80b726b
fffffffff39623f2  abd_alloc+0xf2:                       call   -0x217   <abd_alloc_chunk>
fffffffff39693da  arc_get_data_abd+0x5a:                call   -0x70df  <abd_alloc>
fffffffff3966db7  arc_hdr_alloc_pabd+0x77:              call   +0x25c4  <arc_get_data_abd>
fffffffff3967006  arc_hdr_alloc+0x126:                  call   -0x2cb   <arc_hdr_alloc_pabd>
fffffffff396a890  arc_read+0x5f0:                       call   -0x39b5  <arc_hdr_alloc>
fffffffff3977f17  dbuf_read_impl+0x207:                 call   -0xdc7c  <arc_read>
fffffffff39786a5  dbuf_read+0xd5:                       call   -0x99a   <dbuf_read_impl>
fffffffff3980d38  dmu_buf_hold_array_by_dnode+0x108:    call   -0x876d  <dbuf_read>
fffffffff39826ff  dmu_read_uio_dnode+0x4f:              call   -0x1ad4  <dmu_buf_hold_array_by_dnode>
fffffffff398287c  dmu_read_uio_dbuf+0x4c:               call   -0x1d1   <dmu_read_uio_dnode>
fffffffff3a6c403  zfs_read+0x173:                       call   -0xe9bd8 <dmu_read_uio_dbuf>
fffffffffbb21808  fop_read+0x58:                        call   -0x298e8d
fffffffffba68c9c  pread+0x19c:                          call   +0xb8b0f <fop_read>
fffffffffb800bc9  sys_syscall+0x178:                    call   +0x87db2 <__x86_indirect_thunk_rax>

CPU 2 is also allocating memory (in service of a read):

CPU 2
fffffffffb88834b  mutex_enter+0xb:                      lock cmpxchgq %rdx,(%rdi)
fffffffffb838e40  htable_steal+0x150:                   call   -0x3f5   <htable_steal_active>
fffffffffb839152  htable_alloc+0x182:                   call   -0x467   <htable_steal>
fffffffffb839b6e  htable_create+0x10e:                  call   -0xba3   <htable_alloc>
fffffffffb8319e0  hati_load_common+0x1b0:               call   +0x807b  <htable_create>
fffffffffb831bd0  hat_memload+0x70:                     call   -0x3a5   <hati_load_common>
fffffffffb8b42d0  segkmem_xalloc+0xb0:                  call   -0x82775 <hat_memload>
fffffffffb8b43f7  segkmem_alloc_vn+0x37:                call   -0x1dc   <segkmem_xalloc>
[.. snip ..]

and .. except for CPUs 5, 19, 21, 23, 25, 30, and 31, everyone is somewhere under htable_steal_active. most of those outlier CPUs are all idle, and look like:

CPU 1f
fffffffffb85b3ba  mach_cpu_idle+0xa:                    hlt    
fffffffffb8599ce  cpu_idle+0xfe:                        call   +0x19dd  <mach_cpu_idle>
fffffffffb8598a4  cpu_idle_adaptive+0x14:               call   +0x2f0d7 <__x86_indirect_thunk_rax>
fffffffffb89ec83  idle+0xa3:                            call   -0x162a8 <__x86_indirect_thunk_rdx>
fffffffffb88a276  thread_start+6:                       call   -0x18fb  <__x86_indirect_thunk_rax>

CPU 5 is in the middle of a swtch():

CPU 5
fffffffffb8887f7  mutex_delay_default+7:                decq   %r11
fffffffffb8ad7a5  lock_set_spl_spin+0x95:               call   -0x24e2a <__x86_indirect_thunk_rax>
fffffffffb9cc6b1  disp_lock_enter+0x21:                 call   -0x144436
fffffffffb89ee68  disp+0x68:                            call   +0x12d823
fffffffffb89f0a6  swtch+0xb6:                           call   -0x2ab   <disp>
fffffffffb89ec97  idle+0xb7:                            call   +0x354   <swtch>
fffffffffb88a276  thread_start+6:                       call   -0x18fb  <__x86_indirect_thunk_rax>

i don't think the VM is necessarily deadlocked, but it definitely is not making useful progress. i say this because while most vCPUs are somewhere around trying to acquire the mutex, CPU 7 is clearly done with it:

CPU 7
fffffffff38bfbd0  apix_setspl:                          pushq  %rbp
fffffffffb88831a  lock_clear_splx+0xa:                  call   -0x93f   <splx>
fffffffffb9cc728  disp_lock_exit+0x68:                  call   -0x14441d
fffffffffbaf3be3  turnstile_exit+0x43:                  call   -0x127528
fffffffffb8ad233  mutex_vector_exit+0xc3:               call   +0x246968
fffffffffb838b03  htable_steal_active+0xb3:             call   +0x4f968 <mutex_exit>

... though i haven't checked that everyone is contending on the same mutex.

this all probably would be much more readily debugged from inside the guest with kmdb, which would trivially get us what mutexes are involved. Alan, if you want i think we can try extracting that from here, but if you could set the guest up to land in kmdb on NMI (or at least get a guest core) that would be a much more useful way to spend time.