2.6.32-rc4-git1 -- INFO: possible circular locking dependency detected

2.6.32-rc4-git1 -- INFO: possible circular locking dependency detected

[Miles Lane]

[  823.466853] [ INFO: possible circular locking dependency detected ]
[  823.466866] 2.6.32-rc4-git1 #2
[  823.466873] -------------------------------------------------------
[  823.466884] swapper/0 is trying to acquire lock:
[  823.466893]  (&sta->lock){+.-...}, at: [<f857bda4>]
sta_addba_resp_timer_expired+0x1b/0x50 [mac80211]
[  823.466940]
[  823.466943] but task is already holding lock:
[  823.466953]
(&sta->ampdu_mlme.tid_tx[tid]->addba_resp_timer){+.-...}, at:
[<c1032f22>] run_timer_softirq+0x125/0x1e5
[  823.466984]
[  823.466987] which lock already depends on the new lock.
[  823.466991]
[  823.467000]
[  823.467002] the existing dependency chain (in reverse order) is:
[  823.467013]
[  823.467015] -> #1 (&sta->ampdu_mlme.tid_tx[tid]->addba_resp_timer){+.-...}:
[  823.467037]        [<c104ac2c>] __lock_acquire+0x9fb/0xb6d
[  823.467056]        [<c104adfa>] lock_acquire+0x5c/0x73
[  823.467072]        [<c10336b8>] del_timer_sync+0x29/0x6c
[  823.467089]        [<f857bceb>]
ieee80211_process_addba_resp+0x49/0xa0 [mac80211]
[  823.467121]        [<f8584585>] ieee80211_rx_h_action+0xeb/0x335 [mac80211]
[  823.467157]        [<f8585654>]
ieee80211_invoke_rx_handlers+0xe50/0x10d8 [mac80211]
[  823.467193]        [<f8585d46>]
__ieee80211_rx_handle_packet+0x46a/0x497 [mac80211]
[  823.467229]        [<f8586475>] ieee80211_rx+0x4d1/0x530 [mac80211]
[  823.467263]        [<f89936e3>] ath_rx_send_to_mac80211+0xa0/0xa8 [ath9k]
[  823.467302]        [<f899439e>] ath_rx_tasklet+0x7b6/0x7f5 [ath9k]
[  823.467338]        [<f8992115>] ath9k_tasklet+0x47/0xc7 [ath9k]
[  823.467373]        [<c102f4a1>] tasklet_action+0x8e/0xe1
[  823.467391]        [<c102f95b>] __do_softirq+0x8d/0x117
[  823.467409]
[  823.467412] -> #0 (&sta->lock){+.-...}:
[  823.467430]        [<c104ab2e>] __lock_acquire+0x8fd/0xb6d
[  823.467447]        [<c104adfa>] lock_acquire+0x5c/0x73
[  823.467464]        [<c132526f>] _spin_lock_bh+0x2a/0x39
[  823.467481]        [<f857bda4>]
sta_addba_resp_timer_expired+0x1b/0x50 [mac80211]
[  823.467514]        [<c1032f6d>] run_timer_softirq+0x170/0x1e5
[  823.467531]        [<c102f95b>] __do_softirq+0x8d/0x117
[  823.467548]
[  823.467551] other info that might help us debug this:
[  823.467555]
[  823.467566] 1 lock held by swapper/0:
[  823.467574]  #0:
(&sta->ampdu_mlme.tid_tx[tid]->addba_resp_timer){+.-...}, at:
[<c1032f22>] run_timer_softirq+0x125/0x1e5
[  823.467604]
[  823.467607] stack backtrace:
[  823.467619] Pid: 0, comm: swapper Not tainted 2.6.32-rc4-git1 #2
[  823.467628] Call Trace:
[  823.467643]  [<c13233c8>] ? printk+0xf/0x11
[  823.467659]  [<c1049ef5>] print_circular_bug+0x8a/0x96
[  823.467675]  [<c104ab2e>] __lock_acquire+0x8fd/0xb6d
[  823.467694]  [<c104adfa>] lock_acquire+0x5c/0x73
[  823.467725]  [<f857bda4>] ? sta_addba_resp_timer_expired+0x1b/0x50 [mac80211]
[  823.467742]  [<c132526f>] _spin_lock_bh+0x2a/0x39
[  823.467772]  [<f857bda4>] ? sta_addba_resp_timer_expired+0x1b/0x50 [mac80211]
[  823.467803]  [<f857bda4>] sta_addba_resp_timer_expired+0x1b/0x50 [mac80211]
[  823.467820]  [<c1032f6d>] run_timer_softirq+0x170/0x1e5
[  823.467836]  [<c1032f22>] ? run_timer_softirq+0x125/0x1e5
[  823.467866]  [<f857bd89>] ? sta_addba_resp_timer_expired+0x0/0x50 [mac80211]
[  823.467885]  [<c102f95b>] __do_softirq+0x8d/0x117
[  823.467901]  [<c102f8ce>] ? __do_softirq+0x0/0x117
[  823.467911]  <IRQ>  [<c102faf5>] ? irq_exit+0x38/0x75
[  823.467939]  [<c10045b1>] ? do_IRQ+0x88/0x9c
[  823.467954]  [<c1003175>] ? common_interrupt+0x35/0x3c
[  823.467971]  [<c104007b>] ? sched_clock_tick+0x31/0x77
[  823.467989]  [<c11b84ff>] ? acpi_idle_enter_bm+0x233/0x25e
[  823.468008]  [<c125c232>] ? cpuidle_idle_call+0x65/0x9b
[  823.468023]  [<c1001cd1>] ? cpu_idle+0xb9/0xe8
[  823.468041]  [<c131708b>] ? rest_init+0x67/0x69
[  823.468058]  [<c14e28e8>] ? start_kernel+0x3a3/0x3aa
[  823.468076]  [<c14e2098>] ? i386_start_kernel+0x98/0x9f

