ath9k: irq storm after suspend/resume

Hi,

I am trying to debug this issue:
https://bugzilla.kernel.org/show_bug.cgi?id=39112

An IRQ storm triggers during resume after suspend to RAM. The IRQ storm also triggers during insmod after suspend/resume, even if ath9k is not loaded during suspend.

In the former case, the IRQ storm happens right after the PCI subsystem restores the config space for ath9k.

In the latter case, the IRQ storm happens immediately after request_irq in ath_pci_probe. So I have moved ath9k_init_device ahead of request_irq, in order to call ath9k_hw_set_interrupts(ah,
0) before enabling the interrupt.

But still, the interrupts come. Note that according to /proc/interrupts, the IRQ line is not shared with any other device. I did not manage to determine which interrupt it is exactly, because the device is not in a ready state (SC_OP_INVALID is set) when they happen (in either scenario that triggers the IRQ storm). And SC_OP_INVALID is cleared only much later in ath9k_start.

So, I am at a loss. Any ideas?

Below is the output I get during insmod'ing right after resume (complete logs can be found in the bug report). Below that are the changes I made to produce the output.

Clemens
---

[   53.387989] ath9k 0000:02:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17
[   53.389306] ath9k 0000:02:00.0: setting latency timer to 64
[   53.389371] ath: reset power on
[   53.392725] ath: UNDEFINED -> AWAKE
[   53.392783] ath: serialize_regmode is 0
[   53.438096] ath: Eeprom VER: 14, REV: 13
[   53.438098] ath: Initialize ANI
[   53.438112] ath: Enable MIB counters
[   53.438143] ath: Setup TX queue: 9
[   53.438144] ath: Set queue properties for: 9
[   53.438146] ath: Setup TX queue: 8
[   53.438147] ath: Set queue properties for: 8
[   53.438149] ath: Set queue properties for: 8
[   53.438151] ath: Reset TX queue: 8
[   53.438176] ath: tx ok 0x0 err 0x0 desc 0x100 eol 0x100 urn 0x0
[   53.438178] ath: Setup TX queue: 0
[   53.438179] ath: Set queue properties for: 0
[   53.438181] ath: Setup TX queue: 1
[   53.438182] ath: Set queue properties for: 1
[   53.438184] ath: Setup TX queue: 2
[   53.438185] ath: Set queue properties for: 2
[   53.438186] ath: Setup TX queue: 3
[   53.438187] ath: Set queue properties for: 3
[   53.439692] ath: TX streams 1, RX streams: 1
[   53.439694] ath: EEPROM regdomain: 0x60
[   53.439695] ath: EEPROM indicates we should expect a direct regpair map
[   53.439698] ath: Country alpha2 being used: 00
[   53.439699] ath: Regpair used: 0x60
[   53.439702] cfg80211: Updating information on frequency 2412 MHz for a 20 MHz width channel with regulatory rule:
[   53.439704] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A mBi, 2000 mBm)
[   53.439706] cfg80211: Updating information on frequency 2417 MHz for a 20 MHz width channel with regulatory rule:
[   53.439709] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A mBi, 2000 mBm)
[   53.439710] cfg80211: Updating information on frequency 2422 MHz for a 20 MHz width channel with regulatory rule:
[   53.439713] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A mBi, 2000 mBm)
[   53.439714] cfg80211: Updating information on frequency 2427 MHz for a 20 MHz width channel with regulatory rule:
[   53.439717] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A mBi, 2000 mBm)
[   53.439719] cfg80211: Updating information on frequency 2432 MHz for a 20 MHz width channel with regulatory rule:
[   53.439721] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A mBi, 2000 mBm)
[   53.439723] cfg80211: Updating information on frequency 2437 MHz for a 20 MHz width channel with regulatory rule:
[   53.439725] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A mBi, 2000 mBm)
[   53.439727] cfg80211: Updating information on frequency 2442 MHz for a 20 MHz width channel with regulatory rule:
[   53.439729] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A mBi, 2000 mBm)
[   53.439731] cfg80211: Updating information on frequency 2447 MHz for a 20 MHz width channel with regulatory rule:
[   53.439733] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A mBi, 2000 mBm)
[   53.439735] cfg80211: Updating information on frequency 2452 MHz for a 20 MHz width channel with regulatory rule:
[   53.439737] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A mBi, 2000 mBm)
[   53.439739] cfg80211: Updating information on frequency 2457 MHz for a 20 MHz width channel with regulatory rule:
[   53.439741] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A mBi, 2000 mBm)
[   53.439743] cfg80211: Updating information on frequency 2462 MHz for a 20 MHz width channel with regulatory rule:
[   53.439746] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A mBi, 2000 mBm)
[   53.439747] cfg80211: Updating information on frequency 2467 MHz for a 20 MHz width channel with regulatory rule:
[   53.439750] cfg80211: 2457000 KHz - 2482000 KHz @  KHz), (N/A mBi, 2000 mBm)
[   53.439751] cfg80211: Updating information on frequency 2472 MHz for a 20 MHz width channel with regulatory rule:
[   53.439754] cfg80211: 2457000 KHz - 2482000 KHz @  KHz), (N/A mBi, 2000 mBm)
[   53.439756] cfg80211: Updating information on frequency 2484 MHz for a 20 MHz width channel with regulatory rule:
[   53.439758] cfg80211: 2474000 KHz - 2494000 KHz @  KHz), (N/A mBi, 2000 mBm)
[   53.439761] ath: tx DMA: 512 buffers 1 desc/buf
[   53.439772] ath: tx DMA map: ffff880071f90000 (54600) -> 71f90000 (54600)
[   53.439792] ath: beacon DMA: 4 buffers 1 desc/buf
[   53.439795] ath: beacon DMA map: ffff880071ecc000 (416) -> 71ecc000 (416)
[   53.439797] ath: cachelsz 64 rxbufsize 1926
[   53.439799] ath: rx DMA: 512 buffers 1 desc/buf
[   53.439811] ath: rx DMA map: ffff880071fb0000 (54600) -> 71fb0000 (54600)
[   53.441193] cfg80211: Ignoring regulatory request Set by core since the driver uses its own custom regulatory domain [   53.441269] ieee80211 phy1: Selected rate control algorithm 'ath9k_rate_control'
[   53.441628] Registered led device: ath9k-phy1
[   53.441641] ath9k: disabling interrupts
[   53.442979] ath: disable IER
[   53.442990] ath: 0x0 => 0x0
[   53.442992] ath: new IMR 0x0
[   53.443013] ath9k: requesting irq
[   53.444293] ath9k: interrupt with invalid flag set (1 times)
[   53.444296] wait 500 ms
[   53.446255] ath9k: interrupt with invalid flag set (2 times)
[   53.446288] ath9k: interrupt with invalid flag set (4 times)
[   53.446330] ath9k: interrupt with invalid flag set (8 times)
[   53.446374] ath9k: interrupt with invalid flag set (16 times)
[   53.446453] ath9k: interrupt with invalid flag set (32 times)
[   53.446572] ath9k: interrupt with invalid flag set (64 times)
[   53.446821] ath9k: interrupt with invalid flag set (128 times)
[   53.447319] ath9k: interrupt with invalid flag set (256 times)
[   53.448526] ath9k: interrupt with invalid flag set (512 times)
[   53.450942] ath9k: interrupt with invalid flag set (1024 times)
[   53.454793] ath9k: interrupt with invalid flag set (2048 times)
[   53.462493] ath9k: interrupt with invalid flag set (4096 times)
[   53.477738] ath9k: interrupt with invalid flag set (8192 times)
[   53.508164] ath9k: interrupt with invalid flag set (16384 times)
[   53.571798] ath9k: interrupt with invalid flag set (32768 times)
[   53.697472] ath9k: interrupt with invalid flag set (65536 times)
[   53.832522] irq 17: nobody cared (try booting with the "irqpoll" option)
[   53.834253] Pid: 0, comm: kworker/0:0 Tainted: G         C  3.1.0-rc2-ath9k-debug #16
[   53.835991] Call Trace:
[   53.837727]  <IRQ>  [<ffffffff810c64fd>] __report_bad_irq+0x3d/0xe0
[   53.839487]  [<ffffffff810c693d>] note_interrupt+0x14d/0x210
[   53.841220]  [<ffffffff810c49d9>] handle_irq_event_percpu+0xc9/0x2a0
[   53.842952]  [<ffffffff810c4bf8>] handle_irq_event+0x48/0x70
[   53.844659]  [<ffffffff810c727a>] handle_fasteoi_irq+0x5a/0xe0
[   53.846379]  [<ffffffff81016982>] handle_irq+0x22/0x40
[   53.848073]  [<ffffffff813eb45a>] do_IRQ+0x5a/0xe0
[   53.849751]  [<ffffffff813e80ae>] common_interrupt+0x6e/0x6e
[   53.851438]  <EOI>  [<ffffffff813e4a96>] ? schedule+0x316/0x9b0
[   53.853151]  [<ffffffff812732bb>] ? intel_idle+0xcb/0x120
[   53.854822]  [<ffffffff8127329d>] ? intel_idle+0xad/0x120
[   53.856502]  [<ffffffff81311e66>] cpuidle_idle_call+0xc6/0x350
[   53.858166]  [<ffffffff81013229>] cpu_idle+0xc9/0x120
[   53.859806]  [<ffffffff813d6f71>] start_secondary+0x202/0x209
[   53.861438] handlers:
[   53.863009] [<ffffffffa0557600>] ath_isr
[   53.864524] Disabling IRQ #17
[   53.943777] done waiting
[   53.944849] ieee80211 phy1: Atheros AR9285 Rev:2 mem=0xffffc90010ea0000, irq=17

