Bug 108654 - [CI][DRMTIP] igt@pm_rpm@* - dmesg-warn - *ERROR* DBus power enable timeout!
Summary: [CI][DRMTIP] igt@pm_rpm@* - dmesg-warn - *ERROR* DBus power enable timeout!
Status: RESOLVED FIXED
Alias: None
Product: DRI
Classification: Unclassified
Component: DRM/Intel (show other bugs)
Version: XOrg git
Hardware: Other All
: highest normal
Assignee: Imre Deak
QA Contact: Intel GFX Bugs mailing list
URL:
Whiteboard: ReadyForDev
Keywords:
: 108756 (view as bug list)
Depends on:
Blocks:
 
Reported: 2018-11-05 09:14 UTC by Martin Peres
Modified: 2019-03-08 15:39 UTC (History)
4 users (show)

See Also:
i915 platform: ICL
i915 features: display/Other


Attachments

Description Martin Peres 2018-11-05 09:14:52 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_136/fi-icl-u2/igt@pm_rpm@legacy-planes.html

<7> [181.072491] [drm:gen9_set_dc_state [i915]] Setting DC state from 02 to 00
<7> [181.073073] [drm:intel_power_well_disable [i915]] disabling power well 1
<3> [181.073160] [drm:skl_update_crtcs [i915]] *ERROR* DBus power enable timeout!

<7> [193.976469] [drm:gen9_set_dc_state [i915]] Setting DC state from 00 to 08
<4> [193.976552] ------------[ cut here ]------------
<4> [193.976562] Device suspended during HW access
<4> [193.976644] WARNING: CPU: 2 PID: 1148 at drivers/gpu/drm/i915/intel_drv.h:2098 gen11_fwtable_read32+0x21e/0x260 [i915]
<4> [193.976646] Modules linked in: vgem snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic i915 x86_pkg_temp_thermal coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel snd_hda_intel snd_hda_codec btusb btrtl btbcm snd_hwdep btintel cdc_ether snd_hda_core usbnet e1000e snd_pcm bluetooth mii ecdh_generic prime_numbers
<4> [193.976702] CPU: 2 PID: 1148 Comm: pm_rpm Tainted: G     U  W         4.19.0-gf311f120a0d9-drmtip_136+ #1
<4> [193.976705] Hardware name: Intel Corporation Ice Lake Client Platform/IceLake U DDR4 SODIMM PD RVP TLC, BIOS ICLSFWR1.R00.2402.AD3.1810170014 10/17/2018
<4> [193.976748] RIP: 0010:gen11_fwtable_read32+0x21e/0x260 [i915]
<4> [193.976751] Code: e8 57 e9 ff ff e9 86 fe ff ff 80 3d aa 2d 19 00 00 0f 85 14 fe ff ff 48 c7 c7 48 a3 52 c0 c6 05 96 2d 19 00 01 e8 c2 af c5 e8 <0f> 0b e9 fa fd ff ff e8 d6 c8 cd e8 85 c0 0f 85 5f ff ff ff 48 c7
<4> [193.976754] RSP: 0018:ffff9b03c069b9f8 EFLAGS: 00010282
<4> [193.976758] RAX: 0000000000000000 RBX: ffff88e2d3e00000 RCX: 0000000000000000
<4> [193.976760] RDX: 0000000000000007 RSI: ffffffffaa080e58 RDI: 00000000ffffffff
<4> [193.976762] RBP: 0000000000044fe8 R08: 0000000009d31acd R09: 0000000000000000
<4> [193.976764] R10: ffff88e2d56961b0 R11: 0000000000000000 R12: 0000000000000000
<4> [193.976767] R13: 0000000000000001 R14: ffff88e2d3e00000 R15: ffff88e2dad0efc8
<4> [193.976770] FS:  00007f08e0526980(0000) GS:ffff88e2eff00000(0000) knlGS:0000000000000000
<4> [193.976772] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4> [193.976774] CR2: 00007fbc59d6f000 CR3: 00000004a7cc4003 CR4: 0000000000760ee0
<4> [193.976776] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
<4> [193.976779] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
<4> [193.976781] PKRU: 55555554
<4> [193.976783] Call Trace:
<4> [193.976828]  icl_dbuf_slices_update+0x4f/0x170 [i915]
<4> [193.976900]  skl_update_crtcs+0x2ba/0x2e0 [i915]
<4> [193.976969]  intel_atomic_commit_tail+0x1e3/0xd10 [i915]
<4> [193.977031]  ? intel_atomic_commit_ready+0x3f/0x4c [i915]
<4> [193.977076]  ? __i915_sw_fence_complete+0x1a0/0x250 [i915]
<4> [193.977142]  intel_atomic_commit+0x244/0x330 [i915]
<4> [193.977154]  drm_atomic_helper_update_plane+0xeb/0x100
<4> [193.977165]  setplane_internal+0x97/0x190
<4> [193.977189]  drm_mode_setplane+0xcf/0x190
<4> [193.977197]  ? drm_mode_cursor_common+0x220/0x220
<4> [193.977197]  drm_ioctl_kernel+0x81/0xf0
<4> [193.977197]  drm_ioctl+0x2e6/0x3a0
<4> [193.977197]  ? drm_mode_cursor_common+0x220/0x220
<4> [193.977197]  do_vfs_ioctl+0xa0/0x6d0
<4> [193.977197]  ? __task_pid_nr_ns+0xb9/0x1f0
<4> [193.977197]  ksys_ioctl+0x35/0x60
<4> [193.977197]  __x64_sys_ioctl+0x11/0x20
<4> [193.977197]  do_syscall_64+0x55/0x190
<4> [193.977197]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
<4> [193.977197] RIP: 0033:0x7f08df7b05d7
<4> [193.977197] Code: b3 66 90 48 8b 05 b1 48 2d 00 64 c7 00 26 00 00 00 48 c7 c0 ff ff ff ff c3 66 2e 0f 1f 84 00 00 00 00 00 b8 10 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 81 48 2d 00 f7 d8 64 89 01 48
<4> [193.977197] RSP: 002b:00007fff8fc09d28 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
<4> [193.977197] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f08df7b05d7
<4> [193.977197] RDX: 00007fff8fc09d60 RSI: 00000000c03064b7 RDI: 0000000000000005
<4> [193.977197] RBP: 00007fff8fc09d60 R08: 0000000000000000 R09: 0000000000000001
<4> [193.977197] R10: 0000000000400000 R11: 0000000000000246 R12: 00000000c03064b7
<4> [193.977197] R13: 0000000000000005 R14: 0000000000000000 R15: 0000000000000000
<4> [193.977197] irq event stamp: 230696
<4> [193.977197] hardirqs last  enabled at (230695): [<ffffffffa90fc06a>] console_unlock+0x3fa/0x5f0
<4> [193.977197] hardirqs last disabled at (230696): [<ffffffffa9001930>] trace_hardirqs_off_thunk+0x1a/0x1c
<4> [193.977197] softirqs last  enabled at (230606): [<ffffffffa9c00319>] __do_softirq+0x319/0x48e
<4> [193.977197] softirqs last disabled at (230583): [<ffffffffa9090329>] irq_exit+0xa9/0xc0
<4> [193.977197] WARNING: CPU: 2 PID: 1148 at drivers/gpu/drm/i915/intel_drv.h:2098 gen11_fwtable_read32+0x21e/0x260 [i915]
<4> [193.977197] ---[ end trace cecedd1d30fc6c74 ]---
Comment 1 Martin Peres 2018-11-05 09:17:39 UTC
Bumping the priority to high because this seems related to powerwells and DC states which are definitely important for our users.
Comment 3 Imre Deak 2018-11-05 15:57:06 UTC
We shouldn't touch the HW here, since the output is disabled. The HW update by set_plane is triggered since ddb.enabled_slices in dev_priv / intel_state is updated incorrectly.
Comment 4 Imre Deak 2018-11-30 15:19:27 UTC
*** Bug 108756 has been marked as a duplicate of this bug. ***
Comment 5 Imre Deak 2018-11-30 16:19:00 UTC
I was wondering how this can happen since we have all outputs disabled and
runtime suspended. Then by now icl_dbuf_disable() should have zeroed
dev_priv->wm.skl_hw.ddb.enabled_slices and skl_compute_ddb() copied this
0 to intel_state->wm_results.ddb.enabled_slices during the compute phase
of the problematic commit (since no crtcs are active this 0 should've
been kept as-is). Then here both hw_enabled_slices and required_slices
should be 0, but it's obviously not the case.

