Date: Wed, 18 Feb 2009 10:27:37 -0800 From: Sam Leffler <sam@freebsd.org> To: Bengt Ahlgren <bengta@sics.se> Cc: freebsd-mobile@freebsd.org Subject: Re: Problems with ath at kern.hz=100 Message-ID: <499C5319.10306@freebsd.org> In-Reply-To: <uh7skmby5da.fsf@P142.sics.se> 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>
next in thread | previous in thread | raw e-mail | index | archive | help
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). Sam
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?499C5319.10306>