drivers/net/wireless/ath/ath9k/hw.c +1 -0

index 8dcefe7..fe7780c 100644
@@ -16,6 +16,7 @@
 
  #include <linux/io.h>
  #include <linux/slab.h>
+#include <linux/delay.h>
  #include <asm/unaligned.h>
 
  #include "hw.h"

@@ -532,6 +533,7 @@ static int __ath9k_hw_init(struct ath_hw *ah)

       ah->WARegVal |= (AR_WA_D3_L1_DISABLE | AR_WA_ASPM_TIMER_BASED_DISABLE);

+       ath_dbg(common, ATH_DBG_RESET, "reset power on\n"); if (!ath9k_hw_set_reset_reg(ah, ATH9K_RESET_POWER_ON)) { ath_err(common, "Couldn't reset chip\n"); return -EIO;

drivers/net/wireless/ath/ath9k/main.c +25 -3

index 9098aaa..fdd5dd1 100644
@@ -16,6 +16,7 @@
 
  #include <linux/nl80211.h>
  #include <linux/delay.h>
+#include <linux/log2.h>
  #include "ath9k.h"
  #include "btcoex.h"
 

@@ -770,14 +771,28 @@ irqreturn_t ath_isr(int irq, void *dev)
         * touch anything. Note this can happen early
         * on if the IRQ is shared.
         */
-       if (sc->sc_flags & SC_OP_INVALID)
+       if (sc->sc_flags & SC_OP_INVALID) {
+               static int count = 0;
+               if (count < INT_MAX) {
+                       count++;
+                       if (is_power_of_2(count))
+                               printk(KERN_DEBUG "ath9k: interrupt with invalid flag set (%d times)\n", count);
+               }
                return IRQ_NONE;
+       }
 
 
        /* shared irq, not for us */
 
-       if (!ath9k_hw_intrpend(ah))
+       if (!ath9k_hw_intrpend(ah)) {
+               static int count = 0;
+               if (count < INT_MAX) {
+                       count++;
+                       if (is_power_of_2(count))
+                               printk(KERN_DEBUG "ath9k: shared irq, not for us (%d times)\n", count);
+               }
                return IRQ_NONE;
+       }
 
        /*
         * Figure out the reason(s) for the interrupt.  Note

@@ -792,8 +807,15 @@ irqreturn_t ath_isr(int irq, void *dev)
         * If there are no status bits set, then this interrupt was not
         * for me (should have been caught above).
         */
-       if (!status)
+       if (!status) {
+               static int count = 0;
+               if (count < INT_MAX) {
+                       count++;
+                       if (is_power_of_2(count))
+                               printk(KERN_DEBUG "ath9k: interrupt, but no status bit set (%d times)\n", count);
+               }
                return IRQ_NONE;
+       }
 
        /* Cache the status */
        sc->intrstatus = status;

drivers/net/wireless/ath/ath9k/pci.c +21 -8

index be4ea13..6fdabd8 100644
@@ -242,21 +242,35 @@ static int ath_pci_probe(struct pci_dev *pdev, const struct pci_device_id *id)
        /* Will be cleared in ath9k_start() */
        sc->sc_flags |= SC_OP_INVALID;
 
+       pci_read_config_word(pdev, PCI_SUBSYSTEM_ID, &subsysid);
+       ret = ath9k_init_device(id->device, sc, subsysid, &ath_pci_bus_ops);
+       if (ret) {
+               dev_err(&pdev->dev, "Failed to initialize device\n");
+               goto err_init;
+       }
+
+       {
+               struct ath_hw *ah = sc->sc_ah;
+               printk(KERN_INFO "ath9k: disabling interrupts\n");
+               ath9k_ps_wakeup(sc);
+               mutex_lock(&sc->mutex);
+               ath9k_hw_set_interrupts(ah, 0);
+               mutex_unlock(&sc->mutex);
+               ath9k_ps_restore(sc);
+       }
+
+       printk(KERN_INFO "ath9k: requesting irq\n");
        ret = request_irq(pdev->irq, ath_isr, IRQF_SHARED, "ath9k", sc);
        if (ret) {
                dev_err(&pdev->dev, "request_irq failed\n");
                goto err_irq;
        }
+       printk(KERN_INFO "wait 500 ms\n");
+       msleep(500);
+       printk(KERN_INFO "done waiting\n");
 
        sc->irq = pdev->irq;
 
-       pci_read_config_word(pdev, PCI_SUBSYSTEM_ID, &subsysid);
-       ret = ath9k_init_device(id->device, sc, subsysid, &ath_pci_bus_ops);
-       if (ret) {
-               dev_err(&pdev->dev, "Failed to initialize device\n");
-               goto err_init;
-       }
-
        ath9k_hw_name(sc->sc_ah, hw_name, sizeof(hw_name));
        wiphy_info(hw->wiphy, "%s mem=0x%lx, irq=%d\n",
                   hw_name, (unsigned long)mem, pdev->irq);
--

To unsubscribe from this list: send the line "unsubscribe linux-wireless" in the body of a message to [email protected]
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Quoted 2 lines · Clemens Buchacher

Hi,

Hi Clemens,

Quoted 6 lines

I am trying to debug this issue:
https://bugzilla.kernel.org/show_bug.cgi?id=39112

An IRQ storm triggers during resume after suspend to RAM. The IRQ storm also triggers during insmod after suspend/resume, even if ath9k is not loaded during suspend.

a recent commit, not sure this will help suspend/resume

commit 0682c9b52bf51fbc67c4e79fcbdadcf70bd600f8
Author: Rajkumar Manoharan <[email protected]>
Date:   Sat Aug 13 10:28:09 2011 +0530

   ath9k: Fix rx overrun interrupt storm

   Whenever RXEOL is received, both RXORN and RXEOL got cleared to avoid rx overrun interrupt storm. This was handled only for edma chips. The same scenario was also observered with AR9280, doing frequent channel type switch b/w HT20/40 with bidi traffic that is causing failure to stop rx dma. This patch clears the RXEOL & RXORN interrupts for all chips.

Quoted 16 lines

In the former case, the IRQ storm happens right after the PCI subsystem restores the config space for ath9k.

In the latter case, the IRQ storm happens immediately after request_irq in ath_pci_probe. So I have moved ath9k_init_device ahead of request_irq, in order to call ath9k_hw_set_interrupts(ah,
0) before enabling the interrupt.

But still, the interrupts come. Note that according to /proc/interrupts, the IRQ line is not shared with any other device. I did not manage to determine which interrupt it is exactly, because the device is not in a ready state (SC_OP_INVALID is set) when they happen (in either scenario that triggers the IRQ storm). And SC_OP_INVALID is cleared only much later in ath9k_start.

Quoted 1 line

So, I am at a loss. Any ideas?

please provide the lspci -vvvxx.
also looking at /sys/kernel/debug/ieee80211/phy0/ath9k$ sudo cat interrupt.

also this additional information might help:
in case have you seen this is happening in 32 bit also ? is this happening in wireless-testing  Linux 3.1-rc3 ? or the latest compat wireless?
i did some preliminary testing, not able to recreate it. will try further.thanks!

Quoted 248 lines

Below is the output I get during insmod'ing right after resume (complete logs can be found in the bug report). Below that are the changes I made to produce the output.

Clemens
---

[   53.387989] ath9k 0000:02:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17
[   53.389306] ath9k 0000:02:00.0: setting latency timer to 64
[   53.389371] ath: reset power on
[   53.392725] ath: UNDEFINED -> AWAKE
[   53.392783] ath: serialize_regmode is 0
[   53.438096] ath: Eeprom VER: 14, REV: 13
[   53.438098] ath: Initialize ANI
[   53.438112] ath: Enable MIB counters
[   53.438143] ath: Setup TX queue: 9
[   53.438144] ath: Set queue properties for: 9
[   53.438146] ath: Setup TX queue: 8
[   53.438147] ath: Set queue properties for: 8
[   53.438149] ath: Set queue properties for: 8
[   53.438151] ath: Reset TX queue: 8
[   53.438176] ath: tx ok 0x0 err 0x0 desc 0x100 eol 0x100 urn 0x0
[   53.438178] ath: Setup TX queue: 0
[   53.438179] ath: Set queue properties for: 0
[   53.438181] ath: Setup TX queue: 1
[   53.438182] ath: Set queue properties for: 1
[   53.438184] ath: Setup TX queue: 2
[   53.438185] ath: Set queue properties for: 2
[   53.438186] ath: Setup TX queue: 3
[   53.438187] ath: Set queue properties for: 3
[   53.439692] ath: TX streams 1, RX streams: 1
[   53.439694] ath: EEPROM regdomain: 0x60
[   53.439695] ath: EEPROM indicates we should expect a direct regpair map
[   53.439698] ath: Country alpha2 being used: 00
[   53.439699] ath: Regpair used: 0x60
[   53.439702] cfg80211: Updating information on frequency 2412 MHz for a 20 MHz width channel with regulatory rule:
[   53.439704] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A mBi, 2000 mBm)
[   53.439706] cfg80211: Updating information on frequency 2417 MHz for a 20 MHz width channel with regulatory rule:
[   53.439709] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A mBi, 2000 mBm)
[   53.439710] cfg80211: Updating information on frequency 2422 MHz for a 20 MHz width channel with regulatory rule:
[   53.439713] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A mBi, 2000 mBm)
[   53.439714] cfg80211: Updating information on frequency 2427 MHz for a 20 MHz width channel with regulatory rule:
[   53.439717] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A mBi, 2000 mBm)
[   53.439719] cfg80211: Updating information on frequency 2432 MHz for a 20 MHz width channel with regulatory rule:
[   53.439721] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A mBi, 2000 mBm)
[   53.439723] cfg80211: Updating information on frequency 2437 MHz for a 20 MHz width channel with regulatory rule:
[   53.439725] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A mBi, 2000 mBm)
[   53.439727] cfg80211: Updating information on frequency 2442 MHz for a 20 MHz width channel with regulatory rule:
[   53.439729] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A mBi, 2000 mBm)
[   53.439731] cfg80211: Updating information on frequency 2447 MHz for a 20 MHz width channel with regulatory rule:
[   53.439733] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A mBi, 2000 mBm)
[   53.439735] cfg80211: Updating information on frequency 2452 MHz for a 20 MHz width channel with regulatory rule:
[   53.439737] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A mBi, 2000 mBm)
[   53.439739] cfg80211: Updating information on frequency 2457 MHz for a 20 MHz width channel with regulatory rule:
[   53.439741] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A mBi, 2000 mBm)
[   53.439743] cfg80211: Updating information on frequency 2462 MHz for a 20 MHz width channel with regulatory rule:
[   53.439746] cfg80211: 2402000 KHz - 2472000 KHz @  KHz), (N/A mBi, 2000 mBm)
[   53.439747] cfg80211: Updating information on frequency 2467 MHz for a 20 MHz width channel with regulatory rule:
[   53.439750] cfg80211: 2457000 KHz - 2482000 KHz @  KHz), (N/A mBi, 2000 mBm)
[   53.439751] cfg80211: Updating information on frequency 2472 MHz for a 20 MHz width channel with regulatory rule:
[   53.439754] cfg80211: 2457000 KHz - 2482000 KHz @  KHz), (N/A mBi, 2000 mBm)
[   53.439756] cfg80211: Updating information on frequency 2484 MHz for a 20 MHz width channel with regulatory rule:
[   53.439758] cfg80211: 2474000 KHz - 2494000 KHz @  KHz), (N/A mBi, 2000 mBm)
[   53.439761] ath: tx DMA: 512 buffers 1 desc/buf
[   53.439772] ath: tx DMA map: ffff880071f90000 (54600) -> 71f90000 (54600)
[   53.439792] ath: beacon DMA: 4 buffers 1 desc/buf
[   53.439795] ath: beacon DMA map: ffff880071ecc000 (416) -> 71ecc000 (416)
[   53.439797] ath: cachelsz 64 rxbufsize 1926
[   53.439799] ath: rx DMA: 512 buffers 1 desc/buf
[   53.439811] ath: rx DMA map: ffff880071fb0000 (54600) -> 71fb0000 (54600)
[   53.441193] cfg80211: Ignoring regulatory request Set by core since the driver uses its own custom regulatory domain [   53.441269] ieee80211 phy1: Selected rate control algorithm 'ath9k_rate_control'
[   53.441628] Registered led device: ath9k-phy1
[   53.441641] ath9k: disabling interrupts
[   53.442979] ath: disable IER
[   53.442990] ath: 0x0 => 0x0
[   53.442992] ath: new IMR 0x0
[   53.443013] ath9k: requesting irq
[   53.444293] ath9k: interrupt with invalid flag set (1 times)
[   53.444296] wait 500 ms
[   53.446255] ath9k: interrupt with invalid flag set (2 times)
[   53.446288] ath9k: interrupt with invalid flag set (4 times)
[   53.446330] ath9k: interrupt with invalid flag set (8 times)
[   53.446374] ath9k: interrupt with invalid flag set (16 times)
[   53.446453] ath9k: interrupt with invalid flag set (32 times)
[   53.446572] ath9k: interrupt with invalid flag set (64 times)
[   53.446821] ath9k: interrupt with invalid flag set (128 times)
[   53.447319] ath9k: interrupt with invalid flag set (256 times)
[   53.448526] ath9k: interrupt with invalid flag set (512 times)
[   53.450942] ath9k: interrupt with invalid flag set (1024 times)
[   53.454793] ath9k: interrupt with invalid flag set (2048 times)
[   53.462493] ath9k: interrupt with invalid flag set (4096 times)
[   53.477738] ath9k: interrupt with invalid flag set (8192 times)
[   53.508164] ath9k: interrupt with invalid flag set (16384 times)
[   53.571798] ath9k: interrupt with invalid flag set (32768 times)
[   53.697472] ath9k: interrupt with invalid flag set (65536 times)
[   53.832522] irq 17: nobody cared (try booting with the "irqpoll" option)
[   53.834253] Pid: 0, comm: kworker/0:0 Tainted: G         C  3.1.0-rc2-ath9k-debug #16
[   53.835991] Call Trace:
[   53.837727]  <IRQ>  [<ffffffff810c64fd>] __report_bad_irq+0x3d/0xe0
[   53.839487]  [<ffffffff810c693d>] note_interrupt+0x14d/0x210
[   53.841220]  [<ffffffff810c49d9>] handle_irq_event_percpu+0xc9/0x2a0
[   53.842952]  [<ffffffff810c4bf8>] handle_irq_event+0x48/0x70
[   53.844659]  [<ffffffff810c727a>] handle_fasteoi_irq+0x5a/0xe0
[   53.846379]  [<ffffffff81016982>] handle_irq+0x22/0x40
[   53.848073]  [<ffffffff813eb45a>] do_IRQ+0x5a/0xe0
[   53.849751]  [<ffffffff813e80ae>] common_interrupt+0x6e/0x6e
[   53.851438]  <EOI>  [<ffffffff813e4a96>] ? schedule+0x316/0x9b0
[   53.853151]  [<ffffffff812732bb>] ? intel_idle+0xcb/0x120
[   53.854822]  [<ffffffff8127329d>] ? intel_idle+0xad/0x120
[   53.856502]  [<ffffffff81311e66>] cpuidle_idle_call+0xc6/0x350
[   53.858166]  [<ffffffff81013229>] cpu_idle+0xc9/0x120
[   53.859806]  [<ffffffff813d6f71>] start_secondary+0x202/0x209
[   53.861438] handlers:
[   53.863009] [<ffffffffa0557600>] ath_isr
[   53.864524] Disabling IRQ #17
[   53.943777] done waiting
[   53.944849] ieee80211 phy1: Atheros AR9285 Rev:2 mem=0xffffc90010ea0000, irq=17