What could happen I think is that the store in icl_dbuf_disable() / icl_dbuf_enable() can race with the load in skl_compute_ddb(). So perhaps skl_compute_ddb() copied from dev_priv enabled_slices as 1 or 2 (the only values we compute during a commit), then icl_dbuf_disable() zeroed in a racy way enabled_slices in dev_priv and we get here required_slices being 1 or 2 and hw_enabled_slices being 0.

To fix the above I think we would need to do the following:
1. Do not update enabled_slices in icl_dbuf_enable() / icl_dbuf_disable()
   We instead depend on the DDB HW readout to set the correct initial value
   after module loading/resume and any following commit to update it if
   needed (based on new resolution etc.).

   After this we could still end up with stale values in
   wm.skl_hw.ddb.enabled_slices, for instance if it's 2 b/c of two pipes
   being enabled we wouldn't set it to 1 atm when disabling both pipes
   in the same atomic commit. So we'd also need the following 2 changes.

2. Force-enable only a single slice in icl_dbuf_enable() (as the spec
   requires) keeping the 2nd slice enabled only if BIOS has enabled it
   (DDB HW readout will set the correct enabled_slices afterwards).

3. Make sure we always compute the proper enabled_slices in the atomic
   state, by moving the calculation from intel_get_ddb_size() to
   earlier, performing it even if all crtcs are disabled.

Ville also noticed a related problem where we don't recalculate the slice count during a non-modeset commit, where a plane configuration change would require this (due to the changed pixel bandwidth).
Comment 6 Martin Peres 2018-12-03 14:30:36 UTC
Also seen in BAT: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_5186_167/fi-icl-u3/igt@pm_rpm@basic-rte.html

