lkml.org 
[lkml]   [2009]   [May]   [24]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
SubjectRe: INFO: possible circular locking dependency at cleanup_workqueue_thread
From
Date
Below are the original lockdep output and the one generated by applying
Lei Ming's BFS shortest cycle patch.

It appears to find a slightly shorter variant, removing setup_lock from
the cycle -- but it might be a difference in setup or userland.

Looking again at Oleg's example, I think this again falls short of
finding the L1-L2 inversion, simply because we establish (and therefore
find) the longer cycle first.

Simply because we warn at the first cycle detected, it means we'll never
continue to build dependencies to build shorter ones,.. I think?

/me goes trying to construct a scenario to disprove the above.

On Tue, 2009-05-12 at 09:59 +0200, Zdenek Kabelac wrote:
> =======================================================
> [ INFO: possible circular locking dependency detected ]
> 2.6.30-rc5-00097-gd665355 #59
> -------------------------------------------------------
> pm-suspend/12129 is trying to acquire lock:
> (events){+.+.+.}, at: [<ffffffff80259496>] cleanup_workqueue_thread+0x26/0xd0
>
> but task is already holding lock:
> (cpu_add_remove_lock){+.+.+.}, at: [<ffffffff80246e57>]
> cpu_maps_update_begin+0x17/0x20
>
> which lock already depends on the new lock.
>
>
> the existing dependency chain (in reverse order) is:
>
> -> #5 (cpu_add_remove_lock){+.+.+.}:
> [<ffffffff80271a64>] __lock_acquire+0xc64/0x10a0
> [<ffffffff80271f38>] lock_acquire+0x98/0x140
> [<ffffffff8054e78c>] __mutex_lock_common+0x4c/0x3b0
> [<ffffffff8054ebf6>] mutex_lock_nested+0x46/0x60
> [<ffffffff80246e57>] cpu_maps_update_begin+0x17/0x20
> [<ffffffff80259c33>] __create_workqueue_key+0xc3/0x250
> [<ffffffff80287b20>] stop_machine_create+0x40/0xb0
> [<ffffffff8027a784>] sys_delete_module+0x84/0x270
> [<ffffffff8020c15b>] system_call_fastpath+0x16/0x1b
> [<ffffffffffffffff>] 0xffffffffffffffff
>
> -> #4 (setup_lock){+.+.+.}:
> [<ffffffff80271a64>] __lock_acquire+0xc64/0x10a0
> [<ffffffff80271f38>] lock_acquire+0x98/0x140
> [<ffffffff8054e78c>] __mutex_lock_common+0x4c/0x3b0
> [<ffffffff8054ebf6>] mutex_lock_nested+0x46/0x60
> [<ffffffff80287af7>] stop_machine_create+0x17/0xb0
> [<ffffffff80246f06>] disable_nonboot_cpus+0x26/0x130
> [<ffffffff8027dd8d>] suspend_devices_and_enter+0xbd/0x1b0
> [<ffffffff8027dff7>] enter_state+0x107/0x170
> [<ffffffff8027e0f9>] state_store+0x99/0x100
> [<ffffffff803abe17>] kobj_attr_store+0x17/0x20
> [<ffffffff8033f1e9>] sysfs_write_file+0xd9/0x160
> [<ffffffff802e1c88>] vfs_write+0xb8/0x180
> [<ffffffff802e2771>] sys_write+0x51/0x90
> [<ffffffff8020c15b>] system_call_fastpath+0x16/0x1b
> [<ffffffffffffffff>] 0xffffffffffffffff
>
> -> #3 (dpm_list_mtx){+.+.+.}:
> [<ffffffff80271a64>] __lock_acquire+0xc64/0x10a0
> [<ffffffff80271f38>] lock_acquire+0x98/0x140
> [<ffffffff8054e78c>] __mutex_lock_common+0x4c/0x3b0
> [<ffffffff8054ebf6>] mutex_lock_nested+0x46/0x60
> [<ffffffff804532ff>] device_pm_add+0x1f/0xe0
> [<ffffffff8044b9bf>] device_add+0x45f/0x570
> [<ffffffffa007c578>] wiphy_register+0x158/0x280 [cfg80211]
> [<ffffffffa017567c>] ieee80211_register_hw+0xbc/0x410 [mac80211]
> [<ffffffffa01f7c5c>] iwl3945_pci_probe+0xa1c/0x1080 [iwl3945]
> [<ffffffff803c4307>] local_pci_probe+0x17/0x20
> [<ffffffff803c5458>] pci_device_probe+0x88/0xb0
> [<ffffffff8044e1e9>] driver_probe_device+0x89/0x180
> [<ffffffff8044e37b>] __driver_attach+0x9b/0xa0
> [<ffffffff8044d67c>] bus_for_each_dev+0x6c/0xa0
> [<ffffffff8044e03e>] driver_attach+0x1e/0x20
> [<ffffffff8044d955>] bus_add_driver+0xd5/0x290
> [<ffffffff8044e668>] driver_register+0x78/0x140
> [<ffffffff803c56f6>] __pci_register_driver+0x66/0xe0
> [<ffffffffa00bd05c>] 0xffffffffa00bd05c
> [<ffffffff8020904f>] do_one_initcall+0x3f/0x1c0
> [<ffffffff8027d071>] sys_init_module+0xb1/0x200
> [<ffffffff8020c15b>] system_call_fastpath+0x16/0x1b
> [<ffffffffffffffff>] 0xffffffffffffffff
>
> -> #2 (cfg80211_mutex){+.+.+.}:
> [<ffffffff80271a64>] __lock_acquire+0xc64/0x10a0
> [<ffffffff80271f38>] lock_acquire+0x98/0x140
> [<ffffffff8054e78c>] __mutex_lock_common+0x4c/0x3b0
> [<ffffffff8054ebf6>] mutex_lock_nested+0x46/0x60
> [<ffffffffa007e66a>] reg_todo+0x19a/0x590 [cfg80211]
> [<ffffffff80258f18>] worker_thread+0x1e8/0x3a0
> [<ffffffff8025dc3a>] kthread+0x5a/0xa0
> [<ffffffff8020d23a>] child_rip+0xa/0x20
> [<ffffffffffffffff>] 0xffffffffffffffff
>
> -> #1 (reg_work){+.+.+.}:
> [<ffffffff80271a64>] __lock_acquire+0xc64/0x10a0
> [<ffffffff80271f38>] lock_acquire+0x98/0x140
> [<ffffffff80258f12>] worker_thread+0x1e2/0x3a0
> [<ffffffff8025dc3a>] kthread+0x5a/0xa0
> [<ffffffff8020d23a>] child_rip+0xa/0x20
> [<ffffffffffffffff>] 0xffffffffffffffff
>
> -> #0 (events){+.+.+.}:
> [<ffffffff80271b36>] __lock_acquire+0xd36/0x10a0
> [<ffffffff80271f38>] lock_acquire+0x98/0x140
> [<ffffffff802594bd>] cleanup_workqueue_thread+0x4d/0xd0
> [<ffffffff8053fe79>] workqueue_cpu_callback+0xc9/0x10f
> [<ffffffff805539a8>] notifier_call_chain+0x68/0xa0
> [<ffffffff802630d6>] raw_notifier_call_chain+0x16/0x20
> [<ffffffff8053d9ec>] _cpu_down+0x1cc/0x2d0
> [<ffffffff80246f90>] disable_nonboot_cpus+0xb0/0x130
> [<ffffffff8027dd8d>] suspend_devices_and_enter+0xbd/0x1b0
> [<ffffffff8027dff7>] enter_state+0x107/0x170
> [<ffffffff8027e0f9>] state_store+0x99/0x100
> [<ffffffff803abe17>] kobj_attr_store+0x17/0x20
> [<ffffffff8033f1e9>] sysfs_write_file+0xd9/0x160
> [<ffffffff802e1c88>] vfs_write+0xb8/0x180
> [<ffffffff802e2771>] sys_write+0x51/0x90
> [<ffffffff8020c15b>] system_call_fastpath+0x16/0x1b
> [<ffffffffffffffff>] 0xffffffffffffffff
>
> other info that might help us debug this:
>
> 4 locks held by pm-suspend/12129:
> #0: (&buffer->mutex){+.+.+.}, at: [<ffffffff8033f154>]
> sysfs_write_file+0x44/0x160
> #1: (pm_mutex){+.+.+.}, at: [<ffffffff8027df44>] enter_state+0x54/0x170
> #2: (dpm_list_mtx){+.+.+.}, at: [<ffffffff80452747>] device_pm_lock+0x17/0x20
> #3: (cpu_add_remove_lock){+.+.+.}, at: [<ffffffff80246e57>]
> cpu_maps_update_begin+0x17/0x20
>
> stack backtrace:
> Pid: 12129, comm: pm-suspend Not tainted 2.6.30-rc5-00097-gd665355 #59
> Call Trace:
> [<ffffffff8026fa3d>] print_circular_bug_tail+0x9d/0xe0
> [<ffffffff80271b36>] __lock_acquire+0xd36/0x10a0
> [<ffffffff80270000>] ? mark_lock+0x3e0/0x400
> [<ffffffff80271f38>] lock_acquire+0x98/0x140
> [<ffffffff80259496>] ? cleanup_workqueue_thread+0x26/0xd0
> [<ffffffff802594bd>] cleanup_workqueue_thread+0x4d/0xd0
> [<ffffffff80259496>] ? cleanup_workqueue_thread+0x26/0xd0
> [<ffffffff802703ed>] ? trace_hardirqs_on+0xd/0x10
> [<ffffffff8053fe79>] workqueue_cpu_callback+0xc9/0x10f
> [<ffffffff8054acf1>] ? cpu_callback+0x12/0x280
> [<ffffffff805539a8>] notifier_call_chain+0x68/0xa0
> [<ffffffff802630d6>] raw_notifier_call_chain+0x16/0x20
> [<ffffffff8053d9ec>] _cpu_down+0x1cc/0x2d0
> [<ffffffff80246f90>] disable_nonboot_cpus+0xb0/0x130
> [<ffffffff8027dd8d>] suspend_devices_and_enter+0xbd/0x1b0
> [<ffffffff8027dff7>] enter_state+0x107/0x170
> [<ffffffff8027e0f9>] state_store+0x99/0x100
> [<ffffffff803abe17>] kobj_attr_store+0x17/0x20
> [<ffffffff8033f1e9>] sysfs_write_file+0xd9/0x160
> [<ffffffff802e1c88>] vfs_write+0xb8/0x180
> [<ffffffff8029088c>] ? audit_syscall_entry+0x21c/0x240
> [<ffffffff802e2771>] sys_write+0x51/0x90
> [<ffffffff8020c15b>] system_call_fastpath+0x16/0x1b