drivers/net/wireless/ath/ath9k/hw.c +1 -0

index 8dcefe7..fe7780c 100644
@@ -16,6 +16,7 @@
 
  #include <linux/io.h>
  #include <linux/slab.h>
+#include <linux/delay.h>
  #include <asm/unaligned.h>
 
  #include "hw.h"

@@ -532,6 +533,7 @@ static int __ath9k_hw_init(struct ath_hw *ah)

       ah->WARegVal |= (AR_WA_D3_L1_DISABLE | AR_WA_ASPM_TIMER_BASED_DISABLE);

+       ath_dbg(common, ATH_DBG_RESET, "reset power on\n"); if (!ath9k_hw_set_reset_reg(ah, ATH9K_RESET_POWER_ON)) { ath_err(common, "Couldn't reset chip\n"); return -EIO;

drivers/net/wireless/ath/ath9k/main.c +25 -3

index 9098aaa..fdd5dd1 100644
@@ -16,6 +16,7 @@
 
  #include <linux/nl80211.h>
  #include <linux/delay.h>
+#include <linux/log2.h>
  #include "ath9k.h"
  #include "btcoex.h"
 

@@ -770,14 +771,28 @@ irqreturn_t ath_isr(int irq, void *dev)
         * touch anything. Note this can happen early
         * on if the IRQ is shared.
         */
-       if (sc->sc_flags & SC_OP_INVALID)
+       if (sc->sc_flags & SC_OP_INVALID) {
+               static int count = 0;
+               if (count < INT_MAX) {
+                       count++;
+                       if (is_power_of_2(count))
+                               printk(KERN_DEBUG "ath9k: interrupt with invalid flag set (%d times)\n", count);
+               }
                return IRQ_NONE;
+       }
 
 
        /* shared irq, not for us */
 
-       if (!ath9k_hw_intrpend(ah))
+       if (!ath9k_hw_intrpend(ah)) {
+               static int count = 0;
+               if (count < INT_MAX) {
+                       count++;
+                       if (is_power_of_2(count))
+                               printk(KERN_DEBUG "ath9k: shared irq, not for us (%d times)\n", count);
+               }
                return IRQ_NONE;
+       }
 
        /*
         * Figure out the reason(s) for the interrupt.  Note

@@ -792,8 +807,15 @@ irqreturn_t ath_isr(int irq, void *dev)
         * If there are no status bits set, then this interrupt was not
         * for me (should have been caught above).
         */
-       if (!status)
+       if (!status) {
+               static int count = 0;
+               if (count < INT_MAX) {
+                       count++;
+                       if (is_power_of_2(count))
+                               printk(KERN_DEBUG "ath9k: interrupt, but no status bit set (%d times)\n", count);
+               }
                return IRQ_NONE;
+       }
 
        /* Cache the status */
        sc->intrstatus = status;

drivers/net/wireless/ath/ath9k/pci.c +21 -8

index be4ea13..6fdabd8 100644
@@ -242,21 +242,35 @@ static int ath_pci_probe(struct pci_dev *pdev, const struct pci_device_id *id)
        /* Will be cleared in ath9k_start() */
        sc->sc_flags |= SC_OP_INVALID;
 
+       pci_read_config_word(pdev, PCI_SUBSYSTEM_ID, &subsysid);
+       ret = ath9k_init_device(id->device, sc, subsysid, &ath_pci_bus_ops);
+       if (ret) {
+               dev_err(&pdev->dev, "Failed to initialize device\n");
+               goto err_init;
+       }
+
+       {
+               struct ath_hw *ah = sc->sc_ah;
+               printk(KERN_INFO "ath9k: disabling interrupts\n");
+               ath9k_ps_wakeup(sc);
+               mutex_lock(&sc->mutex);
+               ath9k_hw_set_interrupts(ah, 0);
+               mutex_unlock(&sc->mutex);
+               ath9k_ps_restore(sc);
+       }
+
+       printk(KERN_INFO "ath9k: requesting irq\n");
        ret = request_irq(pdev->irq, ath_isr, IRQF_SHARED, "ath9k", sc);
        if (ret) {
                dev_err(&pdev->dev, "request_irq failed\n");
                goto err_irq;
        }
+       printk(KERN_INFO "wait 500 ms\n");
+       msleep(500);
+       printk(KERN_INFO "done waiting\n");
 
        sc->irq = pdev->irq;
 
-       pci_read_config_word(pdev, PCI_SUBSYSTEM_ID, &subsysid);
-       ret = ath9k_init_device(id->device, sc, subsysid, &ath_pci_bus_ops);
-       if (ret) {
-               dev_err(&pdev->dev, "Failed to initialize device\n");
-               goto err_init;
-       }
-
        ath9k_hw_name(sc->sc_ah, hw_name, sizeof(hw_name));
        wiphy_info(hw->wiphy, "%s mem=0x%lx, irq=%d\n",
                   hw_name, (unsigned long)mem, pdev->irq);
--

Quoted 4 lines

To unsubscribe from this list: send the line "unsubscribe linux-wireless" in the body of a message to [email protected]
More majordomo info at  http://vger.kernel.org/majordomo-info.html

--
shafi

Quoted 9 lines

Quoted 8 lines

But still, the interrupts come. Note that according to /proc/interrupts, the IRQ line is not shared with any other device. I did not manage to determine which interrupt it is exactly, because the device is not in a ready state (SC_OP_INVALID is set) when they happen (in either scenario that triggers the IRQ storm). And SC_OP_INVALID is cleared only much later in ath9k_start.

So, I am at a loss. Any ideas?

Quoted 3 lines

please provide the lspci -vvvxx.
also looking at /sys/kernel/debug/ieee80211/phy0/ath9k$ sudo cat interrupt.

hi, i think this will help, please get the message sudo modprobe ath9k debug=0xffffffff.
few fatal PCI interrupt messages are based on ATH_DEBUG_ANY. thanks.

Quoted 11 lines

Quoted 9 lines

But still, the interrupts come. Note that according to /proc/interrupts, the IRQ line is not shared with any other device. I did not manage to determine which interrupt it is exactly, because the device is not in a ready state (SC_OP_INVALID is set) when they happen (in either scenario that triggers the IRQ storm). And SC_OP_INVALID is cleared only much later in ath9k_start.

So, I am at a loss. Any ideas?

please provide the lspci -vvvxx.

Quoted 2 lines

Quoted 2 lines

also looking at /sys/kernel/debug/ieee80211/phy0/ath9k$ sudo cat interrupt.

Quoted 3 lines

hi, i think this will help, please get the message sudo modprobe ath9k debug=0xffffffff.
few fatal PCI interrupt messages are based on ATH_DEBUG_ANY.

we can also try to disable MIB interrupts though its handled properly now in ath9k

http://www.kernel.org/pub/linux/kernel/people/mcgrof/patches/ath9k/2008-09-25/0001-ath9k-disable-MIB-interrupts-to-fix-interrupt-storm.patch

a recent commit, not sure this will help suspend/resume

commit 0682c9b52bf51fbc67c4e79fcbdadcf70bd600f8
Author: Rajkumar Manoharan <[email protected]>
Date:   Sat Aug 13 10:28:09 2011 +0530

   ath9k: Fix rx overrun interrupt storm

Quoted 2 lines

also this additional information might help:
in case have you seen this is happening in 32 bit also ?

Quoted 2 lines

is this happening in wireless-testing  Linux 3.1-rc3 ? or the latest compat wireless?

Quoted 2 lines

i did some preliminary testing, not able to recreate it. will try further.thanks!

Hi Mohammed,

Quoted 8 lines · Mohammed Shafi

Quoted 8 lines

Quoted 8 lines

But still, the interrupts come. Note that according to /proc/interrupts, the IRQ line is not shared with any other device. I did not manage to determine which interrupt it is exactly, because the device is not in a ready state (SC_OP_INVALID is set) when they happen (in either scenario that triggers the IRQ storm). And SC_OP_INVALID is cleared only much later in ath9k_start.

Quoted 3 lines

Quoted 3 lines

Quoted 1 line

So, I am at a loss. Any ideas?

please provide the lspci -vvvxx.

Please see below.

Quoted 3 lines

Quoted 3 lines

Quoted 3 lines

also looking at /sys/kernel/debug/ieee80211/phy0/ath9k$ sudo cat interrupt.

Those interrupt counters are always zero, because ath_isr never gets to the point where it would gather statistics. The interrupt routine exits right at the start, because SC_OP_INVALID is still set.

       if (sc->sc_flags & SC_OP_INVALID)
               return IRQ_NONE;

By the time the invalid flag is cleared, the IRQ line has long since been disabled, due to 10000 spurios interrupts during less than 500 ms.

Quoted 3 lines

Quoted 3 lines

hi, i think this will help, please get the message sudo modprobe ath9k debug=0xffffffff.
few fatal PCI interrupt messages are based on ATH_DEBUG_ANY.

Whenever I did that in the past, it just added lots of PDADC debug messages.

Quoted 5 lines

we can also try to disable MIB interrupts though its handled properly now in ath9k

http://www.kernel.org/pub/linux/kernel/people/mcgrof/patches/ath9k/2008-09-25/0001-ath9k-disable-MIB-interrupts-to-fix-interrupt-storm.patch

But I am already disabling all interrupts by setting the mask to 0. Unless there are some non-maskable ones?

I wonder if the device is in some crashed state at this point. Is it possible to reset the device in ath_pci_probe?

Quoted 8 lines

a recent commit, not sure this will help suspend/resume

commit 0682c9b52bf51fbc67c4e79fcbdadcf70bd600f8
Author: Rajkumar Manoharan <[email protected]>
Date:   Sat Aug 13 10:28:09 2011 +0530

   ath9k: Fix rx overrun interrupt storm

For the same reason as above, this patch does not touch any code that would get executed.

Quoted 2 lines

Quoted 2 lines

also this additional information might help:
in case have you seen this is happening in 32 bit also ?

I have never had a 32-bit system on this machine.

Quoted 2 lines

Quoted 2 lines

is this happening in wireless-testing  Linux 3.1-rc3 ? or the latest compat wireless?

I think I tried last week, but I can try again.

Quoted 2 lines

Quoted 2 lines

i did some preliminary testing, not able to recreate it. will try further.thanks!

Thanks for trying. Did you turn off network manager? As I described here, it can make the bug go away.

[1] https://bugzilla.kernel.org/show_bug.cgi?id=39112#c5

Clemens
---

02:00.0 Network controller: Atheros Communications Inc. AR9285 Wireless Network Adapter (PCI-Express) (rev 01)
       Subsystem: AzureWave Device 1089
       Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx-
       Status: Cap+ 66MHz- UDF- FastB2B- ParErr- DEVSEL=fast >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
       Latency: 0, Cache Line Size: 64 bytes
       Interrupt: pin A routed to IRQ 17
       Region 0: Memory at d2c00000 (64-bit, non-prefetchable) [size=64K]
       Capabilities: [40] Power Management version 3
               Flags: PMEClk- DSI- D1+ D2- AuxCurrent=375mA PME(D0+,D1+,D2-,D3hot+,D3cold+)
               Status: D0 NoSoftRst- PME-Enable- DSel=0 DScale=0 PME-
       Capabilities: [50] MSI: Enable- Count=1/1 Maskable- 64bit-
               Address: 00000000  Data: 0000
       Capabilities: [60] Express (v2) Legacy Endpoint, MSI 00
               DevCap: MaxPayload 128 bytes, PhantFunc 0, Latency L0s <512ns, L1 <64us
                       ExtTag- AttnBtn- AttnInd- PwrInd- RBE+ FLReset-
               DevCtl: Report errors: Correctable- Non-Fatal- Fatal- Unsupported-
                       RlxdOrd+ ExtTag- PhantFunc- AuxPwr- NoSnoop-
                       MaxPayload 128 bytes, MaxReadReq 512 bytes
               DevSta: CorrErr- UncorrErr- FatalErr- UnsuppReq- AuxPwr+ TransPend-
               LnkCap: Port #0, Speed 2.5GT/s, Width x1, ASPM L0s L1, Latency L0 <512ns, L1 <64us ClockPM- Surprise- LLActRep- BwNot-
               LnkCtl: ASPM Disabled; RCB 64 bytes Disabled- Retrain- CommClk+
                       ExtSynch- ClockPM- AutWidDis- BWInt- AutBWInt-
               LnkSta: Speed 2.5GT/s, Width x1, TrErr- Train- SlotClk+ DLActive- BWMgmt- ABWMgmt-
               DevCap2: Completion Timeout: Not Supported, TimeoutDis+
               DevCtl2: Completion Timeout: 50us to 50ms, TimeoutDis-
               LnkCtl2: Target Link Speed: 2.5GT/s, EnterCompliance- SpeedDis-, Selectable De-emphasis: -6dB Transmit Margin: Normal Operating Range, EnterModifiedCompliance- ComplianceSOS- Compliance De-emphasis: -6dB
               LnkSta2: Current De-emphasis Level: -6dB
       Capabilities: [100 v1] Advanced Error Reporting
               UESta:  DLP- SDES- TLP- FCP- CmpltTO- CmpltAbrt- UnxCmplt- RxOF- MalfTLP- ECRC- UnsupReq- ACSViol-
               UEMsk:  DLP- SDES- TLP- FCP- CmpltTO- CmpltAbrt- UnxCmplt- RxOF- MalfTLP- ECRC- UnsupReq- ACSViol-
               UESvrt: DLP+ SDES+ TLP- FCP+ CmpltTO- CmpltAbrt- UnxCmplt- RxOF+ MalfTLP+ ECRC- UnsupReq- ACSViol-
               CESta:  RxErr- BadTLP- BadDLLP- Rollover- Timeout- NonFatalErr-
               CEMsk:  RxErr- BadTLP- BadDLLP- Rollover- Timeout- NonFatalErr+
               AERCap: First Error Pointer: 00, GenCap+ CGenEn- ChkCap+ ChkEn-
       Capabilities: [140 v1] Virtual Channel
               Caps:   LPEVC=0 RefClk=100ns PATEntryBits=1
               Arb:    Fixed- WRR32- WRR64- WRR128-
               Ctrl:   ArbSelect=Fixed
               Status: InProgress-
               VC0:    Caps:   PATOffset=00 MaxTimeSlots=1 RejSnoopTrans-
                       Arb:    Fixed- WRR32- WRR64- WRR128- TWRR128- WRR256-
                       Ctrl:   Enable+ ID=0 ArbSelect=Fixed TC/VC=ff
                       Status: NegoPending- InProgress-
       Capabilities: [160 v1] Device Serial Number 00-15-17-ff-ff-24-14-12
       Capabilities: [170 v1] Power Budgeting <?>
       Kernel driver in use: ath9k
       Kernel modules: ath9k
00: 8c 16 2b 00 07 00 10 00 01 00 80 02 10 00 00 00
10: 04 00 c0 d2 00 00 00 00 00 00 00 00 00 00 00 00
20: 00 00 00 00 00 00 00 00 00 00 00 00 3b 1a 89 10
30: 00 00 00 00 40 00 00 00 00 00 00 00 03 01 00 00

yes it is, though not a good idea, just thinking of we could get some thing by not setting SC_OP_INVALID flag in ath_pci_probe(it was added to fix a panic, but it did not cause panic for me now).

Quoted 5 lines

       if (sc->sc_flags & SC_OP_INVALID)
               return IRQ_NONE;

i am bit confused looking at bug comments. please correct me. the bug comments say that disabling/making the Network-Manager to sleep triggers the problem.

Quoted 4 lines · Mohammed Shafi

i am bit confused looking at bug comments. please correct me. the bug comments say that disabling/making the Network-Manager to sleep triggers the problem.

That is correct.

is the issue still seen? any improvement with the attached patch..

Hello Mohammed,

Quoted 2 lines · Mohammed Shafi

is the issue still seen? any improvement with the attached patch..

I still have the issue. No change with current wl-testing plus your patch.

Below dmesg output of:

 modprobe ath9k debug=0x0000fffb
 echo mem >/sys/power/state

 # resume

Clemens

---
[   27.575562] ath9k 0000:02:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17
[   27.577970] ath9k 0000:02:00.0: setting latency timer to 64
[   27.581405] ath: UNDEFINED -> AWAKE
[   27.581469] ath: serialize_regmode is 0
[   27.626195] ath: Eeprom VER: 14, REV: 13
[   27.626199] ath: Initialize ANI
[   27.626203] ath: Enable MIB counters
[   27.626240] ath: Setup TX queue: 9
[   27.626243] ath: Set queue properties for: 9
[   27.626248] ath: Setup TX queue: 8
[   27.626251] ath: Set queue properties for: 8
[   27.626255] ath: Set queue properties for: 8
[   27.626259] ath: Reset TX queue: 8
[   27.626286] ath: tx ok 0x0 err 0x0 desc 0x100 eol 0x100 urn 0x0
[   27.626290] ath: Setup TX queue: 0
[   27.626293] ath: Set queue properties for: 0
[   27.626297] ath: Setup TX queue: 1
[   27.626300] ath: Set queue properties for: 1
[   27.626304] ath: Setup TX queue: 2
[   27.626307] ath: Set queue properties for: 2
[   27.626310] ath: Setup TX queue: 3
[   27.626313] ath: Set queue properties for: 3
[   27.627816] ath: TX streams 1, RX streams: 1
[   27.627819] ath: EEPROM regdomain: 0x60
[   27.627822] ath: EEPROM indicates we should expect a direct regpair map
[   27.627828] ath: Country alpha2 being used: 00
[   27.627830] ath: Regpair used: 0x60
[   27.627838] ath: tx DMA: 512 buffers 1 desc/buf
[   27.627857] ath: tx DMA map: ffff88006f250000 (54600) -> 6f250000 (54600)
[   27.627891] ath: beacon DMA: 4 buffers 1 desc/buf
[   27.627897] ath: beacon DMA map: ffff88007198d000 (416) -> 7198d000 (416)
[   27.627902] ath: cachelsz 64 rxbufsize 1926
[   27.627906] ath: rx DMA: 512 buffers 1 desc/buf
[   27.627924] ath: rx DMA map: ffff88006f2b0000 (54600) -> 6f2b0000 (54600)
[   27.629650] ieee80211 phy1: Selected rate control algorithm 'ath9k_rate_control'
[   27.630460] Registered led device: ath9k-phy1
[   27.630475] ieee80211 phy1: Atheros AR9285 Rev:2 mem=0xffffc90021ba0000, irq=17
[   43.855411] PM: Syncing filesystems ... done.
[   43.948410] PM: Preparing system for mem sleep
[   43.949937] Freezing user space processes ... (elapsed 0.01 seconds) done.
[   43.963254] Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.
[   43.976527] PM: Entering mem sleep
[   43.976595] Suspending console(s) (use no_console_suspend to debug)
[   43.977193] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[   43.989161] jmb38x_ms 0000:06:00.3: PCI INT B disabled
[   43.989194] sdhci-pci 0000:06:00.0: PCI INT B disabled
[   43.989232] ath: AWAKE -> FULL-SLEEP
[   43.998370] sd 0:0:0:0: [sda] Stopping disk
[   44.196369] snd_hda_intel 0000:00:1b.0: PCI INT A disabled
[   44.608701] PM: suspend of devices complete after 633.019 msecs
[   44.609142] jme 0000:06:00.5: PME# enabled
[   44.609152] jme 0000:06:00.5: wake-up capability enabled by ACPI
[   44.648588] PM: late suspend of devices complete after 39.960 msecs
[   44.648748] ACPI: Preparing to enter system sleep state S3
[   44.951903] PM: Saving platform NVS memory
[   44.952780] Disabling non-boot CPUs ...
[   44.955081] CPU 1 is now offline
[   45.057696] CPU 2 is now offline
[   45.160822] CPU 3 is now offline
[   45.161227] Extended CMOS year: 2000
[   45.161461] ACPI: Low-level resume complete
[   45.161521] PM: Restoring platform NVS memory
[   45.161951] Extended CMOS year: 2000
[   45.161974] Enabling non-boot CPUs ...
[   45.162070] Booting Node 0 Processor 1 APIC 0x4
[   45.162071] smpboot cpu 1: start_ip = 96000
[   45.173166] Calibrating delay loop (skipped) already calibrated this CPU
[   45.193433] NMI watchdog enabled, takes one hw-pmu counter.
[   45.193554] CPU1 is up
[   45.193622] Booting Node 0 Processor 2 APIC 0x1
[   45.193623] smpboot cpu 2: start_ip = 96000
[   45.194742] Switched to NOHz mode on CPU #1
[   45.204719] Calibrating delay loop (skipped) already calibrated this CPU
[   45.225042] NMI watchdog enabled, takes one hw-pmu counter.
[   45.225176] CPU2 is up
[   45.225257] Booting Node 0 Processor 3 APIC 0x5
[   45.225259] smpboot cpu 3: start_ip = 96000
[   45.228010] Switched to NOHz mode on CPU #2
[   45.236352] Calibrating delay loop (skipped) already calibrated this CPU
[   45.256763] NMI watchdog enabled, takes one hw-pmu counter.
[   45.256925] CPU3 is up
[   45.258831] Switched to NOHz mode on CPU #3
[   45.259072] ACPI: Waking up from system sleep state S3
[   45.580717] intel ips 0000:00:1f.6: MCP limit exceeded: Avg temp 20253, limit 9000
[   45.658244] i915 0000:00:02.0: restoring config space at offset 0xf (was 0x100, writing 0x10b) [   45.658253] i915 0000:00:02.0: restoring config space at offset 0x1 (was 0x900007, writing 0x900407) [   45.658277] mei 0000:00:16.0: restoring config space at offset 0xf (was 0x100, writing 0x10b) [   45.658296] mei 0000:00:16.0: restoring config space at offset 0x4 (was 0x4, writing 0xd540a004) [   45.658304] mei 0000:00:16.0: restoring config space at offset 0x1 (was 0x180000, writing 0x180006) [   45.658332] pci 0000:00:1a.0: restoring config space at offset 0xf (was 0x100, writing 0x10b) [   45.658350] pci 0000:00:1a.0: restoring config space at offset 0x4 (was 0x0, writing 0xd5408000) [   45.658358] pci 0000:00:1a.0: restoring config space at offset 0x1 (was 0x2900000, writing 0x2900006) [   45.658391] snd_hda_intel 0000:00:1b.0: restoring config space at offset 0xf (was 0x100, writing 0x105) [   45.658410] snd_hda_intel 0000:00:1b.0: restoring config space at offset 0x4 (was 0x4, writing 0xd5400004) [   45.658415] snd_hda_intel 0000:00:1b.0: restoring config space at offset 0x3 (was 0x0, writing 0x10) [   45.658421] snd_hda_intel 0000:00:1b.0: restoring config space at offset 0x1 (was 0x100004, writing 0x100002) [   45.658455] pcieport 0000:00:1c.0: restoring config space at offset 0xf (was 0x100, writing 0x10010b) [   45.658467] pcieport 0000:00:1c.0: restoring config space at offset 0x9 (was 0x1fff1, writing 0x7c717c61) [   45.658479] pcieport 0000:00:1c.0: restoring config space at offset 0x3 (was 0x810000, writing 0x810010) [   45.658485] pcieport 0000:00:1c.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100407) [   45.658538] pcieport 0000:00:1c.1: restoring config space at offset 0xf (was 0x200, writing 0x100203) [   45.658550] pcieport 0000:00:1c.1: restoring config space at offset 0x9 (was 0x1fff1, writing 0x7c517c41) [   45.658561] pcieport 0000:00:1c.1: restoring config space at offset 0x3 (was 0x810000, writing 0x810010) [   45.658568] pcieport 0000:00:1c.1: restoring config space at offset 0x1 (was 0x100000, writing 0x100407) [   45.658620] pcieport 0000:00:1c.2: restoring config space at offset 0xf (was 0x300, writing 0x100304) [   45.658632] pcieport 0000:00:1c.2: restoring config space at offset 0x9 (was 0x1fff1, writing 0x7c317c21) [   45.658643] pcieport 0000:00:1c.2: restoring config space at offset 0x3 (was 0x810000, writing 0x810010) [   45.658650] pcieport 0000:00:1c.2: restoring config space at offset 0x1 (was 0x100000, writing 0x100407) [   45.658703] pcieport 0000:00:1c.5: restoring config space at offset 0xf (was 0x200, writing 0x100203) [   45.658714] pcieport 0000:00:1c.5: restoring config space at offset 0x9 (was 0x1fff1, writing 0x7c117c01) [   45.658726] pcieport 0000:00:1c.5: restoring config space at offset 0x3 (was 0x810000, writing 0x810010) [   45.658732] pcieport 0000:00:1c.5: restoring config space at offset 0x1 (was 0x100000, writing 0x100407) [   45.658780] pci 0000:00:1d.0: restoring config space at offset 0xf (was 0x100, writing 0x10a) [   45.658799] pci 0000:00:1d.0: restoring config space at offset 0x4 (was 0x0, writing 0xd5407000) [   45.658807] pci 0000:00:1d.0: restoring config space at offset 0x1 (was 0x2900000, writing 0x2900006) [   45.658831] pci 0000:00:1e.0: restoring config space at offset 0xf (was 0x0, writing 0x100000) [   45.658930] ahci 0000:00:1f.2: restoring config space at offset 0x1 (was 0x2b00007, writing 0x2b00407) [   45.659017] intel ips 0000:00:1f.6: restoring config space at offset 0x1 (was 0x100400, writing 0x100406) [   45.659057] ath9k 0000:02:00.0: restoring config space at offset 0xf (was 0x1ff, writing 0x103) [   45.659077] ath9k 0000:02:00.0: restoring config space at offset 0x4 (was 0x4, writing 0xd2c00004) [   45.659082] ath9k 0000:02:00.0: restoring config space at offset 0x3 (was 0x0, writing 0x10) [   45.659088] ath9k 0000:02:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100007) [   45.659129] sdhci-pci 0000:06:00.0: restoring config space at offset 0xf (was 0x2ff, writing 0x204) [   45.659157] sdhci-pci 0000:06:00.0: restoring config space at offset 0x4 (was 0x0, writing 0xd0407000) [   45.659163] sdhci-pci 0000:06:00.0: restoring config space at offset 0x3 (was 0x800000, writing 0x800010) [   45.659172] sdhci-pci 0000:06:00.0: restoring config space at offset 0x1 (was 0x100000, writing 0x100007) [   45.659218] pci 0000:06:00.2: restoring config space at offset 0xf (was 0x2ff, writing 0x204) [   45.659246] pci 0000:06:00.2: restoring config space at offset 0x4 (was 0x0, writing 0xd0406000) [   45.659253] pci 0000:06:00.2: restoring config space at offset 0x3 (was 0x800000, writing 0x800010) [   45.659262] pci 0000:06:00.2: restoring config space at offset 0x1 (was 0x100000, writing 0x100003) [   45.659308] jmb38x_ms 0000:06:00.3: restoring config space at offset 0xf (was 0x2ff, writing 0x204) [   45.659336] jmb38x_ms 0000:06:00.3: restoring config space at offset 0x4 (was 0x0, writing 0xd0405000) [   45.659342] jmb38x_ms 0000:06:00.3: restoring config space at offset 0x3 (was 0x800000, writing 0x800010) [   45.659351] jmb38x_ms 0000:06:00.3: restoring config space at offset 0x1 (was 0x100000, writing 0x100007) [   45.659397] pci 0000:06:00.4: restoring config space at offset 0xf (was 0x2ff, writing 0x204) [   45.659425] pci 0000:06:00.4: restoring config space at offset 0x4 (was 0x0, writing 0xd0404000) [   45.659431] pci 0000:06:00.4: restoring config space at offset 0x3 (was 0x800000, writing 0x800010) [   45.659441] pci 0000:06:00.4: restoring config space at offset 0x1 (was 0x100000, writing 0x100007) [   45.659487] jme 0000:06:00.5: restoring config space at offset 0xf (was 0x100, writing 0x103) [   45.659508] jme 0000:06:00.5: restoring config space at offset 0x7 (was 0x1, writing 0xa001) [   45.659520] jme 0000:06:00.5: restoring config space at offset 0x4 (was 0x0, writing 0xd0400000) [   45.659526] jme 0000:06:00.5: restoring config space at offset 0x3 (was 0x800000, writing 0x800010) [   45.659535] jme 0000:06:00.5: restoring config space at offset 0x1 (was 0x100000, writing 0x100007) [   45.659759] PM: early resume of devices complete after 1.603 msecs
[   45.659979] i915 0000:00:02.0: setting latency timer to 64
[   45.659996] snd_hda_intel 0000:00:1b.0: PCI INT A -> GSI 22 (level, low) -> IRQ 22
[   45.660003] snd_hda_intel 0000:00:1b.0: setting latency timer to 64
[   45.660050] snd_hda_intel 0000:00:1b.0: irq 45 for MSI/MSI-X
[   45.660126] pci 0000:00:1e.0: setting latency timer to 64
[   45.660144] ahci 0000:00:1f.2: setting latency timer to 64
[   45.660211] ath: FULL-SLEEP -> AWAKE
[   45.663932] sdhci-pci 0000:06:00.0: PCI INT B -> GSI 18 (level, low) -> IRQ 18
[   45.663974] sdhci-pci 0000:06:00.0: setting latency timer to 64
[   45.664037] jmb38x_ms 0000:06:00.3: PCI INT B -> GSI 18 (level, low) -> IRQ 18
[   45.664051] jmb38x_ms 0000:06:00.3: setting latency timer to 64
[   45.664113] jme 0000:06:00.5: wake-up capability disabled by ACPI
[   45.664124] jme 0000:06:00.5: PME# disabled
[   45.664503] ath: disable IER
[   45.664521] ath: Disable MIB counters
[   45.664560] ath: disable IER
[   45.664575] ath: 0x30 => 0x30
[   45.664576] ath: new IMR 0x30
[   45.664672] sd 0:0:0:0: [sda] Starting disk
[   45.667161] ath: Getting spur idx:0 is2Ghz:1 val:8000
[   45.668810] ath: Reset TX queue: 0
[   45.668813] ath: tx ok 0x0 err 0x0 desc 0x101 eol 0x101 urn 0x0
[   45.668815] ath: Reset TX queue: 1
[   45.668817] ath: tx ok 0x0 err 0x0 desc 0x103 eol 0x103 urn 0x0
[   45.668819] ath: Reset TX queue: 2
[   45.668821] ath: tx ok 0x0 err 0x0 desc 0x107 eol 0x107 urn 0x0
[   45.668823] ath: Reset TX queue: 3
[   45.668825] ath: tx ok 0x0 err 0x0 desc 0x10f eol 0x10f urn 0x0
[   45.668827] ath: Reset TXQ, inactive queue: 4
[   45.668828] ath: Reset TXQ, inactive queue: 5
[   45.668830] ath: Reset TXQ, inactive queue: 6
[   45.668831] ath: Reset TXQ, inactive queue: 7
[   45.668832] ath: Reset TX queue: 8
[   45.668842] ath: tx ok 0x0 err 0x0 desc 0x10f eol 0x10f urn 0x0
[   45.668844] ath: Reset TX queue: 9
[   45.668854] ath: tx ok 0x0 err 0x0 desc 0x10f eol 0x10f urn 0x0
[   45.668861] ath: ah->misc_mode 0x4
[   45.670264] ath: Running PA Calibration
[   45.670963] ath: enabling ADC Gain Calibration.
[   45.670964] ath: enabling ADC DC Calibration.
[   45.670965] ath: enabling IQ Calibration.
[   45.670969] ath: starting ADC Gain Calibration
[   45.671139] ath: AWAKE -> FULL-SLEEP
[   45.679552] Extended CMOS year: 2000
[   45.983193] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[   45.985133] ata2.00: ACPI cmd ef/10:06:00:00:00:a0 (SET FEATURES) succeeded
[   45.985136] ata2.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
[   45.988885] ata2.00: ACPI cmd ef/10:06:00:00:00:a0 (SET FEATURES) succeeded
[   45.988889] ata2.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
[   45.989852] ata6: SATA link down (SStatus 0 SControl 300)
[   45.990375] ata2.00: configured for UDMA/100
[   46.120272] irq 17: nobody cared (try booting with the "irqpoll" option)
[   46.120275] Pid: 0, comm: swapper Tainted: G         C  3.1.0-rc7-wl-ARCH3.1.0-rc7-ath9k-debug #2 [   46.120277] Call Trace:
[   46.120280]  <IRQ>  [<ffffffff810c68bd>] __report_bad_irq+0x3d/0xe0
[   46.120290]  [<ffffffff810c6cfd>] note_interrupt+0x14d/0x210
[   46.120293]  [<ffffffff810c4c39>] handle_irq_event_percpu+0xc9/0x2a0
[   46.120296]  [<ffffffff810c4e58>] handle_irq_event+0x48/0x70
[   46.120299]  [<ffffffff810c763a>] handle_fasteoi_irq+0x5a/0xe0
[   46.120303]  [<ffffffff81016982>] handle_irq+0x22/0x40
[   46.120308]  [<ffffffff813ec09a>] do_IRQ+0x5a/0xe0
[   46.120312]  [<ffffffff813e8cee>] common_interrupt+0x6e/0x6e
[   46.120313]  <EOI>  [<ffffffff8131234a>] ? poll_idle+0x3a/0x80
[   46.120319]  [<ffffffff81312323>] ? poll_idle+0x13/0x80
[   46.120321]  [<ffffffff813126f6>] cpuidle_idle_call+0xc6/0x350
[   46.120324]  [<ffffffff81013229>] cpu_idle+0xc9/0x120
[   46.120328]  [<ffffffff813c64e7>] rest_init+0x9b/0xa4
[   46.120330]  [<ffffffff8174dc15>] start_kernel+0x3bf/0x3cc
[   46.120333]  [<ffffffff8174d347>] x86_64_start_reservations+0x132/0x136
[   46.120336]  [<ffffffff8174d140>] ? early_idt_handlers+0x140/0x140
[   46.120338]  [<ffffffff8174d44d>] x86_64_start_kernel+0x102/0x111
[   46.120340] handlers:
[   46.120344] [<ffffffffa053c020>] ath_isr
[   46.120345] Disabling IRQ #17
[   48.371839] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[   48.479286] ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
[   48.479457] ata1.00: ACPI cmd ef/10:06:00:00:00:a0 (SET FEATURES) succeeded
[   48.479463] ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
[   48.516626] ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
[   48.516804] ata1.00: ACPI cmd ef/10:06:00:00:00:a0 (SET FEATURES) succeeded
[   48.516809] ata1.00: ACPI cmd ef/10:03:00:00:00:a0 (SET FEATURES) filtered out
[   48.518731] ata1.00: configured for UDMA/133
[   48.526624] ath: FULL-SLEEP -> AWAKE
[   48.530116] ath: ah->misc_mode 0x4
[   48.530142] ath: AWAKE -> FULL-SLEEP
[   48.530172] PM: resume of devices complete after 2875.994 msecs
[   48.530607] PM: Finishing wakeup.
[   48.530608] Restarting tasks ... done.
[   48.533504] video LNXVIDEO:02: Restoring backlight state

