Re: [ipw3945-devel] 2.6.24-rc5-mm1 -- INFO: possible circular locking dependency detected -- pm-suspend/5800 is trying to acquire lock
On Dec 18, 2007 9:58 PM, Zhu Yi [EMAIL PROTECTED] wrote: On Tue, 2007-12-18 at 15:57 +0100, Johannes Berg wrote: Thanks. This is a bug in iwlwifi. The problem is actually another case where my workqueue debugging with lockdep is triggering a warning :)) Here's the thing: iwl3945_cancel_deferred_work does cancel_delayed_work_sync(priv-init_alive_start); (which is the ((priv-init_alive_start)-work) lock) but it is called from within a locked section of mutex_lock(priv-mutex); (locked from iwl3945_pci_suspend) On the other hand, the task that runs from the init_alive_start workqueue is iwl3945_bg_init_alive_start() which will lock the same mutex. So the deadlock condition is that you can be in cancel_delayed_work_sync() above while the mutex is locked, and be waiting for iwl_3945_bg_init_alive_start() which tries to lock the mutex. Thanks for the analysis. Miles, please try the attached patch. I'll send a patch for both 3945 and 4965 to linux-wireless later. I tested it and it looks good here. Thanks! Miles -- To unsubscribe from this list: send the line unsubscribe netdev in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html
2.6.24-rc5-mm1 -- INFO: possible circular locking dependency detected -- pm-suspend/5800 is trying to acquire lock
I have only seen this happen once, and cannot reproduce it. I'll keep trying, though. Dec 16 22:10:48 syntropy kernel: [ 231.718023] === Dec 16 22:10:48 syntropy kernel: [ 231.718025] [ INFO: possible circular locking dependency detected ] Dec 16 22:10:48 syntropy kernel: [ 231.718028] 2.6.24-rc5-mm1 #7 Dec 16 22:10:48 syntropy kernel: [ 231.718029] --- Dec 16 22:10:48 syntropy kernel: [ 231.718032] pm-suspend/5800 is trying to acquire lock: Dec 16 22:10:48 syntropy kernel: [ 231.718034] ((priv-init_alive_start)-work){--..}, at: [__cancel_work_timer+0x8a/0x17f] __cancel_work_timer+0x8a/0x17f Dec 16 22:10:48 syntropy kernel: [ 231.718045] Dec 16 22:10:48 syntropy kernel: [ 231.718046] but task is already holding lock: Dec 16 22:10:48 syntropy kernel: [ 231.718047] (priv-mutex){--..}, at: [f8a587e7] iwl3945_pci_suspend+0x1d/0x65 [iwl3945] Dec 16 22:10:48 syntropy kernel: [ 231.718065] Dec 16 22:10:48 syntropy kernel: [ 231.718066] which lock already depends on the new lock. Dec 16 22:10:48 syntropy kernel: [ 231.718067] Dec 16 22:10:48 syntropy kernel: [ 231.718068] Dec 16 22:10:48 syntropy kernel: [ 231.718069] the existing dependency chain (in reverse order) is: Dec 16 22:10:48 syntropy kernel: [ 231.718071] Dec 16 22:10:48 syntropy kernel: [ 231.718072] - #1 (priv-mutex){--..}: Dec 16 22:10:48 syntropy kernel: [ 231.718075] [__lock_acquire+0xa17/0xbf4] __lock_acquire+0xa17/0xbf4 Dec 16 22:10:48 syntropy kernel: [ 231.718083] [mac80211:lock_acquire+0x76/0x1d8] lock_acquire+0x76/0x9d Dec 16 22:10:48 syntropy kernel: [ 231.718088] [pcmcia:mutex_lock_nested+0xf7/0xd7d] mutex_lock_nested+0xf7/0x294 Dec 16 22:10:48 syntropy kernel: [ 231.718096][f8a56ff7] iwl3945_bg_init_alive_start+0x2d/0x1d7 [iwl3945] Dec 16 22:10:48 syntropy kernel: [ 231.718109] [run_workqueue+0xbb/0x18b] run_workqueue+0xbb/0x18b Dec 16 22:10:48 syntropy kernel: [ 231.718115] [worker_thread+0xbe/0xcd] worker_thread+0xbe/0xcd Dec 16 22:10:48 syntropy kernel: [ 231.718121] [kthread+0x3b/0x61] kthread+0x3b/0x61 Dec 16 22:10:48 syntropy kernel: [ 231.718126] [kernel_thread_helper+0x7/0x10] kernel_thread_helper+0x7/0x10 Dec 16 22:10:48 syntropy kernel: [ 231.718133][] 0x Dec 16 22:10:48 syntropy kernel: [ 231.718145] Dec 16 22:10:48 syntropy kernel: [ 231.718146] - #0 ((priv-init_alive_start)-work){--..}: Dec 16 22:10:48 syntropy kernel: [ 231.718149] [__lock_acquire+0x93e/0xbf4] __lock_acquire+0x93e/0xbf4 Dec 16 22:10:48 syntropy kernel: [ 231.718155] [mac80211:lock_acquire+0x76/0x1d8] lock_acquire+0x76/0x9d Dec 16 22:10:48 syntropy kernel: [ 231.718161] [__cancel_work_timer+0xb3/0x17f] __cancel_work_timer+0xb3/0x17f Dec 16 22:10:48 syntropy kernel: [ 231.718167] [iwl3945:cancel_delayed_work_sync+0xb/0x0d] cancel_delayed_work_sync+0xb/0xd Dec 16 22:10:48 syntropy kernel: [ 231.718173][f8a542cb] __iwl3945_down+0x51/0x310 [iwl3945] Dec 16 22:10:48 syntropy kernel: [ 231.718184][f8a587f7] iwl3945_pci_suspend+0x2d/0x65 [iwl3945] Dec 16 22:10:48 syntropy kernel: [ 231.718196] [pci_device_suspend+0x1b/0x4b] pci_device_suspend+0x1b/0x4b Dec 16 22:10:48 syntropy kernel: [ 231.718203] [device_suspend+0x17e/0x259] device_suspend+0x17e/0x259 Dec 16 22:10:48 syntropy kernel: [ 231.718210] [suspend_devices_and_enter+0x3d/0x138] suspend_devices_and_enter+0x3d/0x138 Dec 16 22:10:48 syntropy kernel: [ 231.718217] [enter_state+0x121/0x17d] enter_state+0x121/0x17d Dec 16 22:10:48 syntropy kernel: [ 231.718222] [state_store+0x96/0xac] state_store+0x96/0xac Dec 16 22:10:48 syntropy kernel: [ 231.718228] [kobj_attr_store+0x1a/0x22] kobj_attr_store+0x1a/0x22 Dec 16 22:10:48 syntropy kernel: [ 231.718234] [sysfs_write_file+0xb8/0xe3] sysfs_write_file+0xb8/0xe3 Dec 16 22:10:48 syntropy kernel: [ 231.718242] [vfs_write+0xa4/0x120] vfs_write+0xa4/0x120 Dec 16 22:10:48 syntropy kernel: [ 231.718248] [sys_write+0x3b/0x60] sys_write+0x3b/0x60 Dec 16 22:10:48 syntropy kernel: [ 231.718254] [sysenter_past_esp+0x6b/0xc1] sysenter_past_esp+0x6b/0xc1 Dec 16 22:10:48 syntropy kernel: [ 231.718259][] 0x Dec 16 22:10:48 syntropy kernel: [ 231.718269] Dec 16 22:10:48 syntropy kernel: [ 231.718269] other info that might help us debug this: Dec 16 22:10:48 syntropy kernel: [ 231.718271] Dec 16 22:10:48 syntropy kernel: [ 231.718272] 4 locks held by pm-suspend/5800: Dec 16 22:10:48 syntropy kernel: [ 231.718274] #0: (buffer-mutex){--..}, at: [sysfs_write_file+0x25/0xe3] sysfs_write_file+0x25/0xe3 Dec 16 22:10:48 syntropy kernel: [ 231.718280] #1: (pm_mutex){--..}, at: [enter_state+0x166/0x17d] enter_state+0x166/0x17d Dec 16 22:10:48 syntropy kernel: [ 231.718286] #2: (dpm_mtx){--..}, at: [device_suspend+0x2b/0x259] device_suspend+0x2b/0x259 Dec 16 22:10:48 syntropy kernel: [ 231.718291] #3: (priv-mutex){--..}, at: [f8a587e7]
Re: 2.6.24-rc5-mm1 -- INFO: possible circular locking dependency detected -- pm-suspend/5800 is trying to acquire lock
On Tue, 2007-12-18 at 09:03 -0500, Miles Lane wrote: I have only seen this happen once, and cannot reproduce it. I'll keep trying, though. Dec 16 22:10:48 syntropy kernel: [ 231.718023] === Do you have a version that isn't line-wrapped before I try to unwrap it? Thanks, johannes signature.asc Description: This is a digitally signed message part
Re: 2.6.24-rc5-mm1 -- INFO: possible circular locking dependency detected -- pm-suspend/5800 is trying to acquire lock
Sorry. GMail doesn't support sending unwrapped text, as far as I can tell. I will send the log segment to you as an attachment. Also, when I sent my .config inline to Andrew recently, it tripped his spam filter. I'll attach it as well. Thanks. This is a bug in iwlwifi. The problem is actually another case where my workqueue debugging with lockdep is triggering a warning :)) Here's the thing: iwl3945_cancel_deferred_work does cancel_delayed_work_sync(priv-init_alive_start); (which is the ((priv-init_alive_start)-work) lock) but it is called from within a locked section of mutex_lock(priv-mutex); (locked from iwl3945_pci_suspend) On the other hand, the task that runs from the init_alive_start workqueue is iwl3945_bg_init_alive_start() which will lock the same mutex. So the deadlock condition is that you can be in cancel_delayed_work_sync() above while the mutex is locked, and be waiting for iwl_3945_bg_init_alive_start() which tries to lock the mutex. johannes signature.asc Description: This is a digitally signed message part
Re: [ipw3945-devel] 2.6.24-rc5-mm1 -- INFO: possible circular locking dependency detected -- pm-suspend/5800 is trying to acquire lock
On Tue, 2007-12-18 at 15:57 +0100, Johannes Berg wrote: Thanks. This is a bug in iwlwifi. The problem is actually another case where my workqueue debugging with lockdep is triggering a warning :)) Here's the thing: iwl3945_cancel_deferred_work does cancel_delayed_work_sync(priv-init_alive_start); (which is the ((priv-init_alive_start)-work) lock) but it is called from within a locked section of mutex_lock(priv-mutex); (locked from iwl3945_pci_suspend) On the other hand, the task that runs from the init_alive_start workqueue is iwl3945_bg_init_alive_start() which will lock the same mutex. So the deadlock condition is that you can be in cancel_delayed_work_sync() above while the mutex is locked, and be waiting for iwl_3945_bg_init_alive_start() which tries to lock the mutex. Thanks for the analysis. Miles, please try the attached patch. I'll send a patch for both 3945 and 4965 to linux-wireless later. Thanks, -yi diff --git a/drivers/net/wireless/iwlwifi/iwl3945-base.c b/drivers/net/wireless/iwlwifi/iwl3945-base.c index 88cf035..f0303e8 100644 --- a/drivers/net/wireless/iwlwifi/iwl3945-base.c +++ b/drivers/net/wireless/iwlwifi/iwl3945-base.c @@ -6355,8 +6355,6 @@ static void __iwl3945_down(struct iwl3945_priv *priv) /* Unblock any waiting calls */ wake_up_interruptible_all(priv-wait_command_queue); - iwl3945_cancel_deferred_work(priv); - /* Wipe out the EXIT_PENDING status bit if we are not actually * exiting the module */ if (!exit_pending) @@ -6431,6 +6429,8 @@ static void iwl3945_down(struct iwl3945_priv *priv) mutex_lock(priv-mutex); __iwl3945_down(priv); mutex_unlock(priv-mutex); + + iwl3945_cancel_deferred_work(priv); } #define MAX_HW_RESTARTS 5 @@ -8739,10 +8739,9 @@ static void iwl3945_pci_remove(struct pci_dev *pdev) IWL_DEBUG_INFO(*** UNLOAD DRIVER ***\n); - mutex_lock(priv-mutex); set_bit(STATUS_EXIT_PENDING, priv-status); - __iwl3945_down(priv); - mutex_unlock(priv-mutex); + + iwl3945_down(priv); /* Free MAC hash list for ADHOC */ for (i = 0; i IWL_IBSS_MAC_HASH_SIZE; i++) { @@ -8801,12 +8800,10 @@ static int iwl3945_pci_suspend(struct pci_dev *pdev, pm_message_t state) { struct iwl3945_priv *priv = pci_get_drvdata(pdev); - mutex_lock(priv-mutex); - set_bit(STATUS_IN_SUSPEND, priv-status); /* Take down the device; powers it off, etc. */ - __iwl3945_down(priv); + iwl3945_down(priv); if (priv-mac80211_registered) ieee80211_stop_queues(priv-hw); @@ -8815,8 +8812,6 @@ static int iwl3945_pci_suspend(struct pci_dev *pdev, pm_message_t state) pci_disable_device(pdev); pci_set_power_state(pdev, PCI_D3hot); - mutex_unlock(priv-mutex); - return 0; } @@ -8874,8 +8869,6 @@ static int iwl3945_pci_resume(struct pci_dev *pdev) printk(KERN_INFO Coming out of suspend...\n); - mutex_lock(priv-mutex); - pci_set_power_state(pdev, PCI_D0); err = pci_enable_device(pdev); pci_restore_state(pdev); @@ -8889,7 +8882,6 @@ static int iwl3945_pci_resume(struct pci_dev *pdev) pci_write_config_byte(pdev, 0x41, 0x00); iwl3945_resume(priv); - mutex_unlock(priv-mutex); return 0; }