Bug 106353 - [CI] igt@gem_* - dmesg-warn - ODEBUG: free active (active state 0) object type: hrtimer hint: hrtimer_wakeup
Summary: [CI] igt@gem_* - dmesg-warn - ODEBUG: free active (active state 0) object typ...
Status: CLOSED WORKSFORME
Alias: None
Product: DRI
Classification: Unclassified
Component: DRM/Intel (show other bugs)
Version: XOrg git
Hardware: Other All
: medium normal
Assignee: Intel GFX Bugs mailing list
QA Contact: Intel GFX Bugs mailing list
URL:
Whiteboard: ReadyForDev
Keywords:
Depends on:
Blocks:
 
Reported: 2018-05-02 12:19 UTC by Martin Peres
Modified: 2019-04-29 08:47 UTC (History)
2 users (show)

See Also:
i915 platform: BXT, KBL, SKL
i915 features: power/Other


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Martin Peres 2018-05-02 12:19:12 UTC
https://intel-gfx-ci.01.org/tree/drm-tip/CI_DRM_4120/fi-skl-guc/igt@gem_ctx_create@basic-files.html

[   30.094826] Setting dangerous option reset - tainting kernel
[   37.237787] ------------[ cut here ]------------
[   37.238162] ODEBUG: free active (active state 0) object type: hrtimer hint: hrtimer_wakeup+0x0/0x20
[   37.238185] WARNING: CPU: 1 PID: 154 at lib/debugobjects.c:339 debug_print_object+0xd7/0x100
[   37.238191] Modules linked in: snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic i915 x86_pkg_temp_thermal intel_powerclamp coretemp crct10dif_pclmul crc32_pclmul snd_hda_intel ghash_clmulni_intel snd_hda_codec snd_hwdep snd_hda_core e1000e snd_pcm mei_me mei prime_numbers
[   37.238218] CPU: 1 PID: 154 Comm: kworker/u16:4 Tainted: G     U            4.17.0-rc3-CI-CI_DRM_4120+ #1
[   37.238224] Hardware name: System manufacturer System Product Name/Z170 PRO GAMING, BIOS 3402 04/26/2017
[   37.238247] Workqueue: i915 __i915_gem_free_work [i915]
[   37.238252] RIP: 0010:debug_print_object+0xd7/0x100
[   37.238256] RSP: 0018:ffffc90001373be8 EFLAGS: 00010086
[   37.238261] RAX: 0000000000000000 RBX: ffff8801375b3388 RCX: 0000000000000002
[   37.238266] RDX: 0000000080000002 RSI: ffffffff820c3025 RDI: 00000000ffffffff
[   37.238271] RBP: ffffffff82248480 R08: 0000000000000000 R09: 0000000000000000
[   37.238276] R10: ffffc90001373ca8 R11: ffffffff82243e18 R12: ffffffff820bf29f
[   37.238281] R13: ffffffff81114d00 R14: ffffc9003b1f9000 R15: dead000000000100
[   37.238286] FS:  0000000000000000(0000) GS:ffff880236c40000(0000) knlGS:0000000000000000
[   37.238293] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   37.238297] CR2: 00007f6ff34aa000 CR3: 0000000005210002 CR4: 00000000003606e0
[   37.238303] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[   37.238308] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[   37.238313] Call Trace:
[   37.238317]  ? mark_held_locks+0x50/0x80
[   37.238321]  ? _raw_spin_unlock_irqrestore+0x4c/0x60
[   37.238326]  ? trace_hardirqs_on_caller+0xe0/0x1b0
[   37.238331]  ? lock_acquire+0xa6/0x210
[   37.238335]  ? debug_check_no_obj_freed+0xa4/0x210
[   37.238341]  debug_check_no_obj_freed+0x194/0x210
[   37.238346]  __vunmap+0xab/0x100
[   37.238367]  __i915_gem_object_put_pages+0x1ec/0x200 [i915]
[   37.238389]  __i915_gem_free_objects+0x275/0x780 [i915]
[   37.238410]  __i915_gem_free_work+0x5d/0x90 [i915]
[   37.238416]  process_one_work+0x229/0x6a0
[   37.238421]  worker_thread+0x35/0x380
[   37.238426]  ? process_one_work+0x6a0/0x6a0
[   37.238430]  kthread+0x119/0x130
[   37.238434]  ? _kthread_create_on_node+0x60/0x60
[   37.238438]  ret_from_fork+0x3a/0x50
[   37.238443] 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 88 16 0d 82 48 8b 14 c5 00 c9 e6 81 e8 19 0b bf ff <0f> 0b 48 c7 c7 c8 16 0d 82 e8 74 62 c6 ff be 02 00 00 00 48 89 
[   37.238493] irq event stamp: 6922722
[   37.238499] hardirqs last  enabled at (6922721): [<ffffffff8192f97c>] _raw_spin_unlock_irqrestore+0x4c/0x60
[   37.238509] hardirqs last disabled at (6922722): [<ffffffff8192f7ed>] _raw_spin_lock_irqsave+0xd/0x50
[   37.238519] softirqs last  enabled at (6919998): [<ffffffff81c0032b>] __do_softirq+0x32b/0x4e1
[   37.238528] softirqs last disabled at (6919977): [<ffffffff8108b904>] irq_exit+0xa4/0xb0
[   37.238537] WARNING: CPU: 1 PID: 154 at lib/debugobjects.c:339 debug_print_object+0xd7/0x100
[   37.238545] ---[ end trace a269db5d13fd1fbc ]---
[   37.238550] ODEBUG: ODEBUG: debug object originally initialized at:
[   37.238558]    futex_wait+0x77/0x240
[   37.238563]    do_futex+0x486/0xb10
[   37.238569]    __se_sys_futex+0x128/0x170
[   37.238574]    do_syscall_64+0x55/0x190
[   37.238579]    entry_SYSCALL_64_after_hwframe+0x49/0xbe