=======================================================
[ INFO: possible circular locking dependency detected ]
2.6.30-rc6-tip #9
-------------------------------------------------------
bash/6174 is trying to acquire lock:
(events){+.+.+.}, at: [<ffffffff81059076>] cleanup_workqueue_thread+0x28/0x10a

but task is already holding lock:
(cpu_add_remove_lock){+.+.+.}, at: [<ffffffff81046c26>] disable_nonboot_cpus+0x38/0x128

which lock already depends on the new lock.


the existing dependency chain (in reverse order) is:

-> #4 (cpu_add_remove_lock){+.+.+.}:
[<ffffffff8106f74d>] __lock_acquire+0xa80/0xc08
[<ffffffff8106f9dd>] lock_acquire+0x108/0x134
[<ffffffff813553fe>] __mutex_lock_common+0x5e/0x494
[<ffffffff81355883>] mutex_lock_nested+0x19/0x1b
[<ffffffff81046c26>] disable_nonboot_cpus+0x38/0x128
[<ffffffff8107b38e>] suspend_devices_and_enter+0xf5/0x1f4
[<ffffffff8107b623>] enter_state+0x168/0x1ce
[<ffffffff8107b745>] state_store+0xbc/0xdd
[<ffffffff811737fb>] kobj_attr_store+0x17/0x19
[<ffffffff81136620>] sysfs_write_file+0xe9/0x11e
[<ffffffff810e2422>] vfs_write+0xb0/0x10a
[<ffffffff810e254a>] sys_write+0x4c/0x75
[<ffffffff8100bdf2>] system_call_fastpath+0x16/0x1b
[<ffffffffffffffff>] 0xffffffffffffffff

