Bug 111378 - [CI][DRMTIP]igt@perf_pmu@busy-no-semaphores-vcs0 - dmesg-warn- IRQs not enabled as expected
Summary: [CI][DRMTIP]igt@perf_pmu@busy-no-semaphores-vcs0 - dmesg-warn- IRQs not enabl...
Status: RESOLVED FIXED
Alias: None
Product: DRI
Classification: Unclassified
Component: DRM/Intel (show other bugs)
Version: DRI git
Hardware: Other All
: medium normal
Assignee: Intel GFX Bugs mailing list
QA Contact: Intel GFX Bugs mailing list
URL:
Whiteboard: ReadyForDev
Keywords:
Depends on:
Blocks:
 
Reported: 2019-08-12 11:00 UTC by Lakshmi
Modified: 2019-08-19 06:44 UTC (History)
2 users (show)

See Also:
i915 platform: BXT, BYT
i915 features: Perf/PMU

Attachments

Description Lakshmi 2019-08-12 11:00:29 UTC 
https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_340/fi-byt-j1900/igt@perf_pmu@busy-no-semaphores-vcs0.html

<4> [257.742909] ------------[ cut here ]------------
<4> [257.742916] IRQs not enabled as expected
<4> [257.742930] WARNING: CPU: 0 PID: 0 at kernel/softirq.c:169 __local_bh_enable_ip+0xa9/0x100
<4> [257.742936] Modules linked in: vgem snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic i915 btusb btrtl btbcm btintel snd_hda_intel snd_intel_nhlt bluetooth snd_hda_codec coretemp snd_hwdep crct10dif_pclmul snd_hda_core crc32_pclmul ecdh_generic ecc ghash_clmulni_intel snd_pcm r8169 realtek lpc_ich prime_numbers i2c_hid
<4> [257.742991] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G     U  W         5.3.0-rc3-g5d0a06cd532c-drmtip_340+ #1
<4> [257.742998] Hardware name: GIGABYTE GB-BXBT-1900/MZBAYAB-00, BIOS F6 02/17/2015
<4> [257.743008] RIP: 0010:__local_bh_enable_ip+0xa9/0x100
<4> [257.743017] Code: 37 5b 5d c3 8b 80 50 08 00 00 85 c0 75 a9 80 3d 0b be 25 01 00 75 a0 48 c7 c7 f3 0c 06 ac c6 05 fb bd 25 01 01 e8 77 84 ff ff <0f> 0b eb 89 48 89 ef e8 3b 41 06 00 eb 98 e8 e4 5c f4 ff 5b 5d c3
<4> [257.743025] RSP: 0018:ffffa78600003cb8 EFLAGS: 00010086
<4> [257.743035] RAX: 0000000000000000 RBX: 0000000000000200 RCX: 0000000000010302
<4> [257.743042] RDX: 0000000080010302 RSI: 0000000000000000 RDI: 00000000ffffffff
<4> [257.743050] RBP: ffffffffc0494bb3 R08: 0000000000000000 R09: 0000000000000001
<4> [257.743058] R10: 0000000014c8f0e9 R11: 00000000fee2ff8e R12: ffffa23ba8c38008
<4> [257.743065] R13: ffffa23bacc579c0 R14: ffffa23bb7db0f60 R15: ffffa23b9cc8c430
<4> [257.743074] FS:  0000000000000000(0000) GS:ffffa23bbba00000(0000) knlGS:0000000000000000
<4> [257.743082] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4> [257.743089] CR2: 00007fe477b20778 CR3: 000000011f72a000 CR4: 00000000001006f0
<4> [257.743096] Call Trace:
<4> [257.743104]  <IRQ>
<4> [257.743265]  __i915_request_commit+0x240/0x5d0 [i915]
<4> [257.743427]  ? __i915_request_create+0x228/0x4c0 [i915]
<4> [257.743584]  __engine_park+0x64/0x250 [i915]
<4> [257.743730]  ____intel_wakeref_put_last+0x1c/0x70 [i915]
<4> [257.743878]  i915_sample+0x2ee/0x310 [i915]
<4> [257.744030]  ? i915_pmu_cpu_offline+0xb0/0xb0 [i915]
<4> [257.744040]  __hrtimer_run_queues+0x11e/0x4b0
<4> [257.744068]  hrtimer_interrupt+0xea/0x250
<4> [257.744079]  ? lockdep_hardirqs_off+0x79/0xd0
<4> [257.744101]  smp_apic_timer_interrupt+0x96/0x280
<4> [257.744114]  apic_timer_interrupt+0xf/0x20
<4> [257.744125] RIP: 0010:__do_softirq+0xb3/0x4ae
<4> [257.744134] Code: 24 14 0a 00 00 00 48 c7 c7 26 d0 10 ac e8 45 83 8e ff 48 c7 c0 80 97 03 00 65 66 c7 00 00 00 e8 83 0f 5a ff fb b8 ff ff ff ff <41> 0f bc c7 83 c0 01 89 04 24 0f 84 d9 01 00 00 49 c7 c6 00 51 20
<4> [257.744142] RSP: 0018:ffffa78600003f58 EFLAGS: 00000206 ORIG_RAX: ffffffffffffff13
<4> [257.744152] RAX: 00000000ffffffff RBX: ffffffffac217800 RCX: 0000000000000000
<4> [257.744160] RDX: 0000000000000046 RSI: 0000000000000002 RDI: ffffffffac100781
<4> [257.744167] RBP: 0000000000000026 R08: 0000000000000000 R09: 0000000000000000
<4> [257.744175] R10: 0000000000000000 R11: 0000000000000000 R12: ffffffffac203da8
<4> [257.744182] R13: 0000000000000026 R14: 0000000000000000 R15: 0000000000000010
<4> [257.744194]  ? apic_timer_interrupt+0xa/0x20
<4> [257.744231]  ? __do_softirq+0xad/0x4ae
<4> [257.744256]  irq_exit+0xa9/0xc0
<4> [257.744266]  do_IRQ+0xb8/0x160
<4> [257.744283]  common_interrupt+0xf/0xf
<4> [257.744292]  </IRQ>
<4> [257.744302] RIP: 0010:cpuidle_enter_state+0xae/0x450
<4> [257.744312] Code: 44 00 00 31 ff e8 b2 85 90 ff 45 84 f6 74 12 9c 58 f6 c4 02 0f 85 78 03 00 00 31 ff e8 4b a3 97 ff e8 06 b5 9b ff fb 45 85 ed <0f> 88 c9 02 00 00 4c 2b 24 24 48 ba cf f7 53 e3 a5 9b c4 20 49 63
<4> [257.744319] RSP: 0018:ffffffffac203e58 EFLAGS: 00000202 ORIG_RAX: ffffffffffffffd9
<4> [257.744330] RAX: ffffffffac217800 RBX: ffffffffac2a0de0 RCX: 0000000000000000
<4> [257.744337] RDX: 0000000000000046 RSI: 0000000000000006 RDI: ffffffffac100781
<4> [257.744345] RBP: ffffa23bbba446a8 R08: 0000000000000000 R09: 0000000000000000
<4> [257.744352] R10: 0000000000000000 R11: 0000000000000000 R12: 0000003c026cb562
<4> [257.744360] R13: 0000000000000001 R14: 0000000000000000 R15: 0000000000000001
<4> [257.744397]  ? cpuidle_enter_state+0xaa/0x450
<4> [257.744423]  cpuidle_enter+0x24/0x40
<4> [257.744438]  do_idle+0x1f3/0x260
<4> [257.744455]  cpu_startup_entry+0x14/0x20
<4> [257.744467]  start_kernel+0x50d/0x52f
<4> [257.744486]  secondary_startup_64+0xa4/0xb0
<4> [257.744527] irq event stamp: 8085647
<4> [257.744537] hardirqs last  enabled at (8085646): [<ffffffffabc000ad>] __do_softirq+0xad/0x4ae
<4> [257.744547] hardirqs last disabled at (8085647): [<ffffffffab0019ea>] trace_hardirqs_off_thunk+0x1a/0x20
<4> [257.744557] softirqs last  enabled at (8085644): [<ffffffffab0bbe38>] irq_enter+0x58/0x60
<4> [257.744566] softirqs last disabled at (8085645): [<ffffffffab0bbee9>] irq_exit+0xa9/0xc0
<4> [257.744577] WARNING: CPU: 0 PID: 0 at kernel/softirq.c:169 __local_bh_enable_ip+0xa9/0x100
<4> [257.744584] ---[ end trace d3481cdadb973e3f ]---
<4> [257.744592] ------------[ cut here ]------------
<4> [257.744622] DEBUG_LOCKS_WARN_ON(current->hardirq_context)
<4> [257.744633] WARNING: CPU: 0 PID: 0 at kernel/locking/lockdep.c:3355 lockdep_hardirqs_on+0x146/0x1c0
<4> [257.744692] Modules linked in: vgem snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic i915 btusb btrtl btbcm btintel snd_hda_intel snd_intel_nhlt bluetooth snd_hda_codec coretemp snd_hwdep crct10dif_pclmul snd_hda_core crc32_pclmul ecdh_generic ecc ghash_clmulni_intel snd_pcm r8169 realtek lpc_ich prime_numbers i2c_hid
<4> [257.744826] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G     U  W         5.3.0-rc3-g5d0a06cd532c-drmtip_340+ #1
<4> [257.744865] Hardware name: GIGABYTE GB-BXBT-1900/MZBAYAB-00, BIOS F6 02/17/2015
<4> [257.744899] RIP: 0010:lockdep_hardirqs_on+0x146/0x1c0
<4> [257.744925] Code: ef 54 eb de e8 ab 9e 3b 00 85 c0 74 d5 8b 15 c1 a4 22 01 85 d2 75 cb 48 c7 c6 31 d5 06 ac 48 c7 c7 68 94 05 ac e8 4a 7e f9 ff <0f> 0b eb b4 e8 81 9e 3b 00 85 c0 74 ab 44 8b 05 96 a4 22 01 45 85
<4> [257.744994] RSP: 0018:ffffa78600003ca0 EFLAGS: 00010086
<4> [257.745019] RAX: 0000000000000000 RBX: 0000000000000200 RCX: 0000000000010102
<4> [257.745050] RDX: 0000000080010102 RSI: 0000000000000000 RDI: ffffffffab131c5e
<4> [257.745080] RBP: ffffffffab0bbce4 R08: 0000000000000000 R09: 0000000000000000
<4> [257.745110] R10: 0000000000000000 R11: 0000000080000000 R12: ffffa23ba8c38008
<4> [257.745142] R13: ffffa23bacc579c0 R14: ffffa23bb7db0f60 R15: ffffa23b9cc8c430
<4> [257.745174] FS:  0000000000000000(0000) GS:ffffa23bbba00000(0000) knlGS:0000000000000000
<4> [257.745210] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4> [257.745236] CR2: 00007fe477b20778 CR3: 000000011f72a000 CR4: 00000000001006f0
<4> [257.745267] Call Trace:
<4> [257.745283]  <IRQ>
<4> [257.745450]  ? __i915_request_commit+0x223/0x5d0 [i915]
<4> [257.745482]  __local_bh_enable_ip+0x74/0x100
<4> [257.745653]  __i915_request_commit+0x240/0x5d0 [i915]
<4> [257.745828]  ? __i915_request_create+0x228/0x4c0 [i915]
<4> [257.745992]  __engine_park+0x64/0x250 [i915]
<4> [257.746149]  ____intel_wakeref_put_last+0x1c/0x70 [i915]
<4> [257.746311]  i915_sample+0x2ee/0x310 [i915]
<4> [257.746476]  ? i915_pmu_cpu_offline+0xb0/0xb0 [i915]
<4> [257.746508]  __hrtimer_run_queues+0x11e/0x4b0
<4> [257.746540]  hrtimer_interrupt+0xea/0x250
<4> [257.746564]  ? lockdep_hardirqs_off+0x79/0xd0
<4> [257.746594]  smp_apic_timer_interrupt+0x96/0x280
<4> [257.746621]  apic_timer_interrupt+0xf/0x20
<4> [257.746646] RIP: 0010:__do_softirq+0xb3/0x4ae
<4> [257.746670] Code: 24 14 0a 00 00 00 48 c7 c7 26 d0 10 ac e8 45 83 8e ff 48 c7 c0 80 97 03 00 65 66 c7 00 00 00 e8 83 0f 5a ff fb b8 ff ff ff ff <41> 0f bc c7 83 c0 01 89 04 24 0f 84 d9 01 00 00 49 c7 c6 00 51 20
<4> [257.746741] RSP: 0018:ffffa78600003f58 EFLAGS: 00000206 ORIG_RAX: ffffffffffffff13
<4> [257.746777] RAX: 00000000ffffffff RBX: ffffffffac217800 RCX: 0000000000000000
<4> [257.746808] RDX: 0000000000000046 RSI: 0000000000000002 RDI: ffffffffac100781
<4> [257.746839] RBP: 0000000000000026 R08: 0000000000000000 R09: 0000000000000000
<4> [257.746870] R10: 0000000000000000 R11: 0000000000000000 R12: ffffffffac203da8
<4> [257.746901] R13: 0000000000000026 R14: 0000000000000000 R15: 0000000000000010
<4> [257.746935]  ? apic_timer_interrupt+0xa/0x20
<4> [257.746971]  ? __do_softirq+0xad/0x4ae
<4> [257.747000]  irq_exit+0xa9/0xc0
<4> [257.747021]  do_IRQ+0xb8/0x160
<4> [257.747044]  common_interrupt+0xf/0xf
<4> [257.747065]  </IRQ>
<4> [257.747083] RIP: 0010:cpuidle_enter_state+0xae/0x450
<4> [257.747108] Code: 44 00 00 31 ff e8 b2 85 90 ff 45 84 f6 74 12 9c 58 f6 c4 02 0f 85 78 03 00 00 31 ff e8 4b a3 97 ff e8 06 b5 9b ff fb 45 85 ed <0f> 88 c9 02 00 00 4c 2b 24 24 48 ba cf f7 53 e3 a5 9b c4 20 49 63
<4> [257.747180] RSP: 0018:ffffffffac203e58 EFLAGS: 00000202 ORIG_RAX: ffffffffffffffd9
<4> [257.747215] RAX: ffffffffac217800 RBX: ffffffffac2a0de0 RCX: 0000000000000000
<4> [257.747246] RDX: 0000000000000046 RSI: 0000000000000006 RDI: ffffffffac100781
<4> [257.747277] RBP: ffffa23bbba446a8 R08: 0000000000000000 R09: 0000000000000000
<4> [257.747308] R10: 0000000000000000 R11: 0000000000000000 R12: 0000003c026cb562
<4> [257.747339] R13: 0000000000000001 R14: 0000000000000000 R15: 0000000000000001
<4> [257.747385]  ? cpuidle_enter_state+0xaa/0x450
<4> [257.747414]  cpuidle_enter+0x24/0x40
<4> [257.747438]  do_idle+0x1f3/0x260
<4> [257.747463]  cpu_startup_entry+0x14/0x20
<4> [257.747487]  start_kernel+0x50d/0x52f
<4> [257.747519]  secondary_startup_64+0xa4/0xb0
<4> [257.747557] irq event stamp: 8085647
<4> [257.747580] hardirqs last  enabled at (8085646): [<ffffffffabc000ad>] __do_softirq+0xad/0x4ae
<4> [257.747619] hardirqs last disabled at (8085647): [<ffffffffab0019ea>] trace_hardirqs_off_thunk+0x1a/0x20
<4> [257.747661] softirqs last  enabled at (8085644): [<ffffffffab0bbe38>] irq_enter+0x58/0x60
<4> [257.747699] softirqs last disabled at (8085645): [<ffffffffab0bbee9>] irq_exit+0xa9/0xc0
<4> [257.747737] WARNING: CPU: 0 PID: 0 at kernel/locking/lockdep.c:3355 lockdep_hardirqs_on+0x146/0x1c0
<4> [257.747775] ---[ end trace d3481cdadb973e40 ]---
Comment 1 CI Bug Log 2019-08-12 11:03:05 UTC 
The CI Bug Log issue associated to this bug has been updated.

