Slow roaming in mac80211 (2.6.30).

Slow roaming in mac80211 (2.6.30).

[Lars Ericsson]

Johannes,

I'm currently using the 2.6.26 kernel and have started evaluating the
2.6.30.  

For .26 I have made a few patches to fix minor issues related to
roaming.  

The trace below shows a typical roaming:
87.632965	AP 1 drops STA
87.733979	wpa_supplicant trigs a scan
88.629931	mac80211 probes for the old AP	
90.670305	SCAN result to wpa_supplicant
90.702325	wpa_supplicant ready with new AP
92.158037	mac80211 executes the wpa_supplicant decisions
92.164776	we are on line again

Total roaming time is 4,5 seconds, where mac80211 had added 2*2
seconds delay.

A first analysis gives that the two delays are the ieee80211_sta_work()
timeout.  There are many events trigging ieee80211_sta_work(), but
since only the timer sets IEEE80211_STA_REQ_RUN, nothing will happen.

Questions; 
- Why does mac80211 tells the wpa_supplicant that the AP
is gone (87.632965), and then blocks/delays the actions taken by the
wpa_supplicant?  
- Why are some wpa_supplicant actions (90.702325)
not event driven?

It looks to me as if we have to decision makers here. For me the
wpa_supplicant is the one that make the decision. Once the mac80211
gives up and feedback that the AP is gone, it should just sit 
and wait for next decision from the wpa_supplicant.

I had a few patches for this for .26, but since the code is changed
they do not apply. Before I create new patches I would like to get
your opinion on this.

Regards
/Lars
  
-----
[   87.632965] wlan0: deauthenticated (Reason: 1)
[   87.733979] [B] LaE: SCANRQUEST: SSID=AGV
[   88.629931] wlan0: direct probe to AP 00:40:96:a0:e7:e7 try 1
[   88.829932] wlan0: direct probe to AP 00:40:96:a0:e7:e7 try 2
[   89.029944] wlan0: direct probe to AP 00:40:96:a0:e7:e7 try 3
[   89.230016] wlan0: direct probe to AP 00:40:96:a0:e7:e7 timed out
[   90.670305] [B] LaE: SCANRESULT: BSSID=00:40:96:a0:e7:e7, SSID=
, ch= 1, , q=  0, l=  0(-30dBm), n=  0
[   90.670384] [B] LaE: SCANRESULT: BSSID=00:08:21:31:53:87, SSID=
, ch=11, , q=  0, l=  0(-62dBm), n=  0
[   90.670455] [B] LaE: SCANRESULT: BSSID=00:08:21:31:53:87, SSID=AGV
, ch=11, , q=  0, l=  0(-60dBm), n=  0
[   90.670705] ieee80211_ioctl_siwauth: enter
[   90.670777] ieee80211_ioctl_siwencodeext: enter
[   90.670807] ieee80211_set_encryption: enter
[   90.671128] ieee80211_ioctl_siwencodeext: enter
[   90.671165] ieee80211_set_encryption: enter
[   90.671219] ieee80211_ioctl_siwencodeext: enter
[   90.671247] ieee80211_set_encryption: enter
[   90.671297] ieee80211_ioctl_siwencodeext: enter
[   90.671325] ieee80211_set_encryption: enter
[   90.671375] ieee80211_ioctl_siwencodeext: enter
[   90.671404] ieee80211_set_encryption: enter
[   90.671623] ieee80211_ioctl_siwencodeext: enter
[   90.671659] ieee80211_set_encryption: enter
[   90.672062] ieee80211_ioctl_siwauth: enter
[   90.672295] ieee80211_ioctl_siwgenie: enter
[   90.672332] ieee80211_sta_req_auth: queue auth
[   90.672380] ieee80211_ioctl_siwauth: enter
[   90.672420] ieee80211_ioctl_siwauth: enter
[   90.672458] ieee80211_ioctl_siwauth: enter
[   90.672495] ieee80211_ioctl_siwauth: enter
[   90.672532] ieee80211_ioctl_siwauth: enter
[   90.672569] ieee80211_ioctl_siwauth: enter
[   90.672612] ieee80211_ioctl_siwfreq: enter freq=246200000
[   90.702175] ieee80211_ioctl_siwessid: enter ssid=AGV
[   90.702217] ieee80211_sta_req_auth: queue auth
[   90.702325] ieee80211_ioctl_siwap: enter AP=00:08:21:31:53:87
[   90.702372] ieee80211_sta_req_auth: queue auth
[   92.158037] wlan0: authenticate with AP 00:08:21:31:53:87
[   92.159965] wlan0: authenticated
[   92.160002] wlan0: associate with AP 00:08:21:31:53:87
[   92.164733] wlan0: RX ReassocResp from 00:08:21:31:53:87 (capab=0x431
status=0 aid=140)
[   92.164776] wlan0: associated
[   92.166984] ieee80211_ioctl_giwap: enter

