226142 – [bhyve] [panic] mtx_lock_spin: recursed on non-recursive mutex vcpu lock @ /usr/src/sys/amd64/vmm/vmm.c:2246

Bug 226142 - [bhyve] [panic] mtx_lock_spin: recursed on non-recursive mutex vcpu lock @ /usr/src/sys/amd64/vmm/vmm.c:2246

Summary: [bhyve] [panic] mtx_lock_spin: recursed on non-recursive mutex vcpu lock @ /u...

Status:	Closed FIXED

Alias:	None

Product:	Base System
Classification:	Unclassified
Component:	kern (show other bugs)
Version:	CURRENT
Hardware:	amd64 Any

Importance:	--- Affects Only Me
Assignee:	freebsd-virtualization (Nobody)

URL:
Keywords:

Depends on:
Blocks:

Reported:	2018-02-23 16:48 UTC by Dave Cottlehuber
Modified:	2018-04-14 20:52 UTC (History)
CC List:	2 users (show)

See Also:

Attachments
Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.

Description Dave Cottlehuber freebsd_committer

2018-02-23 16:48:37 UTC

# info

- 100% reproducible on starting a bhyve-based vm using vmrun.sh
- recent current r329831, also panics at r329531
- GENERIC + WITH_CTF=1 and DEBUG=-g
- I'll bisect over the next few days to see if I can narrow the commits down
- previously reported on current@ mailing list to no avail

# panic dmesg

[36984] panic: mtx_lock_spin: recursed on non-recursive mutex vcpu lock @ /usr/src/sys/amd64/vmm/vmm.c:2246
[36984] 
[36984] cpuid = 3
[36984] time = 1519121280
[36984] KDB: stack backtrace:
[36984] db_trace_self_wrapper() at db_trace_self_wrapper+0x2b/frame 0xfffffe020c272360
[36984] vpanic() at vpanic+0x18d/frame 0xfffffe020c2723c0
[36984] vpanic() at vpanic/frame 0xfffffe020c272440
[36984] __mtx_lock_spin_flags() at __mtx_lock_spin_flags+0x148/frame 0xfffffe020c272480
[36984] vcpu_get_state() at vcpu_get_state+0x44/frame 0xfffffe020c2724c0
[36984] vmx_pending_intr() at vmx_pending_intr+0xc6/frame 0xfffffe020c272500
[36984] vm_run() at vm_run+0x759/frame 0xfffffe020c272600
[36984] vmmdev_ioctl() at vmmdev_ioctl+0x86b/frame 0xfffffe020c2726a0
[36984] devfs_ioctl() at devfs_ioctl+0xcb/frame 0xfffffe020c2726f0
[36984] VOP_IOCTL_APV() at VOP_IOCTL_APV+0xd9/frame 0xfffffe020c272720
[36984] vn_ioctl() at vn_ioctl+0x124/frame 0xfffffe020c272830
[36984] devfs_ioctl_f() at devfs_ioctl_f+0x1f/frame 0xfffffe020c272850
[36984] kern_ioctl() at kern_ioctl+0x2b9/frame 0xfffffe020c2728b0
[36984] sys_ioctl() at sys_ioctl+0x15c/frame 0xfffffe020c272980
[36984] amd64_syscall() at amd64_syscall+0x79b/frame 0xfffffe020c272ab0
[36984] fast_syscall_common() at fast_syscall_common+0x101/frame 0x7fffdddecee0
[36984] KDB: enter: panic

# debugger

db:0:kdb.enter.panic>  run lockinfo
db:1:lockinfo> show locks
db:1:locks>  show alllocks
db:1:alllocks>  show lockedvnods
Locked vnodes
db:0:kdb.enter.panic>  show pcpu
cpuid        = 3
dynamic pcpu = 0xfffffe0084b95800
curthread    = 0xfffff8017ad76560: pid 12951 tid 103324 "vcpu 0"
curpcb       = 0xfffffe020c272b80
fpcurthread  = none
idlethread   = 0xfffff8010764f560: tid 100006 "idle: cpu3"
curpmap      = 0xfffff80dbaba5130
tssp         = 0xffffffff81d8bfd8
commontssp   = 0xffffffff81d8bfd8
rsp0         = 0xfffffe020c272b80
gs32p        = 0xffffffff81d92c10
ldt          = 0xffffffff81d92c50
tss          = 0xffffffff81d92c40
curvnet      = 0
spin locks held:
db:0:kdb.enter.panic>  bt
Tracing pid 12951 tid 103324 td 0xfffff8017ad76560
kdb_enter() at kdb_enter+0x3b/frame 0xfffffe020c272360
vpanic() at vpanic+0x1aa/frame 0xfffffe020c2723c0
vpanic() at vpanic/frame 0xfffffe020c272440
__mtx_lock_spin_flags() at __mtx_lock_spin_flags+0x148/frame 0xfffffe020c272480
vcpu_get_state() at vcpu_get_state+0x44/frame 0xfffffe020c2724c0
vmx_pending_intr() at vmx_pending_intr+0xc6/frame 0xfffffe020c272500
vm_run() at vm_run+0x759/frame 0xfffffe020c272600
vmmdev_ioctl() at vmmdev_ioctl+0x86b/frame 0xfffffe020c2726a0
devfs_ioctl() at devfs_ioctl+0xcb/frame 0xfffffe020c2726f0
VOP_IOCTL_APV() at VOP_IOCTL_APV+0xd9/frame 0xfffffe020c272720
vn_ioctl() at vn_ioctl+0x124/frame 0xfffffe020c272830
devfs_ioctl_f() at devfs_ioctl_f+0x1f/frame 0xfffffe020c272850
kern_ioctl() at kern_ioctl+0x2b9/frame 0xfffffe020c2728b0
sys_ioctl() at sys_ioctl+0x15c/frame 0xfffffe020c272980
amd64_syscall() at amd64_syscall+0x79b/frame 0xfffffe020c272ab0
fast_syscall_common() at fast_syscall_common+0x101/frame 0x7fffdddecee0
db:0:kdb.enter.panic>  ps
  pid  ppid  pgrp   uid  state   wmesg   wchan               cmd