Has someone figured out which ISR bits are being triggered?

If not, I can likely whip up a patch which adds some relevant printk's. I think it's worth establishing:

* is it a sync/async interrupt;
* is it a fatal interrupt (eg something like a PCI bus error or transaction timeout) or is it a normal ISR bit that keeps firing;
* .. and which one is firing.

if (sc->sc_flags & SC_OP_INVALID) {
printk(KERN_ERR "AR_INTR_SYNC_CAUSE: 0x%08x, AR_INTR_ASYNC_CAUSE: 0x%08x\n",

    REG_READ(ah, AR_INTR_SYNC_CAUSE), REG_READ(ah, AR_INTR_ASYNC_CAUSE));
printk(KERN_ERR "AR_IMR: 0x%08x, AR_ISR: 0x%08x\n",
    REG_READ(ah, AR_IMR),
    REG_READ(ah, AR_ISR));
    return IRQ_NONE;
}

for 1, 2, ..., 99, 128, 256:
AR_INTR_SYNC_CAUSE: 0x00000000, AR_INTR_ASYNC_CAUSE: 0x00000000
AR_IMR: 0xdeadbeef, AR_ISR: 0xdeadbeef

for 512:
AR_INTR_SYNC_CAUSE: 0x00000000, AR_INTR_ASYNC_CAUSE: 0x00000000
AR_IMR: 0x00000000, AR_ISR: 0x00000208

