System freeze - BUG: soft lockup detected on CPU#0!

I'm seeing something similar: my client machines are hiccuping near the start of an active scan.

Is your interrupt count (grep wifi0 /proc/interrupts) going up like crazy during the freeze? For me it jumps somewhere between 50,000-200,000 while normally it's only going up a few times a second. If you "iwpriv ath0 bgscan 0", you may be able to get rid of the 5-minute freezes, but not the freezes during association.

I'm using madwifi trunk r2518 from June 26 and Linux kernel 2.6.18.3. All wireless cards are EnGenius? NMP/EMP-8602 miniPCI. I'm normally using WPA2 with CCMP but I see this even with all authentication turned off (no wpa_supplicant at all).

Here's what I see on the console with "80211debug +scan":

ath0: ieee80211_ioctl_siwscan: active scan request
ath0: ieee80211_start_scan: active scan, duration 2147483647, desired mode auto, append, nopick, once
ath0: scan set 1g, 6g, 11g, 7g, 52a, 56a, 60a, 64a, 36a, 40a, 44a, 48a, 2g, 3g, 4g, 5g, 8g, 9g, 10g, 149a, 153a, 157a, 161a, 165a, 40a, 48a, 56a, 1530
ath0: scan_next: chan   6g ->   1g [active, dwell min 2 max 20]