-----

Re: Slow roaming in mac80211 (2.6.30).

[Johannes Berg]

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

Lars,

> A first analysis gives that the two delays are the ieee80211_sta_work()
> timeout.  There are many events trigging ieee80211_sta_work(), but
> since only the timer sets IEEE80211_STA_REQ_RUN, nothing will happen.

TBH I really no longer know the 2.6.30 code well, so I don't know.

> Questions; 
> - Why does mac80211 tells the wpa_supplicant that the AP
> is gone (87.632965), and then blocks/delays the actions taken by the
> wpa_supplicant?  

The real question is: why the hell is it probing the AP?

> [   87.632965] wlan0: deauthenticated (Reason: 1)
> [   87.733979] [B] LaE: SCANRQUEST: SSID=AGV
> [   88.629931] wlan0: direct probe to AP 00:40:96:a0:e7:e7 try 1
> [   88.829932] wlan0: direct probe to AP 00:40:96:a0:e7:e7 try 2
> [   89.029944] wlan0: direct probe to AP 00:40:96:a0:e7:e7 try 3
> [   89.230016] wlan0: direct probe to AP 00:40:96:a0:e7:e7 timed out

It doesn't really block actions, but it delays the scan because it's
busy doing the probing. So only after the probing fails will it start
the scan, and complete it within about 1.4 seconds.

> - Why are some wpa_supplicant actions (90.702325)
> not event driven?
> 
> It looks to me as if we have to decision makers here. For me the
> wpa_supplicant is the one that make the decision. Once the mac80211
> gives up and feedback that the AP is gone, it should just sit 
> and wait for next decision from the wpa_supplicant.

I agree -- the spurious probing is strange. But I also have to admit
that basically I don't care as long as it works -- most of this is just
a side effect of how wireless extensions work.

> I had a few patches for this for .26, but since the code is changed
> they do not apply. Before I create new patches I would like to get
> your opinion on this.

I would suggest you just use wpa_supplicant -Dnl80211, which should help
a lot with this kind of things.

johannes

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

RE: Slow roaming in mac80211 (2.6.30).

[Lars Ericsson]

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

Johannes,

> The real question is: why the hell is it probing the AP?
> I agree -- the spurious probing is strange. But I also have to admit
> that basically I don't care as long as it works -- most of this is just
> a side effect of how wireless extensions work.

I have further investigated the roaming issues and found two problems.

First ieee80211_rx_mgmt_deauth() and ieee80211_rx_mgmt_disassoc()
sets a retry state at the same time as they tells the wpa_supplicant
that the AP is gone.

Patch lae-mac80211-rm-direct-probe.patch addresses this problem.


Second problem address the auto scan function in
ieee80211_sta_config_auth().  When an incomplete AP information is
found, it start a new scan. This scan will delay the actions taken by
the wpa_supplicant for the scan period.

Patch lae-mac80211-rm-extra-scan-request.patch addresses this problem.

I do not have the knowledge to judge if the patch is correctly
applied/located, but they sure give the desired effect. Old roaming
time was 4,5 seconds for 13 channels and with the above patches it is
down to 400ms for 3 channels. See trace below.


> I would suggest you just use wpa_supplicant -Dnl80211, which 
> should help
> a lot with this kind of things.

I need to patch the kernel for this, rigth ?
Where can I get appropriate patches?

/Lars

-----