for 1024:
AR_INTR_SYNC_CAUSE: 0x00000000, AR_INTR_ASYNC_CAUSE: 0x00000000
AR_IMR: 0x81800964, AR_ISR: 0x00000008

for 2048:
AR_INTR_SYNC_CAUSE: 0x00000000, AR_INTR_ASYNC_CAUSE: 0x00000000
AR_IMR: 0xdeadbeef, AR_ISR: 0xdeadbeef

for 2^12, 2^13, ..., 2^16
AR_INTR_SYNC_CAUSE: 0x00020000, AR_INTR_ASYNC_CAUSE: 0x00000000
AR_IMR: 0xdeadbeef, AR_ISR: 0xdeadbeef

The last ones indeed correspond to AR_INTR_SYNC_MAC_SLEEP_ACCESS that you mentioned. Note that this output is interleaved with device initialization. So I don't know if that causes the register contents to become valid, or if it changes the contents.

If I suspend/resume first, then load the module, then wait for 500 ms after request_irq I get only zeroes, repeated 109 times:

for 1, 2, ..., 99, 2^7, 2^8, ..., 2^16:
AR_IMR: 0x00000000, AR_ISR: 0x00000000
AR_INTR_SYNC_CAUSE: 0x00000000, AR_INTR_ASYNC_CAUSE: 0x00000000

