Skip site navigation (1)Skip section navigation (2)
Date:      Thu, 19 Feb 2009 16:24:49 +0100
From:      Bengt Ahlgren <bengta@sics.se>
To:        Sam Leffler <sam@freebsd.org>
Cc:        freebsd-mobile@freebsd.org
Subject:   Re: Problems with ath at kern.hz=100
Message-ID:  <uh7fxia8n5q.fsf@P142.sics.se>
In-Reply-To: <499C5319.10306@freebsd.org> (Sam Leffler's message of "Wed\, 18 Feb 2009 10\:27\:37 -0800")
References:  <uh7iqnjzzi9.fsf@P142.sics.se> <20090210154047.N38905@sola.nimnet.asn.au> <4991ABA0.4050300@freebsd.org> <uh7fximfatw.fsf@P142.sics.se> <4991DB1F.7060809@freebsd.org> <uh7y6w4zwsq.fsf@P142.sics.se> <499B1E7B.2030908@freebsd.org> <uh7eixwm5o9.fsf@P142.sics.se> <uh7eixvlvwo.fsf@P142.sics.se> <uh7skmby5da.fsf@P142.sics.se> <499C5319.10306@freebsd.org>

next in thread | previous in thread | raw e-mail | index | archive | help
Sam Leffler <sam@freebsd.org> writes:

> Bengt Ahlgren wrote:
>> Bengt Ahlgren <bengta@sics.se> writes:
>>
>>   
>>> Bengt Ahlgren <bengta@sics.se> writes:
>>>
>>>     
>>>> Sam Leffler <sam@freebsd.org> writes:
>>>>
>>>>       
>>>>> Bengt Ahlgren wrote:
>>>>>         
>>>>>> Sam Leffler <sam@freebsd.org> writes:
>>>>>>
>>>>>> [...]
>>>>>>
>>>>>>             
>>>>>>> You've removed all the context of the original problem; I can't recall
>>>>>>> what you were trying to fix.  The ps q drops might be caused by a bug
>>>>>>> that was fixed (I think in RELENG_7).  I don't see what version of
>>>>>>> code you're running so can't tell.
>>>>>>>                 
>>>>>> Sorry, a summary of the problem:
>>>>>>
>>>>>> The system frequently comes into a state where outgoing packets are
>>>>>> held somewhere.  The condition persists for seconds to minutes.  It
>>>>>> goes away by itself, but some of the packets are usually lost.  This
>>>>>> occurs on ath, FreeBSD 7.1-REL, no SMP, with kern.hz=100 (but not with
>>>>>> hz=1000).  Original mail with description can be found here:
>>>>>>
>>>>>> http://lists.freebsd.org/pipermail/freebsd-mobile/2009-February/011343.html
>>>>>>
>>>>>> I have done some more investigation, inserting debug prints in
>>>>>> ath_start (if_ath.c 1.177.2.2.2.1), one just after IFQ_DRV_DEQUEUE
>>>>>> (line 1576), another just before the call to ieee80211_pwrsave (line
>>>>>> 1614).
>>>>>>
>>>>>> Packets are dequeued, but ieee80211_pwrsave is called and nothing
>>>>>> happens.  Below is the output from "athdebug xmit" with these extra
>>>>>> two DPRINTF:s during the queue-up.  Then after a while packets are
>>>>>> sent again.
>>>>>>
>>>>>> Bengt
>>>>>>
>>>>>>             
>>>>> <...debug output removed...>
>>>>>
>>>>> Did you try RELENG_7? ap mode power save was fixed post 7.1 release.
>>>>>         
>>>> I can do that, but I am not using ap mode.  Will it still be useful?
>>>>       
>>> Hmm, I see no difference in ath between 7.1-REL and RELENG_7 (besides
>>> CVS ID strings)???  Are you meaning HEAD?  If so, can I just drop in
>>> src/sys/dev/ath from HEAD in 7.1R?
>>>     
>>
>> You are meaning sys/net80211, right?  I dropped the RELENG_7 version
>> of that into my 7.1-REL tree:
>>
>> # ident /boot/kernel/kernel | grep ieee80211_power
>>      $FreeBSD: src/sys/net80211/ieee80211_power.c,v 1.2.2.1 2009/01/26 20:24:04 dwhite Exp $
>>
>> but there is no difference.  ifconfig shows that powersavemode is off,
>> and it can't be turned on either.  Perhaps normal?
>>   
>
> Yes, there is no sta mode power save support for ath (or any other
> driver that depends on net80211 for doing it).
>
>> # ifconfig -v ath0
>> ath0: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 1500
>>         ether 00:05:4e:4e:1f:c7
>>         inet 193.10.66.253 netmask 0xfffffc00 broadcast 193.10.67.255
>>         media: IEEE 802.11 Wireless Ethernet autoselect (OFDM/36Mbps)
>>         status: associated
>>         ssid SICS channel 1 (2412 Mhz 11g) bssid 00:13:1a:47:7a:33
>>         authmode OPEN privacy OFF deftxkey UNDEF powersavemode OFF
>>         powersavesleep 100 txpower 31.5 txpowmax 17.0 rtsthreshold 2346
>>         fragthreshold 2346 bmiss 7 scanvalid 60 bgscan bgscanintvl 300
>>         bgscanidle 250 roam:rssi11a 7 roam:rate11a 12 roam:rssi11b 7
>>         roam:rate11b 1 roam:rssi11g 7 roam:rate11g 5 -pureg protmode CTS -ht
>>         -htcompat -ampdu ampdulimit 8k ampdudensity - -amsdu -shortgi
>>         htprotmode RTSCTS -puren -wme burst -ff -dturbo roaming AUTO
>>         bintval 100
>>
>> # ifconfig ath0 powersave
>> ifconfig: SIOCS80211: Invalid argument
>>
>> OK, now what?  I turned on "wlandebug power+state" which revealed this
>> during packet queueup.  There is one second between each frame (ping
>> packets):
>>
>> ath0: [00:13:1a:47:7a:33] sta power save mode on
>> ath0: [00:13:1a:47:7a:33] save frame with age 40, 1 now queued
>> ath0: [00:13:1a:47:7a:33] save frame with age 0, 2 now queued
>> ath0: [00:13:1a:47:7a:33] save frame with age 0, 3 now queued
>> ath0: [00:13:1a:47:7a:33] save frame with age 0, 4 now queued
>> ath0: [00:13:1a:47:7a:33] save frame with age 0, 5 now queued
>> ath0: [00:13:1a:47:7a:33] save frame with age 0, 6 now queued
>> ath0: [00:13:1a:47:7a:33] save frame with age 0, 7 now queued
>> ath0: [00:13:1a:47:7a:33] save frame with age 0, 8 now queued
>> ath0: [00:13:1a:47:7a:33] save frame with age 0, 9 now queued
>> ath0: [00:13:1a:47:7a:33] save frame with age 0, 10 now queued
>> ath0: [00:13:1a:47:7a:33] save frame with age 0, 11 now queued
>> ath0: [00:13:1a:47:7a:33] save frame with age 0, 12 now queued
>> ath0: [00:13:1a:47:7a:33] save frame with age 0, 13 now queued
>> ath0: [00:13:1a:47:7a:33] save frame with age 0, 14 now queued
>> ath0: [00:13:1a:47:7a:33] save frame with age 0, 15 now queued
>> ath0: [00:13:1a:47:7a:33] save frame with age 0, 16 now queued
>> ath0: [00:13:1a:47:7a:33] save frame with age 0, 17 now queued
>> ath0: [00:13:1a:47:7a:33] save frame with age 0, 18 now queued
>> ath0: [00:13:1a:47:7a:33] save frame with age 0, 19 now queued
>> ath0: [00:13:1a:47:7a:33] save frame with age 0, 20 now queued
>> ath0: [00:13:1a:47:7a:33] save frame with age 0, 21 now queued
>> ath0: [00:13:1a:47:7a:33] save frame with age 0, 22 now queued
>> ath0: [00:13:1a:47:7a:33] save frame with age 0, 23 now queued
>> ath0: [00:13:1a:47:7a:33] save frame with age 0, 24 now queued
>> ath0: [00:13:1a:47:7a:33] save frame with age 0, 25 now queued
>> ath0: [00:13:1a:47:7a:33] save frame with age 0, 26 now queued
>> ath0: [00:13:1a:47:7a:33] save frame with age 0, 27 now queued
>> ath0: [00:13:1a:47:7a:33] save frame with age 0, 28 now queued
>> ath0: [00:13:1a:47:7a:33] save frame with age 0, 29 now queued
>> ath0: [00:13:1a:47:7a:33] save frame with age 0, 30 now queued
>> ath0: [00:13:1a:47:7a:33] save frame with age 0, 31 now queued
>> ath0: [00:13:1a:47:7a:33] save frame with age 0, 32 now queued
>> ath0: [00:13:1a:47:7a:33] sta power save mode off
>> ath0: [00:13:1a:47:7a:33] flush ps queue, 32 packets queued
>>
>> After reading some code, trying with "wlanstats scan", both at hz=100
>> and 1000, I discovered that while it is scanning, it uses the power
>> save logic to hold packets.  But something goes wrong when hz is too
>> low.
>>   
>
> The ap is told the sta is in power save while off channel but scanning
> should return to the bss channel often to collect frames the ap might
> have buffered for it. Also any bg scan should be canceled if there are
> outbound frames; it appears from the above this is not happening.
>
>> Below is the printout of the log for a full scan with "wlanstats
>> scan+power+state".  It takes several minutes because it halts after
>> several "scan_next: stopped".  So, the scanning is the culprit.  I bet
>> that there is a race condition in the scanning logic!
>>
>> One thing to note is that callout_reset is called with ticks=0 in
>> several places.  That will be interpreted as 1, that is, the callout
>> won't be called immediately, but at the next clock tick.
>>
>> Bengt
>>
>> ath0: ieee80211_bg_scan: active scan, ticks 84796 duration 15
>> ath0: [00:13:1a:47:7a:33] sta power save mode on
>> ath0: scan_next: chan   1g ->   1g [active, dwell min 2 max 15]
>> ath0: ieee80211_add_scan: chan   1g min dwell met (84799 > 84799)
>> ath0: scan_next: chan   1g ->   6g [active, dwell min 2 max 12]
>> ath0: ieee80211_add_scan: chan   6g min dwell met (84802 > 84802)
>> ath0: scan_next: chan   6g ->  11g [active, dwell min 2 max 9]
>> ath0: ieee80211_add_scan: chan  11g min dwell met (84807 > 84805)
>> ath0: scan_next: chan  11g ->   7g [active, dwell min 2 max 4]
>> ath0: scan_next: stopped, [ticks 84812, dwell min 2 scanend 84812]
>> ath0: ieee80211_bg_scan: active scan, ticks 87315 duration 15
>> ath0: scan_next: chan   1g ->  13g [passive, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 87330, dwell min 2 scanend 87330]
>> ath0: ieee80211_bg_scan: active scan, ticks 87335 duration 15
>> ath0: scan_next: chan   1g ->  52a [passive, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 87350, dwell min 2 scanend 87350]
>> ath0: ieee80211_bg_scan: active scan, ticks 87356 duration 15
>> ath0: scan_next: chan   1g ->  56a [passive, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 87371, dwell min 2 scanend 87371]
>> ath0: ieee80211_bg_scan: active scan, ticks 87377 duration 15
>> ath0: scan_next: chan   1g ->  60a [passive, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 87392, dwell min 2 scanend 87392]
>> ath0: ieee80211_bg_scan: active scan, ticks 87397 duration 15
>> ath0: scan_next: chan   1g ->  64a [passive, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 87412, dwell min 2 scanend 87412]
>> ath0: ieee80211_bg_scan: active scan, ticks 87478 duration 15
>> ath0: scan_next: chan   1g ->  36a [passive, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 87493, dwell min 2 scanend 87493]
>> ath0: ieee80211_bg_scan: active scan, ticks 87499 duration 15
>> ath0: scan_next: chan   1g ->  40a [passive, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 87514, dwell min 2 scanend 87514]
>> ath0: ieee80211_bg_scan: active scan, ticks 87519 duration 15
>> ath0: scan_next: chan   1g ->  44a [passive, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 87534, dwell min 2 scanend 87534]
>> ath0: ieee80211_bg_scan: active scan, ticks 87540 duration 15
>> ath0: scan_next: chan   1g ->  48a [passive, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 87555, dwell min 2 scanend 87555]
>> ath0: ieee80211_bg_scan: active scan, ticks 87560 duration 15
>> ath0: scan_next: chan   1g ->  34a [passive, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 87575, dwell min 2 scanend 87575]
>> ath0: ieee80211_bg_scan: active scan, ticks 87581 duration 15
>> ath0: scan_next: chan   1g ->  38a [passive, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 87596, dwell min 2 scanend 87596]
>> ath0: ieee80211_bg_scan: active scan, ticks 87601 duration 15
>> ath0: scan_next: chan   1g ->  42a [passive, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 87616, dwell min 2 scanend 87616]
>> ath0: ieee80211_bg_scan: active scan, ticks 87622 duration 15
>> ath0: scan_next: chan   1g ->  46a [passive, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 87637, dwell min 2 scanend 87637]
>> ath0: ieee80211_bg_scan: active scan, ticks 87642 duration 15
>> ath0: scan_next: chan   1g ->   2g [active, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 87657, dwell min 2 scanend 87657]
>> ath0: ieee80211_bg_scan: active scan, ticks 90151 duration 15
>> ath0: scan_next: chan   1g ->   3g [active, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 90166, dwell min 2 scanend 90166]
>> ath0: ieee80211_bg_scan: active scan, ticks 92660 duration 15
>> ath0: scan_next: chan   1g ->   4g [active, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 92675, dwell min 2 scanend 92675]
>> ath0: beacon miss
>> ath0: ieee80211_bg_scan: active scan, ticks 95271 duration 15
>> ath0: scan_next: chan   1g ->   5g [active, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 95286, dwell min 2 scanend 95286]
>> ath0: beacon miss
>> ath0: ieee80211_bg_scan: active scan, ticks 99715 duration 15
>> ath0: scan_next: chan   1g ->   8g [active, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 99730, dwell min 2 scanend 99730]
>> ath0: ieee80211_bg_scan: active scan, ticks 102224 duration 15
>> ath0: scan_next: chan   1g ->   9g [active, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 102239, dwell min 2 scanend 102239]
>> ath0: ieee80211_bg_scan: active scan, ticks 104732 duration 15
>> ath0: scan_next: chan   1g ->  10g [active, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 104747, dwell min 2 scanend 104747]
>> ath0: ieee80211_bg_scan: active scan, ticks 107241 duration 15
>> ath0: scan_next: chan   1g ->  12g [passive, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 107256, dwell min 2 scanend 107256]
>> ath0: ieee80211_bg_scan: active scan, ticks 107263 duration 15
>> ath0: scan_next: chan   1g ->  14b [passive, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 107278, dwell min 2 scanend 107278]
>> ath0: ieee80211_bg_scan: active scan, ticks 107282 duration 15
>> ath0: scan_next: chan   1g -> 149a [passive, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 107297, dwell min 2 scanend 107297]
>> ath0: ieee80211_bg_scan: active scan, ticks 107303 duration 15
>> ath0: scan_next: chan   1g -> 153a [passive, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 107318, dwell min 2 scanend 107318]
>> ath0: ieee80211_bg_scan: active scan, ticks 107323 duration 15
>> ath0: scan_next: chan   1g -> 157a [passive, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 107338, dwell min 2 scanend 107338]
>> ath0: ieee80211_bg_scan: active scan, ticks 107344 duration 15
>> ath0: scan_next: chan   1g -> 161a [passive, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 107359, dwell min 2 scanend 107359]
>> ath0: ieee80211_bg_scan: active scan, ticks 107366 duration 15
>> ath0: scan_next: chan   1g -> 165a [passive, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 107381, dwell min 2 scanend 107381]
>> ath0: ieee80211_bg_scan: active scan, ticks 107385 duration 15
>> ath0: scan_next: chan   1g -> 100a [passive, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 107400, dwell min 2 scanend 107400]
>> ath0: ieee80211_bg_scan: active scan, ticks 107405 duration 15
>> ath0: scan_next: chan   1g -> 104a [passive, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 107420, dwell min 2 scanend 107420]
>> ath0: ieee80211_bg_scan: active scan, ticks 107426 duration 15
>> ath0: scan_next: chan   1g -> 108a [passive, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 107441, dwell min 2 scanend 107441]
>> ath0: ieee80211_bg_scan: active scan, ticks 107446 duration 15
>> ath0: scan_next: chan   1g -> 112a [passive, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 107461, dwell min 2 scanend 107461]
>> ath0: ieee80211_bg_scan: active scan, ticks 107467 duration 15
>> ath0: scan_next: chan   1g -> 116a [passive, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 107482, dwell min 2 scanend 107482]
>> ath0: ieee80211_bg_scan: active scan, ticks 107487 duration 15
>> ath0: scan_next: chan   1g -> 120a [passive, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 107502, dwell min 2 scanend 107502]
>> ath0: ieee80211_bg_scan: active scan, ticks 107507 duration 15
>> ath0: scan_next: chan   1g -> 124a [passive, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 107522, dwell min 2 scanend 107522]
>> ath0: ieee80211_bg_scan: active scan, ticks 107528 duration 15
>> ath0: scan_next: chan   1g -> 128a [passive, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 107543, dwell min 2 scanend 107543]
>> ath0: ieee80211_bg_scan: active scan, ticks 107548 duration 15
>> ath0: scan_next: chan   1g -> 132a [passive, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 107563, dwell min 2 scanend 107563]
>> ath0: ieee80211_bg_scan: active scan, ticks 107569 duration 15
>> ath0: scan_next: chan   1g -> 136a [passive, dwell min 2 max 14]
>> ath0: scan_next: stopped, [ticks 107584, dwell min 2 scanend 107584]
>> ath0: ieee80211_bg_scan: active scan, ticks 107589 duration 15
>> ath0: scan_next: chan   1g -> 140a [passive, dwell min 2 max 14]
>> ath0: scan_next: done, [ticks 107604, dwell min 2 scanend 107604]
>> ath0: [00:13:1a:47:7a:33] sta power save mode off
>> ath0: notify scan done
>>
>>   
> The above looks wrong; the bg scan should leave the bss channel
> briefly then return to check for frames. Instead it appears it's never
> returning. Also any outbound packets should cause the bg scan to be
> canceled (look for ieee80211_cancel_scan in ath_start).

I think I am getting a bit closer to the real problem.  Check out this
sequence (run with hz=1000 NB!):

ath0: scan_next: stopped, [ticks 14980883, dwell min 20 scanend 14980873]
ath_start: dequeue packet 0xc38ef000
ath_start: power save, packet=0xc38ef000
ath0: [00:13:1a:47:7a:33] save frame with age 40, 1 now queued
ath_start: dequeue packet 0x0
ath0: ieee80211_bg_scan: active scan, ticks 14981030 duration 150
ath0: scan_next: chan   1g ->  13g [passive, dwell min 20 max 149]
ath0: scan_next: stopped, [ticks 14981190, dwell min 20 scanend 14981180]
ath0: ieee80211_bg_scan: active scan, ticks 14981236 duration 150
ath0: scan_next: chan   1g ->  52a [passive, dwell min 20 max 149]
ath0: scan_next: stopped, [ticks 14981396, dwell min 20 scanend 14981386]
ath0: ieee80211_bg_scan: active scan, ticks 14981441 duration 150
ath0: scan_next: chan   1g ->  56a [passive, dwell min 20 max 149]
ath0: scan_next: stopped, [ticks 14981601, dwell min 20 scanend 14981591]
ath0: ieee80211_bg_scan: active scan, ticks 14981645 duration 150
ath0: scan_next: chan   1g ->  60a [passive, dwell min 20 max 149]
ath0: scan_next: stopped, [ticks 14981805, dwell min 20 scanend 14981795]
ath0: ieee80211_bg_scan: active scan, ticks 14981850 duration 150
ath0: scan_next: chan   1g ->  64a [passive, dwell min 20 max 149]
ath0: scan_next: stopped, [ticks 14982010, dwell min 20 scanend 14982000]
ath0: ieee80211_bg_scan: active scan, ticks 14982059 duration 150
ath0: scan_next: chan   1g ->  36a [passive, dwell min 20 max 149]
ath0: scan_next: stopped, [ticks 14982219, dwell min 20 scanend 14982209]
ath0: ieee80211_bg_scan: active scan, ticks 14982259 duration 150
ath0: scan_next: chan   1g ->  40a [passive, dwell min 20 max 149]
ath0: scan_next: stopped, [ticks 14982419, dwell min 20 scanend 14982409]
ath0: ieee80211_bg_scan: active scan, ticks 14982467 duration 150
ath0: scan_next: chan   1g ->  44a [passive, dwell min 20 max 149]
ath0: scan_next: stopped, [ticks 14982627, dwell min 20 scanend 14982617]
ath0: ieee80211_bg_scan: active scan, ticks 14982669 duration 150
ath0: scan_next: chan   1g ->  48a [passive, dwell min 20 max 149]
ath0: scan_next: stopped, [ticks 14982829, dwell min 20 scanend 14982819]
ath0: ieee80211_bg_scan: active scan, ticks 14982874 duration 150
ath0: scan_next: chan   1g ->  34a [passive, dwell min 20 max 149]
ath0: scan_next: stopped, [ticks 14983034, dwell min 20 scanend 14983024]
ath0: ieee80211_bg_scan: active scan, ticks 14983079 duration 150
ath0: scan_next: chan   1g ->  38a [passive, dwell min 20 max 149]
ath0: scan_next: stopped, [ticks 14983239, dwell min 20 scanend 14983229]
ath0: ieee80211_bg_scan: active scan, ticks 14983283 duration 150
ath0: scan_next: chan   1g ->  42a [passive, dwell min 20 max 149]
ath0: scan_next: stopped, [ticks 14983443, dwell min 20 scanend 14983433]
ath0: ieee80211_bg_scan: active scan, ticks 14983488 duration 150
ath0: scan_next: chan   1g ->  46a [passive, dwell min 20 max 149]
ath_start: dequeue packet 0xc37d4d00
ath0: ieee80211_cancel_scan: cancel active scan
ath_start: power save, packet=0xc37d4d00
ath0: [00:13:1a:47:7a:33] save frame with age 0, 2 now queued
ath_start: dequeue packet 0x0
ath0: scan_next: done, [ticks 14983598, dwell min 20 scanend 14983638]
ath0: [00:13:1a:47:7a:33] sta power save mode off

Now, when the first packet arrives (top of the log), IEEE80211_F_SCAN
is NOT set.  scan_next just cleared the flag (line 816 in
ieee80211_scan.c), but because it is not done scanning, power save is
still on.  So, ath_start does not call ieee80211_cancel_scan, but
rather just queues the packet.

When the next packet arrives (bottom of the log), it happens to be in
the middle of a scan period, so IEEE80211_F_SCAN is set, and ath_start
calls ieee80211_cancel_scan, terminating the scan (well after a little
while at least).

Question: after scan_next is run, reporting "stopped", what makes
ieee80211_bg_scan to be called the next time?  In the time between
these two events, IEEE80211_F_SCAN is not set, but power save is "on",
making all packets queue up.  This window apparently gets larger the
lower hz you run on.

IMO, it would be better that ieee80211_cancel_scan immediately
terminated scanning and did callout_drain on scan_next.  But that does
not close the window when IEEE80211_F_SCAN is not set.  So either the
scanning logic needs to change, or the test in ath_start.

Bengt



Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?uh7fxia8n5q.fsf>