<4> [359.043981] ------------[ cut here ]------------
<4> [359.043984] Device suspended during HW access
<4> [359.044079] WARNING: CPU: 0 PID: 2950 at drivers/gpu/drm/i915/intel_drv.h:2097 gen11_fwtable_read32+0x21e/0x260 [i915]
<4> [359.044083] Modules linked in: vgem snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic i915 x86_pkg_temp_thermal coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel snd_hda_intel snd_hda_codec btusb btrtl snd_hwdep btbcm btintel cdc_ether snd_hda_core usbnet e1000e snd_pcm mii bluetooth i2c_i801 ecdh_generic prime_numbers
<4> [359.044119] CPU: 0 PID: 2950 Comm: pm_rpm Tainted: G     U            4.20.0-rc3-g890ed44fe261-repeat_15+ #1
<4> [359.044124] Hardware name: Intel Corporation Ice Lake Client Platform/IceLake U DDR4 SODIMM PD RVP TLC, BIOS ICLSFWR1.R00.2402.AD3.1810170014 10/17/2018
<4> [359.044189] RIP: 0010:gen11_fwtable_read32+0x21e/0x260 [i915]
<4> [359.044194] Code: e8 57 e9 ff ff e9 86 fe ff ff 80 3d 6a 35 19 00 00 0f 85 14 fe ff ff 48 c7 c7 38 3e 7e c0 c6 05 56 35 19 00 01 e8 02 43 9a e0 <0f> 0b e9 fa fd ff ff e8 06 66 a2 e0 85 c0 0f 85 5f ff ff ff 48 c7
<4> [359.044198] RSP: 0018:ffffa67440dffa38 EFLAGS: 00010282
<4> [359.044204] RAX: 0000000000000000 RBX: ffff8f5b5b3a0000 RCX: 0000000000000000
<4> [359.044208] RDX: 0000000000000007 RSI: ffffffffa2087afb RDI: 00000000ffffffff
<4> [359.044211] RBP: 0000000000044fe8 R08: 000000004fd3a046 R09: 0000000000000000
<4> [359.044215] R10: ffff8f5b51a00d10 R11: 0000000000000000 R12: ffff8f5b5b3a04a0
<4> [359.044219] R13: 0000000000000001 R14: ffff8f5b5b3a0000 R15: ffff8f5b5ce78008
<4> [359.044224] FS:  00007f82d124f980(0000) GS:ffff8f5b6fe00000(0000) knlGS:0000000000000000
<4> [359.044228] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4> [359.044233] CR2: 00007fe4b86d0788 CR3: 00000004ab1d8002 CR4: 0000000000760ef0
<4> [359.044237] PKRU: 55555554
<4> [359.044242] Call Trace:
<4> [359.044312]  icl_dbuf_slices_update+0x55/0x160 [i915]
<4> [359.044386]  skl_update_crtcs+0x281/0x2b0 [i915]
<4> [359.044460]  intel_atomic_commit_tail+0x1e3/0xd20 [i915]
<4> [359.044527]  ? intel_atomic_commit_ready+0x3f/0x50 [i915]
<4> [359.044580]  ? __i915_sw_fence_complete+0x1a0/0x250 [i915]
<4> [359.044662]  intel_atomic_commit+0x244/0x330 [i915]
<4> [359.044676]  drm_atomic_helper_set_config+0x7b/0x90
<4> [359.044685]  drm_mode_setcrtc+0x195/0x6b0
<4> [359.044717]  ? drm_mode_getcrtc+0x180/0x180
<4> [359.044724]  drm_ioctl_kernel+0x81/0xf0
<4> [359.044736]  drm_ioctl+0x2de/0x390
<4> [359.044745]  ? drm_mode_getcrtc+0x180/0x180
<4> [359.044768]  do_vfs_ioctl+0xa0/0x6e0
<4> [359.044777]  ? __might_fault+0x39/0x90
<4> [359.044790]  ksys_ioctl+0x35/0x60
<4> [359.044800]  __x64_sys_ioctl+0x11/0x20
<4> [359.044806]  do_syscall_64+0x55/0x190
<4> [359.044815]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
<4> [359.044820] RIP: 0033:0x7f82d04d95d7
<4> [359.044826] Code: b3 66 90 48 8b 05 b1 48 2d 00 64 c7 00 26 00 00 00 48 c7 c0 ff ff ff ff c3 66 2e 0f 1f 84 00 00 00 00 00 b8 10 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 81 48 2d 00 f7 d8 64 89 01 48
<4> [359.044830] RSP: 002b:00007fffe394b328 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
<4> [359.044835] RAX: ffffffffffffffda RBX: 00007fffe394b360 RCX: 00007f82d04d95d7
<4> [359.044839] RDX: 00007fffe394b360 RSI: 00000000c06864a2 RDI: 0000000000000005
<4> [359.044843] RBP: 00007fffe394b360 R08: 0000000000000000 R09: 0000000000000000
<4> [359.044848] R10: 0000000000000000 R11: 0000000000000246 R12: 00000000c06864a2
<4> [359.044851] R13: 0000000000000005 R14: 0000000000000000 R15: 0000000000000000
<4> [359.044870] irq event stamp: 151080
<4> [359.044878] hardirqs last  enabled at (151079): [<ffffffffa10fef59>] console_unlock+0x3f9/0x5f0
<4> [359.044884] hardirqs last disabled at (151080): [<ffffffffa10019b0>] trace_hardirqs_off_thunk+0x1a/0x1c
<4> [359.044890] softirqs last  enabled at (150974): [<ffffffffa1c0033a>] __do_softirq+0x33a/0x4b9
<4> [359.044897] softirqs last disabled at (150969): [<ffffffffa10929f9>] irq_exit+0xa9/0xc0
<4> [359.044964] WARNING: CPU: 0 PID: 2950 at drivers/gpu/drm/i915/intel_drv.h:2097 gen11_fwtable_read32+0x21e/0x260 [i915]
<4> [359.044968] ---[ end trace 56324727958c8cd9 ]---
Comment 7 Martin Peres 2018-12-03 14:32:28 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_5186_224/fi-icl-u3/igt@pm_rpm@module-reload.html

