Poor performance and lockup with rt2800usb and Asus USB-N13 adapter

I recently got an Asus USB-N13 USB Wireless-N adapter which apparently uses a Ralink RT3072 chip. I'm using it with an Asus RT-N16 access point running TomatoUSB. When running Windows the performance is reasonable (about 80 Mbps in both directions). However under Fedora 16 (currently kernel 3.1.2) the performance is abysmal (10 Mbps or less with lots of packet loss). I'll post some debug information below.

I have another adapter, a Trendnet which apparently is an RT3070 and uses the same driver, which works much better (about 50 Mbps) despite being only a 150 Mbps chip (1X MIMO) as opposed to 300 Mbps (2X MIMO) like the Asus. Looking at the Minstrel rc_stat output it seems like a lot of the MCS8-15 rates are being tried but the success is quite poor - I'm not sure if this is a cause of the poor performance or an effect..

While debugging this I also noticed that doing an rmmod on rt2800usb with the adapter plugged in locks up the machine and then spews out soft lockup stack traces on the console. I was only able to capture it off the screen with a camera, but it basically is:

rt2x00usb_work_rxdone
process_one_work
worker_thread
kthread
kernel_thread_helper

The output repeats periodically and it always seems to involve either rt2x00usb_work_rxdone or rt2x00usb_work_txdone so it seems like we're spinning through those functions for some reason. I can post/send the image if anyone wants more details from the stack trace.

Linux nicole 3.1.2-1.fc16.i686 #1 SMP Tue Nov 22 08:56:28 UTC 2011 i686 i686 i386 GNU/Linux

lsusb -vv:

Bus 001 Device 002: ID 0b05:1784 ASUSTek Computer, Inc. USB-N13 802.11n Network Adapter [Ralink RT3072] Device Descriptor:
bLength 18
bDescriptorType 1
bcdUSB 2.00

  bDeviceClass            0 (Defined at Interface level)
  bDeviceSubClass         0
  bDeviceProtocol         0
  bMaxPacketSize0        64
  idVendor           0x0b05 ASUSTek Computer, Inc.
  idProduct          0x1784 USB-N13 802.11n Network Adapter [Ralink RT3072]
  bcdDevice            1.01
  iManufacturer           1 Ralink
  iProduct                2 802.11 n WLAN
  iSerial                 3 1.0
  bNumConfigurations      1

Configuration Descriptor:
bLength 9
bDescriptorType 2
wTotalLength 67
bNumInterfaces 1
bConfigurationValue 1
iConfiguration 0
bmAttributes 0x80
(Bus Powered)
MaxPower 450mA
Interface Descriptor:
bLength 9
bDescriptorType 4
bInterfaceNumber 0
bAlternateSetting 0
bNumEndpoints 7
bInterfaceClass 255 Vendor Specific Class
bInterfaceSubClass 255 Vendor Specific Subclass
bInterfaceProtocol 255 Vendor Specific Protocol
iInterface 5 1.0
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x81 EP 1 IN
bmAttributes 2
Transfer Type Bulk
Synch Type None
Usage Type Data
wMaxPacketSize 0x0200 1x 512 bytes
bInterval 0
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x01 EP 1 OUT
bmAttributes 2
Transfer Type Bulk
Synch Type None
Usage Type Data
wMaxPacketSize 0x0200 1x 512 bytes
bInterval 0
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x02 EP 2 OUT
bmAttributes 2
Transfer Type Bulk
Synch Type None
Usage Type Data
wMaxPacketSize 0x0200 1x 512 bytes
bInterval 0
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x03 EP 3 OUT
bmAttributes 2
Transfer Type Bulk
Synch Type None
Usage Type Data
wMaxPacketSize 0x0200 1x 512 bytes
bInterval 0
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x04 EP 4 OUT
bmAttributes 2
Transfer Type Bulk
Synch Type None
Usage Type Data
wMaxPacketSize 0x0200 1x 512 bytes
bInterval 0
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x05 EP 5 OUT
bmAttributes 2
Transfer Type Bulk
Synch Type None
Usage Type Data
wMaxPacketSize 0x0200 1x 512 bytes
bInterval 0
Endpoint Descriptor:
bLength 7
bDescriptorType 5
bEndpointAddress 0x06 EP 6 OUT
bmAttributes 2
Transfer Type Bulk
Synch Type None
Usage Type Data
wMaxPacketSize 0x0200 1x 512 bytes
bInterval 0
Device Qualifier (for other device speed):
bLength 10
bDescriptorType 6
bcdUSB 2.00

  bDeviceClass            0 (Defined at Interface level)
  bDeviceSubClass         0
  bDeviceProtocol         0

bMaxPacketSize0 64
bNumConfigurations 1
Device Status: 0x0000
(Bus Powered)

From ifconfig (after running some transfer speed tests):

          RX packets:61207 errors:0 dropped:0 overruns:0 frame:0
          TX packets:43886 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000
          RX bytes:78762017 (75.1 MiB)  TX bytes:27862511 (26.5 MiB)