-> #3 (dpm_list_mtx){+.+.+.}:
[<ffffffff8106f74d>] __lock_acquire+0xa80/0xc08
[<ffffffff8106f9dd>] lock_acquire+0x108/0x134
[<ffffffff813553fe>] __mutex_lock_common+0x5e/0x494
[<ffffffff81355883>] mutex_lock_nested+0x19/0x1b
[<ffffffff812312fe>] device_pm_add+0x23/0xcd
[<ffffffff8122ad87>] device_add+0x38b/0x549
[<ffffffff8130de59>] wiphy_register+0x139/0x1ee
[<ffffffff81317dff>] ieee80211_register_hw+0xee/0x3bf
[<ffffffff8126163a>] iwl_setup_mac+0x8b/0xd1
[<ffffffff8126fbcd>] iwl_pci_probe+0x7f5/0x921
[<ffffffff81188d21>] local_pci_probe+0x17/0x1b
[<ffffffff81059262>] do_work_for_cpu+0x18/0x2a
[<ffffffff8105dc98>] kthread+0x5b/0x88
[<ffffffff8100cf7a>] child_rip+0xa/0x20
[<ffffffffffffffff>] 0xffffffffffffffff

-> #2 (cfg80211_mutex){+.+.+.}:
[<ffffffff8106f74d>] __lock_acquire+0xa80/0xc08
[<ffffffff8106f9dd>] lock_acquire+0x108/0x134
[<ffffffff813553fe>] __mutex_lock_common+0x5e/0x494
[<ffffffff81355883>] mutex_lock_nested+0x19/0x1b
[<ffffffff8130f52a>] reg_todo+0x53/0x490
[<ffffffff81058870>] worker_thread+0x250/0x3dc
[<ffffffff8105dc98>] kthread+0x5b/0x88
[<ffffffff8100cf7a>] child_rip+0xa/0x20
[<ffffffffffffffff>] 0xffffffffffffffff

