Bug 111375

Summary: [CI][BAT] igt@perf_pmu@busy-idle-no-semaphores-rcs0 - dmesg-warn - WARNING: CPU: \d+ PID: \d+ at kernel/time/timer.c:\d+ del_timer_sync
Product: DRI Reporter: Martin Peres <martin.peres>
Component: DRM/IntelAssignee: Intel GFX Bugs mailing list <intel-gfx-bugs>
Status: RESOLVED FIXED QA Contact: Intel GFX Bugs mailing list <intel-gfx-bugs>
Severity: normal    
Priority: highest CC: intel-gfx-bugs, lakshminarayana.vudum
Version: XOrg git   
Hardware: Other   
OS: All   
Whiteboard: ReadyForDev
i915 platform: BYT, ICL i915 features: Perf/PMU

Description Martin Peres 2019-08-12 08:50:23 UTC 
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6665/shard-iclb7/igt@perf_pmu@busy-idle-no-semaphores-rcs0.html

<6> [109.060194] [IGT] perf_pmu: starting subtest busy-idle-no-semaphores-rcs0
<4> [109.666659] ------------[ cut here ]------------
<4> [109.666695] WARNING: CPU: 0 PID: 0 at kernel/time/timer.c:1285 del_timer_sync+0x7c/0xb0
<4> [109.666701] Modules linked in: vgem snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic i915 mei_hdcp x86_pkg_temp_thermal coretemp snd_hda_intel crct10dif_pclmul snd_intel_nhlt snd_hda_codec crc32_pclmul cdc_ether snd_hwdep usbnet snd_hda_core e1000e mii ghash_clmulni_intel snd_pcm ptp pps_core mei_me mei prime_numbers
<4> [109.666750] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G     U            5.3.0-rc3-CI-CI_DRM_6665+ #1
<4> [109.666757] Hardware name: Intel Corporation Ice Lake Client Platform/IceLake U DDR4 SODIMM PD RVP, BIOS ICLSFWR1.R00.3234.A01.1906141750 06/14/2019
<4> [109.666766] RIP: 0010:del_timer_sync+0x7c/0xb0
<4> [109.666773] Code: 75 4f 41 56 9d e8 c4 27 05 00 65 8b 05 e5 b2 ec 7e a9 00 00 0f 00 74 22 f6 43 22 20 75 1c 48 c7 c7 40 eb 07 82 e8 3d 39 fe ff <0f> 0b 48 89 df e8 fa fe ff ff 85 c0 79 0e f3 90 48 89 df e8 ec fe
<4> [109.666780] RSP: 0018:ffffc90000003e68 EFLAGS: 00010086
<4> [109.666788] RAX: 0000000000000024 RBX: ffff88848b8e8440 RCX: 0000000000010002
<4> [109.666794] RDX: 0000000000000000 RSI: 00000000000000f6 RDI: 00000000ffffffff
<4> [109.666800] RBP: ffffc90000003e80 R08: 0000000000000000 R09: 0000000000000001
<4> [109.666806] R10: 000000000fc7d7c0 R11: 00000000fec4bb7f R12: ffff88848b8e8468
<4> [109.666812] R13: ffff88848b8e80e8 R14: 0000000000000092 R15: ffff88848a078220
<4> [109.666820] FS:  0000000000000000(0000) GS:ffff88849fc00000(0000) knlGS:0000000000000000
<4> [109.666826] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4> [109.666832] CR2: 00007ff315a30000 CR3: 0000000005210006 CR4: 0000000000760ef0
<4> [109.666838] PKRU: 55555554
<4> [109.666843] Call Trace:
<4> [109.666850]  <IRQ>
<4> [109.666969]  __engine_park+0xbd/0x250 [i915]
<4> [109.667049]  ____intel_wakeref_put_last+0x1c/0x70 [i915]
<4> [109.667125]  i915_sample+0x2ee/0x310 [i915]
<4> [109.667203]  ? i915_pmu_cpu_offline+0xb0/0xb0 [i915]
<4> [109.667208]  __hrtimer_run_queues+0x11e/0x4b0
<4> [109.667222]  hrtimer_interrupt+0xea/0x250
<4> [109.667229]  ? lockdep_hardirqs_off+0x95/0xd0
<4> [109.667241]  smp_apic_timer_interrupt+0x96/0x280
<4> [109.667247]  apic_timer_interrupt+0xf/0x20
<4> [109.667252]  </IRQ>
<4> [109.667259] RIP: 0010:cpuidle_enter_state+0xae/0x450
<4> [109.667264] Code: 44 00 00 31 ff e8 52 27 91 ff 45 84 f6 74 12 9c 58 f6 c4 02 0f 85 78 03 00 00 31 ff e8 0b 44 98 ff e8 26 56 9c 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> [109.667268] RSP: 0018:ffffffff82203e58 EFLAGS: 00000202 ORIG_RAX: ffffffffffffff13
<4> [109.667273] RAX: ffffffff82217800 RBX: ffffffff822a3f40 RCX: 0000000000000000
<4> [109.667277] RDX: 0000000000000046 RSI: 0000000000000006 RDI: ffffffff821363c9
<4> [109.667280] RBP: ffff888499df8ff8 R08: 0000000000000000 R09: 0000000000000000
<4> [109.667284] R10: 0000000000000000 R11: 0000000000000000 R12: 0000001988a3d9de
<4> [109.667288] R13: 0000000000000002 R14: 0000000000000000 R15: 0000000000000002
<4> [109.667307]  ? cpuidle_enter_state+0xaa/0x450
<4> [109.667318]  cpuidle_enter+0x24/0x40
<4> [109.667325]  do_idle+0x1f3/0x260
<4> [109.667335]  cpu_startup_entry+0x14/0x20
<4> [109.667343]  start_kernel+0x506/0x528
<4> [109.667355]  secondary_startup_64+0xa4/0xb0
<4> [109.667374] irq event stamp: 915692
<4> [109.667379] hardirqs last  enabled at (915689): [<ffffffff817d7b7a>] cpuidle_enter_state+0xaa/0x450
<4> [109.667384] hardirqs last disabled at (915690): [<ffffffff810019ea>] trace_hardirqs_off_thunk+0x1a/0x20
<4> [109.667390] softirqs last  enabled at (915692): [<ffffffff810b8028>] irq_enter+0x58/0x60
<4> [109.667394] softirqs last disabled at (915691): [<ffffffff810b800d>] irq_enter+0x3d/0x60
<4> [109.667401] WARNING: CPU: 0 PID: 0 at kernel/time/timer.c:1285 del_timer_sync+0x7c/0xb0
<4> [109.667405] ---[ end trace 3c1ec5157dcb8db0 ]---
<6> [109.678139] [IGT] perf_pmu: exiting, ret=0
Comment 1 CI Bug Log 2019-08-12 08:50:50 UTC 
The CI Bug Log issue associated to this bug has been updated.

