From owner-freebsd-stable@FreeBSD.ORG Thu Nov 15 08:11:30 2007 Return-Path: Delivered-To: freebsd-stable@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id 72C9816A417 for ; Thu, 15 Nov 2007 08:11:30 +0000 (UTC) (envelope-from wundram@beenic.net) Received: from mail.beenic.net (mail.beenic.net [83.246.72.40]) by mx1.freebsd.org (Postfix) with ESMTP id 63AC713C455 for ; Thu, 15 Nov 2007 08:11:29 +0000 (UTC) (envelope-from wundram@beenic.net) Received: from [192.168.1.37] (a89-182-174-138.net-htp.de [89.182.174.138]) (using TLSv1 with cipher DHE-RSA-AES256-SHA (256/256 bits)) (No client certificate requested) by mail.beenic.net (Postfix) with ESMTP id 6ED24A44529 for ; Thu, 15 Nov 2007 09:05:21 +0100 (CET) From: "Heiko Wundram (Beenic)" Organization: Beenic Networks GmbH To: freebsd-stable@freebsd.org User-Agent: KMail/1.9.7 References: <200711140855.49334.wundram@beenic.net> <200711150044.30325.wundram@beenic.net> <473B9141.9050601@errno.com> In-Reply-To: <473B9141.9050601@errno.com> MIME-Version: 1.0 Content-Disposition: inline Date: Thu, 15 Nov 2007 09:12:18 +0100 Content-Type: text/plain; charset="iso-8859-1" Content-Transfer-Encoding: 7bit Message-Id: <200711150912.19334.wundram@beenic.net> Subject: Re: RT256x PCMCIA card under 7.0-BETA2 X-BeenThere: freebsd-stable@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Production branch of FreeBSD source code List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Thu, 15 Nov 2007 08:11:30 -0000 Okay, I'm back at work, and have cable internet here, so that I actually did some debugging and checking up on the problem just now. I think I narrowed the interrupt storm down to the end of scanning with the card. First of all a vmstat -i in three seconds interval while I was simply inserting the card into my PCMCIA slot (and the hotplug scripts did their magic): ----- Thu Nov 15 08:38:58 CET 2007 interrupt total rate irq1: atkbd0 1009 1 irq10: acpi0 229 0 irq14: ata0 8894 11 irq15: ata1 64 0 irq18: pcm0 5731 7 irq19: sis0+ 6542 8 irq20: ohci0 3789 4 irq21: ohci1 31 0 irq23: ehci0 3 0 cpu0: timer 1536343 1995 Total 1562635 2029 ----- Thu Nov 15 08:39:01 CET 2007 - I inserted the card right about here interrupt total rate irq1: atkbd0 1010 1 irq10: acpi0 231 0 irq14: ata0 8915 11 irq15: ata1 64 0 irq17: cbb0 cbb1+ 11 0 irq18: pcm0 5731 7 irq19: sis0+ 6542 8 irq20: ohci0 3798 4 irq21: ohci1 31 0 irq23: ehci0 3 0 cpu0: timer 1542356 1995 Total 1568692 2029 ----- Thu Nov 15 08:39:05 CET 2007 interrupt total rate irq1: atkbd0 1022 1 irq10: acpi0 231 0 irq14: ata0 8932 11 irq15: ata1 64 0 irq17: cbb0 cbb1+ 130576 168 irq18: pcm0 5731 7 irq19: sis0+ 6545 8 irq20: ohci0 3908 5 irq21: ohci1 31 0 irq23: ehci0 3 0 cpu0: timer 1551118 1996 Total 1708161 2198 ----- Thu Nov 15 08:39:08 CET 2007 interrupt total rate irq1: atkbd0 1030 1 irq10: acpi0 231 0 irq14: ata0 8932 11 irq15: ata1 64 0 irq17: cbb0 cbb1+ 351482 450 irq18: pcm0 5731 7 irq19: sis0+ 6545 8 irq20: ohci0 3908 5 irq21: ohci1 31 0 irq23: ehci0 3 0 cpu0: timer 1557218 1996 Total 1935175 2480 ----- Thu Nov 15 08:39:11 CET 2007 interrupt total rate irq1: atkbd0 1041 1 irq10: acpi0 233 0 irq14: ata0 8932 11 irq15: ata1 64 0 irq17: cbb0 cbb1+ 374391 478 irq18: pcm0 5731 7 irq19: sis0+ 6547 8 irq20: ohci0 3952 5 irq21: ohci1 31 0 irq23: ehci0 3 0 cpu0: timer 1563474 1996 Total 1964399 2508 ----- Thu Nov 15 08:39:15 CET 2007 interrupt total rate irq1: atkbd0 1050 1 irq10: acpi0 233 0 irq14: ata0 8932 11 irq15: ata1 64 0 irq17: cbb0 cbb1+ 607853 773 irq18: pcm0 5731 7 irq19: sis0+ 6547 8 irq20: ohci0 3952 5 irq21: ohci1 31 0 irq23: ehci0 3 0 cpu0: timer 1569671 1997 Total 2204067 2804 ----- Thu Nov 15 08:39:18 CET 2007 interrupt total rate irq1: atkbd0 1050 1 irq10: acpi0 233 0 irq14: ata0 8950 11 irq15: ata1 64 0 irq17: cbb0 cbb1+ 728523 922 irq18: pcm0 5731 7 irq19: sis0+ 6547 8 irq20: ohci0 4030 5 irq21: ohci1 31 0 irq23: ehci0 3 0 cpu0: timer 1575704 1994 Total 2330866 2950 ----- Thu Nov 15 08:39:21 CET 2007 interrupt total rate irq1: atkbd0 1050 1 irq10: acpi0 235 0 irq14: ata0 8950 11 irq15: ata1 64 0 irq17: cbb0 cbb1+ 831999 1049 irq18: pcm0 5731 7 irq19: sis0+ 6547 8 irq20: ohci0 4044 5 irq21: ohci1 31 0 irq23: ehci0 3 0 cpu0: timer 1581766 1994 Total 2440420 3077 ----- Thu Nov 15 08:39:24 CET 2007 interrupt total rate irq1: atkbd0 1050 1 irq10: acpi0 235 0 irq14: ata0 8963 11 irq15: ata1 64 0 irq17: cbb0 cbb1+ 1044398 1312 irq18: pcm0 5731 7 irq19: sis0+ 6549 8 irq20: ohci0 4044 5 irq21: ohci1 31 0 irq23: ehci0 3 0 cpu0: timer 1587850 1994 Total 2658918 3340 ----- Thu Nov 15 08:39:27 CET 2007 interrupt total rate irq1: atkbd0 1050 1 irq10: acpi0 235 0 irq14: ata0 8979 11 irq15: ata1 64 0 irq17: cbb0 cbb1+ 1074434 1344 irq18: pcm0 5731 7 irq19: sis0+ 6549 8 irq20: ohci0 4044 5 irq21: ohci1 31 0 irq23: ehci0 3 0 cpu0: timer 1593889 1994 Total 2695009 3372 ----- While the interrupt storm was taking place, my whole system becomes pretty unusable; the X redraw still works, but you can see the scan-lines being redrawn separately, which becomes especially evident in an xterm. I then killed wpa_supplicant, which made the problem disappear almost instantly. I then set up debugging for the card using a sysctl -a net.wlan[.0].debug=-1, and started wpa_supplicant manually: ----- Initializing interface 'ral0' conf '/etc/wpa_supplicant.conf' driver 'default' ctrl_interface 'N/A' bridge 'N/A' Configuration file '/etc/wpa_supplicant.conf' -> '/etc/wpa_supplicant.conf' Reading configuration file '/etc/wpa_supplicant.conf' ctrl_interface_group='0' (DEPRECATED) eapol_version=1 ap_scan=1 fast_reauth=1 Line: 8 - start of a new network block ssid - hexdump_ascii(len=13): 45 6c 6b 65 48 65 69 6b 6f 57 4c 41 4e ElkeHeikoWLAN key_mgmt: 0x2 pairwise: 0x8 group: 0x8 PSK (ASCII passphrase) - hexdump_ascii(len=29): [REMOVED] PSK (from passphrase) - hexdump(len=32): [REMOVED] Priority group 0 id=0 ssid='ElkeHeikoWLAN' Initializing interface (2) 'ral0' EAPOL: SUPP_PAE entering state DISCONNECTED EAPOL: KEY_RX entering state NO_KEY_RECEIVE EAPOL: SUPP_BE entering state INITIALIZE EAP: EAP entering state DISABLED EAPOL: External notification - portEnabled=0 EAPOL: External notification - portValid=0 Own MAC address: 00:80:5a:51:23:53 wpa_driver_bsd_set_wpa: enabled=1 wpa_driver_bsd_set_wpa_internal: wpa=3 privacy=1 wpa_driver_bsd_del_key: keyidx=0 wpa_driver_bsd_del_key: keyidx=1 wpa_driver_bsd_del_key: keyidx=2 wpa_driver_bsd_del_key: keyidx=3 wpa_driver_bsd_set_countermeasures: enabled=0 wpa_driver_bsd_set_drop_unencrypted: enabled=1 Setting scan request: 0 sec 100000 usec Added interface ral0 State: DISCONNECTED -> SCANNING Starting AP scan (broadcast SSID) Trying to get current scan results first without requesting a new scan to speed up initial association Received 0 bytes of scan results (0 BSSes) Scan results: 0 Selecting BSS from priority group 0 Try to find WPA-enabled AP Try to find non-WPA AP No suitable AP found. Setting scan request: 0 sec 0 usec Starting AP scan (broadcast SSID) Received 0 bytes of scan results (0 BSSes) Scan results: 0 Selecting BSS from priority group 0 Try to find WPA-enabled AP Try to find non-WPA AP No suitable AP found. Setting scan request: 5 sec 0 usec Starting AP scan (broadcast SSID) Received 0 bytes of scan results (0 BSSes) Scan results: 0 Selecting BSS from priority group 0 Try to find WPA-enabled AP Try to find non-WPA AP No suitable AP found. Setting scan request: 5 sec 0 usec Starting AP scan (broadcast SSID) Received 0 bytes of scan results (0 BSSes) Scan results: 0 Selecting BSS from priority group 0 Try to find WPA-enabled AP Try to find non-WPA AP No suitable AP found. Setting scan request: 5 sec 0 usec Starting AP scan (broadcast SSID) Received 0 bytes of scan results (0 BSSes) Scan results: 0 Selecting BSS from priority group 0 Try to find WPA-enabled AP Try to find non-WPA AP No suitable AP found. Setting scan request: 5 sec 0 usec CTRL-EVENT-TERMINATING - signal 2 received Removing interface ral0 State: SCANNING -> DISCONNECTED No keys have been configured - skip key clearing EAPOL: External notification - portEnabled=0 EAPOL: External notification - portValid=0 wpa_driver_bsd_set_wpa: enabled=0 wpa_driver_bsd_set_wpa_internal: wpa=0 privacy=0 wpa_driver_bsd_set_drop_unencrypted: enabled=0 wpa_driver_bsd_set_countermeasures: enabled=0 No keys have been configured - skip key clearing Cancelling scan request Cancelling authentication timeout wpa_driver_bsd_set_wpa_internal: wpa=0 privacy=0 ----- The system slowed down to a crawl again while wpa_supplicant was running (which I didn't experience yesterday, but anyway), and after some time I Ctrl+C'd my way out of it, that's the CTRL-EVENT-TERMINATING. While wpa_supplicant was running, the following messages appeared in the dmesg log: ----- ral0: mem 0x88000000-0x88007fff irq 17 at device 0.0 on cardbus0 ral0: MAC/BBP RT2561C, RF RT2527 ral0: Ethernet address: 00:80:5a:51:23:53 ral0: [ITHREAD] ral0: _ieee80211_crypto_delkey: NONE keyix 65535 flags 0x3 rsc 0 tsc 0 len 0 ral0: _ieee80211_crypto_delkey: NONE keyix 65535 flags 0x3 rsc 0 tsc 0 len 0 ral0: _ieee80211_crypto_delkey: NONE keyix 65535 flags 0x3 rsc 0 tsc 0 len 0 ral0: _ieee80211_crypto_delkey: NONE keyix 65535 flags 0x3 rsc 0 tsc 0 len 0 ral0: ieee80211_start_scan: active scan, duration 2147483647, desired mode auto, append, nopick, once ral0: scan set 1g, 6g, 11g, 7g, 13g, 2g, 3g, 4g, 5g, 8g, 9g, 10g, 12g, 14g dwell min 20 max 200 ral0: scan_next: chan 14g -> 1g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 1 ral0: scan_next: chan 1g -> 6g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 6 ral0: scan_next: chan 6g -> 11g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 11 ral0: scan_next: chan 11g -> 7g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 7 ral0: scan_next: chan 7g -> 13g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 13 ral0: scan_next: chan 13g -> 2g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 2 ral0: scan_next: chan 2g -> 3g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 3 ral0: scan_next: chan 3g -> 4g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 4 ral0: scan_next: chan 4g -> 5g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 5 ral0: scan_next: chan 5g -> 8g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 8 ral0: scan_next: chan 8g -> 9g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 9 ral0: scan_next: chan 9g -> 10g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 10 ral0: scan_next: chan 10g -> 12g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 12 ral0: scan_next: chan 12g -> 14g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 14 ral0: scan_next: done, [ticks 1203137, dwell min 20 scanend 2148683983] ral0: notify scan done ral0: ieee80211_start_scan: active scan, duration 2147483647, desired mode auto, append, nopick, once ral0: scan set 1g, 6g, 11g, 7g, 13g, 2g, 3g, 4g, 5g, 8g, 9g, 10g, 12g, 14g dwell min 20 max 200 ral0: scan_next: chan 14g -> 1g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 1 ral0: scan_next: chan 1g -> 6g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 6 ral0: scan_next: chan 6g -> 11g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 11 ral0: scan_next: chan 11g -> 7g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 7 ral0: scan_next: chan 7g -> 13g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 13 ral0: scan_next: chan 13g -> 2g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 2 ral0: scan_next: chan 2g -> 3g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 3 ral0: scan_next: chan 3g -> 4g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 4 ral0: scan_next: chan 4g -> 5g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 5 ral0: scan_next: chan 5g -> 8g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 8 ral0: scan_next: chan 8g -> 9g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 9 ral0: scan_next: chan 9g -> 10g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 10 ral0: scan_next: chan 10g -> 12g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 12 ral0: scan_next: chan 12g -> 14g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 14 ral0: scan_next: done, [ticks 1210935, dwell min 20 scanend 2148691781] ral0: notify scan done ral0: ieee80211_start_scan: active scan, duration 2147483647, desired mode auto, append, nopick, once ral0: scan set 1g, 6g, 11g, 7g, 13g, 2g, 3g, 4g, 5g, 8g, 9g, 10g, 12g, 14g dwell min 20 max 200 ral0: scan_next: chan 14g -> 1g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 1 ral0: scan_next: chan 1g -> 6g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 6 ral0: scan_next: chan 6g -> 11g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 11 ral0: scan_next: chan 11g -> 7g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 7 ral0: scan_next: chan 7g -> 13g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 13 ral0: scan_next: chan 13g -> 2g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 2 ral0: scan_next: chan 2g -> 3g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 3 ral0: scan_next: chan 3g -> 4g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 4 ral0: scan_next: chan 4g -> 5g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 5 ral0: scan_next: chan 5g -> 8g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 8 ral0: scan_next: chan 8g -> 9g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 9 ral0: scan_next: chan 9g -> 10g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 10 ral0: scan_next: chan 10g -> 12g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 12 ral0: scan_next: chan 12g -> 14g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 14 ral0: scan_next: done, [ticks 1218786, dwell min 20 scanend 2148699632] ral0: notify scan done ral0: ieee80211_start_scan: active scan, duration 2147483647, desired mode auto, append, nopick, once ral0: scan set 1g, 6g, 11g, 7g, 13g, 2g, 3g, 4g, 5g, 8g, 9g, 10g, 12g, 14g dwell min 20 max 200 ral0: scan_next: chan 14g -> 1g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 1 ral0: scan_next: chan 1g -> 6g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 6 ral0: scan_next: chan 6g -> 11g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 11 ral0: scan_next: chan 11g -> 7g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 7 ral0: scan_next: chan 7g -> 13g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 13 ral0: scan_next: chan 13g -> 2g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 2 ral0: scan_next: chan 2g -> 3g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 3 ral0: scan_next: chan 3g -> 4g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 4 ral0: scan_next: chan 4g -> 5g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 5 ral0: scan_next: chan 5g -> 8g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 8 ral0: scan_next: chan 8g -> 9g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 9 ral0: scan_next: chan 9g -> 10g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 10 ral0: scan_next: chan 10g -> 12g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 12 ral0: scan_next: chan 12g -> 14g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 14 ral0: scan_next: done, [ticks 1226586, dwell min 20 scanend 2148707432] ral0: notify scan done ral0: ieee80211_start_scan: active scan, duration 2147483647, desired mode auto, append, nopick, once ral0: scan set 1g, 6g, 11g, 7g, 13g, 2g, 3g, 4g, 5g, 8g, 9g, 10g, 12g, 14g dwell min 20 max 200 ral0: scan_next: chan 14g -> 1g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 1 ral0: scan_next: chan 1g -> 6g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 6 ral0: scan_next: chan 6g -> 11g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 11 ral0: scan_next: chan 11g -> 7g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 7 ral0: scan_next: chan 7g -> 13g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 13 ral0: scan_next: chan 13g -> 2g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 2 ral0: scan_next: chan 2g -> 3g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 3 ral0: scan_next: chan 3g -> 4g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 4 ral0: scan_next: chan 4g -> 5g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 5 ral0: scan_next: chan 5g -> 8g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 8 ral0: scan_next: chan 8g -> 9g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 9 ral0: scan_next: chan 9g -> 10g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 10 ral0: scan_next: chan 10g -> 12g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 12 ral0: scan_next: chan 12g -> 14g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 14 ral0: scan_next: done, [ticks 1234404, dwell min 20 scanend 2148715250] ral0: notify scan done ral0: ieee80211_start_scan: active scan, duration 2147483647, desired mode auto, append, nopick, once ral0: scan set 1g, 6g, 11g, 7g, 13g, 2g, 3g, 4g, 5g, 8g, 9g, 10g, 12g, 14g dwell min 20 max 200 ral0: scan_next: chan 14g -> 1g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 1 ral0: scan_next: chan 1g -> 6g [active, dwell min 20 max 200] ral0: ieee80211_ref_node (ieee80211_send_probereq:1492) 0xc4e30000<00:80:5a:51:23:53> refcnt 3 ral0: [ff:ff:ff:ff:ff:ff] send probe req on channel 6 ral0: ieee80211_newstate: INIT -> INIT ral0: ieee80211_cancel_scan: cancel active scan ral0: scan_next: done, [ticks 1239638, dwell min 20 scanend 2148723052] ----- I typed dmesg repeatedly to see the effect it had on the xterm I ran that in (to be able to see the interrupt storm back in action), and found that the xterm started to redraw slowly and the system came to a crawl when the last dmesg lines were "scan_next: done" and "notify scan done". While the scan was taking place (and the card was hopping channels), the system seemed to run normally. The interrupt statistics for this run of wpa_supplicant: ----- Thu Nov 15 08:40:48 CET 2007 interrupt total rate irq1: atkbd0 1518 1 irq10: acpi0 251 0 irq14: ata0 9110 10 irq15: ata1 64 0 irq17: cbb0 cbb1+ 2694545 3061 irq18: pcm0 5731 6 irq19: sis0+ 6580 7 irq20: ohci0 4481 5 irq21: ohci1 31 0 irq23: ehci0 3 0 cpu0: timer 1755671 1995 Total 4477985 5088 ----- Thu Nov 15 08:40:51 CET 2007 interrupt total rate irq1: atkbd0 1558 1 irq10: acpi0 253 0 irq14: ata0 9124 10 irq15: ata1 64 0 irq17: cbb0 cbb1+ 2694593 3051 irq18: pcm0 5731 6 irq19: sis0+ 6583 7 irq20: ohci0 4481 5 irq21: ohci1 31 0 irq23: ehci0 3 0 cpu0: timer 1761689 1995 Total 4484110 5078 ----- Thu Nov 15 08:40:54 CET 2007 interrupt total rate irq1: atkbd0 1558 1 irq10: acpi0 253 0 irq14: ata0 9128 10 irq15: ata1 64 0 irq17: cbb0 cbb1+ 2733783 3085 irq18: pcm0 5731 6 irq19: sis0+ 6585 7 irq20: ohci0 4481 5 irq21: ohci1 31 0 irq23: ehci0 3 0 cpu0: timer 1767916 1995 Total 4529533 5112 ----- Thu Nov 15 08:40:57 CET 2007 interrupt total rate irq1: atkbd0 1558 1 irq10: acpi0 253 0 irq14: ata0 9131 10 irq15: ata1 64 0 irq17: cbb0 cbb1+ 2955278 3324 irq18: pcm0 5731 6 irq19: sis0+ 6585 7 irq20: ohci0 4560 5 irq21: ohci1 31 0 irq23: ehci0 3 0 cpu0: timer 1774080 1995 Total 4757274 5351 ----- Thu Nov 15 08:41:00 CET 2007 interrupt total rate irq1: atkbd0 1558 1 irq10: acpi0 255 0 irq14: ata0 9148 10 irq15: ata1 64 0 irq17: cbb0 cbb1+ 3049490 3418 irq18: pcm0 5731 6 irq19: sis0+ 6585 7 irq20: ohci0 4718 5 irq21: ohci1 31 0 irq23: ehci0 3 0 cpu0: timer 1780125 1995 Total 4857708 5445 ----- Thu Nov 15 08:41:03 CET 2007 interrupt total rate irq1: atkbd0 1558 1 irq10: acpi0 255 0 irq14: ata0 9149 10 irq15: ata1 64 0 irq17: cbb0 cbb1+ 3191541 3565 irq18: pcm0 5731 6 irq19: sis0+ 6587 7 irq20: ohci0 4807 5 irq21: ohci1 31 0 irq23: ehci0 3 0 cpu0: timer 1786188 1995 Total 5005914 5593 ----- It seems as though the scan finish message from the card generates an interrupt, which is either not acknowledged properly, or the card has a bug, which causes this interrupt to be fired repeatedly until the next scan is started or the scan is reset completely. That's about as much debugging as I can do at the moment; if any of you want more info, just let me know, I'm happy to supply any additional information to you which you might need! Thanks for taking the time to look at this! -- Heiko Wundram Product & Application Development