Bug 100113

Summary:	[BSW][BAT] kms_pipe_crc_basic/suspend-read-crc-pipe-c causes dmesg warning
Product:	DRI	Reporter:	Jani Saarinen <jani.saarinen>
Component:	DRM/Intel	Assignee:	Intel GFX Bugs mailing list <intel-gfx-bugs>
Status:	CLOSED WORKSFORME	QA Contact:	Intel GFX Bugs mailing list <intel-gfx-bugs>
Severity:	normal
Priority:	medium	CC:	intel-gfx-bugs
Version:	DRI git
Hardware:	Other
OS:	All
Whiteboard:
i915 platform:	BSW/CHT	i915 features:

Description Jani Saarinen 2017-03-08 12:40:59 UTC

On CI https://intel-gfx-ci.01.org/CI/CI_DRM_2302/fi-bsw-n3050/igt@kms_pipe_crc_basic@suspend-read-crc-pipe-c.html

Not sure what is real component having issue as log indicates issue in swapper

BUG: scheduling while atomic: swapper/1/0/0x00000002
[  537.337380] no locks held by swapper/1/0.
[  537.337385] Modules linked in: vgem intel_powerclamp coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic snd_hda_intel lpc_ich snd_hda_codec snd_hwdep snd_hda_core snd_pcm i2c_designware_platform i2c_designware_core i915 r8169 mii prime_numbers sdhci_acpi i2c_hid sdhci mmc_core
[  537.337507] Preemption disabled at:
[  537.337521] [<ffffffff8103d14d>] start_secondary+0x1d/0x120
[  537.337534] CPU: 1 PID: 0 Comm: swapper/1 Tainted: G     U          4.11.0-rc1-CI-CI_DRM_2302+ #1
[  537.337540] Hardware name:                  /NUC5CPYB, BIOS PYBSWCEL.86A.0055.2016.0812.1130 08/12/2016
[  537.337545] Call Trace:
[  537.337559]  dump_stack+0x67/0x92
[  537.337566]  ? start_secondary+0x1d/0x120
[  537.337573]  __schedule_bug+0x7e/0xe0
[  537.337584]  __schedule+0x88c/0xbd0
[  537.337596]  schedule+0x3b/0x90
[  537.337604]  schedule_hrtimeout_range_clock+0xd1/0x150
[  537.337615]  ? __hrtimer_run_queues+0x530/0x530
[  537.337624]  schedule_hrtimeout+0x12/0x20
[  537.337632]  wait_task_inactive+0x288/0x290
[  537.337647]  __kthread_bind_mask+0x19/0x70
[  537.337655]  kthread_unpark+0x62/0x90
[  537.337665]  cpuhp_online_idle+0x50/0x90
[  537.337674]  cpu_startup_entry+0x13/0x20
[  537.337680]  start_secondary+0x102/0x120
[  537.337689]  start_cpu+0x14/0x14
[  537.337713] ------------[ cut here ]------------
[  537.337719] WARNING: CPU: 1 PID: 0 at kernel/locking/lockdep.c:3541 lock_release+0x4e1/0x4f0
[  537.337722] releasing a pinned lock
[  537.337723] Modules linked in: vgem intel_powerclamp coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic snd_hda_intel lpc_ich snd_hda_codec snd_hwdep snd_hda_core snd_pcm i2c_designware_platform i2c_designware_core i915 r8169 mii prime_numbers sdhci_acpi i2c_hid sdhci mmc_core
[  537.337754] CPU: 1 PID: 0 Comm: swapper/1 Tainted: G     U  W       4.11.0-rc1-CI-CI_DRM_2302+ #1
[  537.337756] Hardware name:                  /NUC5CPYB, BIOS PYBSWCEL.86A.0055.2016.0812.1130 08/12/2016
[  537.337757] Call Trace:
[  537.337761]  dump_stack+0x67/0x92
[  537.337766]  __warn+0xc6/0xe0
[  537.337771]  ? dequeue_task_idle+0xd/0x30
[  537.337774]  warn_slowpath_fmt+0x4a/0x50
[  537.337779]  lock_release+0x4e1/0x4f0
[  537.337784]  _raw_spin_unlock_irq+0x1a/0x50
[  537.337786]  dequeue_task_idle+0xd/0x30
[  537.337790]  deactivate_task+0x94/0x120
[  537.337794]  __schedule+0x474/0xbd0
[  537.337798]  schedule+0x3b/0x90
[  537.337801]  schedule_hrtimeout_range_clock+0xd1/0x150
[  537.337804]  ? __hrtimer_run_queues+0x530/0x530
[  537.337808]  schedule_hrtimeout+0x12/0x20
[  537.337811]  wait_task_inactive+0x288/0x290
[  537.337816]  __kthread_bind_mask+0x19/0x70
[  537.337819]  kthread_unpark+0x62/0x90
[  537.337823]  cpuhp_online_idle+0x50/0x90
[  537.337826]  cpu_startup_entry+0x13/0x20
[  537.337829]  start_secondary+0x102/0x120
[  537.337832]  start_cpu+0x14/0x14
[  537.337837] ---[ end trace 963bcdb3fd781f1d ]---
[  537.337839] bad: scheduling from the idle thread!
[  537.337845] CPU: 1 PID: 0 Comm: swapper/1 Tainted: G     U  W       4.11.0-rc1-CI-CI_DRM_2302+ #1
[  537.337850] Hardware name:                  /NUC5CPYB, BIOS PYBSWCEL.86A.0055.2016.0812.1130 08/12/2016
[  537.337853] Call Trace:
[  537.337860]  dump_stack+0x67/0x92
[  537.337868]  dequeue_task_idle+0x1e/0x30
[  537.337875]  deactivate_task+0x94/0x120
[  537.337883]  __schedule+0x474/0xbd0
[  537.337895]  schedule+0x3b/0x90
[  537.337902]  schedule_hrtimeout_range_clock+0xd1/0x150
[  537.337910]  ? __hrtimer_run_queues+0x530/0x530
[  537.337920]  schedule_hrtimeout+0x12/0x20
[  537.337926]  wait_task_inactive+0x288/0x290
[  537.337939]  __kthread_bind_mask+0x19/0x70
[  537.337947]  kthread_unpark+0x62/0x90
[  537.337954]  cpuhp_online_idle+0x50/0x90
[  537.337962]  cpu_startup_entry+0x13/0x20
[  537.337968]  start_secondary+0x102/0x120
[  537.337975]  start_cpu+0x14/0x14
[  537.337994] ------------[ cut here ]------------
[  537.337999] WARNING: CPU: 1 PID: 0 at kernel/locking/lockdep.c:3663 lock_unpin_lock+0x15b/0x160
[  537.338000] unpinning an unpinned lock
[  537.338001] Modules linked in: vgem intel_powerclamp coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic snd_hda_intel lpc_ich snd_hda_codec snd_hwdep snd_hda_core snd_pcm i2c_designware_platform i2c_designware_core i915 r8169 mii prime_numbers sdhci_acpi i2c_hid sdhci mmc_core
[  537.338031] CPU: 1 PID: 0 Comm: swapper/1 Tainted: G     U  W       4.11.0-rc1-CI-CI_DRM_2302+ #1
[  537.338033] Hardware name:                  /NUC5CPYB, BIOS PYBSWCEL.86A.0055.2016.0812.1130 08/12/2016
[  537.338034] Call Trace:
[  537.338038]  dump_stack+0x67/0x92
[  537.338042]  __warn+0xc6/0xe0
[  537.338046]  warn_slowpath_fmt+0x4a/0x50
[  537.338050]  lock_unpin_lock+0x15b/0x160
[  537.338054]  __schedule+0x2e5/0xbd0
[  537.338059]  schedule+0x3b/0x90
[  537.338062]  schedule_hrtimeout_range_clock+0xd1/0x150
[  537.338065]  ? __hrtimer_run_queues+0x530/0x530
[  537.338069]  schedule_hrtimeout+0x12/0x20
[  537.338074]  wait_task_inactive+0x288/0x290
[  537.338078]  __kthread_bind_mask+0x19/0x70
[  537.338081]  kthread_unpark+0x62/0x90
[  537.338085]  cpuhp_online_idle+0x50/0x90
[  537.338088]  cpu_startup_entry+0x13/0x20
[  537.338091]  start_secondary+0x102/0x120
[  537.338095]  start_cpu+0x14/0x14
[  537.338099] ---[ end trace 963bcdb3fd781f1e ]---
[  537.338905] ------------[ cut here ]------------
[  537.339215] WARNING: CPU: 1 PID: 0 at kernel/sched/sched.h:833 set_next_entity+0xb22/0xfe0
[  537.339217] rq->clock_update_flags < RQCF_ACT_SKIP
[  537.339219] Modules linked in: vgem intel_powerclamp coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic snd_hda_intel lpc_ich snd_hda_codec snd_hwdep snd_hda_core snd_pcm i2c_designware_platform i2c_designware_core i915 r8169 mii prime_numbers sdhci_acpi i2c_hid sdhci mmc_core
[  537.339282] CPU: 1 PID: 0 Comm: swapper/1 Tainted: G     U  W       4.11.0-rc1-CI-CI_DRM_2302+ #1
[  537.339284] Hardware name:                  /NUC5CPYB, BIOS PYBSWCEL.86A.0055.2016.0812.1130 08/12/2016
[  537.339286] Call Trace:
[  537.339291]  dump_stack+0x67/0x92
[  537.339296]  __warn+0xc6/0xe0
[  537.339302]  warn_slowpath_fmt+0x4a/0x50
[  537.339308]  set_next_entity+0xb22/0xfe0
[  537.339316]  pick_next_task_fair+0x76/0x840
[  537.339320]  ? debug_smp_processor_id+0x17/0x20
[  537.339324]  ? prandom_u32+0x39/0x60
[  537.339331]  __schedule+0x10b/0xbd0
[  537.339337]  ? preempt_schedule+0x1f/0x30
[  537.339342]  preempt_schedule_common+0x37/0x90
[  537.339347]  preempt_schedule+0x1f/0x30
[  537.339351]  ___preempt_schedule+0x16/0x18
[  537.339358]  _raw_spin_unlock_irqrestore+0x5b/0x60
[  537.339363]  try_to_wake_up+0x25a/0x650
[  537.339367]  ? _raw_spin_unlock_irqrestore+0x3d/0x60
[  537.339373]  wake_up_state+0xb/0x10
[  537.339377]  kthread_unpark+0x6f/0x90
[  537.339381]  cpuhp_online_idle+0x50/0x90
[  537.339386]  cpu_startup_entry+0x13/0x20
[  537.339390]  start_secondary+0x102/0x120
[  537.339395]  start_cpu+0x14/0x14
[  537.339403] ---[ end trace 963bcdb3fd781f1f ]---

Comment 1 Chris Wilson 2017-03-08 12:54:35 UTC

cpu-hotplug vs kthread

Comment 2 Jani Saarinen 2017-04-05 06:56:59 UTC

Statistics: Failure rate 2/210 run(s) (0%)
Resolving / Whitelisting

Comment 3 Ricardo 2017-06-27 15:19:16 UTC

issue is solved and now closing - Cleaning our bug BD from resolved

Comment 4 Vikram Mulukutla 2017-06-27 17:56:01 UTC

Hi Ricardo,

May I please know how this bug was resolved? I would like to know if my patch [1] helps avoid this race on your platform.

Thanks,
Vikram

[1] https://patchwork.kernel.org/patch/9810479/

Comment 5 Ricardo 2017-06-28 16:21:58 UTC

Hi Vikram, the bug was marked as resolved by our CI engineers as this failure only happend on 2 out of 210 times.. I was only closing the bug to follow the entire bug cycle

Comment 6 Vikram Mulukutla 2017-06-28 20:34:16 UTC

I see. Thank you.. I'm going to use this report as evidence of the BUG on x86. It seems to be identical to what I'm encountering on my ARM platform. It is quite timing sensitive so no surprise that it happens so infrequently!

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.