Bug 192950 - [iwn] Centrino Advanced-N 6205 slow on 11n, better on 11g
Summary: [iwn] Centrino Advanced-N 6205 slow on 11n, better on 11g
Status: Closed FIXED
Alias: None
Product: Base System
Classification: Unclassified
Component: wireless (show other bugs)
Version: CURRENT
Hardware: amd64 Any
: --- Affects Only Me
Assignee: freebsd-wireless (Nobody)
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2014-08-23 19:31 UTC by Johannes M Dieterich
Modified: 2014-09-10 21:45 UTC (History)
3 users (show)

See Also:


Attachments
wifi debug 1 (568.52 KB, text/plain)
2014-08-24 22:54 UTC, Hiren Panchasara
no flags Details
wifi debug 2 (654.89 KB, text/plain)
2014-08-24 22:55 UTC, Hiren Panchasara
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Johannes M Dieterich freebsd_committer freebsd_triage 2014-08-23 19:31:34 UTC
Above mentioned WLAN NIC only manages a maximum upload of 900 kB/s on an 11n network on the 2.4 GHz band in my tests. By recommendation of adrian@, removing ht and falling back to 11g mode improves the upload speed to 1.9 MB/s and download to 2.9 MB/s.

Please see the thread on freebsd-wireless at http://lists.freebsd.org/pipermail/freebsd-wireless/2014-August/004907.html for a more detailed description of the problem.
Comment 1 Adrian Chadd freebsd_committer freebsd_triage 2014-08-23 19:49:26 UTC
Ok, I'll start adding some more debugging to iwn(4) in HEAD and let you know when I'm ready to debug this.

If I forget / move onto something else, here's what I'm going to look at (in order):

* RXON config - antennas, MIMO, etc;
* TX config - link quality setup, PLCP antenna config;