[   37.238586] ======================================================
[   37.238587] WARNING: possible circular locking dependency detected
[   37.238587] 4.17.0-rc3-CI-CI_DRM_4120+ #1 Tainted: G     U           
[   37.238588] ------------------------------------------------------
[   37.238588] kworker/u16:4/154 is trying to acquire lock:
[   37.238588] 000000005c99e3ce ((console_sem).lock){-...}, at: down_trylock+0xa/0x30

[   37.238590] but task is already holding lock:
[   37.238590] 000000005a835f50 (&obj_hash[i].lock){-.-.}, at: debug_check_no_obj_freed+0xa4/0x210

[   37.238592] which lock already depends on the new lock.


[   37.238593] the existing dependency chain (in reverse order) is:

[   37.238594] -> #3 (&obj_hash[i].lock){-.-.}:
[   37.238595]        __debug_object_init+0x74/0x590
[   37.238596]        hrtimer_init+0x1b/0x160
[   37.238596]        init_dl_task_timer+0x17/0x30
[   37.238597]        __sched_fork.isra.16+0xa4/0xf0
[   37.238597]        init_idle+0x53/0x270
[   37.238597]        sched_init+0x42c/0x49f
[   37.238598]        start_kernel+0x269/0x4bb
[   37.238598]        secondary_startup_64+0xa5/0xb0

[   37.238598] -> #2 (&rq->lock){-.-.}:
[   37.238600]        task_fork_fair+0x36/0x160
[   37.238600]        sched_fork+0x123/0x280
[   37.238601]        copy_process.part.7+0x5f4/0x1d30
[   37.238601]        _do_fork+0xe2/0x700
[   37.238601]        kernel_thread+0x20/0x30
[   37.238602]        rest_init+0x1d/0x220
[   37.238602]        start_kernel+0x49b/0x4bb
[   37.238602]        secondary_startup_64+0xa5/0xb0