[  124.597307] wlan0: deauthenticated (Reason: 1)
[  124.597341] LaE: [ieee80211_rx_mgmt_deauth] do not set
IEEE80211_STA_MLME_DIRECT_PROBE
[  124.699253] [B] LaE: SCANRQUEST: SSID=AGV
[  124.699298] LaE: [ieee80211_request_scan(568)] set IEEE80211_STA_REQ_SCAN
[  124.699456] ieee80211_start_scan: enter
[  124.919184] ieee80211_scan_completed: enter
[  124.919577] [B] LaE: SCANRESULT: BSSID=00:08:21:31:53:87, SSID=AGV
, ch=11, , q=  0, l=  0(-56dBm), n=  0
[  124.919655] [B] LaE: SCANRESULT: BSSID=00:08:21:31:53:87, SSID=
, ch=11, , q=  0, l=  0(-56dBm), n=  0
[  124.919726] [B] LaE: SCANRESULT: BSSID=00:40:96:a0:e7:e7, SSID=AGV
, ch= 1, , q=  0, l=  0(-36dBm), n=  0
[  124.919978] ieee80211_ioctl_siwauth: enter
[  124.920053] ieee80211_ioctl_siwencodeext: enter
[  124.920084] ieee80211_set_encryption: enter
[  124.920177] ieee80211_ioctl_siwencodeext: enter
[  124.920210] ieee80211_set_encryption: enter
[  124.920262] ieee80211_ioctl_siwencodeext: enter
[  124.920291] ieee80211_set_encryption: enter
[  124.920341] ieee80211_ioctl_siwencodeext: enter
[  124.920370] ieee80211_set_encryption: enter
[  124.920421] ieee80211_ioctl_siwencodeext: enter
[  124.920449] ieee80211_set_encryption: enter
[  124.920667] ieee80211_ioctl_siwencodeext: enter
[  124.920704] ieee80211_set_encryption: enter
[  124.920774] ieee80211_ioctl_siwauth: enter
[  124.921454] ieee80211_ioctl_siwgenie: enter
[  124.921518] ieee80211_ioctl_siwauth: enter
[  124.921560] ieee80211_ioctl_siwauth: enter
[  124.921598] ieee80211_ioctl_siwauth: enter
[  124.921637] ieee80211_ioctl_siwauth: enter
[  124.921674] ieee80211_ioctl_siwauth: enter
[  124.921712] ieee80211_ioctl_siwauth: enter
[  124.921755] ieee80211_ioctl_siwfreq: enter freq=241200000
[  124.951244] LaE: [ieee80211_sta_config_auth(1847)] disable
ieee80211_start_scan
[  124.951456] ieee80211_ioctl_siwessid: enter ssid=AGV
[  124.951553] LaE: [ieee80211_sta_config_auth(1847)] disable
ieee80211_start_scan
[  124.951641] ieee80211_ioctl_siwap: enter AP=00:40:96:a0:e7:e7
[  124.959261] wlan0: authenticate with AP 00:40:96:a0:e7:e7
[  124.960678] wlan0: authenticated
[  124.960717] wlan0: associate with AP 00:40:96:a0:e7:e7
[  124.962865] wlan0: RX ReassocResp from 00:40:96:a0:e7:e7 (capab=0x431
status=0 aid=6)
[  124.962907] wlan0: associated