Re: 2.6.32-rc4-git1 -- INFO: possible circular locking dependency detected

[Johannes Berg]

[-- Attachment #1: Type: text/plain, Size: 936 bytes --]

On Mon, 2009-10-12 at 08:28 -0400, Miles Lane wrote:
> [  823.466853] [ INFO: possible circular locking dependency detected ]
> [  823.466866] 2.6.32-rc4-git1 #2
> [  823.466873] -------------------------------------------------------
> [  823.466884] swapper/0 is trying to acquire lock:
> [  823.466893]  (&sta->lock){+.-...}, at: [<f857bda4>] sta_addba_resp_timer_expired+0x1b/0x50 [mac80211]
> [  823.466940]
> [  823.466943] but task is already holding lock:
> [  823.466953] (&sta->ampdu_mlme.tid_tx[tid]->addba_resp_timer){+.-...}, at: [<c1032f22>] run_timer_softirq+0x125/0x1e5
> [  823.466984]
> [  823.466987] which lock already depends on the new lock.

Thanks for the report, I'll have to take a look at it, but this appears
to be due to the del_timer_sync() in ieee80211_process_addba_resp().

Guess it never really happens that the AP doesn't respond quickly enough
so the timer hardly fires.

johannes

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 801 bytes --]

Re: 2.6.32-rc4-git1 -- INFO: possible circular locking dependency detected

[Johannes Berg]

Actually ... seems to be easy to fix.

Can you reproduce this reliably? I suspect not. If you can, try the
patch below to make sure -- I'm pretty certain it is a correct patch
anyhow though.

johannes

---
 net/mac80211/agg-tx.c |   12 +++++++++---
 1 file changed, 9 insertions(+), 3 deletions(-)

--- wireless-testing.orig/net/mac80211/agg-tx.c	2009-10-16 19:13:48.000000000 +0900
+++ wireless-testing/net/mac80211/agg-tx.c	2009-10-16 19:15:12.000000000 +0900
@@ -666,11 +666,13 @@ void ieee80211_process_addba_resp(struct
 
 	state = &sta->ampdu_mlme.tid_state_tx[tid];
 
+	del_timer_sync(&sta->ampdu_mlme.tid_tx[tid]->addba_resp_timer);
+
 	spin_lock_bh(&sta->lock);
 
 	if (!(*state & HT_ADDBA_REQUESTED_MSK)) {
 		spin_unlock_bh(&sta->lock);
-		return;
+		goto timer_still_needed;
 	}
 
 	if (mgmt->u.action.u.addba_resp.dialog_token !=
@@ -679,13 +681,13 @@ void ieee80211_process_addba_resp(struct
 #ifdef CONFIG_MAC80211_HT_DEBUG
 		printk(KERN_DEBUG "wrong addBA response token, tid %d\n", tid);
 #endif /* CONFIG_MAC80211_HT_DEBUG */
-		return;
+		goto timer_still_needed;
 	}
 
-	del_timer_sync(&sta->ampdu_mlme.tid_tx[tid]->addba_resp_timer);
 #ifdef CONFIG_MAC80211_HT_DEBUG
 	printk(KERN_DEBUG "switched off addBA timer for tid %d \n", tid);
 #endif /* CONFIG_MAC80211_HT_DEBUG */
+
 	if (le16_to_cpu(mgmt->u.action.u.addba_resp.status)
 			== WLAN_STATUS_SUCCESS) {
 		u8 curstate = *state;
@@ -700,4 +702,8 @@ void ieee80211_process_addba_resp(struct
 		___ieee80211_stop_tx_ba_session(sta, tid, WLAN_BACK_INITIATOR);
 	}
 	spin_unlock_bh(&sta->lock);
+
+	return;
+ timer_still_needed:
+	add_timer(&sta->ampdu_mlme.tid_tx[tid]->addba_resp_timer);
 }