There's other mismatches I've found in the way the antennas are setup and .. well, it's still a mess. Sigh.
Comment 2 Hiren Panchasara freebsd_committer freebsd_triage 2014-08-24 07:43:50 UTC
(In reply to Adrian Chadd from comment #1)
> Ok, I'll start adding some more debugging to iwn(4) in HEAD and let you know
> when I'm ready to debug this.

I also have 6205:
iwn0@pci0:3:0:0:        class=0x028000 card=0x13118086 chip=0x00858086 rev=0x34 hdr=0x00
    vendor     = 'Intel Corporation'
    device     = 'Centrino Advanced-N 6205 [Taylor Peak]'
    class      = network

> 
> If I forget / move onto something else, here's what I'm going to look at (in
> order):
> 
> * RXON config - antennas, MIMO, etc;
> * TX config - link quality setup, PLCP antenna config;

If possible, can you please share how are you going to debug these?

> 
> There's other mismatches I've found in the way the antennas are setup and ..
> well, it's still a mess. Sigh.

I'd like to follow how you debug this and would like to document it.

Thanks a lot in advance.
Comment 3 Hiren Panchasara freebsd_committer freebsd_triage 2014-08-24 10:01:07 UTC
I did a simple iperf test where I ran client on wifi laptop and server on a machine connected to lan in my network. I am seeing 3mbps/sec average.

% ifconfig wlan0
wlan0: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 1500
        ether 08:11:96:f9:b2:ec
        inet 192.168.1.116 netmask 0xffffff00 broadcast 192.168.1.255 
        nd6 options=29<PERFORMNUD,IFDISABLED,AUTO_LINKLOCAL>
        media: IEEE 802.11 Wireless Ethernet MCS mode 11ng
        status: associated
        ssid Point100 channel 1 (2412 MHz 11g ht/20) bssid dc:9f:db:6a:3e:9e
        country US authmode WPA1+WPA2/802.11i privacy ON deftxkey UNDEF
        TKIP 2:128-bit TKIP 3:128-bit txpower 11 bmiss 10 scanvalid 60 bgscan
        bgscanintvl 300 bgscanidle 250 roam:rssi 7 roam:rate 64 protmode CTS
        ampdulimit 64k ampdudensity 8 -amsdutx amsdurx shortgi wme
        roaming MANUAL
Comment 4 Hiren Panchasara freebsd_committer freebsd_triage 2014-08-24 21:53:50 UTC
(In reply to Hiren Panchasara from comment #3)
> I did a simple iperf test where I ran client on wifi laptop and server on a
> machine connected to lan in my network. I am seeing 3mbps/sec average.
> 

Okay, experiment above was wifi(laptop) to ethernet(freebsd router) on the same n/w.

When I installed iperf on my android and did the same experiment, I am barely getting 500kbps. 

 % ifconfig wlan0 list sta 
ADDR               AID CHAN RATE RSSI IDLE  TXSEQ  RXSEQ CAPS FLAG   
dc:9f:db:6a:3e:9e    3    1   7M 25.0    0  15443   6288 EPS  AQEHTRS RSN WME HTCAP ATH
Comment 5 Adrian Chadd freebsd_committer freebsd_triage 2014-08-24 22:30:12 UTC
Hiren - oh you went iperf from STA -> AP -> STA? That's going to suck for lots of reasons.

You should get more than 3mbit/sec iperfing STA->AP->ethernet.

Do this:

* add IWN_DEBUG and IEEE80211_DEBUG to kernel, recompile
* sysctl dev.iwn.0.debug=1
* wlandebug +rate
* log some stuff
* post it here



-a
Comment 6 Hiren Panchasara freebsd_committer freebsd_triage 2014-08-24 22:54:49 UTC
Created attachment 146235 [details]
wifi debug 1
Comment 7 Hiren Panchasara freebsd_committer freebsd_triage 2014-08-24 22:55:22 UTC
Created attachment 146236 [details]
wifi debug 2
Comment 8 Hiren Panchasara freebsd_committer freebsd_triage 2014-08-24 22:57:27 UTC
(In reply to Adrian Chadd from comment #5)
> Hiren - oh you went iperf from STA -> AP -> STA? That's going to suck for
> lots of reasons.
> 
> You should get more than 3mbit/sec iperfing STA->AP->ethernet.
> 
> Do this:
> 
> * add IWN_DEBUG and IEEE80211_DEBUG to kernel, recompile
> * sysctl dev.iwn.0.debug=1
> * wlandebug +rate
> * log some stuff
> * post it here

On my freebsd router on lan:
hirenp@entry:~ % iperf -s -u -i1

and on the laptop on wifi:
flymockour-l7% iperf -c 192.168.1.1 -u -i1 -l1300 -b110m -t10

I see about 3Mbps.

Logs attached.
Comment 9 Adrian Chadd freebsd_committer freebsd_triage 2014-08-24 23:02:07 UTC
(In reply to Hiren Panchasara from comment #6)
> Created attachment 146235 [details]
> wifi debug 1

Hm, so it drops all the way to MCS0 and then never tries a higher rate. I wonder why.
Comment 10 Hiren Panchasara freebsd_committer freebsd_triage 2014-08-24 23:07:23 UTC
(In reply to Adrian Chadd from comment #9)
> (In reply to Hiren Panchasara from comment #6)
> > Created attachment 146235 [details]
> > wifi debug 1
> 
> Hm, so it drops all the way to MCS0 and then never tries a higher rate. I
> wonder why.

Are you talking about following portion of logs?

Aug 24 15:43:42 flymockour-l7 kernel: iwn_set_link_quality: 1stream antenna=0x01, 2stream antenna=0x03, ntxstreams=2
Aug 24 15:43:42 flymockour-l7 kernel: iwn_set_link_quality: i=0, txrate=7, rate=0x87
Aug 24 15:43:42 flymockour-l7 kernel: iwn_set_link_quality: i=1, txrate=6, rate=0x86
Aug 24 15:43:42 flymockour-l7 kernel: iwn_set_link_quality: i=2, txrate=5, rate=0x85
Aug 24 15:43:42 flymockour-l7 kernel: iwn_set_link_quality: i=3, txrate=4, rate=0x84
Aug 24 15:43:42 flymockour-l7 kernel: iwn_set_link_quality: i=4, txrate=3, rate=0x83
Aug 24 15:43:42 flymockour-l7 kernel: iwn_set_link_quality: i=5, txrate=2, rate=0x82
Aug 24 15:43:42 flymockour-l7 kernel: iwn_set_link_quality: i=6, txrate=1, rate=0x81
Aug 24 15:43:42 flymockour-l7 kernel: iwn_set_link_quality: i=7, txrate=0, rate=0x80
Aug 24 15:43:42 flymockour-l7 kernel: iwn_set_link_quality: i=8, txrate=0, rate=0x80
Aug 24 15:43:42 flymockour-l7 kernel: iwn_set_link_quality: i=9, txrate=0, rate=0x80
Aug 24 15:43:42 flymockour-l7 kernel: iwn_set_link_quality: i=10, txrate=0, rate=0x80
Aug 24 15:43:42 flymockour-l7 kernel: iwn_set_link_quality: i=11, txrate=0, rate=0x80
Aug 24 15:43:42 flymockour-l7 kernel: iwn_set_link_quality: i=12, txrate=0, rate=0x80
Aug 24 15:43:42 flymockour-l7 kernel: iwn_set_link_quality: i=13, txrate=0, rate=0x80
Aug 24 15:43:42 flymockour-l7 kernel: iwn_set_link_quality: i=14, txrate=0, rate=0x80
Aug 24 15:43:42 flymockour-l7 kernel: iwn_set_link_quality: i=15, txrate=0, rate=0x80
Comment 11 Hiren Panchasara freebsd_committer freebsd_triage 2014-08-24 23:24:23 UTC
where exactly should I be looking for to know the rate? 

I see following:

Aug 24 15:43:44 flymockour-l7 kernel: iwn_tx_data: qid 0 idx 2 len 56 nsegs 2 rate 0083 plcp 0x00004103
Aug 24 15:43:44 flymockour-l7 kernel: iwn5000_tx_done: qid 0 idx 2 retries 6 nkill 0 rate 80004103 duration 1280 status 201

So, is 80004103 the rate its selecting to send?
Comment 12 Hiren Panchasara freebsd_committer freebsd_triage 2014-08-25 00:00:42 UTC
Tried to follow the rabbit-hole to see where rate is coming from:

Index: if_iwn.c
===================================================================
--- if_iwn.c    (revision 269621)
+++ if_iwn.c    (working copy)
@@ -4281,6 +4281,8 @@
                rate = ni->ni_txrate;
        }
 
+       DPRINTF(sc, IWN_DEBUG_XMIT, "tx rate is: %d in %s \n", rate, __func__);
+
        /* Encrypt the frame if need be. */
        if (wh->i_fc[1] & IEEE80211_FC1_PROTECTED) {
                /* Retrieve key for TX. */

via this codepath:

ieee80211_set_basic_htrates() 
ieee80211_add_htinfo_body()
amrr_rate()
.ir_rate
ieee80211_ratectl_rate()
iwn_tx_data()

In the logs, I get:

Aug 24 16:59:35 flymockour-l7 kernel: tx rate is: 128 in iwn_tx_data

Which I think is:
807 #define IEEE80211_RATE_BASIC            0x80
Comment 13 Hiren Panchasara freebsd_committer freebsd_triage 2014-08-25 00:04:57 UTC
Adrian,

I still couldn't find out where the "step up" in rates should happen and how it should look like. i.e. is there an array of speeds it should step up to?
Comment 14 Adrian Chadd freebsd_committer freebsd_triage 2014-08-25 00:16:12 UTC
Hi,

So the tx path grabs the rate from the net80211 ratectl code.

The link_quality table controls which rates are tried in which order, and I think it's _after_ the rate that is specified by the rate control code - but again, I can't be sure, because I haven't really sat down and figured out what the rate code does.

Ie, if you do this:

* link quality table has MCS0-7 in it;
* you set a rate of MCS8 in the TX frame, btu also say "do link quality retries"

then what happens.

The default rate module for iwn is amrr. It's in net80211. That's what should be outputting debugging when you enable wlandebug +rate.


-a
Comment 15 Adrian Chadd freebsd_committer freebsd_triage 2014-08-25 07:16:45 UTC
The problem seems to be a lack of correct feedback to the AMRR rate control code. It doesn't get informed of the correct number of transmissions, failures and retries, leading to it believing the correct thing to do is continue bumping up the rate.

If you enable IEEE80211_DEBUG in your kernel config, rebuild, then enable debugging via 'wlandebug +rate', you'll likely see the MCS rate continue climbing towards MCS7 or MCS15. This only works in a very clean environment - definitely not with 2GHz.

If you compile with IWN_DEBUG, then sysctl dev.iwn.0.debug=0x1, you'll see information about transmissions and transmit completions. You'll likely see the TX PLCP climb to MCS rate 0xf (MCS15) - with the retry and duration counts will be very high.

I'm not sure if there's a quick fix. I think I'm going to have to add some 11n awareness to the ratectl API (ie, so we can tell it how many retries, how many successes, how many failures, the transmit duration) and then ensure it really is being called upon completion of each sent frame - aggregate or otherwise.

As for the driver - there seems to be multiple places where frame transmisson completes and the rate control code gets called. I'll have to audit these to ensure it's, well, "right".
Comment 16 Adrian Chadd freebsd_committer freebsd_triage 2014-09-07 01:40:04 UTC
r270738 fixed some antenna stuff.
r270742 fixed AMPDU completion notification to AMRR.

This _should_ be better (and it is for me!) but Hiren still reports oddness.
Comment 17 Adrian Chadd freebsd_committer freebsd_triage 2014-09-07 01:40:19 UTC
Also, please test out with the latest -HEAD and see if it behaves better for you.
Comment 18 Hiren Panchasara freebsd_committer freebsd_triage 2014-09-07 01:43:30 UTC
Noticing only 400kbps on ssh from laptop to desktop on wifi.

root@flymockour-l7:/home/hirenp/head/sys/net80211 # sysctl dev.iwn.0.debug=0xff
dev.iwn.0.debug: 0 -> 255
root@flymockour-l7:/home/hirenp/head/sys/net80211 # wlandebug +rate
net.wlan.0.debug: 0x0 => 0x20<rate>

I see the rate is stuck at 0x0080.

Here are logs to send packet no: 1614 to 1616 - just for example.

I've added following printf to see if on successful transfer, ratectl code is getting trigger to ++ the rate. It seems to be firing but not doing the right thing.

Index: if_iwn.c
===================================================================
--- if_iwn.c    (revision 270821)
+++ if_iwn.c    (working copy)
@@ -3500,10 +3500,12 @@
         */
        if (status & IWN_TX_FAIL) {
                ifp->if_oerrors++;
+       DPRINTF(sc, IWN_DEBUG_XMIT, "->%s Not updating rate control if_opackets: %lu\n", __func__, ifp->if_opackets);
                ieee80211_ratectl_tx_complete(vap, ni,
                    IEEE80211_RATECTL_TX_FAILURE, &ackfailcnt, NULL);
        } else {
                ifp->if_opackets++;
+       DPRINTF(sc, IWN_DEBUG_XMIT, "->%s updating rate control if_opackets: %lu\n", __func__, ifp->if_opackets);
                ieee80211_ratectl_tx_complete(vap, ni,
                    IEEE80211_RATECTL_TX_SUCCESS, &ackfailcnt, NULL);
        }

Logs:

64190 Sep  6 18:27:57 flymockour-l7 kernel: ->iwn_tx_done updating rate control if_opackets: 1613
64191 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=63; qid 6 idx 154 flags 0 type 192(RX_PHY) len 68
64192 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=0; qid 6 idx 155 flags 0 type 193(MPDU_RX_DONE) len 168
64193 Sep  6 18:27:57 flymockour-l7 kernel: iwn5000_get_rssi: agc 55 rssi 9766 11051 0 result -56
64194 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=1; qid 6 idx 156 flags 0 type 192(RX_PHY) len 68
64195 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=2; qid 6 idx 157 flags 0 type 193(MPDU_RX_DONE) len 336
64196 Sep  6 18:27:57 flymockour-l7 kernel: iwn5000_get_rssi: agc 29 rssi 4884 5399 0 result -50
64197 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=3; qid 6 idx 158 flags 0 type 157(BEACON_STATS) len 528
64198 Sep  6 18:27:57 flymockour-l7 kernel: iwn_check_rx_recovery: time delta: 102; cck=48, ofdm=2, ht=0, total=152, thresh=5100
64199 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=4; qid 9 idx 1 flags 0 type 168(IWN_CMD_SET_SENSITIVITY) len 4
64200 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=5; qid 6 idx 159 flags 0 type 192(RX_PHY) len 68
64201 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=6; qid 6 idx 160 flags 0 type 193(MPDU_RX_DONE) len 120
64202 Sep  6 18:27:57 flymockour-l7 kernel: iwn5000_get_rssi: agc 56 rssi 10023 11308 0 result -56
64203 Sep  6 18:27:57 flymockour-l7 kernel: iwn_start_locked: called
64204 Sep  6 18:27:57 flymockour-l7 kernel: iwn_tx_data: qid 0 idx 63 len 80 nsegs 2 flags 0x00100018 rate 0x0080 plcp 0x00004100
64205 Sep  6 18:27:57 flymockour-l7 kernel: iwn_start_locked: done
64206 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=7; qid 0 idx 63 flags 0 type 28(TX_DONE) len 44
64207 Sep  6 18:27:57 flymockour-l7 kernel: iwn5000_tx_done: qid 0 idx 63 retries 0 nkill 0 rate 80004100 duration 296 status 201
64208 Sep  6 18:27:57 flymockour-l7 kernel: ->iwn_tx_done updating rate control if_opackets: 1614
64209 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=8; qid 6 idx 172 flags 0 type 192(RX_PHY) len 68
64210 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=9; qid 6 idx 173 flags 0 type 193(MPDU_RX_DONE) len 336
64211 Sep  6 18:27:57 flymockour-l7 kernel: iwn5000_get_rssi: agc 28 rssi 4627 5399 0 result -49
64212 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=10; qid 6 idx 174 flags 0 type 157(BEACON_STATS) len 528
64213 Sep  6 18:27:57 flymockour-l7 kernel: iwn_check_rx_recovery: time delta: 102; cck=11, ofdm=0, ht=0, total=113, thresh=5100
64214 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=11; qid 6 idx 183 flags 0 type 192(RX_PHY) len 68
64215 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=12; qid 6 idx 184 flags 0 type 193(MPDU_RX_DONE) len 336
64216 Sep  6 18:27:57 flymockour-l7 kernel: iwn5000_get_rssi: agc 30 rssi 3858 5398 0 result -52
64217 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=13; qid 6 idx 185 flags 0 type 157(BEACON_STATS) len 528
64218 Sep  6 18:27:57 flymockour-l7 kernel: iwn_check_rx_recovery: time delta: 103; cck=36, ofdm=0, ht=0, total=139, thresh=5150
64219 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=14; qid 6 idx 188 flags 0 type 192(RX_PHY) len 68
64220 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=15; qid 6 idx 189 flags 0 type 193(MPDU_RX_DONE) len 120
64221 Sep  6 18:27:57 flymockour-l7 kernel: iwn5000_get_rssi: agc 55 rssi 9765 11051 0 result -56
64222 Sep  6 18:27:57 flymockour-l7 kernel: iwn_start_locked: called
64223 Sep  6 18:27:57 flymockour-l7 kernel: iwn_tx_data: qid 0 idx 64 len 86 nsegs 2 flags 0x00100018 rate 0x0080 plcp 0x00004100
64224 Sep  6 18:27:57 flymockour-l7 kernel: iwn_start_locked: done
64225 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=16; qid 0 idx 64 flags 0 type 28(TX_DONE) len 44
64226 Sep  6 18:27:57 flymockour-l7 kernel: iwn5000_tx_done: qid 0 idx 64 retries 0 nkill 0 rate 80004100 duration 304 status 201
64227 Sep  6 18:27:57 flymockour-l7 kernel: ->iwn_tx_done updating rate control if_opackets: 1615
64228 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=17; qid 6 idx 200 flags 0 type 192(RX_PHY) len 68
64229 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=18; qid 6 idx 201 flags 0 type 193(MPDU_RX_DONE) len 120
64230 Sep  6 18:27:57 flymockour-l7 kernel: iwn5000_get_rssi: agc 55 rssi 9766 11051 0 result -56
64231 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=19; qid 6 idx 206 flags 0 type 192(RX_PHY) len 68
64232 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=20; qid 6 idx 207 flags 0 type 193(MPDU_RX_DONE) len 336
64233 Sep  6 18:27:57 flymockour-l7 kernel: iwn5000_get_rssi: agc 29 rssi 4885 5656 0 result -49
64234 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=21; qid 6 idx 208 flags 0 type 157(BEACON_STATS) len 528
64235 Sep  6 18:27:57 flymockour-l7 kernel: iwn_check_rx_recovery: time delta: 102; cck=32, ofdm=1, ht=0, total=135, thresh=5100
64236 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=22; qid 6 idx 219 flags 0 type 192(RX_PHY) len 68
64237 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=23; qid 6 idx 220 flags 0 type 193(MPDU_RX_DONE) len 336
64238 Sep  6 18:27:57 flymockour-l7 kernel: iwn5000_get_rssi: agc 33 rssi 4884 6169 0 result -52
64239 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=24; qid 6 idx 221 flags 0 type 157(BEACON_STATS) len 528
64240 Sep  6 18:27:57 flymockour-l7 kernel: iwn_check_rx_recovery: time delta: 104; cck=50, ofdm=0, ht=0, total=154, thresh=5200
64241 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=25; qid 6 idx 222 flags 0 type 162(BEACON_MISSED) len 20
64242 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: beacons missed 0/0
64243 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=26; qid 6 idx 234 flags 0 type 192(RX_PHY) len 68
64244 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=27; qid 6 idx 235 flags 0 type 193(MPDU_RX_DONE) len 336
64245 Sep  6 18:27:57 flymockour-l7 kernel: iwn5000_get_rssi: agc 31 rssi 4114 5399 0 result -52
64246 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=28; qid 6 idx 236 flags 0 type 157(BEACON_STATS) len 528
64247 Sep  6 18:27:57 flymockour-l7 kernel: iwn_check_rx_recovery: time delta: 101; cck=16, ofdm=0, ht=0, total=117, thresh=5050
64248 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=29; qid 6 idx 244 flags 0 type 192(RX_PHY) len 68
64249 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=30; qid 6 idx 245 flags 0 type 193(MPDU_RX_DONE) len 336
64250 Sep  6 18:27:57 flymockour-l7 kernel: iwn5000_get_rssi: agc 31 rssi 3602 5399 0 result -52
64251 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=31; qid 6 idx 246 flags 0 type 157(BEACON_STATS) len 528
64252 Sep  6 18:27:57 flymockour-l7 kernel: iwn_check_rx_recovery: time delta: 102; cck=56, ofdm=0, ht=0, total=158, thresh=5100
64253 Sep  6 18:27:57 flymockour-l7 kernel: iwn_check_rx_recovery: PLCP error threshold raw (56) comparison (5600) over limit (5100); retune!
64254 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=32; qid 6 idx 255 flags 0 type 192(RX_PHY) len 68
64255 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=33; qid 7 idx 0 flags 0 type 193(MPDU_RX_DONE) len 336
64256 Sep  6 18:27:57 flymockour-l7 kernel: iwn5000_get_rssi: agc 31 rssi 3858 5655 0 result -52
64257 Sep  6 18:27:57 flymockour-l7 kernel: iwn_notif_intr: cur=34; qid 7 idx 1 flags 0 type 157(BEACON_STATS) len 528
64258 Sep  6 18:27:57 flymockour-l7 kernel: iwn_check_rx_recovery: time delta: 103; cck=22, ofdm=1, ht=0, total=126, thresh=5150
64259 Sep  6 18:27:58 flymockour-l7 kernel: iwn_notif_intr: cur=35; qid 7 idx 10 flags 0 type 192(RX_PHY) len 68
64260 Sep  6 18:27:58 flymockour-l7 kernel: iwn_notif_intr: cur=36; qid 7 idx 11 flags 0 type 193(MPDU_RX_DONE) len 336
64261 Sep  6 18:27:58 flymockour-l7 kernel: iwn5000_get_rssi: agc 31 rssi 4114 5399 0 result -52
64262 Sep  6 18:27:58 flymockour-l7 kernel: iwn_notif_intr: cur=37; qid 7 idx 12 flags 0 type 157(BEACON_STATS) len 528
64263 Sep  6 18:27:58 flymockour-l7 kernel: iwn_check_rx_recovery: time delta: 102; cck=32, ofdm=2, ht=0, total=136, thresh=5100
64264 Sep  6 18:27:58 flymockour-l7 kernel: iwn_notif_intr: cur=38; qid 7 idx 21 flags 0 type 192(RX_PHY) len 68
64265 Sep  6 18:27:58 flymockour-l7 kernel: iwn_notif_intr: cur=39; qid 7 idx 22 flags 0 type 193(MPDU_RX_DONE) len 336
64266 Sep  6 18:27:58 flymockour-l7 kernel: iwn5000_get_rssi: agc 32 rssi 4371 5656 0 result -52
64267 Sep  6 18:27:58 flymockour-l7 kernel: iwn_notif_intr: cur=40; qid 7 idx 23 flags 0 type 157(BEACON_STATS) len 528
64268 Sep  6 18:27:58 flymockour-l7 kernel: iwn_check_rx_recovery: time delta: 103; cck=22, ofdm=11, ht=0, total=136, thresh=5150
64269 Sep  6 18:27:58 flymockour-l7 kernel: iwn_notif_intr: cur=41; qid 7 idx 24 flags 0 type 162(BEACON_MISSED) len 20
64270 Sep  6 18:27:58 flymockour-l7 kernel: iwn_notif_intr: beacons missed 0/0
64271 Sep  6 18:27:58 flymockour-l7 kernel: iwn_notif_intr: cur=42; qid 7 idx 32 flags 0 type 192(RX_PHY) len 68
64272 Sep  6 18:27:58 flymockour-l7 kernel: iwn_notif_intr: cur=43; qid 7 idx 33 flags 0 type 193(MPDU_RX_DONE) len 168
64273 Sep  6 18:27:58 flymockour-l7 kernel: iwn5000_get_rssi: agc 56 rssi 9766 11308 0 result -56
64274 Sep  6 18:27:58 flymockour-l7 kernel: iwn_notif_intr: cur=44; qid 7 idx 35 flags 0 type 192(RX_PHY) len 68
64275 Sep  6 18:27:58 flymockour-l7 kernel: iwn_notif_intr: cur=45; qid 7 idx 36 flags 0 type 193(MPDU_RX_DONE) len 336
64276 Sep  6 18:27:58 flymockour-l7 kernel: iwn5000_get_rssi: agc 30 rssi 4115 5142 0 result -52
64277 Sep  6 18:27:58 flymockour-l7 kernel: iwn_notif_intr: cur=46; qid 7 idx 37 flags 0 type 157(BEACON_STATS) len 528
64278 Sep  6 18:27:58 flymockour-l7 kernel: iwn_check_rx_recovery: time delta: 102; cck=50, ofdm=13, ht=0, total=165, thresh=5100
64279 Sep  6 18:27:58 flymockour-l7 kernel: iwn_check_rx_recovery: PLCP error threshold raw (63) comparison (6300) over limit (5100); retune!
64280 Sep  6 18:27:58 flymockour-l7 kernel: iwn_start_locked: called
64281 Sep  6 18:27:58 flymockour-l7 kernel: iwn_tx_data: qid 0 idx 65 len 80 nsegs 2 flags 0x00100018 rate 0x0080 plcp 0x00004100
64282 Sep  6 18:27:58 flymockour-l7 kernel: iwn_start_locked: done
64283 Sep  6 18:27:58 flymockour-l7 kernel: iwn_notif_intr: cur=47; qid 0 idx 65 flags 0 type 28(TX_DONE) len 44
64284 Sep  6 18:27:58 flymockour-l7 kernel: iwn5000_tx_done: qid 0 idx 65 retries 0 nkill 0 rate 80004100 duration 296 status 201
64285 Sep  6 18:27:58 flymockour-l7 kernel: ->iwn_tx_done updating rate control if_opackets: 1616
Comment 19 Adrian Chadd freebsd_committer freebsd_triage 2014-09-07 01:44:58 UTC
wlandebug +rate

what happens?
Comment 20 Hiren Panchasara freebsd_committer freebsd_triage 2014-09-07 01:58:08 UTC
18:55 < hiren> Sep  6 18:55:10 flymockour-l7 kernel: wlan0: [dc:9f:db:6a:3e:9e] AMRR: current rate 0, txcnt=11, retrycnt=14
18:55 < hiren> Sep  6 18:55:15 flymockour-l7 kernel: wlan0: [dc:9f:db:6a:3e:9e] AMRR: current rate 0, txcnt=11, retrycnt=20
18:55 < hiren> Sep  6 18:55:20 flymockour-l7 kernel: wlan0: [dc:9f:db:6a:3e:9e] AMRR: current rate 0, txcnt=11, retrycnt=21

I guess because of this much retries rate is not going up.
Comment 21 Johannes M Dieterich freebsd_committer freebsd_triage 2014-09-07 02:47:12 UTC
(In reply to Adrian Chadd from comment #17)
> Also, please test out with the latest -HEAD and see if it behaves better for
> you.
Just installed r271215 and can confirm that the situation is much improved. Without setting -ht, I can get some 3.5 MB/s upload over scp to off-site. I can run more detailed tests if you wish, but I am more than happy with the status as is.

Thanks so much for your work on this! :-)
Comment 22 Hiren Panchasara freebsd_committer freebsd_triage 2014-09-07 07:57:28 UTC
(In reply to dieterich.joh from comment #21)
> (In reply to Adrian Chadd from comment #17)
> > Also, please test out with the latest -HEAD and see if it behaves better for
> > you.
> Just installed r271215 and can confirm that the situation is much improved.
> Without setting -ht, I can get some 3.5 MB/s upload over scp to off-site. I
> can run more detailed tests if you wish, but I am more than happy with the
> status as is.

Are you connecting at 11g? Can you paste ifconfig o/p? 
It'd be nice to see what rate does it go up to? (with wlandebug +rate)
Comment 23 Johannes M Dieterich freebsd_committer freebsd_triage 2014-09-07 12:08:28 UTC
(In reply to Hiren Panchasara from comment #22)
> (In reply to dieterich.joh from comment #21)
> > (In reply to Adrian Chadd from comment #17)
> > > Also, please test out with the latest -HEAD and see if it behaves better for
> > > you.
> > Just installed r271215 and can confirm that the situation is much improved.
> > Without setting -ht, I can get some 3.5 MB/s upload over scp to off-site. I
> > can run more detailed tests if you wish, but I am more than happy with the
> > status as is.
> 
> Are you connecting at 11g? Can you paste ifconfig o/p? 
> It'd be nice to see what rate does it go up to? (with wlandebug +rate)
No, this should be 11n (on the 2.4 GHz band and w/ only 20 MHz channel width, though) as I explicitly configured the access point to not support anything but 11n.

ifconfig:
wlan0: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 1500
	ether XXXXXX
	inet 192.168.1.3 netmask 0xffffff00 broadcast 192.168.1.255 
	nd6 options=29<PERFORMNUD,IFDISABLED,AUTO_LINKLOCAL>
	media: IEEE 802.11 Wireless Ethernet MCS mode 11ng
	status: associated
	ssid XXXXXX channel 10 (2457 MHz 11g ht/20) bssid XXXXXXX
	country US authmode WPA2/802.11i privacy ON deftxkey UNDEF
	TKIP 2:128-bit TKIP 3:128-bit txpower 15 bmiss 10 scanvalid 60 bgscan
	bgscanintvl 300 bgscanidle 250 roam:rssi 7 roam:rate 64 protmode CTS
	ampdulimit 64k ampdudensity 8 -amsdutx amsdurx shortgi wme
	roaming MANUAL

wlandebug + rate:
Sep  7 13:51:54  kernel: wlan0: [] AMRR: current rate 15, txcnt=36, retrycnt=11
Sep  7 13:51:54  kernel: wlan0: [] AMRR: current rate 15, txcnt=37, retrycnt=2
Sep  7 13:51:55  kernel: wlan0: [] AMRR: current rate 15, txcnt=37, retrycnt=6
Sep  7 13:51:55  kernel: wlan0: [] AMRR: current rate 15, txcnt=34, retrycnt=1
Sep  7 13:51:56  kernel: wlan0: [] AMRR: current rate 15, txcnt=38, retrycnt=8
Sep  7 13:51:56  kernel: wlan0: [] AMRR: current rate 15, txcnt=33, retrycnt=2
Sep  7 13:51:57  kernel: wlan0: [] AMRR: current rate 15, txcnt=39, retrycnt=5
Sep  7 13:51:57  kernel: wlan0: [] AMRR: current rate 15, txcnt=33, retrycnt=10
Sep  7 13:51:58  kernel: wlan0: [] AMRR: current rate 15, txcnt=38, retrycnt=20
Sep  7 13:51:58  kernel: wlan0: [] AMRR decreasing rate 14 (txcnt=38 retrycnt=20)
Sep  7 13:51:58  kernel: wlan0: [] AMRR: current rate 14, txcnt=38, retrycnt=5
Sep  7 13:51:59  kernel: wlan0: [] AMRR: current rate 14, txcnt=35, retrycnt=4
Sep  7 13:51:59  kernel: wlan0: [] AMRR: current rate 14, txcnt=34, retrycnt=6
Sep  7 13:52:00  kernel: wlan0: [] AMRR: current rate 14, txcnt=32, retrycnt=1
Sep  7 13:52:00  kernel: wlan0: [] AMRR increasing rate 15 (txcnt=32 retrycnt=1)
Sep  7 13:52:00  kernel: wlan0: [] AMRR: current rate 15, txcnt=31, retrycnt=12
Sep  7 13:52:00  kernel: wlan0: [] AMRR decreasing rate 14 (txcnt=31 retrycnt=12)
Sep  7 13:52:01  kernel: wlan0: [] AMRR: current rate 14, txcnt=36, retrycnt=3
Sep  7 13:52:01  kernel: wlan0: [] AMRR: current rate 14, txcnt=34, retrycnt=6
Sep  7 13:52:02  kernel: wlan0: [] AMRR: current rate 14, txcnt=34, retrycnt=5
Sep  7 13:52:02  kernel: wlan0: [] AMRR: current rate 14, txcnt=34, retrycnt=6
Sep  7 13:52:03  kernel: wlan0: [] AMRR: current rate 14, txcnt=34, retrycnt=5
Sep  7 13:52:03  kernel: wlan0: [] AMRR: current rate 14, txcnt=35, retrycnt=8
Sep  7 13:52:04  kernel: wlan0: [] AMRR: current rate 14, txcnt=30, retrycnt=6
Sep  7 13:52:04  kernel: wlan0: [] AMRR: current rate 14, txcnt=33, retrycnt=0
Sep  7 13:52:04  kernel: wlan0: [] AMRR increasing rate 15 (txcnt=33 retrycnt=0)
Sep  7 13:52:05  kernel: wlan0: [] AMRR: current rate 15, txcnt=26, retrycnt=5
Sep  7 13:52:05  kernel: wlan0: [] AMRR: current rate 15, txcnt=33, retrycnt=12
Sep  7 13:52:05  kernel: wlan0: [] AMRR decreasing rate 14 (txcnt=33 retrycnt=12)
Sep  7 13:52:06  kernel: wlan0: [] AMRR: current rate 14, txcnt=30, retrycnt=8
Sep  7 13:52:06  kernel: wlan0: [] AMRR: current rate 14, txcnt=33, retrycnt=5
Sep  7 13:52:07  kernel: wlan0: [] AMRR: current rate 14, txcnt=27, retrycnt=2
Sep  7 13:52:07  kernel: wlan0: [] AMRR: current rate 14, txcnt=32, retrycnt=9
Sep  7 13:52:08  kernel: wlan0: [] AMRR: current rate 14, txcnt=32, retrycnt=3
Sep  7 13:52:09  kernel: wlan0: [] AMRR: current rate 14, txcnt=27, retrycnt=1
Sep  7 13:52:09  kernel: wlan0: [] AMRR increasing rate 15 (txcnt=27 retrycnt=1)
Sep  7 13:52:09  kernel: wlan0: [] AMRR: current rate 15, txcnt=33, retrycnt=9
Sep  7 13:52:10  kernel: wlan0: [] AMRR: current rate 15, txcnt=32, retrycnt=8
Sep  7 13:52:10  kernel: wlan0: [] AMRR: current rate 15, txcnt=32, retrycnt=7
Sep  7 13:52:11  kernel: wlan0: [] AMRR: current rate 15, txcnt=32, retrycnt=8
Sep  7 13:52:11  kernel: wlan0: [] AMRR: current rate 15, txcnt=33, retrycnt=11
Sep  7 13:52:12  kernel: wlan0: [] AMRR: current rate 15, txcnt=31, retrycnt=11
Sep  7 13:52:12  kernel: wlan0: [] AMRR decreasing rate 14 (txcnt=31 retrycnt=11)
Sep  7 13:52:12  kernel: wlan0: [] AMRR: current rate 14, txcnt=33, retrycnt=8
Sep  7 13:52:13  kernel: wlan0: [] AMRR: current rate 14, txcnt=34, retrycnt=13
Sep  7 13:52:13  kernel: wlan0: [] AMRR decreasing rate 13 (txcnt=34 retrycnt=13)
Sep  7 13:52:13  kernel: wlan0: [] AMRR: current rate 13, txcnt=37, retrycnt=13
Sep  7 13:52:13  kernel: wlan0: [] AMRR decreasing rate 12 (txcnt=37 retrycnt=13)
Sep  7 13:52:14  kernel: wlan0: [] AMRR: current rate 12, txcnt=39, retrycnt=19
Sep  7 13:52:14  kernel: wlan0: [] AMRR decreasing rate 11 (txcnt=39 retrycnt=19)
Sep  7 13:52:14  kernel: wlan0: [] AMRR: current rate 11, txcnt=26, retrycnt=32
Sep  7 13:52:14  kernel: wlan0: [] AMRR decreasing rate 10 (txcnt=26 retrycnt=32)
Sep  7 13:52:15  kernel: wlan0: [] AMRR: current rate 10, txcnt=33, retrycnt=6
Sep  7 13:52:15  kernel: wlan0: [] AMRR: current rate 10, txcnt=33, retrycnt=1
Sep  7 13:52:15  kernel: wlan0: [] AMRR increasing rate 11 (txcnt=33 retrycnt=1)
Sep  7 13:52:16  kernel: wlan0: [] AMRR: current rate 11, txcnt=34, retrycnt=0
Sep  7 13:52:16  kernel: wlan0: [] AMRR increasing rate 12 (txcnt=34 retrycnt=0)
Sep  7 13:52:16  kernel: wlan0: [] AMRR: current rate 12, txcnt=32, retrycnt=7
Sep  7 13:52:17  kernel: wlan0: [] AMRR: current rate 12, txcnt=31, retrycnt=2
Sep  7 13:52:17  kernel: wlan0: [] AMRR increasing rate 13 (txcnt=31 retrycnt=2)
Sep  7 13:52:17  kernel: wlan0: [] AMRR: current rate 13, txcnt=32, retrycnt=1
Sep  7 13:52:17  kernel: wlan0: [] AMRR increasing rate 14 (txcnt=32 retrycnt=1)
Sep  7 13:52:18  kernel: wlan0: [] AMRR: current rate 14, txcnt=28, retrycnt=2
Sep  7 13:52:18  kernel: wlan0: [] AMRR: current rate 14, txcnt=33, retrycnt=0
Sep  7 13:52:18  kernel: wlan0: [] AMRR increasing rate 15 (txcnt=33 retrycnt=0)
Sep  7 13:52:19  kernel: wlan0: [] AMRR: current rate 15, txcnt=33, retrycnt=5
Sep  7 13:52:19  kernel: wlan0: [] AMRR: current rate 15, txcnt=30, retrycnt=9
Sep  7 13:52:20  kernel: wlan0: [] AMRR: current rate 15, txcnt=30, retrycnt=6
Sep  7 13:52:20  kernel: wlan0: [] AMRR: current rate 15, txcnt=32, retrycnt=6
Sep  7 13:52:21  kernel: wlan0: [] AMRR: current rate 15, txcnt=32, retrycnt=3
Sep  7 13:52:21  kernel: wlan0: [] AMRR: current rate 15, txcnt=32, retrycnt=9
Sep  7 13:52:22  kernel: wlan0: [] AMRR: current rate 15, txcnt=26, retrycnt=6
Sep  7 13:52:22  kernel: wlan0: [] AMRR: current rate 15, txcnt=30, retrycnt=10
Sep  7 13:52:23  kernel: wlan0: [] AMRR: current rate 15, txcnt=32, retrycnt=9
Sep  7 13:52:24  kernel: wlan0: [] AMRR: current rate 15, txcnt=33, retrycnt=10
Sep  7 13:52:24  kernel: wlan0: [] AMRR: current rate 15, txcnt=30, retrycnt=6
Sep  7 13:52:25  kernel: wlan0: [] AMRR: current rate 15, txcnt=31, retrycnt=4
Sep  7 13:52:25  kernel: wlan0: [] AMRR: current rate 15, txcnt=17, retrycnt=15
Sep  7 13:52:25  kernel: wlan0: [] AMRR decreasing rate 14 (txcnt=17 retrycnt=15)
Sep  7 13:52:30  kernel: wlan0: [] AMRR: current rate 14, txcnt=11, retrycnt=0
Sep  7 13:52:30  kernel: wlan0: [] AMRR increasing rate 15 (txcnt=11 retrycnt=0)
Sep  7 13:52:31  kernel: wlan0: [] AMRR: current rate 15, txcnt=17, retrycnt=6
Sep  7 13:52:31  kernel: wlan0: [] AMRR decreasing rate 14 (txcnt=17 retrycnt=6)
Sep  7 13:52:31  kernel: wlan0: [] AMRR: current rate 14, txcnt=56, retrycnt=2
Sep  7 13:52:31  kernel: wlan0: [] AMRR increasing rate 15 (txcnt=56 retrycnt=2)

Anything else? :-)
Comment 24 Lars Engels freebsd_committer freebsd_triage 2014-09-07 14:37:05 UTC
To jump in: I'm not having problems on yesterday's HEAD using an 6205:

ubuntu-14.04.1-server-amd64.iso 6.4 MB/s - 195 MB of 572 MB, 59 secs left


wlan0: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 1500
	ether 60:67:20:xx:xx:xx
	inet 192.168.0.11 netmask 0xffffff00 broadcast 192.168.0.255 
	nd6 options=29<PERFORMNUD,IFDISABLED,AUTO_LINKLOCAL>
	media: IEEE 802.11 Wireless Ethernet MCS mode 11ng
	status: associated
	ssid hafenkneipe24GHz channel 1 (2412 MHz 11g ht/20) bssid c4:27:95:xx:xx:xx
	regdomain ETSI country DE authmode WPA2/802.11i privacy ON
	deftxkey UNDEF TKIP 2:128-bit txpower 50 bmiss 10 scanvalid 60 bgscan
	bgscanintvl 300 bgscanidle 250 roam:rssi 7 roam:rate 64 protmode CTS
	ampdulimit 64k ampdudensity 8 -amsdutx amsdurx shortgi wme
	roaming MANUAL
Comment 25 Hiren Panchasara freebsd_committer freebsd_triage 2014-09-08 06:41:27 UTC
wow, I so envy you guys :-)

I've a similar setting but not getting anything more than 400kbps. So weird.
Comment 26 Johannes M Dieterich freebsd_committer freebsd_triage 2014-09-10 21:45:28 UTC
Is fixed for me, trying to clean up. Please (@hiren) reopen if you feel that is required.