[-- Attachment #2: lae-mac80211-rm-extra-scan-request.patch --]
[-- Type: application/octet-stream, Size: 618 bytes --]

diff -Nurp -x '*.o' -x '*.mod.*' -x '*.ko' a/net/mac80211/mlme.c linux-2.6.30.1/net/mac80211/mlme.c
--- a/net/mac80211/mlme.c	2009-07-21 15:48:29.000000000 +0200
+++ linux-2.6.30.1/net/mac80211/mlme.c	2009-07-23 10:14:29.000000000 +0200
@@ -1834,6 +1843,8 @@ static int ieee80211_sta_config_auth(str
 		ieee80211_rx_bss_put(local, bss);
 		ieee80211_sta_reset_auth(sdata);
 		return 0;
+	} else if (1) {
+		printk(KERN_DEBUG "LaE: [%s(%d)] disable ieee80211_start_scan \n", __func__, __LINE__ );
 	} else {
 		if (ifmgd->assoc_scan_tries < IEEE80211_ASSOC_SCANS_MAX_TRIES) {
 			ifmgd->assoc_scan_tries++;

[-- Attachment #3: lae-mac80211-rm-direct-probe.patch --]
[-- Type: application/octet-stream, Size: 1205 bytes --]

diff -Nurp -x '*.o' -x '*.mod.*' -x '*.ko' a/net/mac80211/mlme.c linux-2.6.30.1/net/mac80211/mlme.c
--- a/net/mac80211/mlme.c	2009-07-21 15:48:29.000000000 +0200
+++ linux-2.6.30.1/net/mac80211/mlme.c	2009-07-23 10:14:29.000000000 +0200
@@ -1191,6 +1194,9 @@ static void ieee80211_rx_mgmt_deauth(str
 		printk(KERN_DEBUG "%s: deauthenticated (Reason: %u)\n",
 				sdata->dev->name, reason_code);
 
+	if ( ifmgd->state == IEEE80211_STA_MLME_ASSOCIATED ) {
+		printk(KERN_DEBUG "LaE: [%s] do not set IEEE80211_STA_MLME_DIRECT_PROBE \n", __func__);
+	} else
 	if (!(ifmgd->flags & IEEE80211_STA_EXT_SME) &&
 	    (ifmgd->state == IEEE80211_STA_MLME_AUTHENTICATE ||
 	     ifmgd->state == IEEE80211_STA_MLME_ASSOCIATE ||
@@ -1225,6 +1231,9 @@ static void ieee80211_rx_mgmt_disassoc(s
 		printk(KERN_DEBUG "%s: disassociated (Reason: %u)\n",
 				sdata->dev->name, reason_code);
 
+	if ( ifmgd->state == IEEE80211_STA_MLME_ASSOCIATED ) {
+		printk(KERN_DEBUG "LaE: [%s] do not set IEEE80211_STA_MLME_ASSOCIATE \n", __func__);
+	} else
 	if (!(ifmgd->flags & IEEE80211_STA_EXT_SME) &&
 	    ifmgd->state == IEEE80211_STA_MLME_ASSOCIATED) {
 		ifmgd->state = IEEE80211_STA_MLME_ASSOCIATE;

RE: Slow roaming in mac80211 (2.6.30).

[Johannes Berg]

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

Lars,

> I have further investigated the roaming issues and found two problems.

Thanks!

> First ieee80211_rx_mgmt_deauth() and ieee80211_rx_mgmt_disassoc()
> sets a retry state at the same time as they tells the wpa_supplicant
> that the AP is gone.
> 
> Patch lae-mac80211-rm-direct-probe.patch addresses this problem.

Hmm. I can see that being a problem, we might get away with just
removing the whole retry block. Ultimately though, I don't think it's a
-stable issue.

> Second problem address the auto scan function in
> ieee80211_sta_config_auth().  When an incomplete AP information is
> found, it start a new scan. This scan will delay the actions taken by
> the wpa_supplicant for the scan period.
> 
> Patch lae-mac80211-rm-extra-scan-request.patch addresses this problem.

I don't think this is correct, it will only work properly with
wpa_supplicant I think. Not really sure though.

> > I would suggest you just use wpa_supplicant -Dnl80211, which 
> > should help
> > a lot with this kind of things.
> 
> I need to patch the kernel for this, rigth ?
> Where can I get appropriate patches?

No, you don't need to patch the kernel, you just need to use a git (?)
version of wpa_supplicant.

johannes

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

Re: Slow roaming in mac80211 (2.6.30).

[Lam Yoke Khei]

Hi Lars,

    Would you mind to share your idea or patches on 2.6.26 kernel to improve 
roaming? As I am investigating the solution for short handoff/reassociation 
time (~50ms) via linux wireless stack. Thanks in advance.

Best regards,
Lam

----- Original Message ----- 
From: "Lars Ericsson" <Lars_Ericsson@telia.com>
To: "'Johannes Berg'" <johannes@sipsolutions.net>
Cc: <linux-wireless@vger.kernel.org>; <hostap@shmoo.com>
Sent: Wednesday, July 22, 2009 5:21 AM
Subject: Slow roaming in mac80211 (2.6.30).


>
> Johannes,
>
> I'm currently using the 2.6.26 kernel and have started evaluating the
> 2.6.30.
>
> For .26 I have made a few patches to fix minor issues related to
> roaming.
>
> The trace below shows a typical roaming:
> 87.632965 AP 1 drops STA
> 87.733979 wpa_supplicant trigs a scan
> 88.629931 mac80211 probes for the old AP
> 90.670305 SCAN result to wpa_supplicant
> 90.702325 wpa_supplicant ready with new AP
> 92.158037 mac80211 executes the wpa_supplicant decisions
> 92.164776 we are on line again
>
> Total roaming time is 4,5 seconds, where mac80211 had added 2*2
> seconds delay.
>
> A first analysis gives that the two delays are the ieee80211_sta_work()
> timeout.  There are many events trigging ieee80211_sta_work(), but
> since only the timer sets IEEE80211_STA_REQ_RUN, nothing will happen.
>
> Questions;
> - Why does mac80211 tells the wpa_supplicant that the AP
> is gone (87.632965), and then blocks/delays the actions taken by the
> wpa_supplicant?
> - Why are some wpa_supplicant actions (90.702325)
> not event driven?
>
> It looks to me as if we have to decision makers here. For me the
> wpa_supplicant is the one that make the decision. Once the mac80211
> gives up and feedback that the AP is gone, it should just sit
> and wait for next decision from the wpa_supplicant.
>
> I had a few patches for this for .26, but since the code is changed
> they do not apply. Before I create new patches I would like to get
> your opinion on this.
>
> Regards
> /Lars
>
> -----
> [   87.632965] wlan0: deauthenticated (Reason: 1)
> [   87.733979] [B] LaE: SCANRQUEST: SSID=AGV
> [   88.629931] wlan0: direct probe to AP 00:40:96:a0:e7:e7 try 1
> [   88.829932] wlan0: direct probe to AP 00:40:96:a0:e7:e7 try 2
> [   89.029944] wlan0: direct probe to AP 00:40:96:a0:e7:e7 try 3
> [   89.230016] wlan0: direct probe to AP 00:40:96:a0:e7:e7 timed out
> [   90.670305] [B] LaE: SCANRESULT: BSSID=00:40:96:a0:e7:e7, SSID=
> , ch= 1, , q=  0, l=  0(-30dBm), n=  0
> [   90.670384] [B] LaE: SCANRESULT: BSSID=00:08:21:31:53:87, SSID=
> , ch=11, , q=  0, l=  0(-62dBm), n=  0
> [   90.670455] [B] LaE: SCANRESULT: BSSID=00:08:21:31:53:87, SSID=AGV
> , ch=11, , q=  0, l=  0(-60dBm), n=  0
> [   90.670705] ieee80211_ioctl_siwauth: enter
> [   90.670777] ieee80211_ioctl_siwencodeext: enter
> [   90.670807] ieee80211_set_encryption: enter
> [   90.671128] ieee80211_ioctl_siwencodeext: enter
> [   90.671165] ieee80211_set_encryption: enter
> [   90.671219] ieee80211_ioctl_siwencodeext: enter
> [   90.671247] ieee80211_set_encryption: enter
> [   90.671297] ieee80211_ioctl_siwencodeext: enter
> [   90.671325] ieee80211_set_encryption: enter
> [   90.671375] ieee80211_ioctl_siwencodeext: enter
> [   90.671404] ieee80211_set_encryption: enter
> [   90.671623] ieee80211_ioctl_siwencodeext: enter
> [   90.671659] ieee80211_set_encryption: enter
> [   90.672062] ieee80211_ioctl_siwauth: enter
> [   90.672295] ieee80211_ioctl_siwgenie: enter
> [   90.672332] ieee80211_sta_req_auth: queue auth
> [   90.672380] ieee80211_ioctl_siwauth: enter
> [   90.672420] ieee80211_ioctl_siwauth: enter
> [   90.672458] ieee80211_ioctl_siwauth: enter
> [   90.672495] ieee80211_ioctl_siwauth: enter
> [   90.672532] ieee80211_ioctl_siwauth: enter
> [   90.672569] ieee80211_ioctl_siwauth: enter
> [   90.672612] ieee80211_ioctl_siwfreq: enter freq=246200000
> [   90.702175] ieee80211_ioctl_siwessid: enter ssid=AGV
> [   90.702217] ieee80211_sta_req_auth: queue auth
> [   90.702325] ieee80211_ioctl_siwap: enter AP=00:08:21:31:53:87
> [   90.702372] ieee80211_sta_req_auth: queue auth
> [   92.158037] wlan0: authenticate with AP 00:08:21:31:53:87
> [   92.159965] wlan0: authenticated
> [   92.160002] wlan0: associate with AP 00:08:21:31:53:87
> [   92.164733] wlan0: RX ReassocResp from 00:08:21:31:53:87 (capab=0x431
> status=0 aid=140)
> [   92.164776] wlan0: associated
> [   92.166984] ieee80211_ioctl_giwap: enter
>
> -----
>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-wireless" 
> in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html 

Re: Slow roaming in mac80211 (2.6.30).

[Holger Schurig]

> For .26 I have made a few patches to fix minor issues related
> to roaming.

It might be worthwile for you to publish this code, even it it's 
for an ancient kernel. You can post that to the mailing list and 
mark them as "RFC" instead of "PATCH" in the subject line.

Some people are currently working on roaming support, e.g. 
Helmut. Your patches/findings might give some input or ideas.