[Bug 297648] mca(4) may deadlock on console output mutex

https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=297648

            Bug ID: 297648
           Summary: mca(4) may deadlock on console output mutex
           Product: Base System
           Version: 16.0-CURRENT
          Hardware: Any
                OS: Any
            Status: New
          Severity: Affects Only Me
          Priority: ---
         Component: kern
          Assignee: [email protected]
          Reporter: [email protected]
                CC: [email protected]

Document a known very rare panic that happens when hardware is going to panic
anyway. Unlikely this will be fixed in near future, but better have it
documented so that it can be found by searches. Also, a comment in the source
code will point here.

When mca(4) logs, it first obtains mca_msg_buf lock and kernel printf(9) later
obtains cnputs_mtx lock.  The latter allows recursion, thus a case when an MCA
interrupt is serviced by a thread interrupted during console output is covered.
 However, if a different CPU received MCA earlier, it would grab mca_msg_buf
lock first and then wait on cnputs_mtx, which is already owned by thread one. 
This is a deadlock.  It manifests itself in a panic that may look like:

spin lock 0xffffffff8164aab0 (mca_msg_buf) held by 0xfffff80198ff4780 (tid
102470) too long
spin lock 0xffffffff8164aab0 (mca_msg_buf) held by 0xfffff80198ff4780 (tid
102470) too long
spin lock 0xffffffff8164aab0 (mca_msg_buf) held by 0xfffff80198ff4780 (tid
102470) too long
spin lock 0xffffffff8164aab0 (mca_msg_buf)panic: spin lock held too long
cpuid = 2
time = 1787017227
KDB: stack backtrace:
db_trace_self_wrapper() at db_trace_self_wrapper+0x36/frame 0xfffffe0070647b70
vpanic() at vpanic+0x149/frame 0xfffffe0070647ca0
panic() at panic+0x43/frame 0xfffffe0070647d00
_mtx_lock_indefinite_check() at _mtx_lock_indefinite_check+0x64/frame
0xfffffe0070647d10
_mtx_lock_spin_cookie() at _mtx_lock_spin_cookie+0xe4/frame 0xfffffe0070647d80
mca_log() at mca_log+0xaa8/frame 0xfffffe0070647e20
mca_scan() at mca_scan+0x4d7/frame 0xfffffe0070647ee0
mca_intr() at mca_intr+0x4b/frame 0xfffffe0070647f20
mchk_calltrap() at mchk_calltrap+0x8/frame 0xfffffe0070647f20
--- trap 0x1c, rip = 0xffffffff80cb03a4, rsp = 0xfffffe0343d47280, rbp =
0xfffffe0343d472c0 ---
DELAY() at DELAY+0x74/frame 0xfffffe0343d472c0
ns8250_putc() at ns8250_putc+0x126/frame 0xfffffe0343d472f0
uart_cnputc() at uart_cnputc+0x52/frame 0xfffffe0343d47320
cnputc() at cnputc+0x4b/frame 0xfffffe0343d47350
cnputsn() at cnputsn+0x6a/frame 0xfffffe0343d47380
putchar() at putchar+0x189/frame 0xfffffe0343d47410
kvprintf() at kvprintf+0x12d8/frame 0xfffffe0343d47520
_vprintf() at _vprintf+0x8b/frame 0xfffffe0343d47600
printf() at printf+0x5e/frame 0xfffffe0343d47660
cam_error_print() at cam_error_print+0x3d/frame 0xfffffe0343d47880
cam_periph_error() at cam_periph_error+0x325/frame 0xfffffe0343d47e00
ndadone() at ndadone+0xd0/frame 0xfffffe0343d47e60
xpt_done_process() at xpt_done_process+0x3a0/frame 0xfffffe0343d47ea0
xpt_done_td() at xpt_done_td+0x125/frame 0xfffffe0343d47ef0
fork_exit() at fork_exit+0x7b/frame 0xfffffe0343d47f30
fork_trampoline() at fork_trampoline+0xe/frame 0xfffffe0343d47f30

Note that this thread entered printf(9) from cam(4), but it could be any other
subsystem. If in kgdb you look at trace of tid 102470, that would be an MCA
interrupt handler on a different CPU, that already owns mca_msg_buf and waits
on cnputs_mtx:

#6  cpu_lock_delay () at sys/x86/x86/delay.c:136
#7  0xffffffff808956c7 in _mtx_lock_indefinite_check (m=0x1070650a047569c,
m@entry=0xffffffff8157ed60 <cnputs_mtx>, ldap=0xa047569c,
ldap@entry=0xfffffe0070687d10) at sys/kern/kern_mutex.c:1259
#8  0xffffffff808952f4 in _mtx_lock_spin_cookie (c=0xffffffff8157ed78
<cnputs_mtx+24>, v=<optimized out>) at sys/kern/kern_mutex.c:793
#9  0xffffffff80841496 in cnputsn (p=0xffffffff8164ab60 <mca_msg_buf> "MCA:
Bank 9, Status 0xfe200000000c110a\nMCA: Global Cap 0x000000000f000c14, Status
0x", '0' <repeats 15 times>, "5\nMCA: Vendor \"GenuineIntel\", ID 0x50657, APIC
ID 4\nMCA: CPU 4 UNCOR EN PCC OVER GCACHE L2 ERR error\n"..., n=0x11c)
    at sys/kern/kern_cons.c:576
#10 0xffffffff808413cf in cnputs (p=0x1070650a047569c <error: Cannot access
memory at address 0x1070650a047569c>) at sys/kern/kern_cons.c:590
#11 0xffffffff80913f32 in prf_putbuf (bufr=0x1070650a047569c <error: Cannot
access memory at address 0x1070650a047569c>, flags=0x5, pri=0xffffffff) at
sys/kern/subr_prf.c:449
#12 0xffffffff80ca8d92 in mca_log (mode=<optimized out>,
rec=rec@entry=0xfffffe0070687e68, fatal=0x1) at sys/x86/x86/mca.c:753
#13 0xffffffff80ca7677 in mca_scan (mode=mode@entry=MCE,
recoverablep=recoverablep@entry=0xfffffe0070687eff) at sys/x86/x86/mca.c:1088
#14 0xffffffff80ca70eb in mca_intr () at sys/x86/x86/mca.c:1735

-- 
You are receiving this mail because:
You are the assignee for the bug.