On Wed, Jun 19, 2024 at 6:58 AM Martin Pieuchot <m...@openbsd.org> wrote:
> This is a lock order reversal reported by WITNESS. Thankfully claudio@
> already committed a fix for this on the 16th. So please, try with
> up-to-date sources
Just to be paranoid, I built a kernel with recent sources and
MP_LOCKDEBUG and WITNESS. I experienced both the "lock spun out" error
after "starting network" -- but not on serial console, unfortunately
-- and from `make -j24` as mentioned which I did capture.
Here is the ddb session -- properly capturing each `mach ddbcpu` and
`trace` with hex this time:
__mp_lock_spin: 0xffffff8001292800 lock spun out
Stopped at __mp_lock+0x138: ldr w8, [x23,#712]
ddb{16}> __mp_lock_spin: 0xffffff8001292800 lock spun out
ddb{16}> show panic__mp_lock_spin: 0xffffff8001292800 lock spun out
the kernel did not panic
ddb{16}> trace
db_enter() at __mp_lock+0x134
__mp_lock() at svc_handler+0x42c
svc_handler() at do_el0_sync+0xc8
do_el0_sync() at handle_el0_sync+0x70
handle_el0_sync() at 0x479a436a0
--- trap ---
end of kernel
ddb{16}> mach ddbcpu 0
Stopped at __mp_lock+0x138: ldr w8, [x23,#712]
ddb{0}> trace
db_enter() at __mp_lock+0x134
__mp_lock() at aplintc_irq_handler+0x158
aplintc_irq_handler() at arm_cpu_irq+0x34
arm_cpu_irq() at handle_el1h_irq+0x68
handle_el1h_irq() at db_enter_ddb+0x268
db_enter_ddb() at kdb_trap+0x64
kdb_trap() at db_trapper+0x30
db_trapper() at handle_el1h_sync+0x68
handle_el1h_sync() at db_enter+0x14
db_enter() at aplintc_fiq_handler+0x6c
aplintc_fiq_handler() at arm_cpu_fiq+0x34
arm_cpu_fiq() at handle_el1h_fiq+0x68
handle_el1h_fiq() at aq_lookup+0x80
aq_intr() at arm_cpu_irq+0x34
arm_cpu_irq() at handle_el1h_irq+0x68
handle_el1h_irq() at do_el1h_sync+0x40
do_el1h_sync() at handle_el1h_sync+0x68
handle_el1h_sync() at db_enter+0x14
db_enter() at __mp_lock+0x134
__mp_lock() at softintr_biglock_wrap+0x14
softintr_biglock_wrap() at softintr_dispatch+0x84
softintr_dispatch() at arm_do_pending_intr+0xfc
arm_do_pending_intr() at arm_cpu_fiq+0x34
arm_cpu_fiq() at handle_el1h_fiq+0x68
handle_el1h_fiq() at mtx_enter+0xec
mtx_enter() at sched_idle+0x12c
sched_idle() at proc_trampoline+0xc
ddb{0}> mach ddbcpu 1
Stopped at aplintc_fiq_handler+0x70: b ffffff8000265cb0 <aplin
tc_fiq_handler+0x7c>
ddb{1}> trace
db_enter() at aplintc_fiq_handler+0x6c
aplintc_fiq_handler() at arm_cpu_fiq+0x34
arm_cpu_fiq() at handle_el1h_fiq+0x68
handle_el1h_fiq() at mtx_enter+0xec
mtx_enter() at mi_switch+0x2f0
mi_switch() at sched_idle+0x134
sched_idle() at proc_trampoline+0xc
ddb{1}> mach ddbcpu 2
Stopped at aplintc_fiq_handler+0x70: b ffffff8000265cb0 <aplin
tc_fiq_handler+0x7c>
ddb{2}> trace
db_enter() at aplintc_fiq_handler+0x6c
aplintc_fiq_handler() at arm_cpu_fiq+0x34
arm_cpu_fiq() at handle_el1h_fiq+0x68
handle_el1h_fiq() at mtx_enter+0xec
mtx_enter() at sched_idle+0x12c
sched_idle() at proc_trampoline+0xc
ddb{2}> mach ddbcpu 3
Stopped at aplintc_fiq_handler+0x70: b ffffff8000265cb0 <aplin
tc_fiq_handler+0x7c>
ddb{3}> trace
db_enter() at aplintc_fiq_handler+0x6c
aplintc_fiq_handler() at arm_cpu_fiq+0x34
arm_cpu_fiq() at handle_el1h_fiq+0x68
handle_el1h_fiq() at mtx_enter+0xb8
mtx_enter() at sched_idle+0x12c
sched_idle() at proc_trampoline+0xc
ddb{3}> mach ddbcpu 4
Stopped at aplintc_fiq_handler+0x70: b ffffff8000265cb0 <aplin
tc_fiq_handler+0x7c>
ddb{4}> trace
db_enter() at aplintc_fiq_handler+0x6c
aplintc_fiq_handler() at arm_cpu_fiq+0x34
arm_cpu_fiq() at handle_el1h_fiq+0x68
handle_el1h_fiq() at mtx_enter+0x114
mtx_enter() at sys_sched_yield+0x6c
sys_sched_yield() at svc_handler+0x478
svc_handler() at do_el0_sync+0xc8
do_el0_sync() at handle_el0_sync+0x70
handle_el0_sync() at 0x479a67b88
--- trap ---
end of kernel
ddb{4}> mach ddbcpu 5
Stopped at aplintc_fiq_handler+0x70: b ffffff8000265cb0 <aplin
tc_fiq_handler+0x7c>
ddb{5}> trace
db_enter() at aplintc_fiq_handler+0x6c
aplintc_fiq_handler() at arm_cpu_fiq+0x34
arm_cpu_fiq() at handle_el1h_fiq+0x68
handle_el1h_fiq() at cpu_idle_cycle+0x28
cpu_idle_cycle() at sched_idle+0x218
sched_idle() at proc_trampoline+0xc
ddb{5}> mach ddbcpu 6
Stopped at aplintc_fiq_handler+0x70: b ffffff8000265cb0 <aplin
tc_fiq_handler+0x7c>
ddb{6}> trace
db_enter() at aplintc_fiq_handler+0x6c
aplintc_fiq_handler() at arm_cpu_fiq+0x34
arm_cpu_fiq() at handle_el1h_fiq+0x68
handle_el1h_fiq() at __mp_lock+0x104
__mp_lock() at svc_handler+0x42c
svc_handler() at do_el0_sync+0xc8
do_el0_sync() at handle_el0_sync+0x70
handle_el0_sync() at 0x479a436a0
--- trap ---
end of kernel
ddb{6}> mach ddbcpu 7
Stopped at aplintc_fiq_handler+0x70: b ffffff8000265cb0 <aplin
tc_fiq_handler+0x7c>
ddb{7}> trace
db_enter() at aplintc_fiq_handler+0x6c
aplintc_fiq_handler() at arm_cpu_fiq+0x34
arm_cpu_fiq() at handle_el1h_fiq+0x68
handle_el1h_fiq() at __mp_lock+0x104
__mp_lock() at reaper+0x108
reaper() at proc_trampoline+0xc
ddb{7}> mach ddbcpu 8
Stopped at aplintc_fiq_handler+0x70: b ffffff8000265cb0 <aplin
tc_fiq_handler+0x7c>
ddb{8}> trace
db_enter() at aplintc_fiq_handler+0x6c
aplintc_fiq_handler() at arm_cpu_fiq+0x34
arm_cpu_fiq() at handle_el1h_fiq+0x68
handle_el1h_fiq() at mtx_enter+0xe4
mtx_enter() at exit1+0x534
exit1() at sys___threxit+0x4c
process_untrace() at svc_handler+0x44c
svc_handler() at do_el0_sync+0xc8
do_el0_sync() at handle_el0_sync+0x70
handle_el0_sync() at 0x479a436a0
--- trap ---
end of kernel
ddb{8}> mach ddbcpu 9
Stopped at aplintc_fiq_handler+0x70: b ffffff8000265cb0 <aplin
tc_fiq_handler+0x7c>
ddb{9}> trace
db_enter() at aplintc_fiq_handler+0x6c
aplintc_fiq_handler() at arm_cpu_fiq+0x34
arm_cpu_fiq() at handle_el1h_fiq+0x68
handle_el1h_fiq() at mtx_enter+0xe4
mtx_enter() at sleep_setup+0x58
sleep_setup() at rw_enter+0x154
rw_enter() at sys_futex+0x50
sys_futex() at svc_handler+0x478
svc_handler() at do_el0_sync+0xc8
do_el0_sync() at handle_el0_sync+0x70
handle_el0_sync() at 0x479a37d80
--- trap ---
end of kernel
ddb{9}> mach ddbcpu a
Symbol not found
ddb{9}> mach ddbcpu 0xa
Stopped at aplintc_fiq_handler+0x70: b ffffff8000265cb0 <aplin
tc_fiq_handler+0x7c>
ddb{10}> trace
db_enter() at aplintc_fiq_handler+0x6c
aplintc_fiq_handler() at arm_cpu_fiq+0x34
arm_cpu_fiq() at handle_el1h_fiq+0x68
handle_el1h_fiq() at mtx_enter+0x114
mtx_enter() at sleep_finish+0xb0
sleep_finish() at rw_enter+0x184
rw_enter() at sys_futex+0x50
sys_futex() at svc_handler+0x478
svc_handler() at do_el0_sync+0xc8
do_el0_sync() at handle_el0_sync+0x70
handle_el0_sync() at 0x479a37d80
--- trap ---
end of kernel
ddb{10}> mach ddbcpu 0xb
Stopped at aplintc_fiq_handler+0x70: b ffffff8000265cb0 <aplin
tc_fiq_handler+0x7c>
ddb{11}> trace
db_enter() at aplintc_fiq_handler+0x6c
aplintc_fiq_handler() at arm_cpu_fiq+0x34
arm_cpu_fiq() at handle_el1h_fiq+0x68
handle_el1h_fiq() at mtx_enter+0xe4
mtx_enter() at wakeup_n+0x44
wakeup_n() at sys_futex+0xf0
sys_futex() at svc_handler+0x478
svc_handler() at do_el0_sync+0xc8
do_el0_sync() at handle_el0_sync+0x70
handle_el0_sync() at 0x479a37d80
--- trap ---
end of kernel
ddb{11}> mach ddbcpu 0xc
Stopped at aplintc_fiq_handler+0x70: b ffffff8000265cb0 <aplin
tc_fiq_handler+0x7c>
ddb{12}> trace
db_enter() at aplintc_fiq_handler+0x6c
aplintc_fiq_handler() at arm_cpu_fiq+0x34
arm_cpu_fiq() at handle_el1h_fiq+0x68
handle_el1h_fiq() at cpu_idle_cycle+0x28
cpu_idle_cycle() at sched_idle+0x218
sched_idle() at proc_trampoline+0xc
ddb{12}> mach ddbcpu 0xd
Stopped at aplintc_fiq_handler+0x70: b ffffff8000265cb0 <aplin
tc_fiq_handler+0x7c>
ddb{13}> trace
db_enter() at aplintc_fiq_handler+0x6c
aplintc_fiq_handler() at arm_cpu_fiq+0x34
arm_cpu_fiq() at handle_el1h_fiq+0x68
handle_el1h_fiq() at __mp_lock+0x110
__mp_lock() at svc_handler+0x42c
svc_handler() at do_el0_sync+0xc8
do_el0_sync() at handle_el0_sync+0x70
handle_el0_sync() at 0x479a436a0
--- trap ---
end of kernel
ddb{13}> mach ddbcpu 0xe
Stopped at aplintc_fiq_handler+0x70: b ffffff8000265cb0 <aplin
tc_fiq_handler+0x7c>
ddb{14}> trace
db_enter() at aplintc_fiq_handler+0x6c
aplintc_fiq_handler() at arm_cpu_fiq+0x34
arm_cpu_fiq() at handle_el1h_fiq+0x68
handle_el1h_fiq() at mtx_enter+0xb0
mtx_enter() at mi_switch+0x2f0
mi_switch() at sys_sched_yield+0x8c
sys_sched_yield() at svc_handler+0x478
svc_handler() at do_el0_sync+0xc8
do_el0_sync() at handle_el0_sync+0x70
handle_el0_sync() at 0x479a67b88
--- trap ---
end of kernel
ddb{14}> mach ddbcpu 0xf
Stopped at aplintc_fiq_handler+0x70: b ffffff8000265cb0 <aplin
tc_fiq_handler+0x7c>
ddb{15}> trace
db_enter() at aplintc_fiq_handler+0x6c
aplintc_fiq_handler() at arm_cpu_fiq+0x34
arm_cpu_fiq() at handle_el1h_fiq+0x68
handle_el1h_fiq() at mtx_enter+0xe4
mtx_enter() at mi_switch+0x2f0
mi_switch() at sys_sched_yield+0x8c
sys_sched_yield() at svc_handler+0x478
svc_handler() at do_el0_sync+0xc8
do_el0_sync() at handle_el0_sync+0x70
handle_el0_sync() at 0x479a67b88
--- trap ---
end of kernel
ddb{15}> mach ddbcpu 0x10
Stopped at __mp_lock+0x138: ldr w8, [x23,#712]
ddb{16}> trace
db_enter() at __mp_lock+0x134
__mp_lock() at svc_handler+0x42c
svc_handler() at do_el0_sync+0xc8
do_el0_sync() at handle_el0_sync+0x70
handle_el0_sync() at 0x479a436a0
--- trap ---
end of kernel
ddb{16}> mach ddbcpu 0x11
Stopped at aplintc_fiq_handler+0x70: b ffffff8000265cb0 <aplin
tc_fiq_handler+0x7c>
ddb{17}> trace
db_enter() at aplintc_fiq_handler+0x6c
aplintc_fiq_handler() at arm_cpu_fiq+0x34
arm_cpu_fiq() at handle_el1h_fiq+0x68
handle_el1h_fiq() at cpu_idle_cycle+0x28
cpu_idle_cycle() at sched_idle+0x218
sched_idle() at proc_trampoline+0xc
ddb{17}> mach ddbcpu 0x12
Stopped at aplintc_fiq_handler+0x70: b ffffff8000265cb0 <aplin
tc_fiq_handler+0x7c>
ddb{18}> trace
db_enter() at aplintc_fiq_handler+0x6c
aplintc_fiq_handler() at arm_cpu_fiq+0x34
arm_cpu_fiq() at handle_el1h_fiq+0x68
handle_el1h_fiq() at cpu_idle_cycle+0x28
cpu_idle_cycle() at sched_idle+0x218
sched_idle() at proc_trampoline+0xc
ddb{18}> mach ddbcpu 0x13
Stopped at aplintc_fiq_handler+0x70: b ffffff8000265cb0 <aplin
tc_fiq_handler+0x7c>
ddb{19}> trace
db_enter() at aplintc_fiq_handler+0x6c
aplintc_fiq_handler() at arm_cpu_fiq+0x34
arm_cpu_fiq() at handle_el1h_fiq+0x68
handle_el1h_fiq() at cpu_idle_cycle+0x28
cpu_idle_cycle() at sched_idle+0x218
sched_idle() at proc_trampoline+0xc
ddb{19}> mach ddbcpu 0x14
Stopped at aplintc_fiq_handler+0x70: b ffffff8000265cb0 <aplin
tc_fiq_handler+0x7c>
ddb{20}> trace
db_enter() at aplintc_fiq_handler+0x6c
aplintc_fiq_handler() at arm_cpu_fiq+0x34
arm_cpu_fiq() at handle_el1h_fiq+0x68
handle_el1h_fiq() at cpu_idle_cycle+0x28
cpu_idle_cycle() at sched_idle+0x218
sched_idle() at proc_trampoline+0xc
ddb{20}> mach ddbcpu 0x15
Stopped at aplintc_fiq_handler+0x70: b ffffff8000265cb0 <aplin
tc_fiq_handler+0x7c>
ddb{21}> trace
db_enter() at aplintc_fiq_handler+0x6c
aplintc_fiq_handler() at arm_cpu_fiq+0x34
arm_cpu_fiq() at handle_el1h_fiq+0x68
handle_el1h_fiq() at cpu_idle_cycle+0x28
cpu_idle_cycle() at sched_idle+0x218
sched_idle() at proc_trampoline+0xc
ddb{21}> mach ddbcpu 0x16
Stopped at aplintc_fiq_handler+0x70: b ffffff8000265cb0 <aplin
tc_fiq_handler+0x7c>
ddb{22}> trace
db_enter() at aplintc_fiq_handler+0x6c
aplintc_fiq_handler() at arm_cpu_fiq+0x34
arm_cpu_fiq() at handle_el1h_fiq+0x68
handle_el1h_fiq() at __mp_lock+0x104
__mp_lock() at svc_handler+0x42c
svc_handler() at do_el0_sync+0xc8
do_el0_sync() at handle_el0_sync+0x70
handle_el0_sync() at 0x479a436a0
--- trap ---
end of kernel
ddb{22}> mach ddbcpu 0x17
Stopped at aplintc_fiq_handler+0x70: b ffffff8000265cb0 <aplin
tc_fiq_handler+0x7c>
ddb{23}> trace
db_enter() at aplintc_fiq_handler+0x6c
aplintc_fiq_handler() at arm_cpu_fiq+0x34
arm_cpu_fiq() at handle_el1h_fiq+0x68
handle_el1h_fiq() at mtx_enter+0xe4
mtx_enter() at sys_sched_yield+0x6c
sys_sched_yield() at svc_handler+0x478
svc_handler() at do_el0_sync+0xc8
do_el0_sync() at handle_el0_sync+0x70
handle_el0_sync() at 0x479a67b88
--- trap ---
end of kernel
ddb{23}> ps
PID TID PPID UID S FLAGS WAIT COMMAND
87284 314706 61748 1000 3 0x18000083 fsleep ld
*87284 429333 61748 1000 7 0x1c000003 ld
87284 190531 61748 1000 7 0x1c000003 ld
87284 165830 61748 1000 7 0x1c000003 ld
87284 404071 61748 1000 7 0x1c000003 ld
87284 341943 61748 1000 7 0x1c000003 ld
87284 330576 61748 1000 3 0x1c000023 ld
87284 208320 61748 1000 7 0x1c000003 ld
87284 365115 61748 1000 7 0x1c000003 ld
87284 87991 61748 1000 7 0x1c000003 ld
87284 482580 61748 1000 7 0x1c000003 ld
87284 170325 61748 1000 7 0x1c000003 ld
61748 491383 6076 1000 3 0x810008b sigsusp sh
6076 188509 93429 1000 3 0x810008b sigsusp sh
93429 461963 99665 1000 3 0x1810008b sigsusp make
99665 53468 73355 1000 3 0x800008b sigsusp tcsh
73355 226688 95347 1000 3 0x18000098 kqread sshd-session
95347 499852 24188 0 3 0x18000082 kqread sshd-session
20002 68265 1 35 3 0x18100090 kqread xconsole
33150 59657 1 0 3 0x18000080 sbwait xconsole
50672 395713 44884 0 3 0x18100080 kqread xenodm
69690 483270 67337 0 3 0x18100080 sbwait Xorg
74328 523358 1 0 3 0x18100083 ttyin getty
45486 251573 1 0 3 0x18100083 ttyin getty
27187 496538 1 0 3 0x18100083 ttyin getty
2863 31654 1 0 3 0x18100083 ttyin getty
19078 461890 1 0 3 0x18100083 ttyin getty
67337 424556 44884 35 3 0x18000092 kqread Xorg
67337 495093 44884 35 3 0x1c000092 kqread Xorg
44884 432936 1 0 3 0x18000088 sigsusp xenodm
25566 25699 1 0 3 0x18100098 kqread cron
64565 55956 1 99 3 0x19100090 kqread sndiod
89388 474083 1 110 3 0x18100090 kqread sndiod
398 220070 43267 95 3 0x19100092 kqread smtpd
7416 515617 43267 103 3 0x19100092 kqread smtpd
49178 375979 43267 95 3 0x19100092 kqread smtpd
85158 367781 43267 95 3 0x18100092 kqread smtpd
26299 385615 43267 95 3 0x19100092 kqread smtpd
42391 227692 43267 95 3 0x19100092 kqread smtpd
43267 135998 1 0 3 0x18100080 kqread smtpd
24188 507063 1 0 3 0x18000088 kqread sshd
81961 14601 1 0 3 0x18100080 kqread ntpd
1715 94321 70575 83 3 0x18100092 kqread ntpd
70575 270582 1 83 3 0x19100092 kqread ntpd
73400 373297 2023 74 3 0x19100092 bpf pflogd
2023 452188 1 0 3 0x18000080 sbwait pflogd
43901 12710 44193 73 3 0x19100090 kqread syslogd
44193 185533 1 0 3 0x18100082 sbwait syslogd
53462 369087 1 0 3 0x18100080 kqread resolvd
93095 447202 86164 77 3 0x18100092 kqread dhcpleased
6977 456365 86164 77 3 0x18100092 kqread dhcpleased
86164 15097 1 0 3 0x18000080 kqread dhcpleased
58677 468372 34282 115 3 0x18100092 kqread slaacd
30134 483954 34282 115 3 0x18100092 kqread slaacd
34282 431857 1 0 3 0x18100080 kqread slaacd
61486 218647 0 0 3 0x14200 bored wsdisplay0
61838 401446 0 0 3 0x14200 bored smr
34139 127591 0 0 3 0x14200 pgzero zerothread
92183 359449 0 0 3 0x14200 aiodoned aiodoned
13223 194947 0 0 3 0x14200 syncer update
75057 110178 0 0 3 0x14200 cleaner cleaner
93183 321483 0 0 7 0x14200 reaper
4435 190370 0 0 3 0x14200 pgdaemon pagedaemon
48989 90863 0 0 3 0x14200 usbtsk usbtask
59348 83534 0 0 3 0x14200 usbatsk usbatsk
46075 75523 0 0 3 0x14200 bored sensors
41605 298290 0 0 3 0x14200 bored sleep
82166 77699 0 0 3 0x40014200 idle23
58501 270995 0 0 3 0x40014200 idle22
49238 36032 0 0 7 0x40014200 idle21
14560 374269 0 0 7 0x40014200 idle20
30740 397107 0 0 7 0x40014200 idle19
82709 231848 0 0 7 0x40014200 idle18
4587 206789 0 0 7 0x40014200 idle17
96946 484610 0 0 3 0x40014200 idle16
45547 156727 0 0 3 0x40014200 idle15
16227 68226 0 0 3 0x40014200 idle14
16427 515737 0 0 3 0x40014200 idle13
87229 169229 0 0 7 0x40014200 idle12
21094 332559 0 0 3 0x40014200 idle11
37778 402429 0 0 3 0x40014200 idle10
19554 32522 0 0 3 0x40014200 idle9
45791 210281 0 0 3 0x40014200 idle8
21019 352782 0 0 3 0x40014200 idle7
68979 389356 0 0 3 0x40014200 idle6
91522 279642 0 0 7 0x40014200 idle5
9864 270704 0 0 3 0x40014200 idle4
25038 446573 0 0 7 0x40014200 idle3
17657 427801 0 0 7 0x40014200 idle2
85065 113503 0 0 7 0x40014200 idle1
44027 22065 0 0 3 0x14200 bored softnet3
58125 300036 0 0 3 0x14200 bored softnet2
34271 434229 0 0 3 0x14200 bored softnet1
3452 23091 0 0 3 0x14200 bored softnet0
81531 440363 0 0 3 0x14200 bored systqmp
56257 193002 0 0 3 0x14200 bored systq
87990 242261 0 0 3 0x14200 tmoslp softclockmp
3106 412165 0 0 3 0x40014200 tmoslp softclock
83105 99584 0 0 7 0x40014200 idle0
11466 75176 0 0 3 0x14200 kmalloc kmthread
1 80490 0 0 3 0x8000082 wait init
0 0 -1 0 3 0x10200 scheduler swapper
ddb{23}> show all locks
ddb{23}>