<4> [408.963219] ------------[ cut here ]------------
<7> [408.966313] [drm:intel_runtime_suspend [i915]] Device suspended
<4> [408.966373] Device suspended during HW access
<4> [408.966426] WARNING: CPU: 0 PID: 3996 at drivers/gpu/drm/i915/intel_drv.h:2097 gen11_fwtable_read32+0x21e/0x260 [i915]
<4> [408.966428] Modules linked in: snd_hda_intel i915 vgem snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic btusb btrtl btbcm x86_pkg_temp_thermal coretemp btintel snd_hda_codec crct10dif_pclmul crc32_pclmul ghash_clmulni_intel snd_hwdep snd_hda_core bluetooth snd_pcm cdc_ether usbnet mii e1000e ecdh_generic i2c_i801 prime_numbers [last unloaded: i915]
<4> [408.966449] CPU: 0 PID: 3996 Comm: pm_rpm Tainted: G     U            4.20.0-rc3-g890ed44fe261-repeat_15+ #1
<4> [408.966451] Hardware name: Intel Corporation Ice Lake Client Platform/IceLake U DDR4 SODIMM PD RVP TLC, BIOS ICLSFWR1.R00.2402.AD3.1810170014 10/17/2018
<4> [408.966488] RIP: 0010:gen11_fwtable_read32+0x21e/0x260 [i915]
<4> [408.966491] Code: e8 57 e9 ff ff e9 86 fe ff ff 80 3d 6a 35 19 00 00 0f 85 14 fe ff ff 48 c7 c7 38 de 84 c0 c6 05 56 35 19 00 01 e8 02 a3 93 d3 <0f> 0b e9 fa fd ff ff e8 06 c6 9b d3 85 c0 0f 85 5f ff ff ff 48 c7
<4> [408.966493] RSP: 0018:ffff97f0008b3a38 EFLAGS: 00010282
<4> [408.966496] RAX: 0000000000000000 RBX: ffff96bb1f960000 RCX: 0000000000000000
<4> [408.966498] RDX: 0000000000000007 RSI: ffffffff95087afb RDI: 00000000ffffffff
<4> [408.966500] RBP: 0000000000044fe8 R08: 0000000096bfd571 R09: 0000000000000000
<4> [408.966502] R10: ffff96bb5e5e2e10 R11: 0000000000000000 R12: ffff96bb1f9604a0
<4> [408.966504] R13: 0000000000000001 R14: ffff96bb1f960000 R15: ffff96bb55ab6678
<4> [408.966506] FS:  00007f1666ad4980(0000) GS:ffff96bb6fe00000(0000) knlGS:0000000000000000
<4> [408.966508] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4> [408.966510] CR2: 00007f8ec7ec8000 CR3: 000000049abf8003 CR4: 0000000000760ef0
<4> [408.966512] PKRU: 55555554
<4> [408.966514] Call Trace:
<4> [408.966544]  icl_dbuf_slices_update+0x55/0x160 [i915]
<4> [408.966584]  skl_update_crtcs+0x281/0x2b0 [i915]
<4> [408.966634]  intel_atomic_commit_tail+0x1e3/0xd20 [i915]
<4> [408.966671]  ? intel_atomic_commit_ready+0x3f/0x50 [i915]
<4> [408.966694]  ? __i915_sw_fence_complete+0x1a0/0x250 [i915]
<4> [408.966731]  intel_atomic_commit+0x244/0x330 [i915]
<4> [408.966741]  drm_atomic_helper_set_config+0x7b/0x90
<4> [408.966748]  drm_mode_setcrtc+0x195/0x6b0
<4> [408.966765]  ? drm_mode_getcrtc+0x180/0x180
<4> [408.966769]  drm_ioctl_kernel+0x81/0xf0
<4> [408.966775]  drm_ioctl+0x2de/0x390
<4> [408.966779]  ? drm_mode_getcrtc+0x180/0x180
<4> [408.966792]  do_vfs_ioctl+0xa0/0x6e0
<4> [408.966796]  ? lock_acquire+0xa6/0x1c0
<4> [408.966801]  ? __task_pid_nr_ns+0xb9/0x1f0
<4> [408.966807]  ksys_ioctl+0x35/0x60
<4> [408.966812]  __x64_sys_ioctl+0x11/0x20
<4> [408.966815]  do_syscall_64+0x55/0x190
<4> [408.966820]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
<4> [408.966823] RIP: 0033:0x7f1665d5e5d7
<4> [408.966826] Code: b3 66 90 48 8b 05 b1 48 2d 00 64 c7 00 26 00 00 00 48 c7 c0 ff ff ff ff c3 66 2e 0f 1f 84 00 00 00 00 00 b8 10 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 81 48 2d 00 f7 d8 64 89 01 48
<4> [408.966828] RSP: 002b:00007ffd64005188 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
<4> [408.966831] RAX: ffffffffffffffda RBX: 00007ffd640051c0 RCX: 00007f1665d5e5d7
<4> [408.966833] RDX: 00007ffd640051c0 RSI: 00000000c06864a2 RDI: 0000000000000000
<4> [408.966835] RBP: 00007ffd640051c0 R08: 0000000000000000 R09: 0000000000000000
<4> [408.966837] R10: 0000000000000000 R11: 0000000000000246 R12: 00000000c06864a2
<4> [408.966839] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
<4> [408.966849] irq event stamp: 1319552
<4> [408.966853] hardirqs last  enabled at (1319551): [<ffffffff940fef59>] console_unlock+0x3f9/0x5f0
<4> [408.966856] hardirqs last disabled at (1319552): [<ffffffff940019b0>] trace_hardirqs_off_thunk+0x1a/0x1c
<4> [408.966859] softirqs last  enabled at (1319408): [<ffffffff94c0033a>] __do_softirq+0x33a/0x4b9
<4> [408.966862] softirqs last disabled at (1319399): [<ffffffff940929f9>] irq_exit+0xa9/0xc0
<4> [408.966897] WARNING: CPU: 0 PID: 3996 at drivers/gpu/drm/i915/intel_drv.h:2097 gen11_fwtable_read32+0x21e/0x260 [i915]
<4> [408.966899] ---[ end trace b2b7a32f26c769dd ]---
Comment 8 Martin Peres 2018-12-05 12:54:29 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_5261/shard-iclb4/igt@pm_rpm@universal-planes.html

<4> [780.715455] ------------[ cut here ]------------
<4> [780.715460] RPM wakelock ref not held during HW access
<4> [780.715567] WARNING: CPU: 0 PID: 2964 at drivers/gpu/drm/i915/intel_drv.h:2128 gen11_fwtable_read32+0x1c8/0x260 [i915]
<4> [780.715572] Modules linked in: vgem snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic i915 x86_pkg_temp_thermal coretemp snd_hda_intel crct10dif_pclmul crc32_pclmul snd_hda_codec ghash_clmulni_intel snd_hwdep cdc_ether snd_hda_core usbnet e1000e mii snd_pcm i2c_i801 prime_numbers
<4> [780.715608] CPU: 0 PID: 2964 Comm: pm_rpm Tainted: G     U            4.20.0-rc5-CI-CI_DRM_5261+ #1
<4> [780.715614] Hardware name: Intel Corporation Ice Lake Client Platform/IceLake U DDR4 SODIMM PD RVP TLC, BIOS ICLSFWR1.R00.2402.AD3.1810170014 10/17/2018
<4> [780.715693] RIP: 0010:gen11_fwtable_read32+0x1c8/0x260 [i915]
<4> [780.715698] Code: e8 0f fa e2 e0 e9 0d ff ff ff 80 3d fe bf 19 00 00 0f 85 78 fe ff ff 48 c7 c7 98 60 2d a0 c6 05 ea bf 19 00 01 e8 88 4a eb e0 <0f> 0b e9 5e fe ff ff b9 01 00 00 00 ba 01 00 00 00 89 ee 48 89 df
<4> [780.715702] RSP: 0018:ffffc90000a17a10 EFLAGS: 00010286
<4> [780.715707] RAX: 0000000000000000 RBX: ffff888497bd0000 RCX: 0000000000000006
<4> [780.715711] RDX: 0000000000000006 RSI: ffffffff82129622 RDI: ffffffff820d7aa7
<4> [780.715715] RBP: 0000000000044fe8 R08: 00000000b3e1dae6 R09: 0000000000000000
<4> [780.715718] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
<4> [780.715723] R13: 0000000000000001 R14: ffff8884a597d3d8 R15: 0000000000000000
<4> [780.715728] FS:  00007f5081fd8980(0000) GS:ffff8884afe00000(0000) knlGS:0000000000000000
<4> [780.715733] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4> [780.715737] CR2: 00007f5081ee2000 CR3: 0000000498b24001 CR4: 0000000000760ef0
<4> [780.715742] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
<4> [780.715746] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
<4> [780.715750] PKRU: 55555554
<4> [780.715754] Call Trace:
<4> [780.715806]  icl_dbuf_slices_update+0xdf/0x160 [i915]
<4> [780.715871]  skl_update_crtcs+0x29c/0x2b0 [i915]
<4> [780.715938]  intel_atomic_commit_tail+0x1ea/0xd60 [i915]
<4> [780.716000]  ? intel_atomic_commit_ready+0x3f/0x50 [i915]
<4> [780.716038]  ? __i915_sw_fence_complete+0x1a0/0x250 [i915]
<4> [780.716102]  intel_atomic_commit+0x244/0x330 [i915]
<4> [780.716113]  drm_atomic_helper_update_plane+0xeb/0x100
<4> [780.716123]  setplane_internal+0x97/0x190
<4> [780.716143]  drm_mode_setplane+0xcf/0x190
<4> [780.716153]  ? drm_mode_cursor_common+0x220/0x220
<4> [780.716159]  drm_ioctl_kernel+0x81/0xf0
<4> [780.716168]  drm_ioctl+0x2de/0x390
<4> [780.716175]  ? drm_mode_cursor_common+0x220/0x220
<4> [780.716193]  do_vfs_ioctl+0xa0/0x6e0
<4> [780.716199]  ? lock_acquire+0xa6/0x1c0
<4> [780.716206]  ? __task_pid_nr_ns+0xb9/0x1f0
<4> [780.716214]  ksys_ioctl+0x35/0x60
<4> [780.716222]  __x64_sys_ioctl+0x11/0x20
<4> [780.716228]  do_syscall_64+0x55/0x190
<4> [780.716238]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
<4> [780.716244] RIP: 0033:0x7f50812615d7
<4> [780.716249] Code: b3 66 90 48 8b 05 b1 48 2d 00 64 c7 00 26 00 00 00 48 c7 c0 ff ff ff ff c3 66 2e 0f 1f 84 00 00 00 00 00 b8 10 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 81 48 2d 00 f7 d8 64 89 01 48
<4> [780.716252] RSP: 002b:00007ffd88fa4338 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
<4> [780.716256] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f50812615d7
<4> [780.716259] RDX: 00007ffd88fa4370 RSI: 00000000c03064b7 RDI: 0000000000000005
<4> [780.716262] RBP: 00007ffd88fa4370 R08: 0000000000000000 R09: 0000000000000001
<4> [780.716265] R10: 0000000000400000 R11: 0000000000000246 R12: 00000000c03064b7
<4> [780.716268] R13: 0000000000000005 R14: 0000000000000000 R15: 0000000000000000
<4> [780.716282] irq event stamp: 253204
<4> [780.716288] hardirqs last  enabled at (253203): [<ffffffff810fc764>] vprintk_emit+0x124/0x320
<4> [780.716293] hardirqs last disabled at (253204): [<ffffffff810019b0>] trace_hardirqs_off_thunk+0x1a/0x1c
<4> [780.716297] softirqs last  enabled at (253126): [<ffffffff81c0033a>] __do_softirq+0x33a/0x4b9
<4> [780.716303] softirqs last disabled at (253119): [<ffffffff8108e6a9>] irq_exit+0xa9/0xc0
<4> [780.716361] WARNING: CPU: 0 PID: 2964 at drivers/gpu/drm/i915/intel_drv.h:2128 gen11_fwtable_read32+0x1c8/0x260 [i915]
<4> [780.716364] ---[ end trace ad71a8b88380193b ]---
Comment 9 Martin Peres 2018-12-07 10:14:00 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_5272/shard-iclb7/igt@pm_rpm@legacy-planes.html