Quoted 3 lines · Clemens Buchacher

for 1, 2, ..., 99, 128, 256:
AR_INTR_SYNC_CAUSE: 0x00000000, AR_INTR_ASYNC_CAUSE: 0x00000000
AR_IMR: 0xdeadbeef, AR_ISR: 0xdeadbeef

.. that says some part of the MAC is very asleep. But no interrupt cause bits are set. So I bet it's a shared interrupt.

Quoted 6 lines

If I suspend/resume first, then load the module, then wait for 500 ms after request_irq I get only zeroes, repeated 109 times:

for 1, 2, ..., 99, 2^7, 2^8, ..., 2^16:
AR_IMR: 0x00000000, AR_ISR: 0x00000000
AR_INTR_SYNC_CAUSE: 0x00000000, AR_INTR_ASYNC_CAUSE: 0x00000000

Would you mind also printing the contents of AR_IER there? I wonder if AR_IER is incorrectly being enabled.

Quoted 2 lines

Would you mind also printing the contents of AR_IER there? I wonder if AR_IER is incorrectly being enabled.

Not much more helpful, I'm afraid:

AR_IMR: 0x00000000, AR_ISR: 0x00000000, AR_IER: 0x00000000
AR_INTR_SYNC_CAUSE: 0x00000000, AR_INTR_ASYNC_CAUSE: 0x00000000 (repeated 109 times)

