From owner-freebsd-wireless@FreeBSD.ORG Fri Nov 25 09:39:06 2011 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 B6BE0106566C for ; Fri, 25 Nov 2011 09:39:06 +0000 (UTC) (envelope-from gperez@entel.upc.edu) Received: from dash.upc.es (dash.upc.es [147.83.2.50]) by mx1.freebsd.org (Postfix) with ESMTP id 41E6C8FC16 for ; Fri, 25 Nov 2011 09:39:05 +0000 (UTC) Received: from entelserver.upc.edu (entelserver.upc.es [147.83.39.4]) by dash.upc.es (8.14.1/8.13.1) with ESMTP id pAP9d4Le027336 for ; Fri, 25 Nov 2011 10:39:05 +0100 Received: from webmail.entel.upc.edu (www-entel.upc.es [147.83.39.6]) by entelserver.upc.edu (Postfix) with ESMTP id C83F12CBD0E for ; Fri, 25 Nov 2011 10:38:59 +0100 (CET) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8; format=flowed Content-Transfer-Encoding: 7bit Date: Fri, 25 Nov 2011 10:25:05 +0100 From: Gustau Perez Querol To: Message-ID: <3d4d2d249836fafc6acd885693c02198@webmail.entel.upc.edu> X-Sender: gperez@entel.upc.edu User-Agent: RoundCube Webmail/0.5.1 X-Mail-Scanned: Criba 2.0 + Clamd X-Greylist: Sender IP whitelisted, not delayed by milter-greylist-3.0 (dash.upc.es [147.83.2.50]); Fri, 25 Nov 2011 10:39:05 +0100 (CET) Subject: Big delays between an AR5416 AP and its clients 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: Fri, 25 Nov 2011 09:39:06 -0000 This is the environment: I'm using an AR5416 card acting as an AP with hostap in 11g mode. I'm running g because I did not have time to test the 11n work yet. The box is running CURRENT/AMD64 as of Nov 22th. These are the symptoms: A few days ago I began to see very big delays between the AP and my laptop (which has an AR9287 with FreeBSD/AMD64 CURRENT). I tried a simple icmp with 1 second between pings. The curious thing is that delays increase from 30ms til 100ms (those times are in the same order of magnitude of a ping to google) and then they fall til 30ms again. It did not work like that before. I tested with different clients (an iPhone, a laptop running FreeBSD with an Intel 3945, an asus eeePC laptop with windows7 and other devices). All of them showed the same behavior. Further experiments showed me that the problem appears when any iPhone associates with the AP. As soon as the iPhone deassociates the other clients see no problems at all. ICMP messages get less than a ms to get replied (which are rtt I would expect). I'm pasting online at the end of the mail a simple icmp trace where you can see how it behaves. It shows increasing icmp rtt and then falling to usable time. Then it increases again. This is where I am now: I'm tracking kib's git repository (because I'm helping him as a tester and bug finder with his work with the GEM/KMS thing, that machine has a card giving us a lot of headaches) so I decided to do a bisect to find out which commit introduced the bug with the AR5416. Memory served me well and I could tell at the end of October it worked fine (we have two iphone at home and they worked fine), so it would be something introduced in November. The bisect lead me to r227364, which is one quite large. I took a look at the code, but I'm not used to the ath land. I ensured the previous one did well, with two iPhones there, 3 laptops (2 FreeBSD and one win7), a Wii and a multimedia wifi hard drive. It did well. Using the next commit triggered the problem. I have a custom r227364 compilation with ATH_DEBUG, AH_DEBUG and ATH_GSAPIA there. I also compiled athstat. However now I'm at $WORK and I can not test till this afternoon (I'm at +1UTC). I'll test with athstats the card's behaviour when the iPhone associates and post back to the list. I will take a look at the diff of this revision, but I'm not used to the ath|wireless code in the kernel, so I would say I will not find anything interesting. However I'll spend some time (4 eyes see more than two, they say). Any additional test or if you have any idea where the problem gets introduced so I can take at the code, please let me know. Gustau ****************************************************** bytes from 192.168.1.100: icmp_seq=15 ttl=64 time=0.946 ms 64 bytes from 192.168.1.100: icmp_seq=16 ttl=64 time=1.016 ms 64 bytes from 192.168.1.100: icmp_seq=17 ttl=64 time=1.011 ms 64 bytes from 192.168.1.100: icmp_seq=18 ttl=64 time=1.040 ms 64 bytes from 192.168.1.100: icmp_seq=19 ttl=64 time=0.779 ms 64 bytes from 192.168.1.100: icmp_seq=20 ttl=64 time=0.657 ms 64 bytes from 192.168.1.100: icmp_seq=21 ttl=64 time=0.945 ms 64 bytes from 192.168.1.100: icmp_seq=22 ttl=64 time=88.747 ms 64 bytes from 192.168.1.100: icmp_seq=23 ttl=64 time=109.538 ms 64 bytes from 192.168.1.100: icmp_seq=24 ttl=64 time=29.992 ms 64 bytes from 192.168.1.100: icmp_seq=25 ttl=64 time=0.978 ms 64 bytes from 192.168.1.100: icmp_seq=26 ttl=64 time=74.145 ms 64 bytes from 192.168.1.100: icmp_seq=27 ttl=64 time=97.230 ms 64 bytes from 192.168.1.100: icmp_seq=28 ttl=64 time=17.816 ms 64 bytes from 192.168.1.100: icmp_seq=29 ttl=64 time=41.417 ms 64 bytes from 192.168.1.100: icmp_seq=30 ttl=64 time=62.682 ms 64 bytes from 192.168.1.100: icmp_seq=31 ttl=64 time=84.579 ms 64 bytes from 192.168.1.100: icmp_seq=32 ttl=64 time=107.628 ms 64 bytes from 192.168.1.100: icmp_seq=33 ttl=64 time=27.328 ms 64 bytes from 192.168.1.100: icmp_seq=34 ttl=64 time=50.283 ms ******************************************************