Bug 108553 - [CI][BAT] igt@pm_rpm@module-reload - dmesg-warn - ODEBUG: free active (active state 0) object type: timer_list hint: delayed_work_timer_fn
Summary: [CI][BAT] igt@pm_rpm@module-reload - dmesg-warn - ODEBUG: free active (active...
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:
Keywords:
Depends on:
Blocks:
 
Reported: 2018-10-25 12:48 UTC by Martin Peres
Modified: 2019-02-22 13:50 UTC (History)
1 user (show)

See Also:
i915 platform: GLK
i915 features:

Attachments
Boot log (117.04 KB, text/x-log)
2018-10-25 12:48 UTC, Martin Peres 		no flags Details
Dmesg log (4.12 MB, text/x-log)
2018-10-25 12:50 UTC, Martin Peres 		no flags Details
Run log (34.66 KB, text/x-log)
2018-10-25 12:50 UTC, Martin Peres 		no flags Details
View All

Description Martin Peres 2018-10-25 12:48:46 UTC 
Created attachment 142196 [details]
Boot log

<4> [347.854567] ------------[ cut here ]------------
<3> [347.854969] ODEBUG: free active (active state 0) object type: timer_list hint: delayed_work_timer_fn+0x0/0x10
<4> [347.854987] WARNING: CPU: 1 PID: 3305 at lib/debugobjects.c:329 debug_print_object+0x67/0x90
<4> [347.854990] Modules linked in: i915(-) vgem btusb btrtl btbcm btintel snd_hda_codec_hdmi bluetooth snd_hda_codec_realtek snd_hda_codec_generic x86_pkg_temp_thermal coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel ecdh_generic r8169 i2c_hid snd_hda_codec snd_hwdep snd_hda_core snd_pcm mei_me pinctrl_geminilake pinctrl_intel mei prime_numbers [last unloaded: snd_hda_intel]
<4> [347.855033] CPU: 1 PID: 3305 Comm: pm_rpm Tainted: G     U  W         4.19.0-rc8-CI-CI_DRM_5033+ #1
<4> [347.855035] Hardware name: Intel Corporation NUC7CJYH/NUC7JYB, BIOS JYGLKCPX.86A.0027.2018.0125.1347 01/25/2018
<4> [347.855038] RIP: 0010:debug_print_object+0x67/0x90
<4> [347.855041] Code: 83 c2 01 8b 4b 14 4c 8b 45 00 89 15 2b cc 24 02 8b 53 10 4c 89 e6 48 c7 c7 b8 3c 0d 82 48 8b 14 d5 a0 de e6 81 e8 59 d6 be ff <0f> 0b 5b 83 05 4b 63 eb 00 01 5d 41 5c c3 83 05 40 63 eb 00 01 c3
<4> [347.855044] RSP: 0000:ffffc90000423d08 EFLAGS: 00010082
<4> [347.855048] RAX: 0000000000000000 RBX: ffff88021ea91610 RCX: 0000000000000002
<4> [347.855051] RDX: 0000000080000002 RSI: ffffffff820c30ce RDI: 00000000ffffffff
<4> [347.855053] RBP: ffffffff822490c0 R08: 0000000000000000 R09: 0000000000000000
<4> [347.855055] R10: ffffc90000423ca0 R11: ffffffff822458f8 R12: ffffffff820be755
<4> [347.855058] R13: 0000000000000001 R14: ffff880248150000 R15: dead000000000100
<4> [347.855061] FS:  00007fb4e0826980(0000) GS:ffff880277e80000(0000) knlGS:0000000000000000
<4> [347.855063] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
<4> [347.855066] CR2: 00005594f7a9e283 CR3: 000000026be1a000 CR4: 0000000000340ee0
<4> [347.855068] Call Trace:
<4> [347.855072]  debug_check_no_obj_freed+0x194/0x210
<4> [347.855078]  __free_pages_ok+0x164/0x6a0
<4> [347.855082]  ? rcu_lockdep_current_cpu_online+0x8f/0xd0
<4> [347.855125]  ? i915_driver_release+0x21/0x30 [i915]
<4> [347.855169]  i915_driver_release+0x21/0x30 [i915]
<4> [347.855212]  i915_pci_remove+0x21/0x30 [i915]
<4> [347.855216]  pci_device_remove+0x36/0xb0
<4> [347.855220]  device_release_driver_internal+0x185/0x250
<4> [347.855224]  driver_detach+0x35/0x70
<4> [347.855228]  bus_remove_driver+0x53/0xd0
<4> [347.855231]  pci_unregister_driver+0x25/0xa0
<4> [347.855236]  __se_sys_delete_module+0x162/0x210
<4> [347.855239]  ? do_syscall_64+0xd/0x190
<4> [347.855243]  do_syscall_64+0x55/0x190
<4> [347.855246]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
<4> [347.855249] RIP: 0033:0x7fb4dfabe1b7
<4> [347.855252] Code: 73 01 c3 48 8b 0d d1 8c 2c 00 f7 d8 64 89 01 48 83 c8 ff c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 b8 b0 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d a1 8c 2c 00 f7 d8 64 89 01 48
<4> [347.855254] RSP: 002b:00007ffec75b99b8 EFLAGS: 00000206 ORIG_RAX: 00000000000000b0
<4> [347.855257] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007fb4dfabe1b7
<4> [347.855260] RDX: 0000000000000000 RSI: 0000000000000800 RDI: 000055fa2f7986d8
<4> [347.855262] RBP: 000055fa2f798670 R08: 000055fa2f7986dc R09: 00007fb4dfb0ab40
<4> [347.855264] R10: 00007ffec75b89b4 R11: 0000000000000206 R12: 000055fa2e8f5710
<4> [347.855266] R13: 00007ffec75b9bb0 R14: 0000000000000000 R15: 0000000000000000
<4> [347.855273] irq event stamp: 1388058
<4> [347.855278] hardirqs last  enabled at (1388057): [<ffffffff811fb25d>] __slab_free+0x3ed/0x4f0
<4> [347.855281] hardirqs last disabled at (1388058): [<ffffffff8194113d>] _raw_spin_lock_irqsave+0xd/0x50
<4> [347.855285] softirqs last  enabled at (1386742): [<ffffffff81c0031d>] __do_softirq+0x31d/0x483
<4> [347.855289] softirqs last disabled at (1386735): [<ffffffff8108c539>] irq_exit+0xa9/0xc0
<4> [347.855292] WARNING: CPU: 1 PID: 3305 at lib/debugobjects.c:329 debug_print_object+0x67/0x90
<4> [347.855294] ---[ end trace 63c5d4afa5db0053 ]---
<4> [347.855299] 
<4> [347.855299] ======================================================
<4> [347.855300] WARNING: possible circular locking dependency detected
<4> [347.855301] 4.19.0-rc8-CI-CI_DRM_5033+ #1 Tainted: G     U  W        
<4> [347.855301] ------------------------------------------------------
<4> [347.855302] pm_rpm/3305 is trying to acquire lock:
<4> [347.855302] 00000000f1010ed7 ((console_sem).lock){-.-.}, at: down_trylock+0xa/0x30
<4> [347.855304] 
<4> [347.855305] but task is already holding lock:
<4> [347.855305] 000000007b778c31 (&obj_hash[i].lock){-.-.}, at: debug_check_no_obj_freed+0xa4/0x210
<4> [347.855307] 
<4> [347.855307] which lock already depends on the new lock.
<4> [347.855308] 
<4> [347.855308] 
<4> [347.855309] the existing dependency chain (in reverse order) is:
<4> [347.855309] 
<4> [347.855309] -> #3 (&obj_hash[i].lock){-.-.}:
<4> [347.855311]        __debug_object_init+0x74/0x560
<4> [347.855312]        hrtimer_init+0x1b/0x100
<4> [347.855312]        init_dl_task_timer+0x17/0x30
<4> [347.855313]        __sched_fork.isra.16+0xa4/0xf0
<4> [347.855313]        init_idle+0x53/0x270
<4> [347.855313]        sched_init+0x421/0x471
<4> [347.855314]        start_kernel+0x269/0x4c0
<4> [347.855314]        secondary_startup_64+0xa4/0xb0
<4> [347.855315] 
<4> [347.855315] -> #2 (&rq->lock){-.-.}:
<4> [347.855317]        task_fork_fair+0x36/0x160
<4> [347.855317]        sched_fork+0x118/0x220
<4> [347.855318]        copy_process.part.6+0x6cc/0x2010
<4> [347.855318]        _do_fork+0xe2/0x6b0
<4> [347.855318]        kernel_thread+0x20/0x30
<4> [347.855319]        rest_init+0x1d/0x220
<4> [347.855319]        start_kernel+0x4a0/0x4c0
<4> [347.855320]        secondary_startup_64+0xa4/0xb0
<4> [347.855320] 
<4> [347.855320] -> #1 (&p->pi_lock){-.-.}:
<4> [347.855322]        try_to_wake_up+0x37/0x5f0
<4> [347.855323]        up+0x3b/0x50
<4> [347.855323]        __up_console_sem+0x2e/0x50
<4> [347.855323]        console_unlock+0x30b/0x5f0
<4> [347.855324]        con_font_op+0x31c/0x480
<4> [347.855324]        vt_ioctl+0x8a7/0x11d0
<4> [347.855325]        tty_ioctl+0xee/0x930
<4> [347.855325]        do_vfs_ioctl+0xa0/0x6d0
<4> [347.855326]        ksys_ioctl+0x35/0x60
<4> [347.855326]        __x64_sys_ioctl+0x11/0x20
<4> [347.855327]        do_syscall_64+0x55/0x190
<4> [347.855327]        entry_SYSCALL_64_after_hwframe+0x49/0xbe
<4> [347.855327] 
<4> [347.855328] -> #0 ((console_sem).lock){-.-.}:
<4> [347.855329]        _raw_spin_lock_irqsave+0x33/0x50
<4> [347.855330]        down_trylock+0xa/0x30
<4> [347.855330]        __down_trylock_console_sem+0x20/0x80
<4> [347.855331]        console_trylock+0xe/0x60
<4> [347.855331]        vprintk_emit+0xe6/0x310
<4> [347.855332]        printk+0x4d/0x69
<4> [347.855332]        __warn_printk+0x46/0x90
<4> [347.855333]        debug_print_object+0x67/0x90
<4> [347.855333]        debug_check_no_obj_freed+0x194/0x210
<4> [347.855334]        __free_pages_ok+0x164/0x6a0
<4> [347.855334]        i915_driver_release+0x21/0x30 [i915]
<4> [347.855334]        i915_pci_remove+0x21/0x30 [i915]
<4> [347.855335]        pci_device_remove+0x36/0xb0
<4> [347.855335]        device_release_driver_internal+0x185/0x250
<4> [347.855336]        driver_detach+0x35/0x70
<4> [347.855336]        bus_remove_driver+0x53/0xd0
<4> [347.855337]        pci_unregister_driver+0x25/0xa0
<4> [347.855337]        __se_sys_delete_module+0x162/0x210
<4> [347.855338]        do_syscall_64+0x55/0x190
<4> [347.855338]        entry_SYSCALL_64_after_hwframe+0x49/0xbe
<4> [347.855339] 
<4> [347.855339] other info that might help us debug this:
<4> [347.855339] 
<4> [347.855340] Chain exists of:
<4> [347.855340]   (console_sem).lock --> &rq->lock --> &obj_hash[i].lock
<4> [347.855342] 
<4> [347.855343]  Possible unsafe locking scenario:
<4> [347.855343] 
<4> [347.855344]        CPU0                    CPU1
<4> [347.855344]        ----                    ----
<4> [347.855344]   lock(&obj_hash[i].lock);
<4> [347.855345]                                lock(&rq->lock);
<4> [347.855347]                                lock(&obj_hash[i].lock);
<4> [347.855348]   lock((console_sem).lock);
<4> [347.855349] 
<4> [347.855349]  *** DEADLOCK ***
<4> [347.855349] 
<4> [347.855350] 2 locks held by pm_rpm/3305:
<4> [347.855350]  #0: 00000000fa5e7ac5 (&dev->mutex){....}, at: device_release_driver_internal+0x34/0x250
<4> [347.855352]  #1: 000000007b778c31 (&obj_hash[i].lock){-.-.}, at: debug_check_no_obj_freed+0xa4/0x210
<4> [347.855354] 
<4> [347.855355] stack backtrace:
<4> [347.855356] CPU: 1 PID: 3305 Comm: pm_rpm Tainted: G     U  W         4.19.0-rc8-CI-CI_DRM_5033+ #1
<4> [347.855356] Hardware name: Intel Corporation NUC7CJYH/NUC7JYB, BIOS JYGLKCPX.86A.0027.2018.0125.1347 01/25/2018
<4> [347.855357] Call Trace:
<4> [347.855357]  dump_stack+0x67/0x9b
<4> [347.855358]  print_circular_bug.isra.16+0x1c8/0x2b0
<4> [347.855358]  __lock_acquire+0x1897/0x1b50
<4> [347.855359]  ? lock_acquire+0xa6/0x1c0
<4> [347.855359]  lock_acquire+0xa6/0x1c0
<4> [347.855360]  ? down_trylock+0xa/0x30
<4> [347.855360]  ? vprintk_emit+0xe6/0x310
<4> [347.855360]  _raw_spin_lock_irqsave+0x33/0x50
<4> [347.855361]  ? down_trylock+0xa/0x30
<4> [347.855361]  down_trylock+0xa/0x30
<4> [347.855362]  __down_trylock_console_sem+0x20/0x80
<4> [347.855362]  console_trylock+0xe/0x60
<4> [347.855363]  vprintk_emit+0xe6/0x310
<4> [347.855363]  printk+0x4d/0x69
<4> [347.855363]  ? work_on_cpu_safe+0x50/0x50
<4> [347.855364]  __warn_printk+0x46/0x90
<4> [347.855364]  ? _raw_spin_unlock_irqrestore+0x4c/0x60
<4> [347.855365]  ? work_on_cpu_safe+0x50/0x50
<4> [347.855365]  debug_print_object+0x67/0x90
<4> [347.855366]  debug_check_no_obj_freed+0x194/0x210
<4> [347.855366]  __free_pages_ok+0x164/0x6a0
<4> [347.855367]  ? rcu_lockdep_current_cpu_online+0x8f/0xd0
<4> [347.855367]  ? i915_driver_release+0x21/0x30 [i915]
<4> [347.855368]  i915_driver_release+0x21/0x30 [i915]
<4> [347.855368]  i915_pci_remove+0x21/0x30 [i915]
<4> [347.855368]  pci_device_remove+0x36/0xb0
<4> [347.855369]  device_release_driver_internal+0x185/0x250
<4> [347.855369]  driver_detach+0x35/0x70
<4> [347.855370]  bus_remove_driver+0x53/0xd0
<4> [347.855370]  pci_unregister_driver+0x25/0xa0
<4> [347.855371]  __se_sys_delete_module+0x162/0x210
<4> [347.855371]  ? do_syscall_64+0xd/0x190
<4> [347.855372]  do_syscall_64+0x55/0x190
<4> [347.855372]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
<4> [347.855373] RIP: 0033:0x7fb4dfabe1b7
<4> [347.855374] Code: 73 01 c3 48 8b 0d d1 8c 2c 00 f7 d8 64 89 01 48 83 c8 ff c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 b8 b0 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d a1 8c 2c 00 f7 d8 64 89 01 48
<4> [347.855374] RSP: 002b:00007ffec75b99b8 EFLAGS: 00000206 ORIG_RAX: 00000000000000b0
<4> [347.855375] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007fb4dfabe1b7
<4> [347.855376] RDX: 0000000000000000 RSI: 0000000000000800 RDI: 000055fa2f7986d8
<4> [347.855376] RBP: 000055fa2f798670 R08: 000055fa2f7986dc R09: 00007fb4dfb0ab40
<4> [347.855377] R10: 00007ffec75b89b4 R11: 0000000000000206 R12: 000055fa2e8f5710
<4> [347.855377] R13: 00007ffec75b9bb0 R14: 0000000000000000 R15: 0000000000000000
<6> [347.873811] [IGT] pm_rpm: exiting, ret=0
Comment 1 Martin Peres 2018-10-25 12:50:14 UTC 
Created attachment 142197 [details]
Dmesg log
Comment 2 Martin Peres 2018-10-25 12:50:42 UTC 
Created attachment 142198 [details]
Run log
Comment 3 Chris Wilson 2018-10-25 12:53:31 UTC 
It seems to be warning about a delayed worker still being active within drm_i915_private as we free it. We've recently seen that the hotplug worker is still active on module unload, so it might just be coincidence or another symptom thereof.
Comment 4 Lakshmi 2019-02-22 13:16:22 UTC 
Based on this bug report, this issue occurred ~4 months ago. Second instance was not seen on CI bug log. Closing this bug.
Comment 5 CI Bug Log 2019-02-22 13:50:25 UTC 
The CI Bug Log issue associated to this bug has been archived.

New failures matching the above filters will not be associated to this bug anymore.

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.