From iwconfig (some AP details removed):

wlan2 IEEE 802.11bgn
Mode:Managed Frequency:2.422 GHz
Bit Rate=65 Mb/s Tx-Power=27 dBm
Retry long limit:7 RTS thr:off Fragment thr:off
Power Management:on
Link Quality=70/70 Signal level=-37 dBm
Rx invalid nwid:0 Rx invalid crypt:0 Rx invalid frag:0
Tx excessive retries:836 Invalid misc:37 Missed beacon:0

rc_stats output from sysfs:

type rate throughput ewma prob this prob this succ/attempt
success attempts
HT20/LGI MCS0 6.0 96.0 100.0 0( 0)
17 27
HT20/LGI MCS1 11.2 95.4 100.0 0( 0)
11 13
HT20/LGI MCS2 16.0 96.8 100.0 0( 0)
12 15
HT20/LGI MCS3 10.3 49.5 0.0 0( 0)
57 143
HT20/LGI MCS4 4.3 15.4 0.0 0( 0)
38 167
HT20/LGI MCS5 3.7 11.1 0.0 0( 0)
96 248
HT20/LGI MCS6 11.1 30.6 0.0 0( 0)
255 452

HT20/LGI    MCS7       20.4       52.2        0.0          0(  0) 11871       12290
HT20/LGI    MCS8        5.0       42.5        0.0          0(  0) 

18 38
HT20/LGI MCS9 9.2 44.1 0.0 0( 0)
17 42
HT20/LGI MCS10 12.7 45.3 100.0 0( 0)
24 69
HT20/LGI MCS11 10.8 32.0 0.0 0( 0)
66 293
HT20/LGI MCS12 7.7 18.0 0.0 0( 0)
74 361
HT20/LGI MCS13 11.7 23.9 0.0 0( 0)
69 348
HT20/LGI MCS14 16.3 31.3 0.0 0( 0)
99 369
HT20/LGI MCS15 20.3 37.3 0.0 0( 0)
392 632
HT20/SGI MCS0 6.9 100.0 100.0 0( 0)
1 1
HT20/SGI MCS1 12.9 100.0 100.0 0( 0)
1 1
HT20/SGI t MCS2 17.1 95.1 100.0 0( 0)
11 15
HT20/SGI MCS3 4.2 18.9 0.0 0( 0)
73 278
HT20/SGI MCS4 0.0 0.7 0.0 0( 0)
40 316
HT20/SGI MCS5 12.6 35.0 0.0 0( 0)
106 422
HT20/SGI MCS6 8.8 23.0 0.0 0( 0)
644 1063

HT20/SGI T PMCS7       40.3       97.7      100.0          2(  2) 28626       29571
HT20/SGI    MCS8        7.4       57.4      100.0          0(  0) 

25 47
HT20/SGI MCS9 5.4 24.1 0.0 0( 0)
18 65
HT20/SGI MCS10 0.0 2.8 0.0 0( 0)
31 161
HT20/SGI MCS11 9.6 26.8 100.0 0( 0)
54 386
HT20/SGI MCS12 12.7 27.9 0.0 0( 0)
65 448
HT20/SGI MCS13 10.9 21.3 0.0 0( 0)
94 464
HT20/SGI MCS14 15.7 29.0 0.0 0( 0)
219 560
HT20/SGI MCS15 19.8 35.0 0.0 0( 0)
365 597

Total packet count:: ideal 43018 lookaround 1308
Average A-MPDU length: 1.0

rt2800usb needs fixing. I'm able to reproduce these performance problems locally. They are quite hard to debug, and need some experiments. But I hope I will provide patches soon or leter.

Another thing to investigate. Can yo try to reproduce that with CONFIG_DEBUG_OBJECTS=y
CONFIG_DEBUG_OBJECTS_FREE=y CONFIG_DEBUG_OBJECTS_TIMERS=y CONFIG_DEBUG_OBJECTS_WORK=y CONFIG_DEBUG_OBJECTS_RCU_HEAD=y
CONFIG_DEBUG_SPINLOCK=y
CONFIG_DEBUG_MUTEXES=y
CONFIG_DEBUG_LOCK_ALLOC=y
CONFIG_PROVE_LOCKING=y
CONFIG_LOCKDEP=y
and see if these options print some aditional message when rmmod.

Thanks
Stanislaw

I really appreciate your work! If you want, I can do some tests for you. I've a rt3572 based USB WiFi dongle, which could be tested with a single threaded machine and a multi threaded one.

Good luck!
Andreas

Do you have any leads on what is going wrong? I'm not sure if the issue is with the higher MCS rates not working as well as they should, or with the rate control trying to use them even though they're not working well.

I tried with the Fedora kernel-debug kernel and didn't see much additional output. The stack trace might have a bit more detail:

rt2x00queue_index_inc
rt2x00lib_dmadone
rt2x00usb_kick_rx_entry
rt2x00usb_clear_entry
rt2x00lib_rxdone
rt2x00usb_work_rxdone
process_one_work
worker_thread
kthread
kernel_thread_helper

