Date: Wed, 18 Feb 2009 19:20:01 +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: <uh7skmby5da.fsf@P142.sics.se> In-Reply-To: <uh7eixvlvwo.fsf@P142.sics.se> (Bengt Ahlgren's message of "Wed\, 18 Feb 2009 14\:25\:11 %2B0100") 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>
next in thread | previous in thread | raw e-mail | index | archive | help
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? # 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. 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
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?uh7skmby5da.fsf>