-> #1 (reg_work){+.+.+.}:
[<ffffffff8106f74d>] __lock_acquire+0xa80/0xc08
[<ffffffff8106f9dd>] lock_acquire+0x108/0x134
[<ffffffff810587f7>] worker_thread+0x1d7/0x3dc
[<ffffffff8105dc98>] kthread+0x5b/0x88
[<ffffffff8100cf7a>] child_rip+0xa/0x20
[<ffffffffffffffff>] 0xffffffffffffffff

-> #0 (events){+.+.+.}:
[<ffffffff8106f641>] __lock_acquire+0x974/0xc08
[<ffffffff8106f9dd>] lock_acquire+0x108/0x134
[<ffffffff8105909d>] cleanup_workqueue_thread+0x4f/0x10a
[<ffffffff81343fe4>] workqueue_cpu_callback+0xc9/0x10d
[<ffffffff81359cfd>] notifier_call_chain+0x33/0x5b
[<ffffffff81062254>] raw_notifier_call_chain+0x14/0x16
[<ffffffff81342624>] _cpu_down+0x283/0x2a0
[<ffffffff81046c6b>] disable_nonboot_cpus+0x7d/0x128
[<ffffffff8107b38e>] suspend_devices_and_enter+0xf5/0x1f4
[<ffffffff8107b623>] enter_state+0x168/0x1ce
[<ffffffff8107b745>] state_store+0xbc/0xdd
[<ffffffff811737fb>] kobj_attr_store+0x17/0x19
[<ffffffff81136620>] sysfs_write_file+0xe9/0x11e
[<ffffffff810e2422>] vfs_write+0xb0/0x10a
[<ffffffff810e254a>] sys_write+0x4c/0x75
[<ffffffff8100bdf2>] system_call_fastpath+0x16/0x1b
[<ffffffffffffffff>] 0xffffffffffffffff

other info that might help us debug this:

4 locks held by bash/6174:
#0: (&buffer->mutex){+.+.+.}, at: [<ffffffff81136574>] sysfs_write_file+0x3d/0x11e
#1: (pm_mutex){+.+.+.}, at: [<ffffffff8107b680>] enter_state+0x1c5/0x1ce
#2: (dpm_list_mtx){+.+.+.}, at: [<ffffffff8123084d>] device_pm_lock+0x17/0x19
#3: (cpu_add_remove_lock){+.+.+.}, at: [<ffffffff81046c26>] disable_nonboot_cpus+0x38/0x128

stack backtrace:
Pid: 6174, comm: bash Not tainted 2.6.30-rc6-tip #9
Call Trace:
[<ffffffff8106e92d>] print_circular_bug+0x1cc/0x201
[<ffffffff8106f641>] __lock_acquire+0x974/0xc08
[<ffffffff8106f9dd>] lock_acquire+0x108/0x134
[<ffffffff81059076>] ? cleanup_workqueue_thread+0x28/0x10a
[<ffffffff8105909d>] cleanup_workqueue_thread+0x4f/0x10a
[<ffffffff81059076>] ? cleanup_workqueue_thread+0x28/0x10a
[<ffffffff81343fe4>] workqueue_cpu_callback+0xc9/0x10d
[<ffffffff81359cfd>] notifier_call_chain+0x33/0x5b
[<ffffffff81062254>] raw_notifier_call_chain+0x14/0x16
[<ffffffff81342624>] _cpu_down+0x283/0x2a0
[<ffffffff81046c6b>] disable_nonboot_cpus+0x7d/0x128
[<ffffffff8107b38e>] suspend_devices_and_enter+0xf5/0x1f4
[<ffffffff8107b623>] enter_state+0x168/0x1ce
[<ffffffff8107b745>] state_store+0xbc/0xdd
[<ffffffff811737fb>] kobj_attr_store+0x17/0x19
[<ffffffff81136620>] sysfs_write_file+0xe9/0x11e
[<ffffffff810e2422>] vfs_write+0xb0/0x10a
[<ffffffff810e254a>] sys_write+0x4c/0x75
[<ffffffff8100bdf2>] system_call_fastpath+0x16/0x1b




\
 
 \ /
  Last update: 2009-05-24 21:03    [W:0.093 / U:0.412 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site