RT256x PCMCIA card under 7.0-BETA2
Heiko Wundram (Beenic)
wundram at beenic.net
Thu Nov 15 00:11:30 PST 2007
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: <Ralink Technology RT2561> 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
More information about the freebsd-stable
mailing list