(pause here - serial console freezes, machine won't respond to ping on its ethernet interface)
(pause either lasts 5-10 seconds, or machine reboots)

ath0: scan_next: chan   1g ->   6g [active, dwell min 2 max 20]
[00:66:0f:77:56:ad] new probe_resp on chan 6 (bss chan 6) "xxx01"
[00:66:0f:77:56:ad] caps 0x11 bintval 100 erp 0x5
ath0: ieee80211_add_scan: chan   6g min dwell met (107 > 107)
ath0: scan_next: chan   6g ->  11g [active, dwell min 2 max 20]
ath0: scan_next: chan  11g ->   7g [active, dwell min 2 max 20]
ath0: scan_next: chan   7g ->  52a [active, dwell min 2 max 20]
ath0: scan_next: chan  52a ->  56a [active, dwell min 2 max 20]
ath0: scan_next: chan  56a ->  60a [active, dwell min 2 max 20]
ath0: scan_next: chan  60a ->  64a [active, dwell min 2 max 20]

(and so on...)

dmesg from boot:

ath_hal: 0.9.30.13 (AR5210, AR5211, AR5212, AR5416, RF5111, RF5112, RF2413, RF5413, RF2133)
wlan: 0.8.4.2 (0.9.4)
ath_pci: 0.9.4.5 (0.9.4)
ath_pci: switching rfkill capability off
ath_pci: ath_pci: switching per-packet transmit power control off
ath_rate_sample: 1.2 (0.9.4)
wifi0: 11a rates: 6Mbps 9Mbps 12Mbps 18Mbps 24Mbps 36Mbps 48Mbps 54Mbps
wifi0: 11b rates: 1Mbps 2Mbps 5.5Mbps 11Mbps
wifi0: 11g rates: 1Mbps 2Mbps 5.5Mbps 11Mbps 6Mbps 9Mbps 12Mbps 18Mbps
24Mbps 36Mbps 48Mbps 54Mbps
wifi0: H/W encryption support: WEP AES AES_CCM TKIP
wifi0: mac 10.4 phy 6.1 radio 6.3
wifi0: Use hw queue 8 for CAB traffic
wifi0: Use hw queue 9 for beacons
wifi0: Atheros 5212: mem=0xa0010000, irq=11

Maybe related to #1451.

trivial patch to show mib counter in athstats

athdebug +intr shows a lot of status 0x1000 during the hiccup. Those are MIB interrupts? I patched athstats to show the ast_mib counter, it is going up by up to several hundred thousand at a time during some parts of the scan. Here's a paste from the serial console where the mib counter was being printed every second during a scan:

ath0: ieee80211_add_scan: chan   6g min dwell met (114094 > 114094)
ath0: scan_next: chan   6g ->  11g [active, dwell min 2 max 20]
ath0: scan_next: chan  11g ->   7g [active, dwell min 2 max 20]
ath0: scan_next: chan   7g ->  52a [active, dwell min 2 max 20]
ath0: scan_next: chan  52a ->  56a [active, dwell min 2 max 20]
4586490 mib interrupts
ath0: scan_next: chan  56a ->  60a [active, dwell min 2 max 20]
ath0: scan_next: chan  60a ->  64a [active, dwell min 2 max 20]
ath0: scan_next: chan  64a ->  36a [active, dwell min 2 max 20]
ath0: scan_next: chan  36a ->  40a [active, dwell min 2 max 20]
ath0: scan_next: chan  40a ->  44a [active, dwell min 2 max 20]
4586490 mib interrupts
ath0: scan_next: chan  44a ->  48a [active, dwell min 2 max 20]
ath0: scan_next: chan  48a ->   2g [active, dwell min 2 max 20]
ath0: scan_next: chan   2g ->   3g [active, dwell min 2 max 20]
ath0: scan_next: chan   3g ->   4g [active, dwell min 2 max 20]

***pause here***

4967648 mib interrupts
ath0: scan_next: chan   4g ->   5g [active, dwell min 2 max 20]
ath0: scan_next: chan   5g ->   8g [active, dwell min 2 max 20]
ath0: scan_next: chan   8g ->   9g [active, dwell min 2 max 20]
ath0: scan_next: chan   9g ->  10g [active, dwell min 2 max 20]
ath0: scan_next: chan  10g -> 149a [active, dwell min 2 max 20]
4967648 mib interrupts
ath0: scan_next: chan 149a -> 153a [active, dwell min 2 max 20]
ath0: scan_next: chan 153a -> 157a [active, dwell min 2 max 20]
ath0: scan_next: chan 157a -> 161a [active, dwell min 2 max 20]
ath0: scan_next: chan 161a -> 165a [active, dwell min 2 max 20]
ath0: scan_next: chan 165a ->  40a [active, dwell min 2 max 20]
4967648 mib interrupts

Hi,

I checked and indeed the interrupt count is going like crazy during the freezes.

Output using 'grep wifi0 /proc/interrupts':

a few seconds before a freeze: 11: 973680 XT-PIC-XT ohci_hcd:usb3, ohci_hcd:usb4, ohci_hcd:usb5, eth0, wifi0, CMI8738-MC6, wlan0, radeon@pci:0000:01:00.0

just after the freeze: 11: 1337550 XT-PIC-XT ohci_hcd:usb3, ohci_hcd:usb4, ohci_hcd:usb5, eth0, wifi0, CMI8738-MC6, wlan0, radeon@pci:0000:01:00.0

I have no idea if this but here is what i get when using '80211debug +scan' and 'athdebug +intr'

julien@julien-desktop:~$ sudo 80211debug +scan
Password:
net.ath0.debug: 0x00000000 => 0x00200000<scan>
Details:
       debug   0x40000000 - IFF_DEBUG equivalent
    dumppkts   0x20000000 - dump packets
      crypto   0x10000000 - crypto modules
       input   0x08000000 - packet input handling
       xrate   0x04000000 - rate set handling
      elemid   0x02000000 - element id parsing
        node   0x01000000 - node management
       assoc   0x00800000 - association handling
        auth   0x00400000 - authentication handling
        scan + 0x00200000 - scanning
      output   0x00100000 - packet output handling
       state   0x00080000 - 802.11 state machine
       power   0x00040000 - power save functions
       dot1x   0x00020000 - 802.1x authenticator
     dot1xsm   0x00010000 - 802.1x state machine
      radius   0x00008000 - 802.1x radius client
     raddump   0x00004000 - 802.1x radius packet dump
     radkeys   0x00002000 - 802.1x key dump
         wpa   0x00001000 - WPA/RSN protocol
         acl   0x00000800 - ACL handling
         wme   0x00000400 - WME protocol
      superg   0x00000200 - super G turbo mode
        doth   0x00000100 - 802.11h (DFS/TPC) handling
       inact   0x00000080 - timeout of inactive nodes
        roam   0x00000040 - station mode roaming
julien@julien-desktop:~$ sudo athdebug +intr
dev.wifi0.debug: 0x00000000 => 0x00001000<intr>
Details:
        xmit   0x00000001 - transmission of packets before out to HW
   xmit_desc   0x00000002 - transmit descriptors
        recv   0x00000004 - received packets directly from HW
   recv_desc   0x00000008 - recv descriptors
        rate   0x00000010 - rate control modules
       reset   0x00000020 - reset processing and initialization
        mode   0x00000040 - mode initialization and changes
      beacon   0x00000080 - beacon handling
    watchdog   0x00000100 - watchdog timer
        intr + 0x00001000 - interrupt processing
   xmit_proc   0x00002000 - processing of transmit descriptors
   recv_proc   0x00004000 - processing of receive descriptors
 beacon_proc   0x00008000 - beacon processing
   calibrate   0x00010000 - periodic re-calibration
    keycache   0x00020000 - key cache management
       state   0x00040000 - 802.11 state transitions
        node   0x00080000 - node management
         led   0x00100000 - led management
          ff   0x00200000 - fast frame handling
       turbo   0x00400000 - dynamic turbo handling
       uapsd   0x00800000 - WME/UAPSD handling
        doth   0x01000000 - 802.11h handling
       fatal   0x80000000 - fatal errors
julien@julien-desktop:~$ 

After thoses commands, i do have in my dmesg a lot of '[ 2879.879854] ath_intr: status 0x9' and status 0x1000.
The status 0x9 floods the dmesg when the pc doesn't freeze.
When the pc freezes, i don't have any more 0x9 but the dmesg is flooded with status 0x1000.

Here are the last lines of my dmesg just after a freeze:

............ath_intr: status 0x1000         a lot of time
[ 4205.195220] ath_intr: status 0x1000
[ 4205.195256] ath_intr: status 0x1000
[ 4205.197250] ath_intr: status 0x40
[ 4205.199230] ath_bmiss_tasklet
[ 4205.207539] ath0: ieee80211_cancel_scan: cancel active scan
[ 4205.207602] ath_intr: status 0x40
[ 4205.216088] ath0: scan_next: done, [jiffies 971954, dwell min 5 scanend 2148300629]
[ 4205.216132] ath_intr: status 0x40
[ 4205.225428] ath0: ieee80211_ioctl_siwscan: active scan request
[ 4205.225440] ath0: ieee80211_start_scan: active scan, duration 2147483647, desired mode auto, append, nopick, once
[ 4205.225457] ath0: scan set 1g, 6g, 11g, 7g, 2g, 3g, 4g, 5g, 8g, 9g, 10g, 6g dwell min 5 max 50
[ 4205.225534] ath_intr: status 0x40
[ 4205.229176] ath0: scan_next: chan   1g ->   1g [active, dwell min 5 max 50]
[ 4205.230319] ath_intr: status 0x40
[ 4205.232187] ath_intr: status 0x9
[ 4205.232220] [4a:85:0c:1b:3e:84] new probe_resp on chan 1 (bss chan 1) "HomeSweetHome"
[ 4205.232229] [4a:85:0c:1b:3e:84] caps 0x411 bintval 100 erp 0x4
[ 4205.233720] ath_intr: status 0x9
[ 4205.233740] [4a:85:0c:1b:3e:87] new probe_resp on chan 1 (bss chan 1) "freephonie"
[ 4205.233747] [4a:85:0c:1b:3e:87] caps 0x411 bintval 100 erp 0x4
julien@julien-desktop:~$ 

Besides, it doesn't seem that the 'iwpriv ath0 bgscan 0' avoided the computer to freeze again.

If you want me to compile anything else, or run any other command, etc, i would be glad to help.

thebrowser

Hi,

I initialy set the priority of this isssue as minor but only because I forgot to change it to major or even criticial. If a moderator could change it, it would be great.

This bug is really annoying.

thebrowser

Hi,

after modifying the kernel boot options by adding acpi=off, the freezes still happened before, during and after association, but the output in the dmesg was different:

[  311.114791] BUG: soft lockup detected on CPU#0!
[  311.114826]  [<c015354c>] softlockup_tick+0x9c/0xf0
[  311.114842]  [<c0130643>] update_process_times+0x33/0x80
[  311.114852]  [<c0106c45>] timer_interrupt+0x85/0xb0
[  311.114860]  [<c01538d0>] handle_IRQ_event+0x30/0x60
[  311.114868]  [<c015517d>] handle_level_irq+0x8d/0x120
[  311.114876]  [<c0105b70>] do_IRQ+0x40/0x80
[  311.114883]  [<c0104233>] common_interrupt+0x23/0x30
[  311.114895]  [<c02ee96d>] _spin_unlock_irqrestore+0xd/0x20
[  311.114905]  [<f89d8f87>] ath_intr+0x3a7/0x1060 [ath_pci]
[  311.114929]  [<c012fdb2>] do_timer+0x482/0x820
[  311.114933]  [<c0106c45>] timer_interrupt+0x85/0xb0
[  311.114951]  [<c0122d1c>] scheduler_tick+0x5c/0x110
[  311.114957]  [<f888d266>] ehci_irq+0x26/0x170 [ehci_hcd]
[  311.114975]  [<c01538d0>] handle_IRQ_event+0x30/0x60
[  311.114982]  [<c015517d>] handle_level_irq+0x8d/0x120
[  311.114990]  [<c0105b70>] do_IRQ+0x40/0x80
[  311.114997]  [<c0104233>] common_interrupt+0x23/0x30
[  311.115009]  [<f89a3823>] ieee80211_send_probereq+0x53/0x2b0 [wlan]
[  311.115063]  [<f89aa6b7>] scan_next+0x447/0x4c0 [wlan]
[  311.115089]  [<c013da3c>] enqueue_hrtimer+0x4c/0x80
[  311.115106]  [<f89aa270>] scan_next+0x0/0x4c0 [wlan]
[  311.115124]  [<c012f74f>] run_timer_softirq+0x12f/0x1a0
[  311.115135]  [<c012b422>] __do_softirq+0x82/0x100
[  311.115145]  [<c012b4f5>] do_softirq+0x55/0x60
[  311.115151]  [<c0105b75>] do_IRQ+0x45/0x80
[  311.115156]  [<c018343b>] sys_poll+0x2b/0x40
[  311.115163]  [<c0104233>] common_interrupt+0x23/0x30
[  311.115179]  =======================
[  451.058322] BUG: soft lockup detected on CPU#0!
[  451.058356]  [<c015354c>] softlockup_tick+0x9c/0xf0
[  451.058373]  [<c0130643>] update_process_times+0x33/0x80
[  451.058383]  [<c0106c45>] timer_interrupt+0x85/0xb0
[  451.058392]  [<c01538d0>] handle_IRQ_event+0x30/0x60
[  451.058400]  [<c015517d>] handle_level_irq+0x8d/0x120
[  451.058407]  [<c0105b70>] do_IRQ+0x40/0x80
[  451.058412]  [<f8856ec8>] boomerang_interrupt+0x48/0x460 [3c59x]
[  451.058431]  [<c0104233>] common_interrupt+0x23/0x30
[  451.058443]  [<c02ee96d>] _spin_unlock_irqrestore+0xd/0x20
[  451.058453]  [<f89d8f50>] ath_intr+0x370/0x1060 [ath_pci]
[  451.058477]  [<c0105b75>] do_IRQ+0x45/0x80
[  451.058484]  [<c0104233>] common_interrupt+0x23/0x30
[  451.058497]  [<f883fdb3>] ohci_irq+0xf3/0x220 [ohci_hcd]
[  451.058508]  [<f888d266>] ehci_irq+0x26/0x170 [ehci_hcd]
[  451.058525]  [<c01538d0>] handle_IRQ_event+0x30/0x60
[  451.058533]  [<c015517d>] handle_level_irq+0x8d/0x120
[  451.058540]  [<c0105b70>] do_IRQ+0x40/0x80
[  451.058548]  [<c0104233>] common_interrupt+0x23/0x30
[  451.058560]  [<f89a3823>] ieee80211_send_probereq+0x53/0x2b0 [wlan]
[  451.058614]  [<f89aa6b7>] scan_next+0x447/0x4c0 [wlan]
[  451.058646]  [<c01098bf>] sched_clock+0x5f/0x90
[  451.058654]  [<f89aa270>] scan_next+0x0/0x4c0 [wlan]
[  451.058673]  [<c012f74f>] run_timer_softirq+0x12f/0x1a0
[  451.058684]  [<c012b422>] __do_softirq+0x82/0x100
[  451.058696]  [<c012b4f5>] do_softirq+0x55/0x60
[  451.058701]  [<c0105b75>] do_IRQ+0x45/0x80
[  451.058705]  [<c0105b75>] do_IRQ+0x45/0x80
[  451.058712]  [<c0104233>] common_interrupt+0x23/0x30
[  451.058717]  [<c0101e00>] default_idle+0x0/0x60
[  451.058727]  [<c011c092>] native_safe_halt+0x2/0x10
[  451.058736]  [<c0101e3d>] default_idle+0x3d/0x60
[  451.058740]  [<c0101409>] cpu_idle+0x49/0xd0
[  451.058745]  [<c03d97f5>] start_kernel+0x365/0x420
[  451.058755]  [<c03d9230>] unknown_bootoption+0x0/0x260
[  451.058766]  =======================

It seems no more to have something to do with acpi but now with my other wifi card, wlan.
It is an ACX110 chipset. I'm going to remove this card and check if the freezes still happen.

thebrowser

Hi,

i thought this issue had something to do with my other wifi card (chipset ACX110) because its interface name was wlan0 and because the output of the dmesg contained 'scan_next+0x0/0x4c0 [wlan]'.

But i found that the madwifi driver was also using the term wlan: in the modules, wlanconfig, etc.

I still removed the ACX110 card and deleted thhe acx.ko module files. It didn't solved the issue and there were the same output in the dmesg as in the previous post.

thebrowser

I've had a chance to try this with a couple of Ubiquiti radios in addition to the NMP-8602s I was using before.

EnGenius? NMP-8602: mac 10.4 phy 6.1 radio 6.3: severe; interrupt counter goes up by 100,000 during freeze

Ubiquity SR2: mac 5.9 phy 4.3 radio 4.6: very short freezes (10,000s of interrupts rather than 100,000s)

Ubiquity XR2: mac 10.5 phy 6.1 radio 6.3: about as severe as the NMP-8602

Did you try the patch from #900?

@nbd: Thanks for the pointer. The patch from #900 seems to work around the freezes for me.

@nbd: The patch from #900 seems to partialy work around the freezes:

The freezes still happen but while the freezes before the patch were during several minutes, those after it only long between 0second and 2seconds, and i don't have any more softlock messages in the dmesg.

After have used 'athdebug +intr', I have been able to print the dmesg just after one of those 'micro' freezes:

[            ] ath_intr: status 0x1000      hundreds of time
[ 2558.735998] ath_intr: status 0x1000
[ 2558.737143] ath_intr: status 0x40

The freezes always seem to finish with a 0x40.

There is something else I noticed: when using Applet NetworkManager (0.6.4), after clicking on the access point i want to connect, it opens a window which asks for the wpa password. I noticed that when i put the cursor in the textbox where i need to write the pass and I press any letter without pulling back my finger of the letter, it will always freeze for a something like a second at the moment 7 letters are written into the textbox. Always.

The patch does not fix the problem, it just makes thing less annoying.

thebrowser

Try this one: http ://nbd.name/306-mib_intr_workaround.patch

thank you for the fast reply.

I just made more tests with the #900 patched driver, but this time with my other wifi pci card (ACX110) unplugged.

For what i can say, i haven't seen any other freeze. I checked in the dmesg and i didn't found the 'hundreds of ath_intr: status 0x1000'.

Besides, i understood that the 'seventh letter freeze of NetworkManager' wasn't a driver freeze as it is only the window of NetworkManager that hungs for a second, not the mouse, so nor the kernel.

Also, i have seen the following message: (i saw it only once, it may have nothing to do with the issue)

Aug  1 18:54:51 julien-desktop kernel: [ 1028.134894] wifi0: ath_chan_set: unable to reset channel 8 (2447 MHz) flags 0xc0 'Hardware didn't respond as expected' (HAL status 3)

I've just downloaded your patch, and will try it in one hour.

@nbd: Thanks, your patch works for me.

@nbd: this time, i have nothing else to say than thank you :).

It works perfectly even when my second wifi pci card (ACX110) is plugged in.

I am eager for this patch to be merged with the trunk.

patch added in [2632]