18384 99134 12632  1002  S+      select  0xfffff80152b4e9c0  ssh
12951 53776 53776     0  R+      (threaded)                  bhyve
101692                   S       kqread  0xfffff81c41243400  mevent
102880                   S       uwait   0xfffff80d4915e500  blk-3:0:0-0
102881                   S       uwait   0xfffff8025b2c5800  blk-3:0:0-1
102982                   S       uwait   0xfffff802d198b680  blk-3:0:0-2
102985                   S       uwait   0xfffff8015fdb6a00  blk-3:0:0-3
102988                   S       uwait   0xfffff80721bbab00  blk-3:0:0-4
102990                   S       uwait   0xfffff806a1161b00  blk-3:0:0-5
102994                   S       uwait   0xfffff8010a0db480  blk-3:0:0-6
103009                   S       uwait   0xfffff80aae76f700  blk-3:0:0-7
103016                   S       uwait   0xfffff8073b79d980  blk-4:0-0
103018                   S       uwait   0xfffff8010a0d8900  blk-4:0-1
103020                   S       uwait   0xfffff80618184780  blk-4:0-2
103022                   S       uwait   0xfffff802d198ba00  blk-4:0-3
103024                   S       uwait   0xfffff807ac4e2800  blk-4:0-4
103320                   S       uwait   0xfffff807ac4e2180  blk-4:0-5
103321                   S       uwait   0xfffff8015fdb5b80  blk-4:0-6
103322                   S       uwait   0xfffff807473e9900  blk-4:0-7
103323                   S       uwait   0xfffff80721c41b80  vtnet-5:0 tx
103324                   Run     CPU 3                       vcpu 0
100505                   Run     CPU 11                      vcpu 1
53776 38209 53776     0  Ss+     wait    0xfffff80d4942da70  sh
38209     1 38209     0  Ss      select  0xfffff80cca99d940  tmux
...


# head of dmesg

FreeBSD 12.0-CURRENT #6 r329611+f65afb3cfe82(master): Mon Feb 19 23:19:01 UTC 2018
    root@wintermute:/usr/obj/usr/src/amd64.amd64/sys/GENERIC amd64
FreeBSD clang version 6.0.0 (branches/release_60 325330) (based on LLVM 6.0.0)
WARNING: WITNESS option enabled, expect reduced performance.
VT(efifb): resolution 1280x1024
module_register: cannot register mmc/mmcsd from kernel; already loaded from mmcsd.ko
Module mmc/mmcsd failed to register: 17
CPU: Intel(R) Xeon(R) CPU E5-2667 v4 @ 3.20GHz (3200.07-MHz K8-class CPU)
  Origin="GenuineIntel"  Id=0x406f1  Family=0x6  Model=0x4f  Stepping=1
Features=0xbfebfbff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CLFLUSH,DTS,ACPI,MMX,FXSR,SSE,SSE2,SS,HTT,TM,PBE>
Features2=0x7ffefbff<SSE3,PCLMULQDQ,DTES64,MON,DS_CPL,VMX,SMX,EST,TM2,SSSE3,SDBG,FMA,CX16,xTPR,PDCM,PCID,DCA,SSE4.1,SSE4.2,x2APIC,MOVBE,POPCNT,TSCDLT,AESNI,XSAVE,OSXSAVE,AVX,F16C,RDRAND>
  AMD Features=0x2c100800<SYSCALL,NX,Page1GB,RDTSCP,LM>
  AMD Features2=0x121<LAHF,ABM,Prefetch>
  Structured Extended Features=0x21cbfbb<FSGSBASE,TSCADJ,BMI1,HLE,AVX2,SMEP,BMI2,ERMS,INVPCID,RTM,PQM,NFPUSG,PQE,RDSEED,ADX,SMAP,PROCTRACE>
  XSAVE Features=0x1<XSAVEOPT>
  VT-x: PAT,HLT,MTF,PAUSE,EPT,UG,VPID,VID,PostIntr
  TSC: P-state invariant, performance statistics
real memory  = 137434759168 (131068 MB)
avail memory = 133684940800 (127491 MB)
Event timer "LAPIC" quality 600
ACPI APIC Table: <SUPERM SMCI--MB>
FreeBSD/SMP: Multiprocessor System Detected: 16 CPUs
FreeBSD/SMP: 1 package(s) x 8 core(s) x 2 hardware threads
...

Comment 1 Peter Grehan freebsd_committer

2018-02-27 15:25:19 UTC

The issue (and a proposed fix) is discussed here
    https://reviews.freebsd.org/D14382

Comment 2 Dave Cottlehuber freebsd_committer

2018-02-27 18:53:40 UTC

Thanks Peter! giving it a whirl now; https://github.com/skunkwerks/freebsd/commit/e1f1fbb91c80d7f60801e2487c3e8761d61f7864 for a git-friendly branch.

Comment 3 Dave Cottlehuber freebsd_committer

2018-04-14 20:52:27 UTC

thanks to https://reviews.freebsd.org/D14548 and committed in r330615