It seems that at this point the device is in a bad state.

From what you've shown there, the device _isn't_ firing off interrupts

Well, the question now is whether the device itself is actually firing off interrupts.

From what you've shown there, the device _isn't_ firing off interrupts the normal way.
So I wonder if it's the card or whether it's something else (eg the PCI bus glue.)

Here, you could try inserting this in the SC_OP_INVALID bit, right after you do some logging. I'm still assuming your AR9285 is somehow firing off interrupts.
At this point however I'm all just guessing here. It'd be nice to know whether the device is _really_ sending interrupts or not.

/* Mark _all_ async interrupts as serviced */
REG_WRITE(ah, AR_INTR_ASYNC_CAUSE, 0xffffffff);
REG_READ(ah, AR_INTR_ASYNC_CAUSE);

/* Disable sync interrupt sources */
REG_WRITE(ah, AR_INTR_SYNC_ENABLE, 0);
/* Mark _all_ sync interrupts as serviced */
REG_WRITE(ah, AR_INTR_SYNC_CAUSE, 0xffffffff);
REG_READ(ah, AR_INTR_SYNC_CAUSE);

/* Do a reset of the AHB and host interface */
REG_WRITE(ah, AR_RC, AR_RC_AHB | AR_RC_HOSTIF);
DELAY(100);