### New filters associated

* BYT: igt@perf_pmu@busy-no-semaphores-vcs0 - dmesg-warn- IRQs not enabled as expected 
  (No new failures associated)
Comment 2 CI Bug Log 2019-08-12 13:14:54 UTC 
The CI Bug Log issue associated to this bug has been updated.

### New filters associated

* BYT: igt@runner@aborted - fail - Previous test: perf_pmu (busy-no-semaphores-vcs0)
  - https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_340/fi-byt-j1900/igt@runner@aborted.html
  - https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_340/fi-byt-n2820/igt@runner@aborted.html
Comment 4 Chris Wilson 2019-08-13 20:50:25 UTC 
commit a79ca656b648e6851dd2f1eb0dcef86b278a8908
Author: Chris Wilson <chris@chris-wilson.co.uk>
Date:   Tue Aug 13 20:07:05 2019 +0100

    drm/i915: Push the wakeref->count deferral to the backend
    
    If the backend wishes to defer the wakeref parking, make it responsible
    for unlocking the wakeref (i.e. bumping the counter). This allows it to
    time the unlock much more carefully in case it happens to needs the
    wakeref to be active during its deferral.
    
    For instance, during engine parking we may choose to emit an idle
    barrier (a request). To do so, we borrow the engine->kernel_context
    timeline and to ensure exclusive access we keep the
    engine->wakeref.count as 0. However, to submit that request to HW may
    require a intel_engine_pm_get() (e.g. to keep the submission tasklet
    alive) and before we allow that we have to rewake our wakeref to avoid a
    recursive deadlock.
