Re: amd64-current: inteldrm: witness(4) warnings during boot

[Jonathan Gray]

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
> 

amd64-current: inteldrm: witness(4) warnings during boot

[Scott Cheloha]

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