REG_WRITE(ah, AR_RC, 0);

For the record, instead of going to full sleep, I can reproduce the issue with

 echo devices >/sys/power/pm_test
 echo mem >/sys/power/state

but not with

 echo freezer >/sys/power/pm_test
 echo mem >/sys/power/state

So it could still be a different device that's causing the issue? I can try unloading all kinds of modules. Or is there an option to suspend just one device?

Quoted 6 lines · Clemens Buchacher

For the record, instead of going to full sleep, I can reproduce the issue with

 echo devices >/sys/power/pm_test
 echo mem >/sys/power/state

Quoted 8 lines

but not with

 echo freezer >/sys/power/pm_test
 echo mem >/sys/power/state

So it could still be a different device that's causing the issue? I can try unloading all kinds of modules. Or is there an option to suspend just one device?

Right. So its likely something (more) odd. Yes, see if that's the case :) At this point I'm going to punt this to the power management/ACPI people .:)

Good luck!

Adrian

please try this in case it helps anything
to debug the issue.

this should avoid dead beef and the interrupt when we access MAC
registers when the MAC is asleep. also i did not see MAC irq being not triggerred in your case(AR_INTR_ASYNC_CAUSE should be 0x2) or may be its not an interrupt triggered by the chip itself. thanks

Are you able to completely and utterly disable any/all power saving on ath9k, including APSM if you have it enabled?

Hm, which version of the AR9285 is it, exactly?
Would you just do a quick check (or code hack) and see if it matches the AR_SREV_9285SE_20 (or similar) macro?

It matches AR_SREV_9285, but it does not match AR_SREV_9285E_20.

If the interrupt storm continue occuring, try putting the whole NIC to sleep entirely (ie, call pcipowersave to put the NIC to sleep, then make sure the NIC -stays- asleep somehow, ie so nothing else tries waking it up.

I assume you have disabled the NIC power save option. Not just APSM, etc, but the powersave options in iw. I don't know what they are, sorry, only that they exist.

I suggest modifying ath_intr() so if there is an interrupt storm, disable _all_ sources of interrupts (ie, set sync_cause, async_cause to 0, set imr to 0, set ier to 0) and see if it continues occuring.

If the interrupt storm continue occuring, try putting the whole NIC to sleep entirely (ie, call pcipowersave to put the NIC to sleep, then make sure the NIC -stays- asleep somehow, ie so nothing else tries waking it up - I don't know how to do this, likely you'll have to clear some interface flag so the rest of the ath9k and 802.11 stack thinks the nic is actually down for the count) and see if you're still getting spurious interrupts.

At this point I'd really suggest whacking other devices into the slot to see if they generate the same kind of behaviour.

Looks like you had it right from the start. After unloading the jme module [*1*] I cannot reproduce the IRQ storm any more. From looking at dmesg it should have been obvious, since it also gets IRQ 17 assigned. I don't know how I missed that, I was sure I had checked.

Sorry guys, for most likely wasting your time. And thanks for your patience.

There's a function further down in the isr routine which checks whether the NIC itself posted the interrupt (it checks SYNC_CAUSE/ASYNC_CAUSE.) That should cut down the spam quite a bit and only log the relevant entries for ath9k.