Seems like something that happens on rmmod with the device connected causes these rxdone/txdone functions to go into a tight loop somehow.

I just discovered that at least some problems are related with power save. After "iwconfig wlanX power off" I have pretty short ping times and good throughput, both comparable with vendor driver. But I did not check that on all adapters that I have yet.

Looking a bit more at that seem we stop and wake queues several times between sending each frame. Looks like that thing need to be optimized in mac80211, or some parameters have to be setup properly by rt2x00 ...

Also rt2800 PCI and SOC have PS disabled by default ...

I'm not able to reproduce this, perhaps this is related with debugfs or sysfs files you ware opening?

Thanks
Stanislaw

There is no bug with ping latencies when power save is enabled. Ping send packet every second, between that we put driver in power save mode (i.e. tell AP that we are sleeping and it has to buffer frame to us). When we send ping packet, we wake up and receive packet from a AP after longer time than in normal operation mode.

I did more testing here and I have one device that works very bad, no matter if PS is configured or not. It is

phy6 -> rt2x00_set_chip: Info - Chipset detected - rt: 3071, rf: 0008, rev: 021c.

I'm going to investigate problems with that device, hopefully these are the same problems that Robert and Andreas have.

Stanislaw

Am Thu, 22 Dec 2011 17:18:28 +0100
schrieb Stanislaw Gruszka <[email protected]>:

My device:

phy0 -> rt2x00_set_chip: Info - Chipset detected - rt: 3572, rf: 0009, rev: 0221.

phy0 -> rt2x00lib_request_firmware: Info - Loading firmware file 'rt2870.bin'. phy0 -> rt2x00lib_request_firmware: Info - Firmware detected - version: 0.236.

If CONFIG_RT2X00_DEBUG is switched on, I'm getting millions of entries like these in messages:

[48570.815137] phy0 -> rt2800usb_txdone_entry_check: Warning - Data pending for entry 26 in queue 2
[48570.815150] phy0 -> rt2800usb_txdone_entry_check: Warning - Data pending for entry 26 in queue 2
[48570.815162] phy0 -> rt2800usb_txdone_entry_check: Warning - Data pending for entry 26 in queue 2
[48570.815174] phy0 -> rt2800usb_txdone_entry_check: Warning - Data pending for entry 26 in queue 2

or

[49404.459991] phy0 -> rt2800usb_txdone_entry_check: Warning - TX status report missed for queue 2 entry 32
[49404.462098] phy0 -> rt2800usb_txdone_entry_check: Warning - TX status report missed for queue 2 entry 36
[49404.462123] phy0 -> rt2800usb_txdone_entry_check: Warning - TX status report missed for queue 2 entry 37
[49404.463596] phy0 -> rt2800usb_txdone_entry_check: Warning - TX status report missed for queue 2 entry 40
[49404.463618] phy0 -> rt2800usb_txdone_entry_check: Warning - TX status report missed for queue 2 entry 41

not that often:

[49390.002284] phy0 -> rt2x00usb_watchdog_tx_status: Warning - TX queue 2 status timed out, invoke forced tx handler

I can easily force them running netperf in both directions (TCP_MAERTS and TCP_STREAM). I would be happy with about 12 Mbit/s (that's what I get with the ralink driver with good conditions stable over more than just a few minutes) :-).

BTW: The patch in [1] breaks the driver completely (tested with compat-wireless 3.1rc1).

Thank you very much - it would be a great Christmas present if you could repair this driver!

If you need some testing - I'll do it!

Kind regards,
Andreas

[1]
http://rt2x00.serialmonkey.com/pipermail/users_rt2x00.serialmonkey.com/2011-December/004345.html

Hi Andreas,

I haven't reviewed these patches yet, but did you apply both patches that were sent out earlier today (which replace the one you mention here)?

Also, can you elaborate (preferably as a response to the actual patches) what exactly breaks with these patches? We need that kind of feedback to determine if we should apply these patches, as we (the maintainers) cannot always test and extensively review the patches in a short time.

---
Gertjan

Am Thu, 22 Dec 2011 18:51:12 +0100
schrieb Gertjan van Wingerde <[email protected]>:

Sorry, I missed this one:
http://rt2x00.serialmonkey.com/pipermail/users_rt2x00.serialmonkey.com/2011-December/004344.html

Please excuse me for being unperceptive.
These both patches don't change the behavior significantly for me.

I would like to answer directly to the list / thread, but unfortunately, I don't get any mail from it although I'm subscribed. Therefore I have to poll here:
http://rt2x00.serialmonkey.com/pipermail/users_rt2x00.serialmonkey.com/2011-December/thread.html

Thank you for your response,
kind regards,
Andreas

I confirmed that switching off power save doesn't improve the performance significantly with the Asus USB-N13. I suspect that there must be some difference between the 3070 device and the 3071/3072 that affects this, since the 3070 device I have works much better.