[   37.238603] -> #1 (&p->pi_lock){-.-.}:
[   37.238604]        try_to_wake_up+0x37/0x650
[   37.238605]        up+0x3b/0x50
[   37.238605]        __up_console_sem+0x2e/0x50
[   37.238606]        console_unlock+0x32f/0x640
[   37.238606]        vprintk_emit+0x23b/0x4d0
[   37.238606]        printk+0x4d/0x69
[   37.238607]        drm_dbg+0x7f/0x90
[   37.238607]        do_gmbus_xfer+0x35c/0x440 [i915]
[   37.238608]        gmbus_xfer+0x7a/0x90 [i915]
[   37.238608]        __i2c_transfer+0x117/0x7d0
[   37.238608]        i2c_transfer+0x54/0xe0
[   37.238609]        drm_dp_dual_mode_read+0x5f/0xa0
[   37.238609]        drm_dp_dual_mode_detect+0x40/0x170
[   37.238609]        intel_hdmi_set_edid+0x7e/0x280 [i915]
[   37.238610]        intel_hdmi_detect+0x7e/0xa0 [i915]
[   37.238610]        drm_helper_probe_single_connector_modes+0xd2/0x6d0
[   37.238611]        drm_setup_crtcs+0x159/0xc90
[   37.238611]        __drm_fb_helper_initial_config_and_unlock+0x34/0x4a0
[   37.238612]        intel_fbdev_initial_config+0xf/0x20 [i915]
[   37.238612]        async_run_entry_fn+0x34/0x160
[   37.238612]        process_one_work+0x229/0x6a0
[   37.238613]        worker_thread+0x35/0x380
[   37.238613]        kthread+0x119/0x130
[   37.238614]        ret_from_fork+0x3a/0x50

[   37.238614] -> #0 ((console_sem).lock){-...}:
[   37.238615]        _raw_spin_lock_irqsave+0x33/0x50
[   37.238616]        down_trylock+0xa/0x30
[   37.238616]        __down_trylock_console_sem+0x20/0x80
[   37.238617]        console_trylock+0xe/0x60
[   37.238617]        vprintk_emit+0x22e/0x4d0
[   37.238617]        printk+0x4d/0x69
[   37.238618]        __warn_printk+0x46/0x90
[   37.238618]        debug_print_object+0xd7/0x100
[   37.238618]        debug_check_no_obj_freed+0x194/0x210
[   37.238619]        __vunmap+0xab/0x100
[   37.238619]        __i915_gem_object_put_pages+0x1ec/0x200 [i915]
[   37.238619]        __i915_gem_free_objects+0x275/0x780 [i915]
[   37.238620]        __i915_gem_free_work+0x5d/0x90 [i915]
[   37.238620]        process_one_work+0x229/0x6a0
[   37.238620]        worker_thread+0x35/0x380
[   37.238621]        kthread+0x119/0x130
[   37.238621]        ret_from_fork+0x3a/0x50

[   37.238622] other info that might help us debug this:

[   37.238623] Chain exists of:
[   37.238623]   (console_sem).lock --> &rq->lock --> &obj_hash[i].lock

[   37.238625]  Possible unsafe locking scenario:

[   37.238626]        CPU0                    CPU1
[   37.238626]        ----                    ----
[   37.238626]   lock(&obj_hash[i].lock);
[   37.238627]                                lock(&rq->lock);
[   37.238628]                                lock(&obj_hash[i].lock);
[   37.238629]   lock((console_sem).lock);

[   37.238631]  *** DEADLOCK ***

[   37.238631] 4 locks held by kworker/u16:4/154:
[   37.238631]  #0: 00000000187b427a ((wq_completion)"i915"){+.+.}, at: process_one_work+0x1a3/0x6a0
[   37.238633]  #1: 0000000042f30b9a ((work_completion)(&i915->mm.free_work)){+.+.}, at: process_one_work+0x1a3/0x6a0
[   37.238635]  #2: 000000009d7ef09a (&obj->mm.lock){+.+.}, at: __i915_gem_object_put_pages+0x4f/0x200 [i915]
[   37.238637]  #3: 000000005a835f50 (&obj_hash[i].lock){-.-.}, at: debug_check_no_obj_freed+0xa4/0x210