Comment 5 CI Bug Log 2019-08-15 07:30:30 UTC 
A CI Bug Log filter associated to this bug has been updated:

{- BYT: igt@perf_pmu@busy-no-semaphores-vcs0 - dmesg-warn- IRQs not enabled as expected  -}
{+ APL BYT: igt@perf_pmu@busy-* - dmesg-warn- IRQs not enabled as expected  +}

New failures caught by the filter:

  * https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6706/shard-apl4/igt@perf_pmu@busy-idle-no-semaphores-vecs0.html
  * https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_343/fi-byt-n2820/igt@perf_pmu@busy-hang-rcs0.html
Comment 6 CI Bug Log 2019-08-15 07:33:39 UTC 
A CI Bug Log filter associated to this bug has been updated:

{- BYT: igt@runner@aborted - fail - Previous test: perf_pmu (busy-no-semaphores-vcs0) -}
{+ BYT: igt@runner@aborted - fail - Previous test: perf_pmu ((busy-no-semaphores-vcs0)|(busy-idle-no-semaphores-vecs0)|(busy-hang-rcs0)) +}

New failures caught by the filter:

  * https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6706/shard-apl4/igt@runner@aborted.html
  * https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_343/fi-byt-n2820/igt@runner@aborted.html
Comment 7 Lakshmi 2019-08-15 07:40:17 UTC 
(In reply to CI Bug Log from comment #6)
> A CI Bug Log filter associated to this bug has been updated:
> 
> {- BYT: igt@runner@aborted - fail - Previous test: perf_pmu
> (busy-no-semaphores-vcs0) -}
> {+ BYT: igt@runner@aborted - fail - Previous test: perf_pmu
> ((busy-no-semaphores-vcs0)|(busy-idle-no-semaphores-vecs0)|(busy-hang-rcs0))
> +}
> 
> New failures caught by the filter:
> 
>   *
> https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6706/shard-apl4/
> igt@runner@aborted.html
>   *
> https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_343/fi-byt-n2820/
> igt@runner@aborted.html

Also on APL.
Comment 8 Chris Wilson 2019-08-15 13:19:56 UTC 
commit 62520e3361d2d9e2e41d3958dcc34faee79a3c1a (HEAD -> drm-intel-next-queued, drm-intel/for-linux-next, drm-intel/drm-intel-next-queued)
Author: Chris Wilson <chris@chris-wilson.co.uk>
Date:   Thu Aug 15 05:20:30 2019 +0100

    drm/i915: Move tasklet kicking to __i915_request_queue caller
    
    Since __i915_request_queue() may be called from hardirq (timer) context,
    we cannot use local_bh_disable/enable at the lower level. As we do want
    to kick the tasklet to speed up initial submission or preemption for
    normal client submission, lift it to the normal process context
    callpath.
    
    Signed-off-by: Chris Wilson <chris@chris-wilson.co.uk>
    Reviewed-by: Mika Kuoppala <mika.kuoppala@linux.intel.com>
    Link: https://patchwork.freedesktop.org/patch/msgid/20190815042031.27750-1-chris@chris-wilson.co.uk
Comment 9 CI Bug Log 2019-08-19 06:07:38 UTC 
A CI Bug Log filter associated to this bug has been updated:

{- APL BYT: igt@perf_pmu@busy-* - dmesg-warn- IRQs not enabled as expected  -}
{+ APL BYT: igt@perf_pmu@busy-* - dmesg-warn- IRQs not enabled as expected  +}

New failures caught by the filter:

  * https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_344/fi-byt-j1900/igt@perf_pmu@most-busy-idle-check-all-bcs0.html
Comment 10 CI Bug Log 2019-08-19 06:44:39 UTC 
A CI Bug Log filter associated to this bug has been updated:

{- BYT: igt@runner@aborted - fail - Previous test: perf_pmu ((busy-no-semaphores-vcs0)|(busy-idle-no-semaphores-vecs0)|(busy-hang-rcs0)) -}
{+ BYT: igt@runner@aborted - fail - Previous test: perf_pmu ((busy-no-semaphores-vcs0)|(busy-idle-no-semaphores-vecs0)|(busy-hang-rcs0)) +}

New failures caught by the filter:

  * https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_344/fi-byt-j1900/igt@runner@aborted.html

Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.