Modify

Opened 7 years ago

Closed 5 years ago

Last modified 4 years ago

#9099 closed defect (invalid)

ath9k: Intel-based wireless cards suffer periodic latency spikes & connection drops

Reported by: got_milk <ryan.morrison04@…> Owned by: nbd
Priority: high Milestone: Barrier Breaker 14.07
Component: base system Version: Trunk
Keywords: Cc:

Description

Tested with Intel WiFi Link 5300 AGN (Windows 7 64-bit, Intel drivers 13.3.x, 13.4.x and latest 13.5.x) & Netgear WNDR3700v1, OpenWrt Trunk r26251.

During periods where a load is being placed on the wireless connection, in periodic intervals the wireless connection will suffer latency spikes of 200ms or greater, and in certain instances the wireless connection will temporarily drop for up to 2-3 second periods. No kernel or system log entries are created.

This is reproducible on both the 2.4GHz and 5GHz wireless bands, at both 20MHz and 40MHz channel widths.

In idle states this issue cannot be reproduced.

This is an extension of closed ticket #8830.

Attachments (0)

Change History (26)

comment:1 Changed 7 years ago by jeyjay

This was not only an issue for Intel clients. My Broadcom Wifi and a friend's Broadcom Wifi was also affected. In contrast to Intel clients where the spikes occurs every few seconds, the spikes occurred once in awhile (every couple of minutes for a few seconds). But this *seems* to be solved with the latest changes (see ticket #8830). I will keep my eyes open for that issue. But at the moment I have no possibility to test an Intel client.

comment:2 Changed 7 years ago by got_milk <ryan.morrison04@…>

Built and tested r26273. An improvement was noted - while the latency spikes were occurring as usual, the connection drops were occurring far less frequently (I was able to achieve them once every 10-15 minutes instead of once every 2-5 minutes). Not sure if I fluked out for this one time, will test more tomorrow.

comment:3 Changed 7 years ago by got_milk <ryan.morrison04@…>