### New filters associated

* ICL: igt@perf_pmu@busy-idle-no-semaphores-rcs0 - dmesg-warn - WARNING: CPU: \d+ PID: \d+ at kernel/time/timer.c:\d+ del_timer_sync
  - https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6665/shard-iclb7/igt@perf_pmu@busy-idle-no-semaphores-rcs0.html
Comment 2 Chris Wilson 2019-08-12 08:52:52 UTC 
I was just preparing a patch for that!
Comment 3 CI Bug Log 2019-08-12 10:45:11 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 -  WARNING: CPU: 0 PID: 0 at kernel/softirq.c:114 __local_bh_disable_ip+0x88/0x90
  - https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_340/fi-byt-j1900/igt@perf_pmu@busy-no-semaphores-vcs0.html
  - https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_340/fi-byt-n2820/igt@perf_pmu@busy-no-semaphores-vcs0.html
Comment 4 Lakshmi 2019-08-12 10:46:32 UTC 
(In reply to Chris Wilson from comment #2)
> I was just preparing a patch for that!

Also seen on BYT.
Comment 5 Chris Wilson 2019-08-12 10:48:06 UTC 
(In reply to Lakshmi from comment #4)
> (In reply to Chris Wilson from comment #2)
> > I was just preparing a patch for that!
> 
> Also seen on BYT.

Strictly that's not the same bug ;) That's a different patch in the series.
Comment 6 Lakshmi 2019-08-12 10:51:39 UTC 
(In reply to Chris Wilson from comment #5)
> (In reply to Lakshmi from comment #4)
> > (In reply to Chris Wilson from comment #2)
> > > I was just preparing a patch for that!
> > 
> > Also seen on BYT.
> 
> Strictly that's not the same bug ;) That's a different patch in the series.

OK, I will file a new bug for this failure. Thanks for the quick response.
Comment 7 CI Bug Log 2019-08-12 11:01:43 UTC 
The CI Bug Log issue associated to this bug has been updated.

### Removed filters

* BYT:  igt@perf_pmu@busy-no-semaphores-vcs0 - dmesg-warn -  WARNING: CPU: 0 PID: 0 at kernel/softirq.c:114 __local_bh_disable_ip+0x88/0x90 (added on 16 minutes ago)
Comment 8 Chris Wilson 2019-08-12 13:28:12 UTC 
commit f597625d12ba3528658faf5b0f0aae657430a88a
Author: Chris Wilson <chris@chris-wilson.co.uk>
Date:   Mon Aug 12 10:10:38 2019 +0100

    drm/i915/execlists: Avoid sync calls during park
    
    Since we allow ourselves to use non-process context during parking, we
    cannot allow ourselves to sleep and in particular cannot call
    del_timer_sync() -- but we can use a plain del_timer().
    
    Bugzilla: https://bugs.freedesktop.org/show_bug.cgi?id=111375
    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/20190812091045.29587-1-chris@chris-wilson.co.uk

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.