<4> [783.701792] ------------[ cut here ]------------
<4> [783.701795] RPM wakelock ref not held during HW access
<4> [783.701852] WARNING: CPU: 0 PID: 4145 at drivers/gpu/drm/i915/intel_drv.h:2128 gen11_fwtable_read32+0x1c8/0x260 [i915]
<4> [783.701854] Modules linked in: vgem snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic x86_pkg_temp_thermal i915 coretemp crct10dif_pclmul crc32_pclmul snd_hda_intel cdc_ether snd_hda_codec snd_hwdep usbnet ghash_clmulni_intel mii snd_hda_core e1000e snd_pcm i2c_i801 prime_numbers [last unloaded: vgem]
<4> [783.701872] CPU: 0 PID: 4145 Comm: pm_rpm Tainted: G     U            4.20.0-rc5-CI-CI_DRM_5272+ #1
<4> [783.701875] Hardware name: Intel Corporation Ice Lake Client Platform/IceLake U DDR4 SODIMM PD RVP, BIOS ICLSFWR1.R00.2402.AD3.1810170014 10/17/2018
<4> [783.701917] RIP: 0010:gen11_fwtable_read32+0x1c8/0x260 [i915]
<4> [783.701921] Code: e8 ef e9 de e0 e9 0d ff ff ff 80 3d de bf 19 00 00 0f 85 78 fe ff ff 48 c7 c7 90 70 31 a0 c6 05 ca bf 19 00 01 e8 68 3a e7 e0 <0f> 0b e9 5e fe ff ff b9 01 00 00 00 ba 01 00 00 00 89 ee 48 89 df
<4> [783.701923] RSP: 0018:ffffc9000062ba10 EFLAGS: 00010286
<4> [783.701926] RAX: 0000000000000000 RBX: ffff88849eac0000 RCX: 0000000000000006
<4> [783.701929] RDX: 0000000000000006 RSI: ffffffff821298aa RDI: ffffffff820d7ca7
<4> [783.701931] RBP: 0000000000044fe8 R08: 00000000afec3fc3 R09: 0000000000000000
<4> [783.701933] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
<4> [783.701936] R13: 0000000000000001 R14: ffff8884908fa548 R15: 0000000000000000
<4> [783.701939] FS:  00007f98bd7c9980(0000) GS:ffff8884afe00000(0000) knlGS:0000000000000000
<4> [783.701941] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4> [783.701944] CR2: 00007f80d801d000 CR3: 000000044ea2c005 CR4: 0000000000760ef0
<4> [783.701946] PKRU: 55555554
<4> [783.701947] Call Trace:
<4> [783.701987]  icl_dbuf_slices_update+0xdf/0x160 [i915]
<4> [783.702033]  skl_update_crtcs+0x29c/0x2b0 [i915]
<4> [783.702082]  intel_atomic_commit_tail+0x1ea/0xd70 [i915]
<4> [783.702128]  ? intel_atomic_commit_ready+0x3f/0x50 [i915]
<4> [783.702157]  ? __i915_sw_fence_complete+0x1a0/0x250 [i915]
<4> [783.702203]  intel_atomic_commit+0x244/0x330 [i915]
<4> [783.702211]  drm_atomic_helper_update_plane+0xeb/0x100
<4> [783.702219]  setplane_internal+0x97/0x190
<4> [783.702233]  drm_mode_setplane+0xcf/0x190
<4> [783.702240]  ? drm_mode_cursor_common+0x220/0x220
<4> [783.702244]  drm_ioctl_kernel+0x81/0xf0
<4> [783.702251]  drm_ioctl+0x2de/0x390
<4> [783.702256]  ? drm_mode_cursor_common+0x220/0x220
<4> [783.702269]  do_vfs_ioctl+0xa0/0x6e0
<4> [783.702274]  ? lock_acquire+0xa6/0x1c0
<4> [783.702278]  ? __task_pid_nr_ns+0xb9/0x1f0
<4> [783.702284]  ksys_ioctl+0x35/0x60
<4> [783.702289]  __x64_sys_ioctl+0x11/0x20
<4> [783.702293]  do_syscall_64+0x55/0x190
<4> [783.702298]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
<4> [783.702301] RIP: 0033:0x7f98bca535d7
<4> [783.702304] Code: b3 66 90 48 8b 05 b1 48 2d 00 64 c7 00 26 00 00 00 48 c7 c0 ff ff ff ff c3 66 2e 0f 1f 84 00 00 00 00 00 b8 10 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 81 48 2d 00 f7 d8 64 89 01 48
<4> [783.702307] RSP: 002b:00007fff878179a8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
<4> [783.702310] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f98bca535d7
<4> [783.702312] RDX: 00007fff878179e0 RSI: 00000000c03064b7 RDI: 0000000000000005
<4> [783.702314] RBP: 00007fff878179e0 R08: 0000000000000000 R09: 0000000000000001
<4> [783.702316] R10: 0000000000400000 R11: 0000000000000246 R12: 00000000c03064b7
<4> [783.702318] R13: 0000000000000005 R14: 0000000000000000 R15: 0000000000000000
<4> [783.702329] irq event stamp: 100046
<4> [783.702333] hardirqs last  enabled at (100045): [<ffffffff810fc764>] vprintk_emit+0x124/0x320
<4> [783.702336] hardirqs last disabled at (100046): [<ffffffff810019b0>] trace_hardirqs_off_thunk+0x1a/0x1c
<4> [783.702339] softirqs last  enabled at (99968): [<ffffffff81c0033a>] __do_softirq+0x33a/0x4b9
<4> [783.702343] softirqs last disabled at (99933): [<ffffffff8108e6a9>] irq_exit+0xa9/0xc0
<4> [783.702384] WARNING: CPU: 0 PID: 4145 at drivers/gpu/drm/i915/intel_drv.h:2128 gen11_fwtable_read32+0x1c8/0x260 [i915]
<4> [783.702386] ---[ end trace 346b1910a3fff3c5 ]---
Comment 10 Lakshmi 2018-12-21 08:44:58 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_176/fi-icl-u3/igt@pm_rpm@cursor.html

