thr3ads.net - freebsd stable - RT256x PCMCIA card under 7.0-BETA2 [Nov 2007]

If this information is useful, please help other people find it:
Share via:

Heiko Wundram (Beenic)

2007-Nov-14 00:22 UTC

RT256x PCMCIA card under 7.0-BETA2

Hi all!

I just recently bought a RT2561C based (at least I think so) wireless card, 
which is also happily recognized by the ral-driver:

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]

As soon as I plug in the card and the netif script starts wpa_supplicant and 
dhclient, the laptop this is plugged into receives an interrupt storm on cbb0 
(having 80% interrupt time), which leads to a noticeable slowdown of the 
whole system:

phoenix# vmstat -i
interrupt                          total       rate
irq1: atkbd0                        9773          3
irq10: acpi0                         729          0
irq14: ata0                        17173          6
irq15: ata1                           64          0
irq17: cbb0 cbb1+               10408993       4217
irq18: pcm0                         5753          2
irq19: sis0+                       33302         13
irq20: ohci0                         207          0
irq21: ohci1                       44261         17
irq23: ehci0                           1          0
cpu0: timer                      4926468       1996
Total                           15446724       6258
phoenix#

This snapshot was taken some time after I killed wpa_supplicant (when it had 
been up for about 10 seconds).

When I manually start wpa_supplicant (with no stations in reach), there is no 
interrupt storm, but just normal activity with around 7-10 interrupts on cbb0 
per second.

I can also manually scan using the card (but ifconfig scan never finishes, but 
will show the stations in reach when doing an ifconfig list scan after ^C-ing 
the ifconfig scan), but cannot attach to any WPA access point in 
scanning-reach with wpa_supplicant (the only type of stations I have access 
to; I cannot test with WEP at the moment); enabling net.wlan.debug and 
net.wlan.0.debug also shows the scan taking place and the keys being set to 
the card, but nothing else from there.

The card itself is a "Conceptronic C54RC Version 2.0", which I guess
explains
the difference (in hardware) between the note in the manpage of ral(4) for 
this adapter and the actual hardware type it finds:

     Conceptronic C54RC           RT2560     CardBus

Anyway, doing a pciconv -lv leads to a different result than the actual driver 
reports, which is compatible with the hardware specification in the manpage:

ral0@pci0:2:0:0:        class=0x028000 card=0x3c231948 chip=0x03021814 
rev=0x00 hdr=0x00
    vendor     = 'Ralink Technology, Corp'
    device     = 'RT2525 2.4GHz transceiver + RT2560 MAC/BBP wireless
a/b'
    class      = network

The kernel all of this runs under is a (slightly) modified GENERIC 7.0-BETA2 
(from yesterday evening CET; an older 7.0-BETA2 didn't exhibit the interrupt
storm behaviour, but was similar for the rest), with SMP disabled and 
SCHED_ULE instead of SCHED_4BSD.

As debug.ral isn't available under the 7.0 ral-driver (which is referenced
in
the FreeBSD setup page http://damien.bergamini.free.fr/ral/ral-freebsd.html), 
I have no immediately obvious means of debugging what's actually happening 
when the interrupt storm takes place, and why the card won't attach to the
AP
even though the same wpa_supplicant config works using an ndis-wrapped driver 
for a different PCMCIA-card (Broadcom-based).

Thanks for any hint you can give me!

-- 
Heiko Wundram
Product & Application Development

Heiko Wundram (Beenic)

2007-Nov-14 11:59 UTC

head link

RT256x PCMCIA card under 7.0-BETA2

Am Mittwoch, 14. November 2007 20:48:00 schrieb Sam
Leffler:> I don't think I can help w/ the interrupt storm but you didn't
provide
> any logs for wpa_supplicant or wlandebug so it's hard to help w/ that
> issue.
Sorry for not providing any logs, but I just got the card yesterday, and 
haven't had an access point in reach during the day (at work) so far.
I'll
try to get better logging (esp. with net.wlan.debug=-1 and 
net.wlan.0.debug=-1) this evening, which I'll gladly post the revelant parts
of.

I just thought that maybe this was a "known" issue with this
"newer" chipset I
seem to have found with this card "Version 2.0."

-- 
Heiko Wundram
Product & Application Development

Heiko Wundram (Beenic)

2007-Nov-14 15:46 UTC

head link

RT256x PCMCIA card under 7.0-BETA2

Am Mittwoch, 14. November 2007 08:55:49 schrieb Heiko Wundram
(Beenic):> <snip>
Just for an update: I was stupid, really stupid enough not to check with any 
of the APs I tried to connect to whether they had MAC-filtering enabled, and 
all of them did. I turned that off just now for my private AP, and now the 
connect works fine.

I also can't reproduce the interrupt storm behaviour in case I have a
working
AP in range (which is also at the moment my only means to connect to the 
internet and post mails), but will try to do that tomorrow when I have cable 
internet back and no AP in range.

Sorry for the traffic, I really should take more time reading the debugging 
output next time; if I'd done that earlier, it would've become apparent
that
connection setup using wpa_supplicant was working fine, but only the 
authentication got rejected, which lead me to think about the MAC-filtering 
in the first place.

-- 
Heiko Wundram
Product & Application Development

Heiko Wundram (Beenic)

2007-Nov-15 00:11 UTC

head link

RT256x PCMCIA card under 7.0-BETA2

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

freebsd stable - Nov 2007 - RT256x PCMCIA card under 7.0-BETA2

RT256x PCMCIA card under 7.0-BETA2

RT256x PCMCIA card under 7.0-BETA2

RT256x PCMCIA card under 7.0-BETA2

RT256x PCMCIA card under 7.0-BETA2