wpa_supplicant 0.7.3 slow to associate, 0.6.10 is ok

[Dan Williams]

On Mon, 2012-08-13 at 12:13 +0200, Koen Beel wrote:
> On Fri, Aug 10, 2012 at 5:16 PM, Jouni Malinen <j at w1.fi> wrote:
> > On Fri, Aug 10, 2012 at 04:57:28PM +0200, Koen Beel wrote:
> >> In a product we are building, we are using wpa_supplicant to connect
> >> to a WPA2-PSK secured AP and are experiencing pretty low association
> >> times when using wpa_supplicant 0.7.3.
> >> After a very large number of test cylces (many 100's), we see that the
> >> association time is somewhere between 8 and 10 seconds.
> >
> > Which driver are you using? Are you using ap_scan=2 or 1 (default)? Is
> > the card dual band (i.e., will it scan both 2.4 GHz and 5 GHz channels)?
> 
> We are using ap_scan = 1 (default). Don't think the ap_scan=2 is
> supported by the driver.
> The card is a dual band card from Redpine Signals. The driver is
> proprietary. We do have the source code and can check things in the
> driver if needed, but we cannot share the source code itself.
> 
> 
> >> We have also done some test using the 0.6.10 version and here we see
> >> that the association time is only between 1 and 2 seconds.
> 
> One thing I did forget to mention is this. With the 0.6.10 association
> time is only 1 - 2 seconds, but from time to time it takes about 20
> seconds. We don't know the reason for this.
> 
> Also when reviewing the association times of the 0.7.3, we see that
> some of the test cycles it takes about 10 extra to finish association.
> So for a small number of test cycles we see that the association time
> is about 18 - 20 seconds instead of 8 - 10.
> And for an even smaller number of test cycles we see 28 - 30 seconds.
> ...
> 
> > Please send debug logs with timestamps (-dt on command line) from both
> > 0.6.10 and 0.7.3.
> 
> See attachment. (in separate e-mails due to file size limit on ML)
> 
> On strange thing we see in the logs for 0.7.3 (but not in the logs of
> 0.6.10) is the following:
> 
> 58.697437: Scan timeout - try to get results
> ioctl[SIOCGIWSCAN]: Resource temporarily unavailable
> 58.697906: Failed to get scan results
> 58.698000: Failed to get scan results - try scanning again
> 58.698125: Setting scan request: 1 sec 0 usec
> 59.698750: Starting AP scan for wildcard SSID
> ioctl[SIOCSIWSCAN]: Resource temporarily unavailable
> 59.699156: Scan requested (ret=-1) - scan timeout 5 seconds
> 59.699281: Failed to initiate AP scan.
> 59.699406: Setting scan request: 1 sec 0 usec

That means the driver is refusing the scan request, possibly because
it's already doing a scan and doesn't like being asked to do another one
while it's already busy.  My personal opinion is that drivers should
handle this, and I spent a good chunk of time about 4 years ago
modifying the in-kernel drivers to handle this just fine.

Unfortunately WEXT doesn't have a mechanism to indicate that a scan is
currently in-progress, and it never will, so your best option is to
modify the driver.  What you'll be doing here is find out where the
driver returns EBUSY from the SIWSCAN handler (it may be deeper in the
code than the handler itself) and instead detect when a scan is already
in-progress and return '0' (success) instead.  The SIWSCAN handler is
just a request to start a scan; the results are sent later, and the
supplicant will handle that part just fine.

For example, from the 'airo' driver:

	/* If there's already a scan in progress, don't
	 * trigger another one. */
	if (ai->scan_timeout > 0)
		goto out;

	<start a scan>
out:
	...
	return 0;

Another thing you may want to do is cache the scan results and expire
them on a timer if the driver doesn't already do that, as expiring the
scan results immediately after they are requested causes a number
problems that I'm happy to elaborate.

An example of this is:

commit 9e75af30d529d54fc650586776c100d0665c0c93
Author: Dan Williams
Date:   Thu Mar 16 13:46:29 2006 -0500

    [PATCH] wireless/airo: cache wireless scans

And then after that, convert the driver to nl80211 :)  WEXT is dead.

Dan