<4> [203.896823] ------------[ cut here ]------------
<4> [203.896830] RPM wakelock ref not held during HW access
<4> [203.896969] WARNING: CPU: 0 PID: 1336 at drivers/gpu/drm/i915/intel_drv.h:2134 gen11_fwtable_read32+0x1c8/0x260 [i915]
<4> [203.896976] Modules linked in: vgem snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic i915 x86_pkg_temp_thermal coretemp crct10dif_pclmul crc32_pclmul snd_hda_intel ghash_clmulni_intel snd_hda_codec snd_hwdep snd_hda_core e1000e btusb btrtl btbcm btintel snd_pcm bluetooth cdc_ether usbnet mii ecdh_generic i2c_i801 prime_numbers
<4> [203.897030] CPU: 0 PID: 1336 Comm: pm_rpm Tainted: G     U            4.20.0-rc7-g29cd50b134a4-drmtip_176+ #1
<4> [203.897037] Hardware name: Intel Corporation Ice Lake Client Platform/IceLake U DDR4 SODIMM PD RVP TLC, BIOS ICLSFWR1.R00.2402.AD3.1810170014 10/17/2018
<4> [203.897132] RIP: 0010:gen11_fwtable_read32+0x1c8/0x260 [i915]
<4> [203.897141] Code: e8 ef 31 b8 e0 e9 0d ff ff ff 80 3d 4c c8 19 00 00 0f 85 78 fe ff ff 48 c7 c7 98 32 58 c0 c6 05 38 c8 19 00 01 e8 c8 cb c0 e0 <0f> 0b e9 5e fe ff ff b9 01 00 00 00 ba 01 00 00 00 89 ee 48 89 df
<4> [203.897147] RSP: 0018:ffffafc0c039b990 EFLAGS: 00010282
<4> [203.897154] RAX: 0000000000000000 RBX: ffffa13d91f10000 RCX: 0000000000000006
<4> [203.897158] RDX: 0000000000000006 RSI: ffffffffa20ff77a RDI: ffffffffa20ab197
<4> [203.897163] RBP: 0000000000044fe8 R08: 00000000f36dd0cc R09: 0000000000000000
<4> [203.897168] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
<4> [203.897173] R13: 0000000000000001 R14: ffffa13da519dd28 R15: 0000000000000000
<4> [203.897180] FS:  00007f0519173980(0000) GS:ffffa13dafe00000(0000) knlGS:0000000000000000
<4> [203.897186] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4> [203.897191] CR2: 00007f1d658bf788 CR3: 00000004a823e004 CR4: 0000000000760ef0
<4> [203.897196] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
<4> [203.897201] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
<4> [203.897206] PKRU: 55555554
<4> [203.897210] Call Trace:
<4> [203.897284]  icl_dbuf_slices_update+0xdf/0x160 [i915]
<4> [203.897375]  skl_update_crtcs+0x29c/0x2b0 [i915]
<4> [203.897473]  intel_atomic_commit_tail+0x1ea/0xdb0 [i915]
<4> [203.897564]  ? intel_atomic_commit_ready+0x3f/0x50 [i915]
<4> [203.897625]  ? __i915_sw_fence_complete+0x1a0/0x250 [i915]
<4> [203.897716]  intel_atomic_commit+0x244/0x330 [i915]
<4> [203.897733]  drm_atomic_helper_update_plane+0xeb/0x100
<4> [203.897749]  drm_mode_cursor_universal+0x128/0x240
<4> [203.897782]  drm_mode_cursor_common+0x1a3/0x220
<4> [203.897809]  ? drm_mode_setplane+0x190/0x190
<4> [203.897817]  drm_mode_cursor_ioctl+0x48/0x70
<4> [203.897831]  drm_ioctl_kernel+0x81/0xf0
<4> [203.897845]  drm_ioctl+0x2de/0x390
<4> [203.897857]  ? drm_mode_setplane+0x190/0x190
<4> [203.897872]  ? seq_read+0x1e1/0x3c0
<4> [203.897895]  do_vfs_ioctl+0xa0/0x6e0
<4> [203.897904]  ? lock_acquire+0xa6/0x1c0
<4> [203.897915]  ? __task_pid_nr_ns+0xb9/0x1f0
<4> [203.897929]  ksys_ioctl+0x35/0x60
<4> [203.897942]  __x64_sys_ioctl+0x11/0x20
<4> [203.897953]  do_syscall_64+0x55/0x190
<4> [203.897963]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
<4> [203.897970] RIP: 0033:0x7f05183fc5d7
<4> [203.897977] Code: b3 66 90 48 8b 05 b1 48 2d 00 64 c7 00 26 00 00 00 48 c7 c0 ff ff ff ff c3 66 2e 0f 1f 84 00 00 00 00 00 b8 10 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 81 48 2d 00 f7 d8 64 89 01 48
<4> [203.897983] RSP: 002b:00007ffc8e19d718 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
<4> [203.897990] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f05183fc5d7
<4> [203.897995] RDX: 00007ffc8e19d750 RSI: 00000000c01c64a3 RDI: 0000000000000005
<4> [203.898000] RBP: 00007ffc8e19d750 R08: 0000000000000000 R09: 0000000000000030
<4> [203.898006] R10: 00000000ffffffd0 R11: 0000000000000246 R12: 00000000c01c64a3
<4> [203.898011] R13: 0000000000000005 R14: 0000000000000000 R15: 0000000000000000
<4> [203.898036] irq event stamp: 244364
<4> [203.898044] hardirqs last  enabled at (244363): [<ffffffffa1101164>] vprintk_emit+0x124/0x320
<4> [203.898051] hardirqs last disabled at (244364): [<ffffffffa10019b0>] trace_hardirqs_off_thunk+0x1a/0x1c
<4> [203.898059] softirqs last  enabled at (244304): [<ffffffffa1c0033a>] __do_softirq+0x33a/0x4b9
<4> [203.898066] softirqs last disabled at (244297): [<ffffffffa1093009>] irq_exit+0xa9/0xc0
<4> [203.898152] WARNING: CPU: 0 PID: 1336 at drivers/gpu/drm/i915/intel_drv.h:2134 gen11_fwtable_read32+0x1c8/0x260 [i915]
<4> [203.898158] ---[ end trace 98c932eaa674fd7f ]---
Comment 11 CI Bug Log 2019-01-08 10:13:08 UTC
A CI Bug Log filter associated to this bug has been updated:

