From owner-freebsd-wireless@FreeBSD.ORG Sun Mar 25 18:44:57 2012 Return-Path: Delivered-To: freebsd-wireless@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [69.147.83.52]) by hub.freebsd.org (Postfix) with ESMTP id 82325106566C; Sun, 25 Mar 2012 18:44:57 +0000 (UTC) (envelope-from adrian.chadd@gmail.com) Received: from mail-iy0-f182.google.com (mail-iy0-f182.google.com [209.85.210.182]) by mx1.freebsd.org (Postfix) with ESMTP id 3360F8FC16; Sun, 25 Mar 2012 18:44:56 +0000 (UTC) Received: by iahk25 with SMTP id k25so9357021iah.13 for ; Sun, 25 Mar 2012 11:44:56 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20120113; h=message-id:date:from:to:cc:reply-to:subject:in-reply-to:x-mailer :mime-version:content-type; bh=X4r+FqnKHHEpz8YQy90IYFFkeFYG6KGlqISxVrYsX90=; b=c/hHac677RCVzohYFNyO4IxBZVmjshLEbrBi3ScWUClnf8ZoNSTVBlQwoS9RQGA3tZ haAJhoff6UInvlBjoExyJtAmbRhhA3ZAwI00Cuml83vckPec2YJfTSdFULwTr+Pn7neD lb3ujNI60c1PW7ph3azJv5My0kTJ7lngR9dQpY0OupBibEk7XyO99C2lqwYqzIt7KdcF /10rt+dX4n7Ku3hge6KNMmKT6xrkS+80pBwVq5eyps6G1wfCUpCCOACGfu9X5+9SEzD2 YzhWW51i0izq8ZBX9YuPQ8p+l73YNF+IRsqOydnHyUbdBhQSfYUHX/XSFSJ0f7bG7vpq bIVw== Received: by 10.68.129.133 with SMTP id nw5mr47351071pbb.159.1332701096267; Sun, 25 Mar 2012 11:44:56 -0700 (PDT) Received: from www.palm.com ([32.153.132.214]) by mx.google.com with ESMTPS id w10sm10704915pbb.20.2012.03.25.11.44.47 (version=SSLv3 cipher=OTHER); Sun, 25 Mar 2012 11:44:55 -0700 (PDT) Message-ID: <4f6f67a7.4a0c440a.3941.ffffc865@mx.google.com> Date: Sun, 25 Mar 2012 11:44:49 -0700 From: "Adrian Chadd" To: "Lytochkin Boris" , "freebsd-wireless@freebsd.org" In-Reply-To: X-Mailer: Palm webOS v1.0.1 MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: quoted-printable X-Content-Filtered-By: Mailman/MimeDel 2.1.5 Cc: Subject: Re: [ath][CURRENT] Triangle-shaped network performance X-BeenThere: freebsd-wireless@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list Reply-To: Adrian Chadd 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:44:57 -0000 Hi, The LOR is known. I'd love to fix it but I have other things to do first. Try running athstats 1 and watch the rate of errors change over time. Disable HT40 as on ongested channels it's going to behave very oddly. Adrian Sent from my Palm Pre on AT&T On Mar 25, 2012 11:27 AM, Lytochkin Boris <lytboris@gmail.com> wrote:= 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=3D32 time=3D78ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D54ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D77ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D100ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D123ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D164ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D189ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D177ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D199ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D220ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D243ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D265ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D288ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D310ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D340ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D367ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D373ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D416ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D414ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D425ms TTL=3D64 Timeout. Reply from 192.168.1.5: bytes=3D32 time=3D39ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D57ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D81ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D104ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D130ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D147ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D174ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D193ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D214ms TTL=3D64 Timeout. Reply from 192.168.1.5: bytes=3D32 time=3D297ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D314ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D330ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D355ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D376ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D402ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D422ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D445ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D467ms TTL=3D64 Timeout. Reply from 192.168.1.5: bytes=3D32 time=3D40ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D62ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D96ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D116ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D133ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D159ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D176ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D188ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D223ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D233ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D321ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D285ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D298ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D320ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D350ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D374ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D396ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D420ms TTL=3D64 Timeout. Timeout. Reply from 192.168.1.5: bytes=3D32 time=3D24ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D43ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D65ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D89ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D109ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D131ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D154ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D176ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D200ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D221ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D244ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D268ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D290ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D314ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D357ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D359ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D392ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D430ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D429ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D448ms TTL=3D64 Timeout. Timeout. Reply from 192.168.1.5: bytes=3D32 time=3D66ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D89ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D118ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D138ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D154ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D163ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D185ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D227ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D229ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D261ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D274ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D297ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D318ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D340ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D366ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D388ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D408ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D431ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D452ms TTL=3D64 Timeout. Reply from 192.168.1.5: bytes=3D32 time=3D38ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D62ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D83ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D105ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D128ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D151ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D171ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D195ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D217ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D248ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D278ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D291ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D304ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D317ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D337ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D339ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D361ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D383ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D405ms TTL=3D64 Reply from 192.168.1.5: bytes=3D32 time=3D427ms TTL=3D64 Timeout. Reply from 192.168.1.5: bytes=3D32 time=3D42ms TTL=3D64 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=3D8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> 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=3D29<PERFORMNUD,IFDISABLED,AUTO_LINKLOCAL> media: IEEE 802.11 Wireless Ethernet autoselect mode 11ng <hosta= p> 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 =2E.. ath0@pci0:2:13:0: class=3D0x028000 card=3D0x2091168c chip=3D0x0029168c rev=3D0x01 hdr=3D0x00 vendor =3D 'Atheros Communications Inc.' device =3D 'AR922X Wireless Network Adapter' class =3D network =2E.. 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 =3D 0x2821d143, esp =3D 0xbfbfeabc, ebp =3D 0xbfbfeb18 --- --=20 Boris Lytochkin