From owner-freebsd-wireless@FreeBSD.ORG Sun Mar 25 18:27:42 2012 Return-Path: Delivered-To: freebsd-wireless@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id 5CDFB1065674; Sun, 25 Mar 2012 18:27:42 +0000 (UTC) (envelope-from lytboris@gmail.com) Received: from mail-wi0-f178.google.com (mail-wi0-f178.google.com [209.85.212.178]) by mx1.freebsd.org (Postfix) with ESMTP id B08148FC08; Sun, 25 Mar 2012 18:27:41 +0000 (UTC) Received: by wibhq7 with SMTP id hq7so2988371wib.13 for ; Sun, 25 Mar 2012 11:27:34 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20120113; h=mime-version:date:message-id:subject:from:to:cc:content-type; bh=JV67Kk2695VMY6COz7YCBRQQQU7160wJvz7ReXjDdaw=; b=mheqPsDTj2ulcnMLbsKcRiXZ9byl0fQACJ8erBlRFkNlGiLPZhVPvjWyx7PsOQpCXh A8UAdxXfWw+02K3FCZj5AI4CVFny2IchYl615z4QihYFCQXf291yJw0pMfmi3+OaDnOq d/0G1txh1cA5200lxcb7PwsPUG3BlThINUmla5gq0WoGGVrVuneDbVUitUVIWiVTfcUc VJRjVI4DAtOshYlxKPyWui8XVXrD47gmWXdwQDbkfqtm/2tkeRFx1ob+/bN7Upt4JqWc DyXXRH2oJZxDrttsVbjhTKVdCVgR0NqKZGcOHZyHqIQ0gE19rTcNYp7KKABwMWRqjXlP WH2g== MIME-Version: 1.0 Received: by 10.180.104.65 with SMTP id gc1mr12411471wib.13.1332700054639; Sun, 25 Mar 2012 11:27:34 -0700 (PDT) Received: by 10.223.72.6 with HTTP; Sun, 25 Mar 2012 11:27:34 -0700 (PDT) Date: Sun, 25 Mar 2012 22:27:34 +0400 Message-ID: From: Lytochkin Boris To: freebsd-wireless@freebsd.org Content-Type: text/plain; charset=ISO-8859-1 Cc: Subject: [ath][CURRENT] Triangle-shaped network performance X-BeenThere: freebsd-wireless@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: "Discussions of 802.11 stack, tools device driver development." List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Sun, 25 Mar 2012 18:27:42 -0000 Hi. I'm digging in appalling wireless network performance on my home router: fetching file from local NAS can run an 20kb/s rates while running 802.11n capable ath card. I found some curious fact: network performance is lagging periodically in triangle-shaped form. Look an this ping to router from my laptop: >ping 192.168.1.5 -t -w 1 Reply from 192.168.1.5: bytes=32 time=78ms TTL=64 Reply from 192.168.1.5: bytes=32 time=54ms TTL=64 Reply from 192.168.1.5: bytes=32 time=77ms TTL=64 Reply from 192.168.1.5: bytes=32 time=100ms TTL=64 Reply from 192.168.1.5: bytes=32 time=123ms TTL=64 Reply from 192.168.1.5: bytes=32 time=164ms TTL=64 Reply from 192.168.1.5: bytes=32 time=189ms TTL=64 Reply from 192.168.1.5: bytes=32 time=177ms TTL=64 Reply from 192.168.1.5: bytes=32 time=199ms TTL=64 Reply from 192.168.1.5: bytes=32 time=220ms TTL=64 Reply from 192.168.1.5: bytes=32 time=243ms TTL=64 Reply from 192.168.1.5: bytes=32 time=265ms TTL=64 Reply from 192.168.1.5: bytes=32 time=288ms TTL=64 Reply from 192.168.1.5: bytes=32 time=310ms TTL=64 Reply from 192.168.1.5: bytes=32 time=340ms TTL=64 Reply from 192.168.1.5: bytes=32 time=367ms TTL=64 Reply from 192.168.1.5: bytes=32 time=373ms TTL=64 Reply from 192.168.1.5: bytes=32 time=416ms TTL=64 Reply from 192.168.1.5: bytes=32 time=414ms TTL=64 Reply from 192.168.1.5: bytes=32 time=425ms TTL=64 Timeout. Reply from 192.168.1.5: bytes=32 time=39ms TTL=64 Reply from 192.168.1.5: bytes=32 time=57ms TTL=64 Reply from 192.168.1.5: bytes=32 time=81ms TTL=64 Reply from 192.168.1.5: bytes=32 time=104ms TTL=64 Reply from 192.168.1.5: bytes=32 time=130ms TTL=64 Reply from 192.168.1.5: bytes=32 time=147ms TTL=64 Reply from 192.168.1.5: bytes=32 time=174ms TTL=64 Reply from 192.168.1.5: bytes=32 time=193ms TTL=64 Reply from 192.168.1.5: bytes=32 time=214ms TTL=64 Timeout. Reply from 192.168.1.5: bytes=32 time=297ms TTL=64 Reply from 192.168.1.5: bytes=32 time=314ms TTL=64 Reply from 192.168.1.5: bytes=32 time=330ms TTL=64 Reply from 192.168.1.5: bytes=32 time=355ms TTL=64 Reply from 192.168.1.5: bytes=32 time=376ms TTL=64 Reply from 192.168.1.5: bytes=32 time=402ms TTL=64 Reply from 192.168.1.5: bytes=32 time=422ms TTL=64 Reply from 192.168.1.5: bytes=32 time=445ms TTL=64 Reply from 192.168.1.5: bytes=32 time=467ms TTL=64 Timeout. Reply from 192.168.1.5: bytes=32 time=40ms TTL=64 Reply from 192.168.1.5: bytes=32 time=62ms TTL=64 Reply from 192.168.1.5: bytes=32 time=96ms TTL=64 Reply from 192.168.1.5: bytes=32 time=116ms TTL=64 Reply from 192.168.1.5: bytes=32 time=133ms TTL=64 Reply from 192.168.1.5: bytes=32 time=159ms TTL=64 Reply from 192.168.1.5: bytes=32 time=176ms TTL=64 Reply from 192.168.1.5: bytes=32 time=188ms TTL=64 Reply from 192.168.1.5: bytes=32 time=223ms TTL=64 Reply from 192.168.1.5: bytes=32 time=233ms TTL=64 Reply from 192.168.1.5: bytes=32 time=321ms TTL=64 Reply from 192.168.1.5: bytes=32 time=285ms TTL=64 Reply from 192.168.1.5: bytes=32 time=298ms TTL=64 Reply from 192.168.1.5: bytes=32 time=320ms TTL=64 Reply from 192.168.1.5: bytes=32 time=350ms TTL=64 Reply from 192.168.1.5: bytes=32 time=374ms TTL=64 Reply from 192.168.1.5: bytes=32 time=396ms TTL=64 Reply from 192.168.1.5: bytes=32 time=420ms TTL=64 Timeout. Timeout. Reply from 192.168.1.5: bytes=32 time=24ms TTL=64 Reply from 192.168.1.5: bytes=32 time=43ms TTL=64 Reply from 192.168.1.5: bytes=32 time=65ms TTL=64 Reply from 192.168.1.5: bytes=32 time=89ms TTL=64 Reply from 192.168.1.5: bytes=32 time=109ms TTL=64 Reply from 192.168.1.5: bytes=32 time=131ms TTL=64 Reply from 192.168.1.5: bytes=32 time=154ms TTL=64 Reply from 192.168.1.5: bytes=32 time=176ms TTL=64 Reply from 192.168.1.5: bytes=32 time=200ms TTL=64 Reply from 192.168.1.5: bytes=32 time=221ms TTL=64 Reply from 192.168.1.5: bytes=32 time=244ms TTL=64 Reply from 192.168.1.5: bytes=32 time=268ms TTL=64 Reply from 192.168.1.5: bytes=32 time=290ms TTL=64 Reply from 192.168.1.5: bytes=32 time=314ms TTL=64 Reply from 192.168.1.5: bytes=32 time=357ms TTL=64 Reply from 192.168.1.5: bytes=32 time=359ms TTL=64 Reply from 192.168.1.5: bytes=32 time=392ms TTL=64 Reply from 192.168.1.5: bytes=32 time=430ms TTL=64 Reply from 192.168.1.5: bytes=32 time=429ms TTL=64 Reply from 192.168.1.5: bytes=32 time=448ms TTL=64 Timeout. Timeout. Reply from 192.168.1.5: bytes=32 time=66ms TTL=64 Reply from 192.168.1.5: bytes=32 time=89ms TTL=64 Reply from 192.168.1.5: bytes=32 time=118ms TTL=64 Reply from 192.168.1.5: bytes=32 time=138ms TTL=64 Reply from 192.168.1.5: bytes=32 time=154ms TTL=64 Reply from 192.168.1.5: bytes=32 time=163ms TTL=64 Reply from 192.168.1.5: bytes=32 time=185ms TTL=64 Reply from 192.168.1.5: bytes=32 time=227ms TTL=64 Reply from 192.168.1.5: bytes=32 time=229ms TTL=64 Reply from 192.168.1.5: bytes=32 time=261ms TTL=64 Reply from 192.168.1.5: bytes=32 time=274ms TTL=64 Reply from 192.168.1.5: bytes=32 time=297ms TTL=64 Reply from 192.168.1.5: bytes=32 time=318ms TTL=64 Reply from 192.168.1.5: bytes=32 time=340ms TTL=64 Reply from 192.168.1.5: bytes=32 time=366ms TTL=64 Reply from 192.168.1.5: bytes=32 time=388ms TTL=64 Reply from 192.168.1.5: bytes=32 time=408ms TTL=64 Reply from 192.168.1.5: bytes=32 time=431ms TTL=64 Reply from 192.168.1.5: bytes=32 time=452ms TTL=64 Timeout. Reply from 192.168.1.5: bytes=32 time=38ms TTL=64 Reply from 192.168.1.5: bytes=32 time=62ms TTL=64 Reply from 192.168.1.5: bytes=32 time=83ms TTL=64 Reply from 192.168.1.5: bytes=32 time=105ms TTL=64 Reply from 192.168.1.5: bytes=32 time=128ms TTL=64 Reply from 192.168.1.5: bytes=32 time=151ms TTL=64 Reply from 192.168.1.5: bytes=32 time=171ms TTL=64 Reply from 192.168.1.5: bytes=32 time=195ms TTL=64 Reply from 192.168.1.5: bytes=32 time=217ms TTL=64 Reply from 192.168.1.5: bytes=32 time=248ms TTL=64 Reply from 192.168.1.5: bytes=32 time=278ms TTL=64 Reply from 192.168.1.5: bytes=32 time=291ms TTL=64 Reply from 192.168.1.5: bytes=32 time=304ms TTL=64 Reply from 192.168.1.5: bytes=32 time=317ms TTL=64 Reply from 192.168.1.5: bytes=32 time=337ms TTL=64 Reply from 192.168.1.5: bytes=32 time=339ms TTL=64 Reply from 192.168.1.5: bytes=32 time=361ms TTL=64 Reply from 192.168.1.5: bytes=32 time=383ms TTL=64 Reply from 192.168.1.5: bytes=32 time=405ms TTL=64 Reply from 192.168.1.5: bytes=32 time=427ms TTL=64 Timeout. Reply from 192.168.1.5: bytes=32 time=42ms TTL=64 This hell happens some minutes after successful boot and working with ~1ms pings. Than it booms and this triangle nightmare starts. >uname -a FreeBSD gate.home 10.0-CURRENT FreeBSD 10.0-CURRENT #1: Fri Feb 17 23:48:28 MSK 2012 root@gate.home:/usr/obj/usr/src/sys/GATEv2 i386 (I tried today's kernel - bug is still there regardless of ATH_ENABLE_11N option). >ifconfig -v wlan0 wlan0: flags=8843 metric 0 mtu 1500 ether b0:48:7a:da:0e:59 inet6 fe80::b248:7aff:feda:e59%wlan0 prefixlen 64 tentative scopeid 0x10 inet 192.168.2.1 netmask 0xffffff00 broadcast 192.168.2.255 nd6 options=29 media: IEEE 802.11 Wireless Ethernet autoselect mode 11ng status: running ssid starlink channel 11 (2462 MHz 11g ht/40-) bssid b0:48:7a:da:0e:59 regdomain ETSI country RU indoor ecm authmode WPA -wps -tsn privacy MIXED deftxkey 3 AES-CCM 2:128-bit AES-CCM 3:128-bit powersavemode OFF powersavesleep 100 txpower 50 txpowmax 50.0 -dotd rtsthreshold 2346 fragthreshold 2346 bmiss 7 11a ucast NONE mgmt 6 Mb/s mcast 6 Mb/s maxretry 6 11b ucast NONE mgmt 1 Mb/s mcast 1 Mb/s maxretry 6 11g ucast NONE mgmt 1 Mb/s mcast 1 Mb/s maxretry 6 turboA ucast NONE mgmt 6 Mb/s mcast 6 Mb/s maxretry 6 turboG ucast NONE mgmt 1 Mb/s mcast 1 Mb/s maxretry 6 sturbo ucast NONE mgmt 6 Mb/s mcast 6 Mb/s maxretry 6 11na ucast NONE mgmt 12 MCS mcast 12 MCS maxretry 6 11ng ucast NONE mgmt 2 MCS mcast 2 MCS maxretry 6 half ucast NONE mgmt 3 Mb/s mcast 3 Mb/s maxretry 6 quarter ucast NONE mgmt 1 Mb/s mcast 1 Mb/s maxretry 6 scanvalid 60 -bgscan bgscanintvl 300 bgscanidle 250 roam:11a rssi 7dBm rate 12 Mb/s roam:11b rssi 7dBm rate 1 Mb/s roam:11g rssi 7dBm rate 5 Mb/s roam:turboA rssi 7dBm rate 12 Mb/s roam:turboG rssi 7dBm rate 12 Mb/s roam:sturbo rssi 7dBm rate 12 Mb/s roam:11na rssi 7dBm MCS 1 roam:11ng rssi 7dBm MCS 1 roam:half rssi 7dBm rate 6 Mb/s roam:quarter rssi 7dBm rate 3 Mb/s -pureg protmode CTS ht htcompat ampdu ampdulimit 64k ampdudensity 8 amsdu shortgi htprotmode RTSCTS -puren -smps -rifs wme burst -dwds -hidessid apbridge dtimperiod 1 doth -dfs inact bintval 1000 AC_BE cwmin 4 cwmax 6 aifs 3 txopLimit 0 -acm ack cwmin 4 cwmax 10 aifs 3 txopLimit 0 -acm AC_BK cwmin 4 cwmax 10 aifs 7 txopLimit 0 -acm ack cwmin 4 cwmax 10 aifs 7 txopLimit 0 -acm AC_VI cwmin 3 cwmax 4 aifs 1 txopLimit 94 -acm ack cwmin 3 cwmax 4 aifs 2 txopLimit 94 -acm AC_VO cwmin 2 cwmax 3 aifs 1 txopLimit 47 -acm ack cwmin 2 cwmax 3 aifs 2 txopLimit 47 -acm groups: wlan ~>athstats 17532 data frames received 12450 data frames transmit 4 tx frames with an alternate rate 2060 long on-chip tx retries 187 tx failed 'cuz too many retries MCS5 current transmit rate 417 tx frames with no ack marked 11805 tx frames with short preamble 1003 rx failed 'cuz of bad CRC 1495 beacons transmitted 26 periodic calibrations -0/+0 TDMA slot adjust (usecs, smoothed) 63 rssi of last ack 64 avg recv rssi -96 rx noise floor 229 tx frames through raw api 1726 A-MPDU sub-frames received 513 CRC errors for non-last A-MPDU subframes 272 CRC errors for last subframe in an A-MPDU 308 A-MPDU sub-frame TX attempt success 10389 cabq frames transmitted 746 cabq xmit overflowed beacon interval 1 OFDM weak signal detect 388 listen time 3 ANI disabled OFDM weak signal detect 1 ANI disabled CCK weak signal threshold 21671 cumulative OFDM phy error count 130597 cumulative CCK phy error count 30 ANI forced listen time to zero 2060 missing ACK's 1374 bad FCS 13 average rssi (beacons only) Antenna profile: [0] tx 12052 rx 12 [1] tx 0 rx 17520 >pciconf -l -v ... ath0@pci0:2:13:0: class=0x028000 card=0x2091168c chip=0x0029168c rev=0x01 hdr=0x00 vendor = 'Atheros Communications Inc.' device = 'AR922X Wireless Network Adapter' class = network ... Do somebody have any ideas where to dig next? ps. There is LOR on router startup: Mar 25 22:11:49 gate kernel: lock order reversal: Mar 25 22:11:49 gate kernel: 1st 0xc54b46c0 ath0_node_lock (ath0_node_lock) @ /usr/src/sys/net80211/ieee80211_ioctl.c:1341 Mar 25 22:11:49 gate kernel: 2nd 0xc54b3014 ath0_com_lock (ath0_com_lock) @ /usr/src/sys/net80211/ieee80211_node.c:2510 Mar 25 22:11:49 gate kernel: KDB: stack backtrace: Mar 25 22:11:49 gate kernel: db_trace_self_wrapper(c0cae317,6372732f,7379732f,74656e2f,31323038,...) at db_trace_self_wrapper+0x26 Mar 25 22:11:49 gate kernel: kdb_backtrace(c086e65b,c0cb1d64,c0ee7060,9ce,d6f478d8,...) at kdb_backtrace+0x2a Mar 25 22:11:49 gate kernel: _witness_debugger(c0cb1d64,c54b3014,c54b3004,c3d55590,c0cc7c06,...) at _witness_debugger+0x25 Mar 25 22:11:49 gate kernel: witness_checkorder(c54b3014,9,c0cc7c06,9ce,0,...) at witness_checkorder+0x86b Mar 25 22:11:49 gate kernel: _mtx_lock_flags(c54b3014,0,c0cc7c06,9ce,64,...) at _mtx_lock_flags+0xcc Mar 25 22:11:49 gate kernel: ieee80211_node_leave(c6ef4000,c0,2,c6ef4000,c54b46ac,...) at ieee80211_node_leave+0xb3 Mar 25 22:11:49 gate kernel: domlme(d6f47974,c6ef4000,c0cc7140,53d,d6f479a6,...) at domlme+0x83 Mar 25 22:11:49 gate kernel: setmlme_common(2,d6f479a2,2a,30000,11080002,...) at setmlme_common+0x132 Mar 25 22:11:49 gate kernel: ieee80211_ioctl_setmlme(c0ee7060,c6a1cc30,c0ee7060,c0d4ccd8,c6a1cb80,...) at ieee80211_ioctl_setmlme+0xa4 Mar 25 22:11:49 gate kernel: ieee80211_ioctl_set80211(c6a1cb80,1b9,d6f47a80,c0882524,c54b3000,...) at ieee80211_ioctl_set80211+0x554 Mar 25 22:11:49 gate kernel: ieee80211_ioctl(c646f400,801c69ea,c551ecc0,c0cbe319,d6f47ac0,...) at ieee80211_ioctl+0x300 Mar 25 22:11:49 gate kernel: in_control(c6a661a0,801c69ea,c551ecc0,c646f400,c6a1cb80,...) at in_control+0x235 Mar 25 22:11:49 gate kernel: ifioctl(c6a661a0,801c69ea,c551ecc0,c6a1cb80,c68fa9d8,...) at ifioctl+0x18c4 Mar 25 22:11:49 gate kernel: soo_ioctl(c68fa9d8,801c69ea,c551ecc0,c3da2180,c6a1cb80,...) at soo_ioctl+0x44f Mar 25 22:11:49 gate kernel: kern_ioctl(c6a1cb80,3,801c69ea,c551ecc0,f47cec,...) at kern_ioctl+0x22d Mar 25 22:11:49 gate kernel: sys_ioctl(c6a1cb80,d6f47cec,48,19ce87f7,206,...) at sys_ioctl+0x13f Mar 25 22:11:49 gate kernel: syscall(d6f47d28) at syscall+0x2e0 Mar 25 22:11:49 gate kernel: Xint0x80_syscall() at Xint0x80_syscall+0x21 Mar 25 22:11:49 gate kernel: --- syscall (54, FreeBSD ELF32, sys_ioctl), eip = 0x2821d143, esp = 0xbfbfeabc, ebp = 0xbfbfeb18 --- -- Boris Lytochkin