[   37.238639] stack backtrace:
[   37.238639] CPU: 1 PID: 154 Comm: kworker/u16:4 Tainted: G     U            4.17.0-rc3-CI-CI_DRM_4120+ #1
[   37.238640] Hardware name: System manufacturer System Product Name/Z170 PRO GAMING, BIOS 3402 04/26/2017
[   37.238640] Workqueue: i915 __i915_gem_free_work [i915]
[   37.238641] Call Trace:
[   37.238641]  dump_stack+0x67/0x9b
[   37.238642]  print_circular_bug.isra.18+0x1c8/0x2b0
[   37.238642]  __lock_acquire+0x1897/0x1b50
[   37.238642]  ? lock_acquire+0xa6/0x210
[   37.238643]  lock_acquire+0xa6/0x210
[   37.238643]  ? down_trylock+0xa/0x30
[   37.238643]  ? sched_clock_cpu+0x10/0xe0
[   37.238644]  ? vprintk_emit+0x22e/0x4d0
[   37.238644]  _raw_spin_lock_irqsave+0x33/0x50
[   37.238645]  ? down_trylock+0xa/0x30
[   37.238645]  down_trylock+0xa/0x30
[   37.238646]  __down_trylock_console_sem+0x20/0x80
[   37.238646]  console_trylock+0xe/0x60
[   37.238646]  vprintk_emit+0x22e/0x4d0
[   37.238647]  ? clock_was_set_work+0x20/0x20
[   37.238647]  printk+0x4d/0x69
[   37.238648]  ? clock_was_set_work+0x20/0x20
[   37.238648]  __warn_printk+0x46/0x90
[   37.238648]  ? clock_was_set_work+0x20/0x20
[   37.238649]  debug_print_object+0xd7/0x100
[   37.238649]  ? mark_held_locks+0x50/0x80
[   37.238649]  ? _raw_spin_unlock_irqrestore+0x4c/0x60
[   37.238650]  ? trace_hardirqs_on_caller+0xe0/0x1b0
[   37.238650]  ? lock_acquire+0xa6/0x210
[   37.238651]  ? debug_check_no_obj_freed+0xa4/0x210
[   37.238651]  debug_check_no_obj_freed+0x194/0x210
[   37.238651]  __vunmap+0xab/0x100
[   37.238652]  __i915_gem_object_put_pages+0x1ec/0x200 [i915]
[   37.238652]  __i915_gem_free_objects+0x275/0x780 [i915]
[   37.238652]  __i915_gem_free_work+0x5d/0x90 [i915]
[   37.238653]  process_one_work+0x229/0x6a0
[   37.238653]  worker_thread+0x35/0x380
[   37.238654]  ? process_one_work+0x6a0/0x6a0
[   37.238654]  kthread+0x119/0x130
[   37.238655]  ? _kthread_create_on_node+0x60/0x60
[   37.238655]  ret_from_fork+0x3a/0x50
Comment 1 Chris Wilson 2018-05-02 12:22:23 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.
Comment 2 Martin Peres 2018-05-02 12:42:22 UTC
Adding Tomi for him to make this run.
Comment 3 Chris Wilson 2018-05-25 11:42:59 UTC
The kasan + vmap=n turned up nothing, not even an oops.
Comment 4 Martin Peres 2018-05-28 17:08:43 UTC
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 ]---
Comment 5 Martin Peres 2018-06-01 07:28:45 UTC
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 ]---
Comment 6 Martin Peres 2018-06-05 12:13:09 UTC
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
Comment 7 Chris Wilson 2018-09-14 21:02:41 UTC
Pretty sure this was never our bug and that it has since disappeared...
Comment 8 Martin Peres 2018-09-20 17:28:31 UTC
(In reply to Chris Wilson from comment #7)
> Pretty sure this was never our bug and that it has since disappeared...

Agreed! Closing
Comment 9 Lakshmi 2019-04-29 08:47:29 UTC
(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.