[rt2x00-users] rt2800pci: broken for 5GHz AP - throughput issues, stalls and completely dead device

[Andreas Hartmann]

Hello,

I tested rt2800pci (device rt2860 - Linksys WMP600N) on a smp machine
with 5 GHz / 802.11n / 40 MHz as AP with netperf and
compat-wireless-2012-03-16 on linux 3.1.10 64bit.

Radio condition is optimal (2 m difference between supplicant and AP,
nothing but air in between (the performance with 2.4 GHz is 14 Mbit/s
TX and 10 Mbit/s RX (as seen by the AP)).

The additional patches "mac80211: revert: retry sending failed BAR
frames later instead of tearing down aggr-v2.patch" and "correct
beaconing" are applied.

I configured hostapd (git-head from yesterday) like this (only relevant
configuration entries):

country_code=DE
ieee80211d=1
hw_mode=a
channel=36
max_num_sta=255
rts_threshold=2347
fragm_threshold=2346
preamble=1
ignore_broadcast_ssid=0
wmm_enabled=1
wmm_ac_bk_cwmin=4
wmm_ac_bk_cwmax=10
wmm_ac_bk_aifs=7
wmm_ac_bk_txop_limit=0
wmm_ac_bk_acm=0
ieee80211n=1
ht_capab=[HT40+][SHORT-GI-40][SHORT-GI-20][TX-STBC1][MAX-AMSDU-3839][RX-STBC12][SMPS-STATIC][GF]
wpa=10
wpa_key_mgmt=WPA-EAP
wpa_pairwise=CCMP
rsn_pairwise=CCMP

crda is version 1.1.1, iw is version 3.3, regdb is 2011.04.28.

As supplicant, I used rt3572 based Linksys WUSB600Nv2 with rt5572sta.


What are the problems?
======================

1. The initial throughput after login is very bad: 5 kBit/s TX and 5.5
   MBit/s RX.
2. Starting of netperf doesn't work most of the time - you have to do a
   ping (e.g.) before to start BA session.
3. After some time of working and restarting netperf after BA session
   has been closed, the device is completely dead.

None of these problems here described appear with the Linksys
WAP610N / 5GHz or even with rt2800pci / 2.4 GHz. If I use rt2800usb
instead of rt3572sta on the supplicant, the problems got even worse.



Following is an example, how the problems can be seen in messages. But
to be honest - they can't be seen at all :-(. But I tried to clarify
what I described above in a few words as a summary. Lets start with
the loading of the complete module stack:

Mar 17 07:34:07 pci kernel: [10493.014876] cfg80211: Calling CRDA to update world regulatory domain
Mar 17 07:34:07 pci kernel: [10493.019958] cfg80211: World regulatory domain updated:
Mar 17 07:34:07 pci kernel: [10493.019961] cfg80211:   (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
Mar 17 07:34:07 pci kernel: [10493.019963] cfg80211:   (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
Mar 17 07:34:07 pci kernel: [10493.019965] cfg80211:   (2457000 KHz - 2482000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
Mar 17 07:34:07 pci kernel: [10493.019967] cfg80211:   (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
Mar 17 07:34:07 pci kernel: [10493.019969] cfg80211:   (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
Mar 17 07:34:07 pci kernel: [10493.019971] cfg80211:   (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
Mar 17 07:34:07 pci kernel: [10493.019983] cfg80211: Calling CRDA for country: DE
Mar 17 07:34:07 pci kernel: [10493.023730] rt2800pci 0000:06:07.0: PCI INT A -> GSI 21 (level, low) -> IRQ 21
Mar 17 07:34:07 pci kernel: [10493.024960] cfg80211: Regulatory domain changed to country: DE
Mar 17 07:34:07 pci kernel: [10493.024962] cfg80211:   (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
Mar 17 07:34:07 pci kernel: [10493.024964] cfg80211:   (2400000 KHz - 2483500 KHz @ 40000 KHz), (N/A, 2000 mBm)
Mar 17 07:34:07 pci kernel: [10493.024966] cfg80211:   (5150000 KHz - 5250000 KHz @ 40000 KHz), (N/A, 2000 mBm)
Mar 17 07:34:07 pci kernel: [10493.024967] cfg80211:   (5250000 KHz - 5350000 KHz @ 40000 KHz), (N/A, 2000 mBm)
Mar 17 07:34:07 pci kernel: [10493.024969] cfg80211:   (5470000 KHz - 5725000 KHz @ 40000 KHz), (N/A, 2698 mBm)
Mar 17 07:34:07 pci kernel: [10493.032302] phy0 -> rt2x00_set_chip: Info - Chipset detected - rt: 2860, rf: 0002, rev: 0103.
Mar 17 07:34:07 pci kernel: [10493.035805] ieee80211 phy0: Selected rate control algorithm 'minstrel_ht'
Mar 17 07:34:07 pci kernel: [10493.036780] Registered led device: rt2800pci-phy0::radio
Mar 17 07:34:07 pci kernel: [10493.036799] Registered led device: rt2800pci-phy0::assoc
Mar 17 07:34:07 pci kernel: [10493.036814] Registered led device: rt2800pci-phy0::quality
Mar 17 07:34:07 pci ifup:     wlan0     device: RaLink RT2800 802.11n PCI
Mar 17 07:34:07 pci ifup:               No configuration found for wlan0
Mar 17 07:34:09 pci kernel: [10495.059541] device wlan0 entered promiscuous mode
Mar 17 07:34:09 pci kernel: [10495.059568] phy0 -> rt2x00lib_request_firmware: Info - Loading firmware file 'rt2860.bin'.
Mar 17 07:34:09 pci kernel: [10495.062342] phy0 -> rt2x00lib_request_firmware: Info - Firmware detected - version: 0.34.
Mar 17 07:34:09 pci kernel: [10495.070754] phy0 -> rt2x00mac_conf_tx: Info - Configured TX queue 0 - CWmin: 3, CWmax: 4, Aifs: 2, TXop: 102.
Mar 17 07:34:09 pci kernel: [10495.070763] phy0 -> rt2x00mac_conf_tx: Info - Configured TX queue 1 - CWmin: 4, CWmax: 5, Aifs: 2, TXop: 188.
Mar 17 07:34:09 pci kernel: [10495.070771] phy0 -> rt2x00mac_conf_tx: Info - Configured TX queue 2 - CWmin: 5, CWmax: 10, Aifs: 3, TXop: 0.
Mar 17 07:34:09 pci kernel: [10495.070779] phy0 -> rt2x00mac_conf_tx: Info - Configured TX queue 3 - CWmin: 5, CWmax: 10, Aifs: 7, TXop: 0.
Mar 17 07:34:09 pci kernel: [10495.074893] br1: port 3(wlan0) entering forwarding state
Mar 17 07:34:09 pci kernel: [10495.074896] br1: port 3(wlan0) entering forwarding state
Mar 17 07:34:14 pci kernel: [10500.331579] phy0 -> rt2x00mac_conf_tx: Info - Configured TX queue 0 - CWmin: 2, CWmax: 3, Aifs: 1, TXop: 47.
Mar 17 07:34:14 pci kernel: [10500.331622] phy0 -> rt2x00mac_conf_tx: Info - Configured TX queue 1 - CWmin: 3, CWmax: 4, Aifs: 1, TXop: 94.
Mar 17 07:34:14 pci kernel: [10500.331658] phy0 -> rt2x00mac_conf_tx: Info - Configured TX queue 2 - CWmin: 4, CWmax: 6, Aifs: 3, TXop: 0.
Mar 17 07:34:14 pci kernel: [10500.331692] phy0 -> rt2x00mac_conf_tx: Info - Configured TX queue 3 - CWmin: 4, CWmax: 10, Aifs: 7, TXop: 0.
...
[parts of login process]
...
Mar 17 07:34:21 pci hostapd: wlan0: STA 00:25:9c:11:22:33 IEEE 802.1X: Sending EAP Packet (identifier 200)
Mar 17 07:34:24 pci hostapd: Last message 'wlan0: STA 00:25:9c:' repeated 1 times, supressed by syslog-ng on pci.domain.net
Mar 17 07:34:24 pci kernel: [10509.772098] Open BA session requested for 00:25:9c:11:22:33 tid 0
Mar 17 07:34:24 pci kernel: [10509.781137] activated addBA response timer on tid 0
Mar 17 07:34:24 pci kernel: [10509.781722] switched off addBA timer for tid 0
Mar 17 07:34:24 pci kernel: [10509.781726] Aggregation is on for tid 0
Mar 17 07:34:29 pci kernel: [10514.912116] tx session timer expired on tid 0
Mar 17 07:34:29 pci kernel: [10514.912157] Tx BA session stop requested for 00:25:9c:11:22:33 tid 0
Mar 17 07:34:29 pci kernel: [10514.921147] Stopping Tx BA session for 00:25:9c:11:22:33 tid 0
Mar 17 07:34:29 pci kernel: [10514.921346] Open BA session requested for 00:25:9c:11:22:33 tid 0
Mar 17 07:34:29 pci kernel: [10514.937046] activated addBA response timer on tid 0
Mar 17 07:34:29 pci kernel: [10514.937561] switched off addBA timer for tid 0
Mar 17 07:34:29 pci kernel: [10514.937565] Aggregation is on for tid 0
Mar 17 07:34:30 pci hostapd: wlan0: STA 00:25:9c:11:22:33 IEEE 802.1X: Sending EAP Packet (identifier 200)
Mar 17 07:34:30 pci hostapd: wlan0: STA 00:25:9c:11:22:33 IEEE 802.1X: received EAP packet (code=2 id=200 len=6) from STA: EAP Response-TLS (13)
Mar 17 07:34:30 pci hostapd: wlan0: STA 00:25:9c:11:22:33 RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.00 sec
Mar 17 07:34:30 pci hostapd: wlan0: STA 00:25:9c:11:22:33 IEEE 802.1X: decapsulated EAP packet (code=1 id=201 len=1254) from RADIUS server: EAP-Request-TLS (13)
Mar 17 07:34:30 pci hostapd: wlan0: STA 00:25:9c:11:22:33 IEEE 802.1X: Sending EAP Packet (identifier 201)
Mar 17 07:34:30 pci hostapd: wlan0: STA 00:25:9c:11:22:33 IEEE 802.1X: received EAP packet (code=2 id=201 len=1408) from STA: EAP Response-TLS (13)
Mar 17 07:34:30 pci hostapd: wlan0: STA 00:25:9c:11:22:33 RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.00 sec
Mar 17 07:34:30 pci hostapd: wlan0: STA 00:25:9c:11:22:33 IEEE 802.1X: decapsulated EAP packet (code=1 id=202 len=6) from RADIUS server: EAP-Request-TLS (13)
Mar 17 07:34:30 pci hostapd: wlan0: STA 00:25:9c:11:22:33 IEEE 802.1X: Sending EAP Packet (identifier 202)
Mar 17 07:34:30 pci hostapd: wlan0: STA 00:25:9c:11:22:33 IEEE 802.1X: received EAP packet (code=2 id=202 len=1046) from STA: EAP Response-TLS (13)
Mar 17 07:34:30 pci hostapd: wlan0: STA 00:25:9c:11:22:33 RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.00 sec
Mar 17 07:34:30 pci hostapd: wlan0: STA 00:25:9c:11:22:33 IEEE 802.1X: decapsulated EAP packet (code=1 id=203 len=69) from RADIUS server: EAP-Request-TLS (13)
Mar 17 07:34:30 pci hostapd: wlan0: STA 00:25:9c:11:22:33 IEEE 802.1X: Sending EAP Packet (identifier 203)
Mar 17 07:34:30 pci hostapd: wlan0: STA 00:25:9c:11:22:33 IEEE 802.1X: received EAP packet (code=2 id=203 len=6) from STA: EAP Response-TLS (13)
Mar 17 07:34:30 pci hostapd: wlan0: STA 00:25:9c:11:22:33 RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.00 sec
Mar 17 07:34:30 pci hostapd: wlan0: STA 00:25:9c:11:22:33 IEEE 802.1X: old identity 'supp1 at domain.net' updated with User-Name from Access-Accept 'supp1'
Mar 17 07:34:30 pci hostapd: wlan0: STA 00:25:9c:11:22:33 IEEE 802.1X: decapsulated EAP packet (code=3 id=203 len=4) from RADIUS server: EAP Success
Mar 17 07:34:30 pci hostapd: wlan0: STA 00:25:9c:11:22:33 IEEE 802.1X: Sending EAP Packet (identifier 203)
Mar 17 07:34:30 pci hostapd: wlan0: STA 00:25:9c:11:22:33 WPA: sending 1/4 msg of 4-Way Handshake
Mar 17 07:34:30 pci hostapd: wlan0: STA 00:25:9c:11:22:33 WPA: received EAPOL-Key frame (2/4 Pairwise)
Mar 17 07:34:30 pci hostapd: wlan0: STA 00:25:9c:11:22:33 WPA: sending 3/4 msg of 4-Way Handshake
Mar 17 07:34:30 pci hostapd: wlan0: STA 00:25:9c:11:22:33 WPA: received EAPOL-Key frame (4/4 Pairwise)
Mar 17 07:34:30 pci hostapd: wlan0: STA 00:25:9c:11:22:33 WPA: pairwise key handshake completed (RSN)
Mar 17 07:34:30 pci hostapd: wlan0: STA 00:25:9c:11:22:33 IEEE 802.1X: authorizing port
Mar 17 07:34:30 pci hostapd: wlan0: STA 00:25:9c:11:22:33 RADIUS: starting accounting session 4F643066-00000000
Mar 17 07:34:30 pci hostapd: wlan0: STA 00:25:9c:11:22:33 IEEE 802.1X: authenticated - EAP type: 13 (TLS)
Mar 17 07:34:30 pci hostapd: wlan0: STA 00:25:9c:11:22:33 WPA: Added PMKSA cache entry (IEEE 802.1X)
Mar 17 07:34:30 pci hostapd: wlan0: RADIUS Received 20 bytes from RADIUS server
Mar 17 07:34:30 pci hostapd: wlan0: RADIUS Received RADIUS message
Mar 17 07:34:30 pci hostapd: wlan0: STA 00:25:9c:11:22:33 RADIUS: Received RADIUS packet matched with a pending request, round trip time 0.00 sec
Mar 17 07:34:31 pci kernel: [10516.755212] Rx A-MPDU request on tid 0 result 0
Mar 17 07:35:16 pci kernel: [10562.000113] tx session timer expired on tid 0
Mar 17 07:35:16 pci kernel: [10562.000143] Tx BA session stop requested for 00:25:9c:11:22:33 tid 0
Mar 17 07:35:16 pci kernel: [10562.009048] Stopping Tx BA session for 00:25:9c:11:22:33 tid 0

netperf started
poor throughput of AP:
TX: 5 kbit/s
RX: 5.5 Mbit/s

netperf stopped

Mar 17 07:36:03 pci kernel: [10608.692299] Tx BA session stop requested for 00:25:9c:11:22:33 tid 0
Mar 17 07:36:03 pci kernel: [10608.701022] Stopping Tx BA session for 00:25:9c:11:22:33 tid 0

ping
waiting for reopen of BA session (if the BA session isn't opened 
before netperf is started, netperf won't work (=data stream is 0) -
most of the time)

Mar 17 07:35:29 pci kernel: [10575.346964] Open BA session requested for 00:25:9c:11:22:33 tid 0
Mar 17 07:35:29 pci kernel: [10575.355149] activated addBA response timer on tid 0
Mar 17 07:35:29 pci kernel: [10575.355638] switched off addBA timer for tid 0
Mar 17 07:35:29 pci kernel: [10575.355643] Aggregation is on for tid 0

ping stopped
netperf started again
TX: 10 Mbit/s
RX: 8.6 Mbit/s

Mar 17 07:35:53 pci kernel: [10599.065017] ieee80211 phy0: release an RX reorder frame due to timeout on earlier frames
Mar 17 07:35:53 pci kernel: [10599.065021] ieee80211 phy0: release an RX reorder frame due to timeout on earlier frames
Mar 17 07:35:53 pci kernel: [10599.065024] ieee80211 phy0: release an RX reorder frame due to timeout on earlier frames
Mar 17 07:35:53 pci kernel: [10599.065026] ieee80211 phy0: release an RX reorder frame due to timeout on earlier frames
Mar 17 07:35:53 pci kernel: [10599.065028] ieee80211 phy0: release an RX reorder frame due to timeout on earlier frames
Mar 17 07:35:53 pci kernel: [10599.065030] ieee80211 phy0: release an RX reorder frame due to timeout on earlier frames
Mar 17 07:35:53 pci kernel: [10599.065032] ieee80211 phy0: release an RX reorder frame due to timeout on earlier frames
Mar 17 07:36:03 pci kernel: [10608.692299] Tx BA session stop requested for 00:25:9c:11:22:33 tid 0
Mar 17 07:36:03 pci kernel: [10608.701022] Stopping Tx BA session for 00:25:9c:11:22:33 tid 0
Mar 17 07:36:03 pci kernel: [10608.786081] Open BA session requested for 00:25:9c:11:22:33 tid 0
Mar 17 07:36:03 pci kernel: [10608.795804] activated addBA response timer on tid 0
Mar 17 07:36:03 pci kernel: [10608.831854] switched off addBA timer for tid 0
Mar 17 07:36:03 pci kernel: [10608.831856] Aggregation is on for tid 0
Mar 17 07:36:13 pci kernel: [10619.290983] Tx BA session stop requested for 00:25:9c:11:22:33 tid 0
Mar 17 07:36:13 pci kernel: [10619.299155] Stopping Tx BA session for 00:25:9c:11:22:33 tid 0
Mar 17 07:36:13 pci kernel: [10619.372708] Open BA session requested for 00:25:9c:11:22:33 tid 0
Mar 17 07:36:13 pci kernel: [10619.381117] activated addBA response timer on tid 0
Mar 17 07:36:13 pci kernel: [10619.387187] switched off addBA timer for tid 0
Mar 17 07:36:13 pci kernel: [10619.387189] Aggregation is on for tid 0
Mar 17 07:36:44 pci kernel: [10649.895062] Tx BA session stop requested for 00:25:9c:11:22:33 tid 0
Mar 17 07:36:44 pci kernel: [10649.908149] Stopping Tx BA session for 00:25:9c:11:22:33 tid 0
Mar 17 07:36:44 pci kernel: [10649.999093] Open BA session requested for 00:25:9c:11:22:33 tid 0
Mar 17 07:36:44 pci kernel: [10650.008033] activated addBA response timer on tid 0
Mar 17 07:36:44 pci kernel: [10650.015082] switched off addBA timer for tid 0
Mar 17 07:36:44 pci kernel: [10650.015084] Aggregation is on for tid 0

...

netperf stopped

Mar 17 07:42:19 pci kernel: [10985.136041] tx session timer expired on tid 0
Mar 17 07:42:19 pci kernel: [10985.136139] Tx BA session stop requested for 00:25:9c:11:22:33 tid 0
Mar 17 07:42:19 pci kernel: [10985.145156] Stopping Tx BA session for 00:25:9c:11:22:33 tid 0

netperf start

-> no data stream any more, no start of BA session

netperf stop

ping (which works) or waiting for opening BA because of some other
reason

netperf start works again with old throughput.

netperf stopped again

ping

pause (30s - BA session is stopped meanwhile)

netperf start (-> no data stream)

ping (no reply)

-> AP-device is dead. It's impossible to reconnect (Association works,
Authentication times out (from the point of view of the supplicant)).
You hvae to reload the driver to get it working again.


=> (re-)starting of netperf isn't a problem, as long 
   as the TX BA session isn't stopped (most of the time).



Kind regards,
Andreas