{- ICL: igt@pm_rpm@(module-reload|basic-rte) - dmesg-warn - Device suspended during HW access -}
{+ ICL: igt@pm_rpm@* - dmesg-warn - Device suspended during HW access +}

New failures caught by the filter:

* https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_177/fi-icl-u3/igt@pm_rpm@modeset-lpsp-stress-no-wait.html
Comment 12 Jani Saarinen 2019-01-18 12:54:57 UTC
Ville, you have something for this already?
Comment 13 CI Bug Log 2019-02-21 14:16:12 UTC
A CI Bug Log filter associated to this bug has been updated:

{- ICL: igt@runner@aborted - fail - Previous test: pm_rpm (fences) -}
{+ ICL: igt@runner@aborted - fail - Previous test: i915_pm_rpm +}

New failures caught by the filter:

* https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_5640/shard-iclb1/igt@runner@aborted.html
Comment 14 Jani Saarinen 2019-03-05 08:18:42 UTC
Imre, do you know status if this bug?
Comment 15 Imre Deak 2019-03-05 11:25:48 UTC
(In reply to CI Bug Log from comment #13)
> A CI Bug Log filter associated to this bug has been updated:
> 
> {- ICL: igt@runner@aborted - fail - Previous test: pm_rpm (fences) -}
> {+ ICL: igt@runner@aborted - fail - Previous test: i915_pm_rpm +}
> 
> New failures caught by the filter:
> 
> *
> https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_5640/shard-iclb1/
> igt@runner@aborted.html

Hm, the above one gets stuck during kms_frontbuffer_tracking and has the following error:

<3>[  531.484666] [drm:pipe_config_err [i915]] *ERROR* mismatch in pixel_rate (expected 138780, found 92519)
<3>[  531.485032] [drm:pipe_config_err [i915]] *ERROR* mismatch in base.adjusted_mode.crtc_clock (expected 138780, found 92519)
<4>[  531.485111] ------------[ cut here ]------------
<4>[  531.485116] pipe state doesn't match!
<4>[  531.485225] WARNING: CPU: 2 PID: 2088 at drivers/gpu/drm/i915/intel_display.c:12503 intel_atomic_commit_tail+0x1224/0x1290 [i915

So not sure how it's related to the originally reported bug, which should be about the "DBus power enable timeout" error.

So I think this new one here is an unrelated issue and would need to be tracked somewhere else.

This ticket (bug 108654) OTOH was fixed by

commit ad3e7b824c185125f281d56a9e8f614effcdae91
Author: Ville Syrjälä <ville.syrjala@linux.intel.com>
Date:   Wed Jan 30 17:51:10 2019 +0200

  drm/i915: Don't use the second dbuf slice on icl

and so can be closed.
Comment 16 Martin Peres 2019-03-06 14:19:27 UTC
(In reply to Imre Deak from comment #15)
> (In reply to CI Bug Log from comment #13)
> > A CI Bug Log filter associated to this bug has been updated:
> > 
> > {- ICL: igt@runner@aborted - fail - Previous test: pm_rpm (fences) -}
> > {+ ICL: igt@runner@aborted - fail - Previous test: i915_pm_rpm +}
> > 
> > New failures caught by the filter:
> > 
> > *
> > https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_5640/shard-iclb1/
> > igt@runner@aborted.html

Links to igt@runner@aborted are often wrong because if one run got more than 1 abort, they will all write to the same file and that leads to seeing only one of them.

> 
> Hm, the above one gets stuck during kms_frontbuffer_tracking and has the
> following error:
> 
> <3>[  531.484666] [drm:pipe_config_err [i915]] *ERROR* mismatch in
> pixel_rate (expected 138780, found 92519)
> <3>[  531.485032] [drm:pipe_config_err [i915]] *ERROR* mismatch in
> base.adjusted_mode.crtc_clock (expected 138780, found 92519)
> <4>[  531.485111] ------------[ cut here ]------------
> <4>[  531.485116] pipe state doesn't match!
> <4>[  531.485225] WARNING: CPU: 2 PID: 2088 at
> drivers/gpu/drm/i915/intel_display.c:12503
> intel_atomic_commit_tail+0x1224/0x1290 [i915
> 
> So not sure how it's related to the originally reported bug, which should be
> about the "DBus power enable timeout" error.
> 
> So I think this new one here is an unrelated issue and would need to be
> tracked somewhere else.
> 
> This ticket (bug 108654) OTOH was fixed by
> 
> commit ad3e7b824c185125f281d56a9e8f614effcdae91
> Author: Ville Syrjälä <ville.syrjala@linux.intel.com>
> Date:   Wed Jan 30 17:51:10 2019 +0200
> 
>   drm/i915: Don't use the second dbuf slice on icl
> 
> and so can be closed.

We still hit this issue:

icl-y: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_5700/fi-icl-y/igt@i915_pm_rpm@basic-rte.html
icl-u3: https://intel-gfx-ci.01.org/tree/drm-tip/IGT_4862/fi-icl-u3/igt@i915_pm_rpm@universal-planes.html
icl-u2: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_5663/fi-icl-u2/igt@i915_pm_rpm@basic-rte.html
shard-iclb: https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_5694/shard-iclb1/igt@i915_pm_rpm@universal-planes.html

For more info, check the cibuglog data!
Comment 17 Imre Deak 2019-03-06 16:30:35 UTC
(In reply to Martin Peres from comment #16)
> (In reply to Imre Deak from comment #15)
> > (In reply to CI Bug Log from comment #13)
> > > A CI Bug Log filter associated to this bug has been updated:
> > > 
> > > {- ICL: igt@runner@aborted - fail - Previous test: pm_rpm (fences) -}
> > > {+ ICL: igt@runner@aborted - fail - Previous test: i915_pm_rpm +}
> > > 
> > > New failures caught by the filter:
> > > 
> > > *
> > > https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_5640/shard-iclb1/
> > > igt@runner@aborted.html
> 
> Links to igt@runner@aborted are often wrong because if one run got more than
> 1 abort, they will all write to the same file and that leads to seeing only
> one of them.

Okay. In the above case I also looked at the actual dmesg

https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_5640/shard-iclb1/dmesg23.log

which also doesn't have the "DBus power enable.." error message. But I suppose the error happened then on another ICL shard instance.

> 
> > 
> > Hm, the above one gets stuck during kms_frontbuffer_tracking and has the
> > following error:
> > 
> > <3>[  531.484666] [drm:pipe_config_err [i915]] *ERROR* mismatch in
> > pixel_rate (expected 138780, found 92519)
> > <3>[  531.485032] [drm:pipe_config_err [i915]] *ERROR* mismatch in
> > base.adjusted_mode.crtc_clock (expected 138780, found 92519)
> > <4>[  531.485111] ------------[ cut here ]------------
> > <4>[  531.485116] pipe state doesn't match!
> > <4>[  531.485225] WARNING: CPU: 2 PID: 2088 at
> > drivers/gpu/drm/i915/intel_display.c:12503
> > intel_atomic_commit_tail+0x1224/0x1290 [i915
> > 
> > So not sure how it's related to the originally reported bug, which should be
> > about the "DBus power enable timeout" error.
> > 
> > So I think this new one here is an unrelated issue and would need to be
> > tracked somewhere else.
> > 
> > This ticket (bug 108654) OTOH was fixed by
> > 
> > commit ad3e7b824c185125f281d56a9e8f614effcdae91
> > Author: Ville Syrjälä <ville.syrjala@linux.intel.com>
> > Date:   Wed Jan 30 17:51:10 2019 +0200
> > 
> >   drm/i915: Don't use the second dbuf slice on icl
> > 
> > and so can be closed.
> 
> We still hit this issue:
> 
> icl-y:
> https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_5700/fi-icl-y/
> igt@i915_pm_rpm@basic-rte.html
> icl-u3:
> https://intel-gfx-ci.01.org/tree/drm-tip/IGT_4862/fi-icl-u3/
> igt@i915_pm_rpm@universal-planes.html
> icl-u2:
> https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_5663/fi-icl-u2/
> igt@i915_pm_rpm@basic-rte.html
> shard-iclb:
> https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_5694/shard-iclb1/
> igt@i915_pm_rpm@universal-planes.html
> 
> For more info, check the cibuglog data!

Ok, thanks for the above links, I think I know where the problem is, will follow up with a fix.
Comment 18 Imre Deak 2019-03-08 08:18:38 UTC
Should be fixed by

Author: Imre Deak <imre.deak@intel.com>
Date:   Thu Mar 7 12:32:35 2019 +0200

    drm/i915/icl: Prevent incorrect DBuf enabling
Comment 19 Jani Saarinen 2019-03-08 09:49:57 UTC
Resolving again to wait CI results.
Comment 20 Martin Peres 2019-03-08 14:55:54 UTC
(In reply to Jani Saarinen from comment #19)
> Resolving again to wait CI results.

There is NEEDINFO for that...

And anyway, the patch is a workaround, not a fix. So re-opening.
Comment 21 Imre Deak 2019-03-08 15:25:27 UTC
(In reply to Martin Peres from comment #20)
> (In reply to Jani Saarinen from comment #19)
> > Resolving again to wait CI results.
> 
> There is NEEDINFO for that...
> 
> And anyway, the patch is a workaround, not a fix. So re-opening.

The patch does fix the problem where we tried to enable/disable DBuf slices incorrectly. As a result we shouldn't get the timeout error and possibly other related failures.

So imo the reported bug is fixed, we shouldn't get these error messages/conditions. It would be also good to be certain in this by way of having the bug open only if the error messages/conditions reappear. The task to toggle the second Dbuf slice on-demand should be tracked separately imo.
Comment 22 Martin Peres 2019-03-08 15:39:17 UTC
(In reply to Imre Deak from comment #21)
> (In reply to Martin Peres from comment #20)
> > (In reply to Jani Saarinen from comment #19)
> > > Resolving again to wait CI results.
> > 
> > There is NEEDINFO for that...
> > 
> > And anyway, the patch is a workaround, not a fix. So re-opening.
> 
> The patch does fix the problem where we tried to enable/disable DBuf slices
> incorrectly. As a result we shouldn't get the timeout error and possibly
> other related failures.
> 
> So imo the reported bug is fixed, we shouldn't get these error
> messages/conditions. It would be also good to be certain in this by way of
> having the bug open only if the error messages/conditions reappear. The task
> to toggle the second Dbuf slice on-demand should be tracked separately imo.

ACK. I'll tentatively resolve the bug then, and wait for some time before closing it for real (after getting enough data to prove it got fixed).


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.