Built and tested r26356 with the patch supplied by nbd in ticket 8830 (http://nbd.name/900-nl80211_enable_qosdata.patch).

With this configuration, I can no longer produce any connection drops. The deauthenticated due to local deauth request messages have also entirely disappeared. However, the latency spikes continue to occur (adding on an additional 60-200ms for a few seconds).

comment:4 Changed 7 years ago by nbd

Please try this mac80211 patch: http://nbd.name/580-minstrel_aggr_delay.patch

comment:5 Changed 7 years ago by nbd

  • Owner changed from developers to nbd
  • Status changed from new to accepted

comment:6 follow-up: Changed 7 years ago by jeyjay

Patch added in r26444 / r26445. No need to install the above patch.

comment:7 in reply to: ↑ 6 Changed 7 years ago by Alex

Took some time to happen again, but still reproducible.
Then exactly the same - for 3 seconds its okay, then for more than 3 nothing is comming through. And that repeats until a client reboot.. . Damn combination with the Intel driver.

comment:8 Changed 7 years ago by vaden@…

There is a great deal of similarity between what you report immediately above and what we observe on the Ubiquiti Rocket M900 and Loco M900.

We are at trunk r26524.

What are your signal strengths?

comment:9 follow-up: Changed 7 years ago by vaden@…

Here's the output of iperf which demonstrates how similar our problems may be:

root@cpe-crockett:~# iperf -c shell.texoma.net -i 3 -t 60
------------------------------------------------------------
Client connecting to shell.texoma.net, TCP port 5001
TCP window size: 16.0 KByte (default)
------------------------------------------------------------
[  3] local 209.151.124.10 port 46997 connected with 209.151.96.22 port 5001
[ ID] Interval       Transfer     Bandwidth
[  3]  0.0- 3.0 sec   384 KBytes  1.05 Mbits/sec
[  3]  3.0- 6.0 sec   384 KBytes  1.05 Mbits/sec
[  3]  6.0- 9.0 sec   128 KBytes   350 Kbits/sec
[  3]  9.0-12.0 sec   128 KBytes   350 Kbits/sec
[  3] 12.0-15.0 sec   128 KBytes   350 Kbits/sec
[  3] 15.0-18.0 sec   256 KBytes   699 Kbits/sec
[  3] 18.0-21.0 sec   640 KBytes  1.75 Mbits/sec
[  3] 21.0-24.0 sec   640 KBytes  1.75 Mbits/sec
[  3] 24.0-27.0 sec  0.00 Bytes  0.00 bits/sec
[  3] 27.0-30.0 sec   256 KBytes   699 Kbits/sec
[  3] 30.0-33.0 sec   256 KBytes   699 Kbits/sec
[  3] 33.0-36.0 sec   512 KBytes  1.40 Mbits/sec
[  3] 36.0-39.0 sec   384 KBytes  1.05 Mbits/sec
[  3] 39.0-42.0 sec  0.00 Bytes  0.00 bits/sec
[  3] 42.0-45.0 sec  0.00 Bytes  0.00 bits/sec
[  3] 45.0-48.0 sec  0.00 Bytes  0.00 bits/sec
[  3] 48.0-51.0 sec  0.00 Bytes  0.00 bits/sec
[  3] 51.0-54.0 sec  0.00 Bytes  0.00 bits/sec
[  3] 54.0-57.0 sec   384 KBytes  1.05 Mbits/sec
[  3] 57.0-60.0 sec   128 KBytes   350 Kbits/sec
[  3]  0.0-60.3 sec  4.63 MBytes   643 Kbits/sec
root@cpe-crockett:~# 

comment:10 in reply to: ↑ 9 Changed 7 years ago by vaden@…

During periods of poor connectivity, load is unusually high:

root@cpe-crockett:~# uptime

08:33:50 up 8:33, load average: 3.91, 1.64, 0.73

and system can take several seconds to respond to a cli command.

comment:11 Changed 7 years ago by nbd

Larry, just because the iperf output is similar does not mean the issues is related. In this case I'm quite sure it's something completely unrelated.

comment:12 Changed 7 years ago by anonymous

Read and understood.

regards/ldv

comment:13 follow-up: Changed 7 years ago by nbd

Please try r26545

comment:14 in reply to: ↑ 13 ; follow-up: Changed 7 years ago by Alex

Tested with r26716.

Was much more stable!
But only until i changed powersafe mode on the client which lead to a: deauthenticated due to local deauth request. (But unfortunately this was not reproduceable so easily just with changing powersafe mode the next time, regardless if it lead to a deauthentication or not.)

After the connection came back (just 1-2 seconds later) the bug was there again. Propably this hints you to some useful direction. (The deauthentication happend more often before, so propably the reason why its more stable now is just that the deauthentication happens far less?)

The last times there was always a deautentication (followed by: authenticated, associated (aid 2), pairwise key handshake completed (RSN)) when the bug appeared.

And just informational - the WPA: received EAPOL-Key 2/2 Group with unexpected replay counter now happens more often than some versions before.

Currently testing r26771, but I don't see anything changed for this case in that version.

Replying to nbd:

Please try r26545

comment:15 in reply to: ↑ 14 Changed 7 years ago by anonymous

I'm behind but r26771 gave me:

May 17 18:39:17 OpenWrt daemon.info hostapd: wlan0: STA 00:xx:xx:xx:xx:xx WPA: group key handshake completed (RSN)
May 17 18:39:17 OpenWrt daemon.info hostapd: wlan0: STA 00:yy:yy:yy:yy:yy WPA: group key handshake completed (RSN)
May 17 18:49:17 OpenWrt daemon.info hostapd: wlan0: STA 00:xx:xx:xx:xx:xx WPA: group key handshake completed (RSN)
May 17 18:49:20 OpenWrt daemon.info hostapd: wlan0: STA 00:yy:yy:yy:yy:yy IEEE 802.11: deauthenticated due to local deauth request
May 17 18:49:20 OpenWrt daemon.info hostapd: wlan0: STA 00:yy:yy:yy:yy:yy IEEE 802.11: authenticated
May 17 18:49:20 OpenWrt daemon.info hostapd: wlan0: STA 00:yy:yy:yy:yy:yy IEEE 802.11: associated (aid 2)
May 17 18:49:20 OpenWrt daemon.info hostapd: wlan0: STA 00:yy:yy:yy:yy:yy WPA: pairwise key handshake completed (RSN)
-
May 17 18:49:24 OpenWrt daemon.info hostapd: wlan0: STA 00:yy:yy:yy:yy:yy IEEE 802.11: authenticated
May 17 18:49:24 OpenWrt daemon.info hostapd: wlan0: STA 00:yy:yy:yy:yy:yy IEEE 802.11: associated (aid 2)
May 17 18:49:24 OpenWrt daemon.info hostapd: wlan0: STA 00:yy:yy:yy:yy:yy WPA: pairwise key handshake completed (RSN)
...
repeated every 3 to 4 seconds
...
May 17 18:53:16 OpenWrt daemon.info hostapd: wlan0: STA 00:yy:yy:yy:yy:yy IEEE 802.11: authenticated
May 17 18:53:16 OpenWrt daemon.info hostapd: wlan0: STA 00:yy:yy:yy:yy:yy IEEE 802.11: associated (aid 2)
May 17 18:53:16 OpenWrt daemon.info hostapd: wlan0: STA 00:yy:yy:yy:yy:yy WPA: pairwise key handshake completed (RSN)

What was better is, that a client interface disable/enable was enough.
Before a reboot was necessary.
So now testing current trunk again.

Replying to Alex:

Tested with r26716.

Was much more stable!
But only until i changed powersafe mode on the client which lead to a: deauthenticated due to local deauth request. (But unfortunately this was not reproduceable so easily just with changing powersafe mode the next time, regardless if it lead to a deauthentication or not.)

After the connection came back (just 1-2 seconds later) the bug was there again. Propably this hints you to some useful direction. (The deauthentication happend more often before, so propably the reason why its more stable now is just that the deauthentication happens far less?)

The last times there was always a deautentication (followed by: authenticated, associated (aid 2), pairwise key handshake completed (RSN)) when the bug appeared.

And just informational - the WPA: received EAPOL-Key 2/2 Group with unexpected replay counter now happens more often than some versions before.

Currently testing r26771, but I don't see anything changed for this case in that version.

Replying to nbd:

Please try r26545

comment:16 follow-ups: Changed 7 years ago by nbd

Please try current trunk. There were some hostapd updates which might be related to this issue.

comment:17 in reply to: ↑ 16 Changed 7 years ago by anonymous

Replying to nbd:

Please try current trunk. There were some hostapd updates which might be related to this issue.

nothing to change,still have ' deauthenticated due to local deauth request
'

comment:18 in reply to: ↑ 16 Changed 7 years ago by anonymous

Still appearing on r27589.

Replying to nbd:

Please try current trunk. There were some hostapd updates which might be related to this issue.

comment:19 Changed 7 years ago by anonymous

comment:20 Changed 7 years ago by nbd

Please try latest version again, the removal of the 420-* patch and some other changes have improved stability

comment:21 Changed 6 years ago by nbd

  • Resolution set to no_response
  • Status changed from accepted to closed

comment:22 Changed 5 years ago by pontillo@…

  • Resolution no_response deleted
  • Status changed from closed to reopened

I'm using OpenWrt Attitude Adjustment 12.09-rc1 / LuCI 0.11 Branch (0.11+svn9425) and seeing this issue. (on a Buffalo WRZ-HP-G300NH, if it matters.)

I tried modifying the script in /lib/wifi to renice hostapd but I ended up having to enter failsafe mode; the network wouldn't come up. Any suggestions of what to try to do to debug this?

Here's what I see in the logs:

Dec 27 13:11:09 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: disconnected due to excessive missing ACKs
Dec 27 13:11:39 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: deauthenticated due to inactivity (timer DEAUTH/REMOVE)
Dec 27 13:11:39 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: authenticated
Dec 27 13:11:39 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: associated (aid 1)
Dec 27 13:11:39 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx WPA: pairwise key handshake completed (RSN)
Dec 27 13:13:57 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: authenticated
Dec 27 13:13:57 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: associated (aid 1)

comment:23 Changed 5 years ago by pontillo@…

Here's the full log for that mac address.

Dec 27 12:56:30 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: authenticated
Dec 27 12:56:30 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: associated (aid 1)
Dec 27 12:56:30 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx WPA: pairwise key handshake completed (RSN)
Dec 27 12:57:29 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: authenticated
Dec 27 12:57:29 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: associated (aid 1)
Dec 27 12:57:29 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx WPA: pairwise key handshake completed (RSN)
Dec 27 12:57:55 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: authenticated
Dec 27 12:57:55 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: associated (aid 1)
Dec 27 12:57:55 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx WPA: pairwise key handshake completed (RSN)
Dec 27 13:00:50 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: disconnected due to excessive missing ACKs
Dec 27 13:01:20 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: deauthenticated due to inactivity (timer DEAUTH/REMOVE)
Dec 27 13:01:20 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: authenticated
Dec 27 13:01:20 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: authenticated
Dec 27 13:01:20 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: associated (aid 1)
Dec 27 13:01:20 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: associated (aid 1)
Dec 27 13:01:21 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx WPA: pairwise key handshake completed (RSN)
Dec 27 13:05:24 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: disconnected due to excessive missing ACKs
Dec 27 13:05:54 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: deauthenticated due to inactivity (timer DEAUTH/REMOVE)
Dec 27 13:05:55 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: authenticated
Dec 27 13:05:55 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: associated (aid 1)
Dec 27 13:05:55 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx WPA: pairwise key handshake completed (RSN)
Dec 27 13:07:51 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx WPA: group key handshake completed (RSN)
Dec 27 13:11:09 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: disconnected due to excessive missing ACKs
Dec 27 13:11:39 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: deauthenticated due to inactivity (timer DEAUTH/REMOVE)
Dec 27 13:11:39 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: authenticated
Dec 27 13:11:39 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: associated (aid 1)
Dec 27 13:11:39 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx WPA: pairwise key handshake completed (RSN)
Dec 27 13:13:57 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: authenticated
Dec 27 13:13:57 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: associated (aid 1)
Dec 27 13:13:57 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx WPA: pairwise key handshake completed (RSN)
Dec 27 13:17:51 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx WPA: group key handshake completed (RSN)
Dec 27 13:27:51 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx WPA: group key handshake completed (RSN)
Dec 27 13:37:51 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx WPA: group key handshake completed (RSN)
Dec 27 13:41:34 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: authenticated
Dec 27 13:41:34 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: associated (aid 1)
Dec 27 13:41:34 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx WPA: pairwise key handshake completed (RSN)
Dec 27 13:47:07 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: disassociated due to inactivity
Dec 27 13:47:08 OpenWrt daemon.info hostapd: wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: deauthenticated due to inactivity (timer DEAUTH/REMOVE)

This is an Intel card on Windows 7 running on 2.4 GHz with WPA2-PSK/AES.

comment:24 Changed 5 years ago by pontillo@…

OK, never trust Microsoft to keep your wireless drivers up to date. I was using the driver update feature in the Windows 7 Device Manager to check if the wireless drivers were up-to-date. It said they were. I then went to an Intel site and it updated the driver by sever major revisions into the future. The problem is now resolved. It was the Intel wireless drivers.

Sorry to re-open such an old defect. Hope this helps someone else.

comment:25 Changed 5 years ago by jow

  • Resolution set to invalid
  • Status changed from reopened to closed

comment:26 Changed 4 years ago by jow

  • Milestone changed from Attitude Adjustment 12.09 to Barrier Breaker 14.07

Milestone Attitude Adjustment 12.09 deleted

Add Comment

Modify Ticket

Action
as closed .
The resolution will be deleted. Next status will be 'reopened'.
Author


E-mail address and user name can be saved in the Preferences.

 
Note: See TracTickets for help on using tickets.