Re: amd64-current: inteldrm: witness(4) warnings during boot
On Wed, Sep 16, 2020 at 02:03:21PM -0500, Scott Cheloha wrote: > Yesterday I enabled witness(4) to debug something unrelated and > started seeing traces during boot. > > My kernel is up-to-date as of yesterday night. My inteldrm firmware > is also up-to-date. > > The traces appear during every cold boot. Here is the most recent set > from my last reboot, plucked from the dmesg: linux style SINGLE_DEPTH_NESTING annotations do not map cleanly to witness. All the drm witness traces never seem to be helpful but there is no way to indicate that people should not report them. > > root on sd0a (847a92f1384e1964.a) swap on sd0b dump on sd0b > witness: lock order reversal: > 1st 0xfd844b4aad98 i915_active (>mutex) > 2nd 0x8026ff10 vmlk (>mutex) > lock order ">mutex"(rwlock) -> ">mutex"(rwlock) first seen at: > #0 witness_checkorder+0x466 > #1 rw_enter+0x67 > #2 i915_active_acquire+0x47 > #3 i915_vma_pin+0x2c4 > #4 i915_ggtt_pin+0x62 > #5 intel_gt_init+0xb9 > #6 i915_gem_init+0xa3 > #7 i915_driver_probe+0x821 > #8 inteldrm_attachhook+0x45 > #9 config_process_deferred_mountroot+0x6b > #10 main+0x723 > lock order ">mutex"(rwlock) -> ">mutex"(rwlock) first seen at: > #0 witness_checkorder+0x466 > #1 rw_enter+0x67 > #2 i915_vma_pin+0x250 > #3 i915_ggtt_pin+0x62 > #4 intel_ring_pin+0x65 > #5 __intel_context_active+0x33 > #6 i915_active_acquire+0x85 > #7 __intel_context_do_pin+0x3b > #8 intel_engines_init+0x4e1 > #9 intel_gt_init+0x130 > #10 i915_gem_init+0xa3 > #11 i915_driver_probe+0x821 > #12 inteldrm_attachhook+0x45 > #13 config_process_deferred_mountroot+0x6b > #14 main+0x723 > witness: acquiring duplicate lock of same type: ">mutex" > 1st i915_active > 2nd i915_active > Starting stack trace... > witness_checkorder(80eb23c8,9,0) at witness_checkorder+0x809 > rw_enter(80eb23b8,11) at rw_enter+0x67 > i915_active_acquire(80eb23b0) at i915_active_acquire+0x47 > __intel_context_active(fd844b4aad80) at __intel_context_active+0x4d > i915_active_acquire(fd844b4aad80) at i915_active_acquire+0x85 > __intel_context_do_pin(fd844b4aacb0) at __intel_context_do_pin+0x3b > intel_engines_init(80272060) at intel_engines_init+0x4e1 > intel_gt_init(80272060) at intel_gt_init+0x130 > i915_gem_init(8026d000) at i915_gem_init+0xa3 > i915_driver_probe(8026d000,82029be8) at > i915_driver_probe+0x821 > inteldrm_attachhook(8026d000) at inteldrm_attachhook+0x45 > config_process_deferred_mountroot() at config_process_deferred_mountroot+0x6b > main(0) at main+0x723 > end trace frame: 0x0, count: 244 > End of stack trace. > inteldrm0: 2560x1440, 32bpp > wsdisplay0 at inteldrm0 mux 1: console (std, vt100 emulation), using wskbd0 > wsdisplay0: screen 1-5 added (std, vt100 emulation) > iwm0: hw rev 0x230, fw ver 34.0.1, address 98:3b:8f:ef:6b:ef > witness: acquiring duplicate lock of same type: ">mutex" > 1st wakeref.mutex > 2nd wakeref.mutex > Starting stack trace... > witness_checkorder(80272500,9,0) at witness_checkorder+0x809 > rw_enter_write(802724f0) at rw_enter_write+0x43 > __intel_wakeref_get_first(802724e8) at __intel_wakeref_get_first+0x28 > __engine_unpark(8086c180) at __engine_unpark+0x46 > __intel_wakeref_get_first(8086c180) at __intel_wakeref_get_first+0x4a > i915_active_acquire_preallocate_barrier(fd83d3bf5d88,8086c000) at > i915_active_acquire_preallocate_barrier+0xa8 > __intel_context_do_pin(fd83d3bf5cb8) at __intel_context_do_pin+0xa6 > i915_gem_do_execbuffer(8026d078,81364000,8000451ff000,8135a800,0) > at i915_gem_do_execbuffer+0x288f > i915_gem_execbuffer2_ioctl(8026d078,8000451ff000,81364000) > at i915_gem_execbuffer2_ioctl+0x1da > drm_do_ioctl(8026d078,100,80406469,8000451ff000) at > drm_do_ioctl+0x274 > drmioctl(15700,80406469,8000451ff000,3,8000452c2f98) at drmioctl+0xdc > VOP_IOCTL(fd83d1e435c8,80406469,8000451ff000,3,fd8450fa8480,8000452c2f98) > at VOP_IOCTL+0x55 > vn_ioctl(fd83d22725f8,80406469,8000451ff000,8000452c2f98) at > vn_ioctl+0x75 > sys_ioctl(8000452c2f98,8000451ff110,8000451ff170) at > sys_ioctl+0x2d4 > syscall(8000451ff1e0) at syscall+0x389 > Xsyscall() at Xsyscall+0x128 > end of kernel > end trace frame: 0x7f7ca3a0, count: 241 > End of stack trace. > witness: acquiring duplicate lock of same type: ">lock" > 1st >lock > 2nd >lock > Starting stack trace... > witness_checkorder(8147a628,9,0) at witness_checkorder+0x809 > mtx_enter(8147a618) at mtx_enter+0x3c > i915_active_ref(814a2bf0,81477000,8147a2e8) at > i915_active_ref+0x1fd > i915_vma_move_to_active(814a2af8,8147a2e8,8018) at > i915_vma_move_to_active+0x5c > i915_gem_do_execbuffer(8026d078,81364000,8000451ff000,81483000,0) > at i915_gem_do_execbuffer+0x323a >
panic: ieee80211_encrypt: key unset for sw crypto: 0 on 6.8-beta
This one seems random, on that machine I see it first time. CVS checkout
is basically the build time as I first do cvs up and then make.
OpenBSD 6.8-beta (GENERIC.MP) #73: Sun Sep 13 15:23:23 UTC 2020
r...@pc1.home.local:/home/mkucharski/openbsd/src/sys/arch/amd64/compile/GENERIC.MP
# ls -1 /var/db/pkg/ | grep -e -firmware-
athn-firmware-1.1p4
vmm-firmware-1.11.0p3
panic: ieee80211_encrypt: key unset for sw crypto: 0
Stopped at db_enter+0x10: popq%rbp
TIDPIDUID PRFLAGS PFLAGS CPU COMMAND
db_enter() at db_enter+0x10
panic(81e14354) at panic+0x12a
ieee80211_encrypt(8009c048,fd80cfe73900,80cab1a8) at
ieee80211_encrypt+0x5f
ar5008_tx(8009c000,fd80cfe73900,80cab000,0) at
ar5008_tx+0x179
athn_start(8009c048) at athn_start+0x108
ar5008_intr(8009c000) at ar5008_intr+0x216
intr_handler(8000225ae400,8008e600) at intr_handler+0x6e
Xintr_ioapic_level3_untramp() at Xintr_ioapic_level3_untramp+0x1a3
acpicpu_idle() at acpicpu_idle+0x11f
sched_idle(820edff0) at sched_idle+0x27e
end trace frame: 0x0, count: 5
https://www.openbsd.org/ddb.html describes the minimum info required in bug
reports. Insufficient info makes it difficult to find and fix bugs.
ddb{0}> set $lines = 0
ddb{0}> set $maxwidth = 0
ddb{0}> show panic
ieee80211_encrypt: key unset for sw crypto: 0
ddb{0}> trace
db_enter() at db_enter+0x10
panic(81e14354) at panic+0x12a
ieee80211_encrypt(8009c048,fd80cfe73900,80cab1a8) at
ieee80211_encrypt+0x5f
ar5008_tx(8009c000,fd80cfe73900,80cab000,0) at
ar5008_tx+0x179
athn_start(8009c048) at athn_start+0x108
ar5008_intr(8009c000) at ar5008_intr+0x216
intr_handler(8000225ae400,8008e600) at intr_handler+0x6e
Xintr_ioapic_level3_untramp() at Xintr_ioapic_level3_untramp+0x1a3
acpicpu_idle() at acpicpu_idle+0x11f
sched_idle(820edff0) at sched_idle+0x27e
end trace frame: 0x0, count: -10
ddb{0}> show registers
rdi 0x820f80d0kprintf_mutex
rsi 0x5
rbp 0x8000225ae140
rbx 0x8000225ae150
rdx 0xc8000c10
rcx0x282
rax 0x1
r80x8000225ae100
r9 0
r10 0xc01573d4f68d778f
r11 0x98ddf1021cc7fae3
r12 0x38
r13 0x8000225ae1f0
r140x100
r15 0x81e14354pp_r600_decoded_lanes+0xebac
rip 0x81529ce0db_enter+0x10
cs 0x8
rflags 0x282
rsp 0x8000225ae140
ss 0x10
db_enter+0x10: popq%rbp
ddb{0}> show proc
PROC (idle0) pid=382939 stat=onproc
flags process=14000 proc=4200
pri=0, usrpri=50, nice=20
forw=0xd7981ee8b12181d4, list=0x8000f8b0,0x8000f158
process=0x8000d620 user=0x8000225a9000,
vmspace=0x821f2c58
estcpu=0, cpticks=23009481, pctcpu=0.0
user=0, sys=0, intr=1
ddb{0}> ps
PID TID PPIDUID S FLAGS WAIT COMMAND
53424 57045 38449 0 30x100082 nanosleep sleep
50116 356838 45021 0 30x100082 nanosleep sleep
22526 215536 10762 0 30x100083 ttyin ksh
75173 305461 1577 30x90 poll openvpn
58097 185498 10762 0 30x100083 ttyin ksh
10762 118644 1 0 30x100080 kqreadtmux
18237 308163 1 0 30x100083 ttyin getty
88227 59324 1 0 30x100098 poll cron
89706 370738 1 0 30x100080 htplevhotplugd
45021 254474 1 0 30x10008b pause sh
7678 418133 1 0 30x82 kqreadcupsd
41143 215752 1572 30x90 poll dbus-daemon
38449 510863 1 0 30x10008b pause sh
17512 407584 47024 95 30x100092 kqreadsmtpd
80599 455578 47024103 30x100092 kqreadsmtpd
82543 213560 47024 95 30x100092 kqreadsmtpd
99925 364250 47024 95 30x100092 kqreadsmtpd
76184 140593 47024 95 30x100092 kqreadsmtpd
68500 323266 47024 95 30x100092 kqreadsmtpd
47024 294473 1 0 30x100080 kqreadsmtpd
16207 418076 1 77 30x100090 poll dhcpd
58665 57312 1 0 30x80 selectsshd
85275 308189 1 0 30x100080 poll ntpd
88739 126290 33601 83 30x100092 poll ntpd
33601 497501 1 83 30x100092 poll ntpd
99690 334255 1 53 30x90 kqreadunbound
47579 222680
amd64-current: inteldrm: witness(4) warnings during boot
Yesterday I enabled witness(4) to debug something unrelated and started seeing traces during boot. My kernel is up-to-date as of yesterday night. My inteldrm firmware is also up-to-date. The traces appear during every cold boot. Here is the most recent set from my last reboot, plucked from the dmesg: root on sd0a (847a92f1384e1964.a) swap on sd0b dump on sd0b witness: lock order reversal: 1st 0xfd844b4aad98 i915_active (>mutex) 2nd 0x8026ff10 vmlk (>mutex) lock order ">mutex"(rwlock) -> ">mutex"(rwlock) first seen at: #0 witness_checkorder+0x466 #1 rw_enter+0x67 #2 i915_active_acquire+0x47 #3 i915_vma_pin+0x2c4 #4 i915_ggtt_pin+0x62 #5 intel_gt_init+0xb9 #6 i915_gem_init+0xa3 #7 i915_driver_probe+0x821 #8 inteldrm_attachhook+0x45 #9 config_process_deferred_mountroot+0x6b #10 main+0x723 lock order ">mutex"(rwlock) -> ">mutex"(rwlock) first seen at: #0 witness_checkorder+0x466 #1 rw_enter+0x67 #2 i915_vma_pin+0x250 #3 i915_ggtt_pin+0x62 #4 intel_ring_pin+0x65 #5 __intel_context_active+0x33 #6 i915_active_acquire+0x85 #7 __intel_context_do_pin+0x3b #8 intel_engines_init+0x4e1 #9 intel_gt_init+0x130 #10 i915_gem_init+0xa3 #11 i915_driver_probe+0x821 #12 inteldrm_attachhook+0x45 #13 config_process_deferred_mountroot+0x6b #14 main+0x723 witness: acquiring duplicate lock of same type: ">mutex" 1st i915_active 2nd i915_active Starting stack trace... witness_checkorder(80eb23c8,9,0) at witness_checkorder+0x809 rw_enter(80eb23b8,11) at rw_enter+0x67 i915_active_acquire(80eb23b0) at i915_active_acquire+0x47 __intel_context_active(fd844b4aad80) at __intel_context_active+0x4d i915_active_acquire(fd844b4aad80) at i915_active_acquire+0x85 __intel_context_do_pin(fd844b4aacb0) at __intel_context_do_pin+0x3b intel_engines_init(80272060) at intel_engines_init+0x4e1 intel_gt_init(80272060) at intel_gt_init+0x130 i915_gem_init(8026d000) at i915_gem_init+0xa3 i915_driver_probe(8026d000,82029be8) at i915_driver_probe+0x821 inteldrm_attachhook(8026d000) at inteldrm_attachhook+0x45 config_process_deferred_mountroot() at config_process_deferred_mountroot+0x6b main(0) at main+0x723 end trace frame: 0x0, count: 244 End of stack trace. inteldrm0: 2560x1440, 32bpp wsdisplay0 at inteldrm0 mux 1: console (std, vt100 emulation), using wskbd0 wsdisplay0: screen 1-5 added (std, vt100 emulation) iwm0: hw rev 0x230, fw ver 34.0.1, address 98:3b:8f:ef:6b:ef witness: acquiring duplicate lock of same type: ">mutex" 1st wakeref.mutex 2nd wakeref.mutex Starting stack trace... witness_checkorder(80272500,9,0) at witness_checkorder+0x809 rw_enter_write(802724f0) at rw_enter_write+0x43 __intel_wakeref_get_first(802724e8) at __intel_wakeref_get_first+0x28 __engine_unpark(8086c180) at __engine_unpark+0x46 __intel_wakeref_get_first(8086c180) at __intel_wakeref_get_first+0x4a i915_active_acquire_preallocate_barrier(fd83d3bf5d88,8086c000) at i915_active_acquire_preallocate_barrier+0xa8 __intel_context_do_pin(fd83d3bf5cb8) at __intel_context_do_pin+0xa6 i915_gem_do_execbuffer(8026d078,81364000,8000451ff000,8135a800,0) at i915_gem_do_execbuffer+0x288f i915_gem_execbuffer2_ioctl(8026d078,8000451ff000,81364000) at i915_gem_execbuffer2_ioctl+0x1da drm_do_ioctl(8026d078,100,80406469,8000451ff000) at drm_do_ioctl+0x274 drmioctl(15700,80406469,8000451ff000,3,8000452c2f98) at drmioctl+0xdc VOP_IOCTL(fd83d1e435c8,80406469,8000451ff000,3,fd8450fa8480,8000452c2f98) at VOP_IOCTL+0x55 vn_ioctl(fd83d22725f8,80406469,8000451ff000,8000452c2f98) at vn_ioctl+0x75 sys_ioctl(8000452c2f98,8000451ff110,8000451ff170) at sys_ioctl+0x2d4 syscall(8000451ff1e0) at syscall+0x389 Xsyscall() at Xsyscall+0x128 end of kernel end trace frame: 0x7f7ca3a0, count: 241 End of stack trace. witness: acquiring duplicate lock of same type: ">lock" 1st >lock 2nd >lock Starting stack trace... witness_checkorder(8147a628,9,0) at witness_checkorder+0x809 mtx_enter(8147a618) at mtx_enter+0x3c i915_active_ref(814a2bf0,81477000,8147a2e8) at i915_active_ref+0x1fd i915_vma_move_to_active(814a2af8,8147a2e8,8018) at i915_vma_move_to_active+0x5c i915_gem_do_execbuffer(8026d078,81364000,8000451ff000,81483000,0) at i915_gem_do_execbuffer+0x323a i915_gem_execbuffer2_ioctl(8026d078,8000451ff000,81364000) at i915_gem_execbuffer2_ioctl+0x1da drm_do_ioctl(8026d078,100,80406469,8000451ff000) at drm_do_ioctl+0x274 drmioctl(15700,80406469,8000451ff000,3,8000452c2f98) at drmioctl+0xdc VOP_IOCTL(fd83d1e435c8,80406469,8000451ff000,3,fd8450fa8480,8000452c2f98) at VOP_IOCTL+0x55 vn_ioctl(fd83d22725f8,80406469,8000451ff000,8000452c2f98) at vn_ioctl+0x75
