| Summary: | [CI] igt@gem_* - dmesg-warn - ODEBUG: free active (active state 0) object type: hrtimer hint: hrtimer_wakeup | ||
|---|---|---|---|
| Product: | DRI | Reporter: | Martin Peres <martin.peres> |
| 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, tomi.p.sarvela |
| Version: | XOrg git | ||
| Hardware: | Other | ||
| OS: | All | ||
| Whiteboard: | ReadyForDev | ||
| i915 platform: | BXT, KBL, SKL | i915 features: | power/Other |
|
Description
Martin Peres
2018-05-02 12:19:12 UTC
There is no way we have a timer inside our obj->pages map. The only timers that might be in vmalloced memory are on-stack. Maybe we should do a KASAN + CONFIG_STACK_VMAP=n. Adding Tomi for him to make this run. The kasan + vmap=n turned up nothing, not even an oops. Also found in a run 6 days ago on BXT: https://intel-gfx-ci.01.org/tree/drm-tip/drmtip_46/fi-bxt-j4205/igt@gem_exec_schedule@preempt-queue-contexts-bsd.html [ 309.079881] ------------[ cut here ]------------ [ 309.080535] ODEBUG: free active (active state 0) object type: hrtimer hint: hrtimer_wakeup+0x0/0x20 [ 309.080569] WARNING: CPU: 3 PID: 1546 at lib/debugobjects.c:339 debug_print_object+0xd7/0x100 [ 309.080584] Modules linked in: vgem snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic i915 snd_hda_intel x86_pkg_temp_thermal intel_powerclamp snd_hda_codec coretemp crct10dif_pclmul snd_hwdep crc32_pclmul ghash_clmulni_intel snd_hda_core snd_pcm r8169 mii lpc_ich mei_me mei prime_numbers pinctrl_broxton pinctrl_intel [ 309.080670] CPU: 3 PID: 1546 Comm: kworker/u8:33 Tainted: G U 4.17.0-rc5-gda383fb02111-drmtip_46+ #1 [ 309.080688] Hardware name: To Be Filled By O.E.M. To Be Filled By O.E.M./J4205-ITX, BIOS P1.10 09/29/2016 [ 309.080756] Workqueue: i915 __i915_gem_free_work [i915] [ 309.080769] RIP: 0010:debug_print_object+0xd7/0x100 [ 309.080779] RSP: 0018:ffffb7a8c0957be8 EFLAGS: 00010086 [ 309.080792] RAX: 0000000000000000 RBX: ffff99fc98427e08 RCX: 0000000000000002 [ 309.080806] RDX: 0000000080000002 RSI: ffffffffbc086656 RDI: 00000000ffffffff [ 309.080820] RBP: ffffffffbc248c00 R08: 0000000000000000 R09: 0000000000000000 [ 309.080833] R10: ffffb7a8c0957ca8 R11: ffffffffbc244598 R12: ffffffffbc0a1d9f [ 309.080847] R13: ffffffffbb118c50 R14: ffffb7a8c3e84000 R15: dead000000000100 [ 309.080861] FS: 0000000000000000(0000) GS:ffff99fcbfd80000(0000) knlGS:0000000000000000 [ 309.080876] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 309.080888] CR2: 00007fdc3650c9a8 CR3: 000000026443e000 CR4: 00000000003406e0 [ 309.080901] Call Trace: [ 309.080911] ? mark_held_locks+0x50/0x80 [ 309.080922] ? _raw_spin_unlock_irqrestore+0x4c/0x60 [ 309.080934] ? trace_hardirqs_on_caller+0xe0/0x1b0 [ 309.080947] ? lock_acquire+0xa6/0x210 [ 309.080957] ? debug_check_no_obj_freed+0xa4/0x210 [ 309.080971] debug_check_no_obj_freed+0x194/0x210 [ 309.080986] __vunmap+0xab/0x100 [ 309.081045] __i915_gem_object_put_pages+0x1a7/0x200 [i915] [ 309.081109] __i915_gem_free_objects+0x275/0x780 [i915] [ 309.081173] __i915_gem_free_work+0x5d/0x90 [i915] [ 309.081185] process_one_work+0x229/0x6a0 [ 309.081198] worker_thread+0x35/0x380 [ 309.081208] ? process_one_work+0x6a0/0x6a0 [ 309.081218] kthread+0x119/0x130 [ 309.081228] ? _kthread_create_on_node+0x60/0x60 [ 309.081240] ret_from_fork+0x3a/0x50 [ 309.081253] Code: 02 01 e8 2d 38 05 00 8b 43 10 4d 89 e9 4c 89 e6 8b 4b 14 4c 8b 45 00 48 c7 c7 10 8a 0a bc 48 8b 14 c5 e0 45 e4 bb e8 49 6e bf ff <0f> 0b 48 c7 c7 50 8a 0a bc e8 c4 c6 c6 ff be 02 00 00 00 48 89 [ 309.081365] irq event stamp: 711844 [ 309.081375] hardirqs last enabled at (711843): [<ffffffffbb9487fc>] _raw_spin_unlock_irqrestore+0x4c/0x60 [ 309.081394] hardirqs last disabled at (711844): [<ffffffffbb94866d>] _raw_spin_lock_irqsave+0xd/0x50 [ 309.081412] softirqs last enabled at (711076): [<ffffffffbbc0032b>] __do_softirq+0x32b/0x4e1 [ 309.081430] softirqs last disabled at (711071): [<ffffffffbb08f714>] irq_exit+0xa4/0xb0 [ 309.081446] WARNING: CPU: 3 PID: 1546 at lib/debugobjects.c:339 debug_print_object+0xd7/0x100 [ 309.081462] ---[ end trace 8c792c819b7f1a70 ]--- [ 309.081472] ODEBUG: ODEBUG: debug object originally initialized at: [ 309.081486] futex_wait+0x77/0x240 [ 309.081495] do_futex+0x486/0xb10 [ 309.081504] __se_sys_futex+0x128/0x170 [ 309.081513] do_syscall_64+0x55/0x190 [ 309.081523] entry_SYSCALL_64_after_hwframe+0x49/0xbe [ 309.081537] ====================================================== [ 309.081538] WARNING: possible circular locking dependency detected [ 309.081539] 4.17.0-rc5-gda383fb02111-drmtip_46+ #1 Tainted: G U [ 309.081540] ------------------------------------------------------ [ 309.081540] kworker/u8:33/1546 is trying to acquire lock: [ 309.081541] 0000000094eae43d ((console_sem).lock){-...}, at: down_trylock+0xa/0x30 [ 309.081544] but task is already holding lock: [ 309.081545] 000000004b79b31d (&obj_hash[i].lock){-.-.}, at: debug_check_no_obj_freed+0xa4/0x210 [ 309.081548] which lock already depends on the new lock. [ 309.081550] the existing dependency chain (in reverse order) is: [ 309.081551] -> #3 (&obj_hash[i].lock){-.-.}: [ 309.081553] __debug_object_init+0x74/0x590 [ 309.081554] hrtimer_init+0x1b/0x160 [ 309.081555] init_dl_task_timer+0x17/0x30 [ 309.081556] __sched_fork.isra.16+0xa4/0xf0 [ 309.081556] init_idle+0x53/0x270 [ 309.081557] sched_init+0x42c/0x49f [ 309.081558] start_kernel+0x269/0x4c2 [ 309.081559] secondary_startup_64+0xa5/0xb0 [ 309.081560] -> #2 (&rq->lock){-.-.}: [ 309.081562] task_fork_fair+0x36/0x160 [ 309.081563] sched_fork+0x123/0x280 [ 309.081564] copy_process.part.7+0x5f4/0x1d30 [ 309.081564] _do_fork+0xe2/0x700 [ 309.081565] kernel_thread+0x20/0x30 [ 309.081566] rest_init+0x1d/0x220 [ 309.081566] start_kernel+0x4a2/0x4c2 [ 309.081567] secondary_startup_64+0xa5/0xb0 [ 309.081568] -> #1 (&p->pi_lock){-.-.}: [ 309.081571] try_to_wake_up+0x37/0x650 [ 309.081571] up+0x3b/0x50 [ 309.081572] __up_console_sem+0x2e/0x50 [ 309.081573] console_unlock+0x32f/0x640 [ 309.081573] con_install+0xc0/0xd0 [ 309.081574] tty_init_dev+0x6c/0x1e0 [ 309.081575] tty_open+0x2e6/0x3e0 [ 309.081576] chrdev_open+0xa2/0x1c0 [ 309.081576] do_dentry_open.isra.1+0x19c/0x2f0 [ 309.081577] path_openat+0x4fe/0xb00 [ 309.081578] do_filp_open+0x96/0x110 [ 309.081579] do_sys_open+0x1b8/0x240 [ 309.081579] do_syscall_64+0x55/0x190 [ 309.081580] entry_SYSCALL_64_after_hwframe+0x49/0xbe [ 309.081581] -> #0 ((console_sem).lock){-...}: [ 309.081584] _raw_spin_lock_irqsave+0x33/0x50 [ 309.081584] down_trylock+0xa/0x30 [ 309.081585] __down_trylock_console_sem+0x20/0x80 [ 309.081586] console_trylock+0xe/0x60 [ 309.081587] vprintk_emit+0x22e/0x4d0 [ 309.081587] printk+0x4d/0x69 [ 309.081588] __warn_printk+0x46/0x90 [ 309.081589] debug_print_object+0xd7/0x100 [ 309.081590] debug_check_no_obj_freed+0x194/0x210 [ 309.081590] __vunmap+0xab/0x100 [ 309.081591] __i915_gem_object_put_pages+0x1a7/0x200 [i915] [ 309.081592] __i915_gem_free_objects+0x275/0x780 [i915] [ 309.081593] __i915_gem_free_work+0x5d/0x90 [i915] [ 309.081594] process_one_work+0x229/0x6a0 [ 309.081595] worker_thread+0x35/0x380 [ 309.081595] kthread+0x119/0x130 [ 309.081596] ret_from_fork+0x3a/0x50 [ 309.081597] other info that might help us debug this: [ 309.081598] Chain exists of: [ 309.081599] (console_sem).lock --> &rq->lock --> &obj_hash[i].lock [ 309.081603] Possible unsafe locking scenario: [ 309.081604] CPU0 CPU1 [ 309.081605] ---- ---- [ 309.081605] lock(&obj_hash[i].lock); [ 309.081607] lock(&rq->lock); [ 309.081609] lock(&obj_hash[i].lock); [ 309.081610] lock((console_sem).lock); [ 309.081612] *** DEADLOCK *** [ 309.081613] 4 locks held by kworker/u8:33/1546: [ 309.081614] #0: 00000000440e11f9 ((wq_completion)"i915"){+.+.}, at: process_one_work+0x1a3/0x6a0 [ 309.081617] #1: 00000000e349877b ((work_completion)(&i915->mm.free_work)){+.+.}, at: process_one_work+0x1a3/0x6a0 [ 309.081620] #2: 00000000de0e7429 (&obj->mm.lock){+.+.}, at: __i915_gem_object_put_pages+0x4f/0x200 [i915] [ 309.081623] #3: 000000004b79b31d (&obj_hash[i].lock){-.-.}, at: debug_check_no_obj_freed+0xa4/0x210 [ 309.081627] stack backtrace: [ 309.081628] CPU: 3 PID: 1546 Comm: kworker/u8:33 Tainted: G U 4.17.0-rc5-gda383fb02111-drmtip_46+ #1 [ 309.081629] Hardware name: To Be Filled By O.E.M. To Be Filled By O.E.M./J4205-ITX, BIOS P1.10 09/29/2016 [ 309.081630] Workqueue: i915 __i915_gem_free_work [i915] [ 309.081631] Call Trace: [ 309.081631] dump_stack+0x67/0x9b [ 309.081632] print_circular_bug.isra.18+0x1c8/0x2b0 [ 309.081633] __lock_acquire+0x1897/0x1b50 [ 309.081633] ? lock_acquire+0xa6/0x210 [ 309.081634] lock_acquire+0xa6/0x210 [ 309.081634] ? down_trylock+0xa/0x30 [ 309.081635] ? sched_clock_cpu+0x10/0xe0 [ 309.081635] ? vprintk_emit+0x22e/0x4d0 [ 309.081636] _raw_spin_lock_irqsave+0x33/0x50 [ 309.081636] ? down_trylock+0xa/0x30 [ 309.081637] down_trylock+0xa/0x30 [ 309.081638] __down_trylock_console_sem+0x20/0x80 [ 309.081638] console_trylock+0xe/0x60 [ 309.081639] vprintk_emit+0x22e/0x4d0 [ 309.081639] ? clock_was_set_work+0x20/0x20 [ 309.081640] printk+0x4d/0x69 [ 309.081640] ? clock_was_set_work+0x20/0x20 [ 309.081641] __warn_printk+0x46/0x90 [ 309.081641] ? clock_was_set_work+0x20/0x20 [ 309.081642] debug_print_object+0xd7/0x100 [ 309.081643] ? mark_held_locks+0x50/0x80 [ 309.081643] ? _raw_spin_unlock_irqrestore+0x4c/0x60 [ 309.081644] ? trace_hardirqs_on_caller+0xe0/0x1b0 [ 309.081644] ? lock_acquire+0xa6/0x210 [ 309.081645] ? debug_check_no_obj_freed+0xa4/0x210 [ 309.081646] debug_check_no_obj_freed+0x194/0x210 [ 309.081646] __vunmap+0xab/0x100 [ 309.081647] __i915_gem_object_put_pages+0x1a7/0x200 [i915] [ 309.081647] __i915_gem_free_objects+0x275/0x780 [i915] [ 309.081648] __i915_gem_free_work+0x5d/0x90 [i915] [ 309.081648] process_one_work+0x229/0x6a0 [ 309.081649] worker_thread+0x35/0x380 [ 309.081650] ? process_one_work+0x6a0/0x6a0 [ 309.081650] kthread+0x119/0x130 [ 309.081651] ? _kthread_create_on_node+0x60/0x60 [ 309.081651] ret_from_fork+0x3a/0x50 [ 309.082769] ------------[ cut here ]------------ [ 309.082791] ODEBUG: free active (active state 0) object type: hrtimer hint: hrtimer_wakeup+0x0/0x20 [ 309.082829] WARNING: CPU: 3 PID: 1546 at lib/debugobjects.c:339 debug_print_object+0xd7/0x100 [ 309.082849] Modules linked in: vgem snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic i915 snd_hda_intel x86_pkg_temp_thermal intel_powerclamp snd_hda_codec coretemp crct10dif_pclmul snd_hwdep crc32_pclmul ghash_clmulni_intel snd_hda_core snd_pcm r8169 mii lpc_ich mei_me mei prime_numbers pinctrl_broxton pinctrl_intel [ 309.082993] CPU: 3 PID: 1546 Comm: kworker/u8:33 Tainted: G U W 4.17.0-rc5-gda383fb02111-drmtip_46+ #1 [ 309.083012] Hardware name: To Be Filled By O.E.M. To Be Filled By O.E.M./J4205-ITX, BIOS P1.10 09/29/2016 [ 309.083104] Workqueue: i915 __i915_gem_free_work [i915] [ 309.083117] RIP: 0010:debug_print_object+0xd7/0x100 [ 309.083132] RSP: 0018:ffffb7a8c0957be8 EFLAGS: 00010086 [ 309.083150] RAX: 0000000000000000 RBX: ffff99fcb18c1988 RCX: 0000000000000002 [ 309.083169] RDX: 0000000080000002 RSI: ffffffffbc086656 RDI: 00000000ffffffff [ 309.083186] RBP: ffffffffbc248c00 R08: 0000000000000000 R09: 0000000000000000 [ 309.083203] R10: ffffb7a8c0957ca8 R11: ffffffffbc244598 R12: ffffffffbc0a1d9f [ 309.083219] R13: ffffffffbb118c50 R14: ffffb7a8c3e84000 R15: dead000000000100 [ 309.083233] FS: 0000000000000000(0000) GS:ffff99fcbfd80000(0000) knlGS:0000000000000000 [ 309.083248] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 309.083260] CR2: 00007fdc3650c9a8 CR3: 000000026443e000 CR4: 00000000003406e0 [ 309.083274] Call Trace: [ 309.083287] ? lock_acquire+0xa6/0x210 [ 309.083302] ? lock_acquire+0xa6/0x210 [ 309.083312] ? debug_check_no_obj_freed+0xa4/0x210 [ 309.083324] ? __free_object+0xa9/0xb0 [ 309.083336] debug_check_no_obj_freed+0x194/0x210 [ 309.083352] __vunmap+0xab/0x100 [ 309.083413] __i915_gem_object_put_pages+0x1a7/0x200 [i915] [ 309.083479] __i915_gem_free_objects+0x275/0x780 [i915] [ 309.083542] __i915_gem_free_work+0x5d/0x90 [i915] [ 309.083556] process_one_work+0x229/0x6a0 [ 309.083571] worker_thread+0x35/0x380 [ 309.083582] ? process_one_work+0x6a0/0x6a0 [ 309.083592] kthread+0x119/0x130 [ 309.083601] ? _kthread_create_on_node+0x60/0x60 [ 309.083615] ret_from_fork+0x3a/0x50 [ 309.083628] Code: 02 01 e8 2d 38 05 00 8b 43 10 4d 89 e9 4c 89 e6 8b 4b 14 4c 8b 45 00 48 c7 c7 10 8a 0a bc 48 8b 14 c5 e0 45 e4 bb e8 49 6e bf ff <0f> 0b 48 c7 c7 50 8a 0a bc e8 c4 c6 c6 ff be 02 00 00 00 48 89 [ 309.083743] irq event stamp: 711844 [ 309.083753] hardirqs last enabled at (711843): [<ffffffffbb9487fc>] _raw_spin_unlock_irqrestore+0x4c/0x60 [ 309.083772] hardirqs last disabled at (711844): [<ffffffffbb94866d>] _raw_spin_lock_irqsave+0xd/0x50 [ 309.083791] softirqs last enabled at (711076): [<ffffffffbbc0032b>] __do_softirq+0x32b/0x4e1 [ 309.083809] softirqs last disabled at (711071): [<ffffffffbb08f714>] irq_exit+0xa4/0xb0 [ 309.083825] WARNING: CPU: 3 PID: 1546 at lib/debugobjects.c:339 debug_print_object+0xd7/0x100 [ 309.083841] ---[ end trace 8c792c819b7f1a71 ]--- [ 309.083852] ODEBUG: ODEBUG: debug object originally initialized at: [ 309.083867] futex_wait+0x77/0x240 [ 309.083877] do_futex+0x486/0xb10 [ 309.083886] __se_sys_futex+0x128/0x170 [ 309.083896] do_syscall_64+0x55/0x190 [ 309.083906] entry_SYSCALL_64_after_hwframe+0x49/0xbe [ 309.083953] ------------[ cut here ]------------ [ 309.083975] ODEBUG: free active (active state 0) object type: hrtimer hint: hrtimer_wakeup+0x0/0x20 [ 309.084010] WARNING: CPU: 3 PID: 1546 at lib/debugobjects.c:339 debug_print_object+0xd7/0x100 [ 309.084029] Modules linked in: vgem snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic i915 snd_hda_intel x86_pkg_temp_thermal intel_powerclamp snd_hda_codec coretemp crct10dif_pclmul snd_hwdep crc32_pclmul ghash_clmulni_intel snd_hda_core snd_pcm r8169 mii lpc_ich mei_me mei prime_numbers pinctrl_broxton pinctrl_intel [ 309.084117] CPU: 3 PID: 1546 Comm: kworker/u8:33 Tainted: G U W 4.17.0-rc5-gda383fb02111-drmtip_46+ #1 [ 309.084135] Hardware name: To Be Filled By O.E.M. To Be Filled By O.E.M./J4205-ITX, BIOS P1.10 09/29/2016 [ 309.084222] Workqueue: i915 __i915_gem_free_work [i915] [ 309.084238] RIP: 0010:debug_print_object+0xd7/0x100 [ 309.084248] RSP: 0018:ffffb7a8c0957be8 EFLAGS: 00010086 [ 309.084260] RAX: 0000000000000000 RBX: ffff99fca94d6608 RCX: 0000000000000002 [ 309.084273] RDX: 0000000080000002 RSI: ffffffffbc086656 RDI: 00000000ffffffff [ 309.084287] RBP: ffffffffbc248c00 R08: 0000000000000000 R09: 0000000000000000 [ 309.084301] R10: ffffb7a8c0957ca8 R11: ffffffffbc244598 R12: ffffffffbc0a1d9f [ 309.084314] R13: ffffffffbb118c50 R14: ffffb7a8c3e84000 R15: dead000000000100 [ 309.084329] FS: 0000000000000000(0000) GS:ffff99fcbfd80000(0000) knlGS:0000000000000000 [ 309.084344] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 309.084355] CR2: 00007fdc3650c9a8 CR3: 000000026443e000 CR4: 00000000003406e0 [ 309.084369] Call Trace: [ 309.084381] ? lock_acquire+0xa6/0x210 [ 309.084393] ? lock_acquire+0xa6/0x210 [ 309.084404] ? debug_check_no_obj_freed+0xa4/0x210 [ 309.084415] ? __free_object+0xa9/0xb0 [ 309.084427] debug_check_no_obj_freed+0x194/0x210 [ 309.084443] __vunmap+0xab/0x100 [ 309.084514] __i915_gem_object_put_pages+0x1a7/0x200 [i915] [ 309.084582] __i915_gem_free_objects+0x275/0x780 [i915] [ 309.084647] __i915_gem_free_work+0x5d/0x90 [i915] [ 309.084662] process_one_work+0x229/0x6a0 [ 309.084677] worker_thread+0x35/0x380 [ 309.084688] ? process_one_work+0x6a0/0x6a0 [ 309.084698] kthread+0x119/0x130 [ 309.084709] ? _kthread_create_on_node+0x60/0x60 [ 309.084722] ret_from_fork+0x3a/0x50 [ 309.084736] Code: 02 01 e8 2d 38 05 00 8b 43 10 4d 89 e9 4c 89 e6 8b 4b 14 4c 8b 45 00 48 c7 c7 10 8a 0a bc 48 8b 14 c5 e0 45 e4 bb e8 49 6e bf ff <0f> 0b 48 c7 c7 50 8a 0a bc e8 c4 c6 c6 ff be 02 00 00 00 48 89 [ 309.084855] irq event stamp: 711844 [ 309.084867] hardirqs last enabled at (711843): [<ffffffffbb9487fc>] _raw_spin_unlock_irqrestore+0x4c/0x60 [ 309.084886] hardirqs last disabled at (711844): [<ffffffffbb94866d>] _raw_spin_lock_irqsave+0xd/0x50 [ 309.084905] softirqs last enabled at (711076): [<ffffffffbbc0032b>] __do_softirq+0x32b/0x4e1 [ 309.084923] softirqs last disabled at (711071): [<ffffffffbb08f714>] irq_exit+0xa4/0xb0 [ 309.084942] WARNING: CPU: 3 PID: 1546 at lib/debugobjects.c:339 debug_print_object+0xd7/0x100 [ 309.084958] ---[ end trace 8c792c819b7f1a72 ]--- Definitely not a one-off, and definitely visible right now :) https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_4266/shard-kbl4/igt@gem_exec_await@wide-contexts.html [ 148.822603] ------------[ cut here ]------------ [ 148.822915] ODEBUG: free active (active state 0) object type: hrtimer hint: hrtimer_wakeup+0x0/0x20 [ 148.822929] WARNING: CPU: 0 PID: 6 at lib/debugobjects.c:339 debug_print_object+0xd7/0x100 [ 148.822935] Modules linked in: vgem snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic i915 snd_hda_intel x86_pkg_temp_thermal intel_powerclamp coretemp snd_hda_codec crct10dif_pclmul crc32_pclmul snd_hwdep snd_hda_core btusb ghash_clmulni_intel btrtl btbcm btintel snd_pcm bluetooth e1000e ecdh_generic mei_me mei prime_numbers [ 148.822972] CPU: 0 PID: 6 Comm: kworker/u8:0 Tainted: G U 4.17.0-rc7-CI-CI_DRM_4266+ #1 [ 148.822979] Hardware name: /NUC7i5BNB, BIOS BNKBL357.86A.0054.2017.1025.1822 10/25/2017 [ 148.823003] Workqueue: i915 __i915_gem_free_work [i915] [ 148.823009] RIP: 0010:debug_print_object+0xd7/0x100 [ 148.823014] RSP: 0018:ffffc90000077be8 EFLAGS: 00010086 [ 148.823019] RAX: 0000000000000000 RBX: ffff880157d56488 RCX: 0000000000000002 [ 148.823025] RDX: 0000000080000002 RSI: ffffffff820c48a5 RDI: 00000000ffffffff [ 148.823031] RBP: ffffffff82248480 R08: 0000000000000000 R09: 0000000000000000 [ 148.823036] R10: ffffc90000077ca8 R11: ffffffff82243e18 R12: ffffffff820c0b1f [ 148.823042] R13: ffffffff81115790 R14: ffffc90003470000 R15: dead000000000100 [ 148.823048] FS: 0000000000000000(0000) GS:ffff88027ec00000(0000) knlGS:0000000000000000 [ 148.823055] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 148.823060] CR2: 00007f7723cbd9a8 CR3: 0000000005210006 CR4: 00000000003606f0 [ 148.823065] Call Trace: [ 148.823070] ? mark_held_locks+0x50/0x80 [ 148.823075] ? _raw_spin_unlock_irqrestore+0x4c/0x60 [ 148.823080] ? trace_hardirqs_on_caller+0xe0/0x1b0 [ 148.823086] ? lock_acquire+0xa6/0x210 [ 148.823090] ? debug_check_no_obj_freed+0xa4/0x210 [ 148.823096] debug_check_no_obj_freed+0x194/0x210 [ 148.823103] __vunmap+0xab/0x100 [ 148.823125] __i915_gem_object_put_pages+0x1ec/0x200 [i915] [ 148.823148] __i915_gem_free_objects+0x275/0x780 [i915] [ 148.823171] __i915_gem_free_work+0x5d/0x90 [i915] [ 148.823177] process_one_work+0x229/0x6a0 [ 148.823184] worker_thread+0x35/0x380 [ 148.823189] ? process_one_work+0x6a0/0x6a0 [ 148.823193] kthread+0x119/0x130 [ 148.823197] ? kthread_flush_work_fn+0x10/0x10 [ 148.823203] ret_from_fork+0x3a/0x50 [ 148.823208] Code: 02 01 e8 3d 38 05 00 8b 43 10 4d 89 e9 4c 89 e6 8b 4b 14 4c 8b 45 00 48 c7 c7 08 2f 0d 82 48 8b 14 c5 40 cb e6 81 e8 19 01 bf ff <0f> 0b 48 c7 c7 48 2f 0d 82 e8 64 59 c6 ff be 02 00 00 00 48 89 [ 148.823257] irq event stamp: 2465622 [ 148.823262] hardirqs last enabled at (2465621): [<ffffffff81930b6c>] _raw_spin_unlock_irqrestore+0x4c/0x60 [ 148.823270] hardirqs last disabled at (2465622): [<ffffffff819309dd>] _raw_spin_lock_irqsave+0xd/0x50 [ 148.823278] softirqs last enabled at (2461560): [<ffffffff81c0032b>] __do_softirq+0x32b/0x4e1 [ 148.823286] softirqs last disabled at (2461553): [<ffffffff8108c284>] irq_exit+0xa4/0xb0 [ 148.823293] WARNING: CPU: 0 PID: 6 at lib/debugobjects.c:339 debug_print_object+0xd7/0x100 [ 148.823300] ---[ end trace 7b673478a9a0fd9b ]--- [ 148.823304] ODEBUG: ODEBUG: debug object originally initialized at: [ 148.823311] futex_wait+0x77/0x240 [ 148.823315] do_futex+0x486/0xb10 [ 148.823320] __se_sys_futex+0x128/0x170 [ 148.823324] do_syscall_64+0x55/0x190 [ 148.823328] entry_SYSCALL_64_after_hwframe+0x49/0xbe [ 148.823334] ====================================================== [ 148.823335] WARNING: possible circular locking dependency detected [ 148.823335] 4.17.0-rc7-CI-CI_DRM_4266+ #1 Tainted: G U [ 148.823335] ------------------------------------------------------ [ 148.823336] kworker/u8:0/6 is trying to acquire lock: [ 148.823336] 00000000f82870ee ((console_sem).lock){-...}, at: down_trylock+0xa/0x30 [ 148.823338] but task is already holding lock: [ 148.823338] 000000007fd8375f (&obj_hash[i].lock){-.-.}, at: debug_check_no_obj_freed+0xa4/0x210 [ 148.823339] which lock already depends on the new lock. [ 148.823340] the existing dependency chain (in reverse order) is: [ 148.823341] -> #3 (&obj_hash[i].lock){-.-.}: [ 148.823342] __debug_object_init+0x74/0x590 [ 148.823342] hrtimer_init+0x1b/0x160 [ 148.823342] init_dl_task_timer+0x17/0x30 [ 148.823343] __sched_fork.isra.16+0xa4/0xf0 [ 148.823343] init_idle+0x53/0x270 [ 148.823343] sched_init+0x42c/0x49f [ 148.823343] start_kernel+0x269/0x4bb [ 148.823344] secondary_startup_64+0xa5/0xb0 [ 148.823344] -> #2 (&rq->lock){-.-.}: [ 148.823345] task_fork_fair+0x36/0x160 [ 148.823346] sched_fork+0x123/0x280 [ 148.823346] copy_process.part.7+0x5f4/0x1d30 [ 148.823346] _do_fork+0xe2/0x700 [ 148.823346] kernel_thread+0x20/0x30 [ 148.823347] rest_init+0x1d/0x220 [ 148.823347] start_kernel+0x49b/0x4bb [ 148.823347] secondary_startup_64+0xa5/0xb0 [ 148.823348] -> #1 (&p->pi_lock){-.-.}: [ 148.823349] try_to_wake_up+0x37/0x650 [ 148.823349] up+0x3b/0x50 [ 148.823349] __up_console_sem+0x2e/0x50 [ 148.823350] console_unlock+0x32f/0x640 [ 148.823350] register_framebuffer+0x24c/0x350 [ 148.823350] __drm_fb_helper_initial_config_and_unlock+0x22a/0x4a0 [ 148.823351] intel_fbdev_initial_config+0xf/0x20 [i915] [ 148.823351] async_run_entry_fn+0x34/0x160 [ 148.823351] process_one_work+0x229/0x6a0 [ 148.823351] worker_thread+0x35/0x380 [ 148.823352] kthread+0x119/0x130 [ 148.823352] ret_from_fork+0x3a/0x50 [ 148.823352] -> #0 ((console_sem).lock){-...}: [ 148.823354] _raw_spin_lock_irqsave+0x33/0x50 [ 148.823354] down_trylock+0xa/0x30 [ 148.823354] __down_trylock_console_sem+0x20/0x80 [ 148.823354] console_trylock+0xe/0x60 [ 148.823355] vprintk_emit+0x22e/0x4d0 [ 148.823355] printk+0x4d/0x69 [ 148.823355] __warn_printk+0x46/0x90 [ 148.823355] debug_print_object+0xd7/0x100 [ 148.823356] debug_check_no_obj_freed+0x194/0x210 [ 148.823356] __vunmap+0xab/0x100 [ 148.823356] __i915_gem_object_put_pages+0x1ec/0x200 [i915] [ 148.823357] __i915_gem_free_objects+0x275/0x780 [i915] [ 148.823357] __i915_gem_free_work+0x5d/0x90 [i915] [ 148.823357] process_one_work+0x229/0x6a0 [ 148.823358] worker_thread+0x35/0x380 [ 148.823358] kthread+0x119/0x130 [ 148.823358] ret_from_fork+0x3a/0x50 [ 148.823359] other info that might help us debug this: [ 148.823359] Chain exists of: [ 148.823359] (console_sem).lock --> &rq->lock --> &obj_hash[i].lock [ 148.823361] Possible unsafe locking scenario: [ 148.823362] CPU0 CPU1 [ 148.823362] ---- ---- [ 148.823362] lock(&obj_hash[i].lock); [ 148.823363] lock(&rq->lock); [ 148.823364] lock(&obj_hash[i].lock); [ 148.823364] lock((console_sem).lock); [ 148.823365] *** DEADLOCK *** [ 148.823366] 4 locks held by kworker/u8:0/6: [ 148.823366] #0: 0000000014cc212b ((wq_completion)"i915"){+.+.}, at: process_one_work+0x1a3/0x6a0 [ 148.823367] #1: 0000000071ed54ba ((work_completion)(&i915->mm.free_work)){+.+.}, at: process_one_work+0x1a3/0x6a0 [ 148.823369] #2: 0000000020c47fc7 (&obj->mm.lock){+.+.}, at: __i915_gem_object_put_pages+0x4f/0x200 [i915] [ 148.823370] #3: 000000007fd8375f (&obj_hash[i].lock){-.-.}, at: debug_check_no_obj_freed+0xa4/0x210 [ 148.823372] stack backtrace: [ 148.823372] CPU: 0 PID: 6 Comm: kworker/u8:0 Tainted: G U 4.17.0-rc7-CI-CI_DRM_4266+ #1 [ 148.823372] Hardware name: /NUC7i5BNB, BIOS BNKBL357.86A.0054.2017.1025.1822 10/25/2017 [ 148.823373] Workqueue: i915 __i915_gem_free_work [i915] [ 148.823373] Call Trace: [ 148.823373] dump_stack+0x67/0x9b [ 148.823374] print_circular_bug.isra.18+0x1c8/0x2b0 [ 148.823374] __lock_acquire+0x1897/0x1b50 [ 148.823374] ? lock_acquire+0xa6/0x210 [ 148.823375] lock_acquire+0xa6/0x210 [ 148.823375] ? down_trylock+0xa/0x30 [ 148.823375] ? sched_clock_cpu+0x10/0xe0 [ 148.823375] ? vprintk_emit+0x22e/0x4d0 [ 148.823376] _raw_spin_lock_irqsave+0x33/0x50 [ 148.823376] ? down_trylock+0xa/0x30 [ 148.823376] down_trylock+0xa/0x30 [ 148.823377] __down_trylock_console_sem+0x20/0x80 [ 148.823377] console_trylock+0xe/0x60 [ 148.823377] vprintk_emit+0x22e/0x4d0 [ 148.823377] ? clock_was_set_work+0x20/0x20 [ 148.823378] printk+0x4d/0x69 [ 148.823378] ? clock_was_set_work+0x20/0x20 [ 148.823378] __warn_printk+0x46/0x90 [ 148.823378] ? clock_was_set_work+0x20/0x20 [ 148.823379] debug_print_object+0xd7/0x100 [ 148.823379] ? mark_held_locks+0x50/0x80 [ 148.823379] ? _raw_spin_unlock_irqrestore+0x4c/0x60 [ 148.823380] ? trace_hardirqs_on_caller+0xe0/0x1b0 [ 148.823380] ? lock_acquire+0xa6/0x210 [ 148.823380] ? debug_check_no_obj_freed+0xa4/0x210 [ 148.823380] debug_check_no_obj_freed+0x194/0x210 [ 148.823381] __vunmap+0xab/0x100 [ 148.823381] __i915_gem_object_put_pages+0x1ec/0x200 [i915] [ 148.823381] __i915_gem_free_objects+0x275/0x780 [i915] [ 148.823382] __i915_gem_free_work+0x5d/0x90 [i915] [ 148.823382] process_one_work+0x229/0x6a0 [ 148.823382] worker_thread+0x35/0x380 [ 148.823382] ? process_one_work+0x6a0/0x6a0 [ 148.823383] kthread+0x119/0x130 [ 148.823383] ? kthread_flush_work_fn+0x10/0x10 [ 148.823383] ret_from_fork+0x3a/0x50 [ 148.827461] ------------[ cut here ]------------ [ 148.827470] ODEBUG: free active (active state 0) object type: hrtimer hint: hrtimer_wakeup+0x0/0x20 [ 148.827484] WARNING: CPU: 0 PID: 6 at lib/debugobjects.c:339 debug_print_object+0xd7/0x100 [ 148.827491] Modules linked in: vgem snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic i915 snd_hda_intel x86_pkg_temp_thermal intel_powerclamp coretemp snd_hda_codec crct10dif_pclmul crc32_pclmul snd_hwdep snd_hda_core btusb ghash_clmulni_intel btrtl btbcm btintel snd_pcm bluetooth e1000e ecdh_generic mei_me mei prime_numbers [ 148.827531] CPU: 0 PID: 6 Comm: kworker/u8:0 Tainted: G U W 4.17.0-rc7-CI-CI_DRM_4266+ #1 [ 148.827538] Hardware name: /NUC7i5BNB, BIOS BNKBL357.86A.0054.2017.1025.1822 10/25/2017 [ 148.827575] Workqueue: i915 __i915_gem_free_work [i915] [ 148.827583] RIP: 0010:debug_print_object+0xd7/0x100 [ 148.827587] RSP: 0000:ffffc90000077be8 EFLAGS: 00010086 [ 148.827593] RAX: 0000000000000000 RBX: ffff880158d22908 RCX: 0000000000000002 [ 148.827599] RDX: 0000000080000002 RSI: ffffffff820c48a5 RDI: 00000000ffffffff [ 148.827604] RBP: ffffffff82248480 R08: 0000000000000000 R09: 0000000000000000 [ 148.827610] R10: ffffc90000077ca8 R11: ffffffff82243e18 R12: ffffffff820c0b1f [ 148.827616] R13: ffffffff81115790 R14: ffffc90003470000 R15: dead000000000100 [ 148.827622] FS: 0000000000000000(0000) GS:ffff88027ec00000(0000) knlGS:0000000000000000 [ 148.827629] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 148.827634] CR2: 00007fc0178ddb98 CR3: 0000000005210006 CR4: 00000000003606f0 [ 148.827639] Call Trace: [ 148.827645] ? lock_acquire+0xa6/0x210 [ 148.827650] ? lock_acquire+0xa6/0x210 [ 148.827655] ? debug_check_no_obj_freed+0xa4/0x210 [ 148.827660] ? __free_object+0xa9/0xb0 [ 148.827665] debug_check_no_obj_freed+0x194/0x210 [ 148.827672] __vunmap+0xab/0x100 [ 148.827704] __i915_gem_object_put_pages+0x1ec/0x200 [i915] [ 148.827730] __i915_gem_free_objects+0x275/0x780 [i915] [ 148.827754] __i915_gem_free_work+0x5d/0x90 [i915] [ 148.827762] process_one_work+0x229/0x6a0 [ 148.827768] worker_thread+0x35/0x380 [ 148.827773] ? process_one_work+0x6a0/0x6a0 [ 148.827778] kthread+0x119/0x130 [ 148.827783] ? kthread_flush_work_fn+0x10/0x10 [ 148.827788] ret_from_fork+0x3a/0x50 [ 148.827794] Code: 02 01 e8 3d 38 05 00 8b 43 10 4d 89 e9 4c 89 e6 8b 4b 14 4c 8b 45 00 48 c7 c7 08 2f 0d 82 48 8b 14 c5 40 cb e6 81 e8 19 01 bf ff <0f> 0b 48 c7 c7 48 2f 0d 82 e8 64 59 c6 ff be 02 00 00 00 48 89 [ 148.827844] irq event stamp: 2465622 [ 148.827849] hardirqs last enabled at (2465621): [<ffffffff81930b6c>] _raw_spin_unlock_irqrestore+0x4c/0x60 [ 148.827857] hardirqs last disabled at (2465622): [<ffffffff819309dd>] _raw_spin_lock_irqsave+0xd/0x50 [ 148.827865] softirqs last enabled at (2461560): [<ffffffff81c0032b>] __do_softirq+0x32b/0x4e1 [ 148.827873] softirqs last disabled at (2461553): [<ffffffff8108c284>] irq_exit+0xa4/0xb0 [ 148.827881] WARNING: CPU: 0 PID: 6 at lib/debugobjects.c:339 debug_print_object+0xd7/0x100 [ 148.827887] ---[ end trace 7b673478a9a0fd9c ]--- https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_4269_38/fi-cnl-y3/igt@gem_ctx_create@basic-files.html [ 58.312435] Setting dangerous option reset - tainting kernel [ 64.416419] ------------[ cut here ]------------ [ 64.416797] ODEBUG: free active (active state 0) object type: hrtimer hint: hrtimer_wakeup+0x0/0x20 [ 64.416814] WARNING: CPU: 0 PID: 129 at lib/debugobjects.c:339 debug_print_object+0xd7/0x100 [ 64.416822] Modules linked in: snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic i915 snd_hda_intel snd_hda_codec x86_pkg_temp_thermal intel_powerclamp coretemp snd_hwdep crct10dif_pclmul snd_hda_core crc32_pclmul ghash_clmulni_intel e1000e snd_pcm mei_me mei prime_numbers [ 64.416859] CPU: 0 PID: 129 Comm: kworker/u8:2 Tainted: G U 4.17.0-rc7-g25dda01a94cb-repeat_1+ #1 [ 64.416868] Hardware name: Intel Corporation CannonLake Client Platform/CannonLake Y LPDDR4 RVP, BIOS CNLSFWR1.R00.X122.B01.1801151045 01/15/2018 [ 64.416901] Workqueue: i915 __i915_gem_free_work [i915] [ 64.416908] RIP: 0010:debug_print_object+0xd7/0x100 [ 64.416914] RSP: 0018:ffffb8ce404c3be8 EFLAGS: 00010086 [ 64.416920] RAX: 0000000000000000 RBX: ffffa3c412834a88 RCX: 0000000000000002 [ 64.416927] RDX: 0000000080000002 RSI: ffffffff84086cfe RDI: 00000000ffffffff [ 64.416934] RBP: ffffffff84248c00 R08: 0000000000000000 R09: 0000000000000000 [ 64.416941] R10: ffffb8ce404c3ca8 R11: ffffffff84244598 R12: ffffffff840a24bf [ 64.416948] R13: ffffffff831196c0 R14: ffffb8ce6f8cb000 R15: dead000000000100 [ 64.416955] FS: 0000000000000000(0000) GS:ffffa3c4ef800000(0000) knlGS:0000000000000000 [ 64.416964] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 64.416970] CR2: 00007f3581620f80 CR3: 0000000212210006 CR4: 0000000000760ef0 [ 64.416977] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 [ 64.416984] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400 [ 64.416991] PKRU: 55555554 [ 64.416995] Call Trace: [ 64.417000] ? mark_held_locks+0x50/0x80 [ 64.417007] ? _raw_spin_unlock_irqrestore+0x4c/0x60 [ 64.417013] ? trace_hardirqs_on_caller+0xe0/0x1b0 [ 64.417020] ? lock_acquire+0xa6/0x210 [ 64.417026] ? debug_check_no_obj_freed+0xa4/0x210 [ 64.417034] debug_check_no_obj_freed+0x194/0x210 [ 64.417042] __vunmap+0xab/0x100 [ 64.417068] __i915_gem_object_put_pages+0x1a7/0x200 [i915] [ 64.417096] __i915_gem_free_objects+0x275/0x780 [i915] [ 64.417125] __i915_gem_free_work+0x5d/0x90 [i915] [ 64.417132] process_one_work+0x229/0x6a0 [ 64.417139] worker_thread+0x35/0x380 [ 64.417144] ? process_one_work+0x6a0/0x6a0 [ 64.417150] kthread+0x119/0x130 [ 64.417155] ? kthread_flush_work_fn+0x10/0x10 [ 64.417162] ret_from_fork+0x3a/0x50 [ 64.417169] Code: 02 01 e8 2d 38 05 00 8b 43 10 4d 89 e9 4c 89 e6 8b 4b 14 4c 8b 45 00 48 c7 c7 30 91 0a 84 48 8b 14 c5 20 48 e4 83 e8 49 67 bf ff <0f> 0b 48 c7 c7 70 91 0a 84 e8 44 c0 c6 ff be 02 00 00 00 48 89 [ 64.417230] irq event stamp: 786892 [ 64.417236] hardirqs last enabled at (786891): [<ffffffff8394993c>] _raw_spin_unlock_irqrestore+0x4c/0x60 [ 64.417246] hardirqs last disabled at (786892): [<ffffffff839497ad>] _raw_spin_lock_irqsave+0xd/0x50 [ 64.417256] softirqs last enabled at (786418): [<ffffffff83c0032b>] __do_softirq+0x32b/0x4e1 [ 64.417265] softirqs last disabled at (786411): [<ffffffff83090104>] irq_exit+0xa4/0xb0 [ 64.417274] WARNING: CPU: 0 PID: 129 at lib/debugobjects.c:339 debug_print_object+0xd7/0x100 [ 64.417283] ---[ end trace b30c46be45d46de9 ]--- [ 64.417288] ODEBUG: ODEBUG: debug object originally initialized at: [ 64.417295] futex_wait+0x77/0x240 [ 64.417300] do_futex+0x486/0xb10 [ 64.417305] __se_sys_futex+0x128/0x170 [ 64.417311] do_syscall_64+0x55/0x190 [ 64.417316] entry_SYSCALL_64_after_hwframe+0x49/0xbe [ 64.417323] ====================================================== [ 64.417324] WARNING: possible circular locking dependency detected [ 64.417324] 4.17.0-rc7-g25dda01a94cb-repeat_1+ #1 Tainted: G U [ 64.417325] ------------------------------------------------------ [ 64.417325] kworker/u8:2/129 is trying to acquire lock: [ 64.417325] 0000000013453dd1 ((console_sem).lock){-...}, at: down_trylock+0xa/0x30 [ 64.417327] but task is already holding lock: [ 64.417327] 0000000026752c6c (&obj_hash[i].lock){-.-.}, at: debug_check_no_obj_freed+0xa4/0x210 [ 64.417329] which lock already depends on the new lock. [ 64.417330] the existing dependency chain (in reverse order) is: [ 64.417331] -> #3 (&obj_hash[i].lock){-.-.}: [ 64.417332] __debug_object_init+0x74/0x590 [ 64.417333] hrtimer_init+0x1b/0x160 [ 64.417333] init_dl_task_timer+0x17/0x30 [ 64.417333] __sched_fork.isra.16+0xa4/0xf0 [ 64.417334] init_idle+0x53/0x270 [ 64.417334] sched_init+0x42c/0x49f [ 64.417334] start_kernel+0x269/0x4c2 [ 64.417335] secondary_startup_64+0xa5/0xb0 [ 64.417335] -> #2 (&rq->lock){-.-.}: [ 64.417337] task_fork_fair+0x36/0x160 [ 64.417337] sched_fork+0x123/0x280 [ 64.417337] copy_process.part.7+0x5f4/0x1d30 [ 64.417338] _do_fork+0xe2/0x700 [ 64.417338] kernel_thread+0x20/0x30 [ 64.417338] rest_init+0x1d/0x220 [ 64.417339] start_kernel+0x4a2/0x4c2 [ 64.417339] secondary_startup_64+0xa5/0xb0 [ 64.417339] -> #1 (&p->pi_lock){-.-.}: [ 64.417341] try_to_wake_up+0x37/0x650 [ 64.417341] up+0x3b/0x50 [ 64.417341] __up_console_sem+0x2e/0x50 [ 64.417342] console_unlock+0x32f/0x640 [ 64.417342] register_framebuffer+0x24c/0x350 [ 64.417343] __drm_fb_helper_initial_config_and_unlock+0x22a/0x4a0 [ 64.417343] intel_fbdev_initial_config+0xf/0x20 [i915] [ 64.417343] async_run_entry_fn+0x34/0x160 [ 64.417344] process_one_work+0x229/0x6a0 [ 64.417344] worker_thread+0x35/0x380 [ 64.417344] kthread+0x119/0x130 [ 64.417345] ret_from_fork+0x3a/0x50 [ 64.417345] -> #0 ((console_sem).lock){-...}: [ 64.417347] _raw_spin_lock_irqsave+0x33/0x50 [ 64.417347] down_trylock+0xa/0x30 [ 64.417347] __down_trylock_console_sem+0x20/0x80 [ 64.417348] console_trylock+0xe/0x60 [ 64.417348] vprintk_emit+0x22e/0x4d0 [ 64.417348] printk+0x4d/0x69 [ 64.417349] __warn_printk+0x46/0x90 [ 64.417349] debug_print_object+0xd7/0x100 [ 64.417349] debug_check_no_obj_freed+0x194/0x210 [ 64.417350] __vunmap+0xab/0x100 [ 64.417350] __i915_gem_object_put_pages+0x1a7/0x200 [i915] [ 64.417350] __i915_gem_free_objects+0x275/0x780 [i915] [ 64.417351] __i915_gem_free_work+0x5d/0x90 [i915] [ 64.417351] process_one_work+0x229/0x6a0 [ 64.417351] worker_thread+0x35/0x380 [ 64.417352] kthread+0x119/0x130 [ 64.417352] ret_from_fork+0x3a/0x50 [ 64.417353] other info that might help us debug this: [ 64.417353] Chain exists of: [ 64.417354] (console_sem).lock --> &rq->lock --> &obj_hash[i].lock [ 64.417356] Possible unsafe locking scenario: [ 64.417356] CPU0 CPU1 [ 64.417357] ---- ---- [ 64.417357] lock(&obj_hash[i].lock); [ 64.417358] lock(&rq->lock); [ 64.417359] lock(&obj_hash[i].lock); [ 64.417360] lock((console_sem).lock); [ 64.417361] *** DEADLOCK *** [ 64.417361] 4 locks held by kworker/u8:2/129: [ 64.417362] #0: 000000005ff4f972 ((wq_completion)"i915"){+.+.}, at: process_one_work+0x1a3/0x6a0 [ 64.417363] #1: 00000000ab4ebc16 ((work_completion)(&i915->mm.free_work)){+.+.}, at: process_one_work+0x1a3/0x6a0 [ 64.417365] #2: 00000000f093260c (&obj->mm.lock){+.+.}, at: __i915_gem_object_put_pages+0x4f/0x200 [i915] [ 64.417366] #3: 0000000026752c6c (&obj_hash[i].lock){-.-.}, at: debug_check_no_obj_freed+0xa4/0x210 [ 64.417368] stack backtrace: [ 64.417369] CPU: 0 PID: 129 Comm: kworker/u8:2 Tainted: G U 4.17.0-rc7-g25dda01a94cb-repeat_1+ #1 [ 64.417369] Hardware name: Intel Corporation CannonLake Client Platform/CannonLake Y LPDDR4 RVP, BIOS CNLSFWR1.R00.X122.B01.1801151045 01/15/2018 [ 64.417370] Workqueue: i915 __i915_gem_free_work [i915] [ 64.417370] Call Trace: [ 64.417371] dump_stack+0x67/0x9b [ 64.417371] print_circular_bug.isra.18+0x1c8/0x2b0 [ 64.417371] __lock_acquire+0x1897/0x1b50 [ 64.417372] ? lock_acquire+0xa6/0x210 [ 64.417372] lock_acquire+0xa6/0x210 [ 64.417372] ? down_trylock+0xa/0x30 [ 64.417373] ? sched_clock_cpu+0x10/0xe0 [ 64.417373] ? vprintk_emit+0x22e/0x4d0 [ 64.417373] _raw_spin_lock_irqsave+0x33/0x50 [ 64.417374] ? down_trylock+0xa/0x30 [ 64.417374] down_trylock+0xa/0x30 [ 64.417375] __down_trylock_console_sem+0x20/0x80 [ 64.417375] console_trylock+0xe/0x60 [ 64.417375] vprintk_emit+0x22e/0x4d0 [ 64.417375] ? clock_was_set_work+0x20/0x20 [ 64.417376] printk+0x4d/0x69 [ 64.417376] ? clock_was_set_work+0x20/0x20 [ 64.417376] __warn_printk+0x46/0x90 [ 64.417377] ? clock_was_set_work+0x20/0x20 [ 64.417377] debug_print_object+0xd7/0x100 [ 64.417377] ? mark_held_locks+0x50/0x80 [ 64.417378] ? _raw_spin_unlock_irqrestore+0x4c/0x60 [ 64.417378] ? trace_hardirqs_on_caller+0xe0/0x1b0 [ 64.417379] ? lock_acquire+0xa6/0x210 [ 64.417379] ? debug_check_no_obj_freed+0xa4/0x210 [ 64.417379] debug_check_no_obj_freed+0x194/0x210 [ 64.417380] __vunmap+0xab/0x100 [ 64.417380] __i915_gem_object_put_pages+0x1a7/0x200 [i915] [ 64.417380] __i915_gem_free_objects+0x275/0x780 [i915] [ 64.417381] __i915_gem_free_work+0x5d/0x90 [i915] [ 64.417381] process_one_work+0x229/0x6a0 [ 64.417381] worker_thread+0x35/0x380 [ 64.417382] ? process_one_work+0x6a0/0x6a0 [ 64.417382] kthread+0x119/0x130 [ 64.417382] ? kthread_flush_work_fn+0x10/0x10 [ 64.417383] ret_from_fork+0x3a/0x50 Pretty sure this was never our bug and that it has since disappeared... (In reply to Chris Wilson from comment #7) > Pretty sure this was never our bug and that it has since disappeared... Agreed! Closing (In reply to Chris Wilson from comment #7) > Pretty sure this was never our bug and that it has since disappeared... How about this failure? NOTOURBUG? https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_6003/shard-skl5/igt@i915_selftest@mock_requests.html <4> [170.238404] ? i915_gem_free_object+0x110/0x110 [i915] <4> [170.239169] ? i915_gem_context_free+0xc1/0x240 [i915] <4> [170.239502] i915_gem_context_free+0xc1/0x240 [i915] <3> [170.378163] ODEBUG: free active (active state 0) object type: work_struct hint: __i915_gem_free_work+0x0/0x90 [i915] <4> [170.378591] CPU: 2 PID: 1039 Comm: i915_selftest Tainted: G U W 5.1.0-rc6-CI-CI_DRM_6003+ #1 <4> [170.379886] i915_request_mock_selftests+0x2a/0x70 [i915] <4> [170.380675] i915_mock_selftests+0x27/0x50 [i915] <4> [170.381025] i915_init+0x12/0x73 [i915] <4> [170.382581] i915_selftest/1039 is trying to acquire lock: <4> [170.382702] drm_dbg+0x7f/0x90 <4> [170.382707] intel_dp_aux_xfer+0x8d/0x890 [i915] <4> [170.382710] intel_dp_aux_transfer+0xa7/0x200 [i915] <4> [170.382712] drm_dp_dpcd_access+0x76/0x110 <4> [170.382715] drm_dp_dpcd_read+0x29/0xc0 <4> [170.382717] intel_dp_read_dpcd+0x38/0x120 [i915] <4> [170.382719] intel_dp_init_connector+0x6b2/0xe80 [i915] <4> [170.382722] intel_ddi_init+0x454/0x550 [i915] <4> [170.382724] intel_modeset_init+0x16c6/0x19c0 [i915] <4> [170.382726] i915_driver_load+0xd9d/0x18a0 [i915] <4> [170.382729] i915_pci_probe+0x29/0xa0 [i915] <4> [170.382801] i915_request_mock_selftests+0x2a/0x70 [i915] <4> [170.382805] i915_mock_selftests+0x27/0x50 [i915] <4> [170.382807] i915_init+0x12/0x73 [i915] <4> [170.382878] 1 lock held by i915_selftest/1039: <4> [170.382894] CPU: 2 PID: 1039 Comm: i915_selftest Tainted: G U W 5.1.0-rc6-CI-CI_DRM_6003+ #1 <4> [170.382935] ? __i915_gem_free_objects+0x720/0x720 [i915] <4> [170.382939] ? __i915_gem_free_objects+0x720/0x720 [i915] <4> [170.382956] i915_request_mock_selftests+0x2a/0x70 [i915] <4> [170.382962] i915_mock_selftests+0x27/0x50 [i915] <4> [170.382965] i915_init+0x12/0x73 [i915] |
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.