[WARNING] at kernel/irq/manage.c:421 __enable_irq

[WARNING] at kernel/irq/manage.c:421 __enable_irq

[Steven Rostedt]

I'm getting this on my main box. I'm running 3.3.6 but I also tried out
the latest Linus kernel (as of yesterday) and it has it too:

[    1.572757] ------------[ cut here ]------------
[    1.573063] WARNING: at /home/rostedt/work/git/nobackup/linux-build.git/kerne
l/irq/manage.c:421 __enable_irq+0x38/0xc0()
[    1.573663] Hardware name: System Product Name
[    1.573936] Unbalanced enable for IRQ 16
[    1.574184] Modules linked in: usb_storage ata_generic(+) uas ohci_hcd ata_pi
ix via82cxxx(+) ehci_hcd libata scsi_mod ide_pci_generic ide_core xhci_hcd r8169
 mii usbcore usb_common
[    1.575829] Pid: 177, comm: modprobe Not tainted 3.3.6-custom+ #2
[    1.576185] Call Trace:
[    1.576364]  [<ffffffff8103789f>] warn_slowpath_common+0x7f/0xc0
[    1.576717]  [<ffffffff81037996>] warn_slowpath_fmt+0x46/0x50
[    1.577055]  [<ffffffff810b9d68>] __enable_irq+0x38/0xc0
[    1.577372]  [<ffffffff810b9e37>] enable_irq+0x47/0x90
[    1.577684]  [<ffffffffa00b5938>] ide_probe_port+0x398/0x6a0 [ide_core]
[    1.578067]  [<ffffffff8132b09b>] ? dmi_check_system+0x2b/0x60
[    1.578410]  [<ffffffffa00b5fc9>] ide_host_register+0x2d9/0x730 [ide_core]
[    1.578807]  [<ffffffffa00bbbba>] ide_pci_init_two+0x4ba/0x7c0 [ide_core]
[    1.579198]  [<ffffffff8106e501>] ? get_parent_ip+0x11/0x50
[    1.579530]  [<ffffffff81448edd>] ? sub_preempt_count+0x9d/0xd0
[    1.579878]  [<ffffffff81445746>] ? _raw_spin_unlock+0x16/0x40
[    1.580224]  [<ffffffffa00bbed6>] ide_pci_init_one+0x16/0x20 [ide_core]
[    1.580607]  [<ffffffffa009491e>] via_init_one+0x237/0x25c [via82cxxx]
[    1.580983]  [<ffffffff8106e501>] ? get_parent_ip+0x11/0x50
[    1.581315]  [<ffffffffa00940a0>] ? via82cxxx_cable_detect+0xa0/0xa0 [via82cxxx]
[    1.581747]  [<ffffffff81265dfc>] local_pci_probe+0x5c/0xd0
[    1.582545]  [<ffffffff81267721>] pci_device_probe+0x101/0x120
[    1.582890]  [<ffffffff812febae>] driver_probe_device+0x7e/0x1b0
[    1.583242]  [<ffffffff812fed8b>] __driver_attach+0xab/0xb0
[    1.583572]  [<ffffffff812fece0>] ? driver_probe_device+0x1b0/0x1b0
[    1.583937]  [<ffffffff812fd226>] bus_for_each_dev+0x56/0x90
[    1.584271]  [<ffffffff812fe83e>] driver_attach+0x1e/0x20
[    1.584593]  [<ffffffff812fe4a0>] bus_add_driver+0x1a0/0x260
[    1.584928]  [<ffffffffa003e000>] ? 0xffffffffa003dfff
[    1.585238]  [<ffffffff812ff2e6>] driver_register+0x76/0x140
[    1.585573]  [<ffffffff81448d5d>] ? notifier_call_chain.isra.0+0x4d/0x70
[    1.585958]  [<ffffffffa003e000>] ? 0xffffffffa003dfff
[    1.586268]  [<ffffffff812673e5>] __pci_register_driver+0x55/0xd0
[    1.586624]  [<ffffffff8102c763>] ? set_memory_nx+0x43/0x50
[    1.586955]  [<ffffffffa003e01e>] via_ide_init+0x1e/0x1000 [via82cxxx]
[    1.587333]  [<ffffffff810001cf>] do_one_initcall+0x3f/0x170
[    1.587668]  [<ffffffff8109aaee>] sys_init_module+0xbe/0x230
[    1.588004]  [<ffffffff8144e129>] ia32_do_call+0x13/0x13
[    1.588322] ---[ end trace 78e7b514db9ce361 ]---
[    1.588632] Probing IDE interface ide1...

The code in ide_probe_port() does the following:

        irqd = hwif->irq;
        if (irqd)
                disable_irq(hwif->irq);

        if (ide_port_wait_ready(hwif) == -EBUSY)
                printk(KERN_DEBUG "%s: Wait for ready failed before probe !\n", hwif->name);

        /*
         * Second drive should only exist if first drive was found,
         * but a lot of cdrom drives are configured as single slaves.
         */
        ide_port_for_each_dev(i, drive, hwif) {
                (void) probe_for_drive(drive);
                if (drive->dev_flags & IDE_DFLAG_PRESENT)
                        rc = 0;
        }

        /*
         * Use cached IRQ number. It might be (and is...) changed by probe
         * code above
         */
        if (irqd)
                enable_irq(irqd);

We disable the interrupt for the device (hwif->irq), do the probes, and
then enable the irq if it existed. The problem is that the probe resets
the depth count of the irq descriptor. I ran some traces, and added some
trace_printks, to confirm it.

Coming into this function, the desc->depth is 1. The disable_irq() sets
the depth to 2. Then the probe calls irq_startup() that resets the depth
to 0.

Then the enable_irq(irqd) is called with depth of 0, and produces the
above warning.

Here's the output of the trace:


           <...>-183   [000] ....     0.950828: disable_irq <-ide_probe_port
           <...>-183   [000] ....     0.950830: __disable_irq_nosync <-disable_irq
           <...>-183   [000] d..1     0.950831: __disable_irq <-__disable_irq_nosync
           <...>-183   [000] d..1     0.950832: __disable_irq: irq=16 depth=2
           <...>-193   [002] d..1     1.057579: irq_startup: irq=16 depth=0
           <...>-183   [001] ....     1.518815: enable_irq <-ide_probe_port
           <...>-183   [001] d..1     1.518817: __enable_irq <-enable_irq
           <...>-183   [001] d..1     1.518818: __enable_irq: irq=16 depth=0
           <...>-183   [001] d..1     1.518819: __enable_irq: warning irq=16

I had trace_printk's in __disable_irq, __enable_irq, and irq_startup,
and I traced '*disable_irq*,*enable_irq*' functions.

The depth was printed after the increment in __disable_irq() and before
the decrement in __enable_irq().

-- Steve

Re: [WARNING] at kernel/irq/manage.c:421 __enable_irq

[Thomas Gleixner]

On Tue, 15 May 2012, Steven Rostedt wrote:
> The code in ide_probe_port() does the following:

Right, you just forgot to show the most interesting gem of that code:

	/*
	 * We must always disable IRQ, as probe_for_drive will assert IRQ, but
	 * we'll install our IRQ driver much later...
	 */

If there is no handler installed for that interrupt, then it's already
disabled.

So what they possibly try to deal with is a shared interrupt, where
there is already an handler installed. In that case you need to
disable the interrupt to avoid an interrupt storm, when thew IDE probe
asserts the irq.

Though I don't know why the probe code must result in asserting the
interrupt line, except when this IDE crap cannot disable the interrupt
at the device level. I wouldn't be surprised ....

>         irqd = hwif->irq;
>         if (irqd)
>                 disable_irq(hwif->irq);
> 
>         if (ide_port_wait_ready(hwif) == -EBUSY)
>                 printk(KERN_DEBUG "%s: Wait for ready failed before probe !\n", hwif->name);
> 
>         /*
>          * Second drive should only exist if first drive was found,
>          * but a lot of cdrom drives are configured as single slaves.
>          */
>         ide_port_for_each_dev(i, drive, hwif) {
>                 (void) probe_for_drive(drive);
>                 if (drive->dev_flags & IDE_DFLAG_PRESENT)
>                         rc = 0;
>         }
> 
>         /*
>          * Use cached IRQ number. It might be (and is...) changed by probe
>          * code above
>          */

This comment is great. What the heck is changed and why ? And what
happens if it is _NOT_ changed ? Oh, well.....

At least I can't find code which touches hwif->irq in the probe
functions.

>         if (irqd)
>                 enable_irq(irqd);

So this code is wrong and unsafe in various aspects. I wonder why it
didn't blow up before. Maybe init ordering changed ....

> We disable the interrupt for the device (hwif->irq), do the probes, and
> then enable the irq if it existed. The problem is that the probe resets
> the depth count of the irq descriptor. I ran some traces, and added some

probe CANNOT do that. See below.

> trace_printks, to confirm it.
> 
> Coming into this function, the desc->depth is 1. The disable_irq() sets
> the depth to 2. Then the probe calls irq_startup() that resets the depth
> to 0.

probe CANNOT call irq_startup().

There are only two possibilites for irq_startup() calls:

      request_irq() and irq_probe_on()

I can't find irq autoprobing in drivers/ide, so something else is
installing an interrupt handler for irq 16 or autoprobing interrupts.

Can you figure that out with the tracer ?

           <...>-183   [000] ....     0.950828: disable_irq <-ide_probe_port
           <...>-183   [000] ....     0.950830: __disable_irq_nosync <-disable_irq
           <...>-183   [000] d..1     0.950831: __disable_irq <-__disable_irq_nosync
           <...>-183   [000] d..1     0.950832: __disable_irq: irq=16 depth=2

And the trace confirms my theory. ide_probe_port() is run from TID 183

           <...>-193   [002] d..1     1.057579: irq_startup: irq=16 depth=0

irq_startup() is run from TID 193

           <...>-183   [001] ....     1.518815: enable_irq <-ide_probe_port
           <...>-183   [001] d..1     1.518817: __enable_irq <-enable_irq
           <...>-183   [001] d..1     1.518818: __enable_irq: irq=16 depth=0
           <...>-183   [001] d..1     1.518819: __enable_irq: warning irq=16

So you trigger the following case

   CPU0	       	   	     CPU1

   disable_irq(16);
   probe....		     request_irq(16,...); or irq_probe_on();
   enable_irq(16);

And there is nothing the core code can do about that. What's worse is
that when the request_irq() is done right before the probe code
results in asserting the irq line, then an interrupt storm will break
lose and disable irq 16 because the other device returns IRQ_NONE.

That's what you get for doing parallel device probing :)

I have an idea how to fix that proper. Will send out patches later.

Thanks,

	tglx

Re: [WARNING] at kernel/irq/manage.c:421 __enable_irq

[Steven Rostedt]

On Wed, 2012-05-16 at 13:27 +0200, Thomas Gleixner wrote:
> On Tue, 15 May 2012, Steven Rostedt wrote:
> > The code in ide_probe_port() does the following:
> 
> Right, you just forgot to show the most interesting gem of that code:
> 
> 	/*
> 	 * We must always disable IRQ, as probe_for_drive will assert IRQ, but
> 	 * we'll install our IRQ driver much later...
> 	 */

Heh, I would have kept that, but I was more interested in cut and
pasting code than comments. I'll make sure to keep comments in emails
too.


> >         if (irqd)
> >                 enable_irq(irqd);
> 
> So this code is wrong and unsafe in various aspects. I wonder why it
> didn't blow up before. Maybe init ordering changed ....
> 

Or it always did. This is on my main box that I reboot once every 100
days or so. I'm not usually present when the machine comes online, nor
do I search dmesg for warnings. Although, yesterday I did. This could
have been complaining from day one.


> I have an idea how to fix that proper. Will send out patches later.

I'll test them, but it's a bit of a pain, as it would require me
shutting down evolution, xchat, firefox, chrome and all my emacs
windows :-)  This is why I don't reboot this box often.

-- Steve

Re: [WARNING] at kernel/irq/manage.c:421 __enable_irq

[Thomas Gleixner]

On Wed, 16 May 2012, Steven Rostedt wrote:
> On Wed, 2012-05-16 at 13:27 +0200, Thomas Gleixner wrote:
> > I have an idea how to fix that proper. Will send out patches later.
> 
> I'll test them, but it's a bit of a pain, as it would require me
> shutting down evolution, xchat, firefox, chrome and all my emacs
> windows :-)  This is why I don't reboot this box often.

Ok. Here you go. Compile tested only.

--------------->
Subject: ide: Request irq before calling irq_probe_port
From: Thomas Gleixner <tglx@linutronix.de>
Date: Wed, 16 May 2012 15:53:41 +0200

Steven reported that the warning in __enable_irq(), which yells about
an unbalanced enable_irq() call, is triggered in context of
ide_probe_port().

What happens is:

CPU0               CPU1
disable_irq(X);
ide_do_probe();    request_irq(X, ....);
enable_irq(X)

request_irq() which happens on a non used interrupt undoes nested
disables and enables the interrupt immediately. So the magic probe
code in ide_probe_port() will trigger the unbalanced warning when
enabling the irq at the end of the probe routine. A similar problem
exists when a concurrent device init uses the irq auto probe
functions.

The only solution for this is to request the interrupt _BEFORE_
calling the probe code. That prevents a parallel request_irq for the
same irq line to unconditionally undo the disabled state.

The code contains a few magics which are - as far as I understand the
current code - simply leftovers of the historic ide implementation.

The following comment is completely bogus:
 /*
  * Use cached IRQ number. It might be (and is...) changed by probe
  * code above
  */

hwif->irq is set up _BEFORE_ the probe code is called. There is no
function which modifies it in the context of the probe code.

Sigh, why can't people just clean up the mess when they change the
code flow?

Also the check for hwif->irq != 0 there in the probe code is backwards
as well. Why should we do probing first and then discard the hw
interface because the function which installs the irq handler disables
the interface when hwif->irq == 0 ???

There is nothing wrong with installing the interrupt handler before
calling the probe code. All it takes is a check in the interrupt
handler, so it can nicely coexist with another shared interrupt
handler on the same irq line. 

Famous last words: This shouldn't break anything as the code needs to
deal with shared interrupts anyway.

While at it remove the host.irq_handler member as it is unused and
just adds extra confusion. TBH, I can't be bothered to split that into
a separate patch. I wasted enough time already staring into that
trainwreck.

Reported-by: Steven Rostedt <rostedt@goodmis.org>
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
Link: http://lkml.kernel.org/r/1337131823.6724.11.camel@gandalf.stny.rr.com
---
 drivers/ide/ide-io.c    |    3 +++
 drivers/ide/ide-probe.c |   46 +++++++++++++++++-----------------------------
 include/linux/ide.h     |    3 +--
 3 files changed, 21 insertions(+), 31 deletions(-)

Index: linux-2.6/drivers/ide/ide-io.c
===================================================================
--- linux-2.6.orig/drivers/ide/ide-io.c
+++ linux-2.6/drivers/ide/ide-io.c
@@ -779,6 +779,9 @@ irqreturn_t ide_intr (int irq, void *dev
 	int plug_device = 0;
 	struct request *uninitialized_var(rq_in_flight);
 
+	if (!(hwif->port_flags & IDE_PFLAG_IRQENA))
+		return IRQ_NONE;
+
 	if (host->host_flags & IDE_HFLAG_SERIALIZE) {
 		if (hwif != host->cur_port)
 			goto out_early;
Index: linux-2.6/drivers/ide/ide-probe.c
===================================================================
--- linux-2.6.orig/drivers/ide/ide-probe.c
+++ linux-2.6/drivers/ide/ide-probe.c
@@ -678,7 +678,6 @@ EXPORT_SYMBOL_GPL(ide_undecoded_slave);
 static int ide_probe_port(ide_hwif_t *hwif)
 {
 	ide_drive_t *drive;
-	unsigned int irqd;
 	int i, rc = -ENODEV;
 
 	BUG_ON(hwif->present);
@@ -688,12 +687,12 @@ static int ide_probe_port(ide_hwif_t *hw
 		return -EACCES;
 
 	/*
-	 * We must always disable IRQ, as probe_for_drive will assert IRQ, but
-	 * we'll install our IRQ driver much later...
+	 * Sigh. The probe code want's to be alone, so we have to
+	 * disable the interrupt line. We cannot disable it reliably
+	 * at the device level, so we have to disable it at the irq
+	 * line level.
 	 */
-	irqd = hwif->irq;
-	if (irqd)
-		disable_irq(hwif->irq);
+	disable_irq(hwif->irq);
 
 	if (ide_port_wait_ready(hwif) == -EBUSY)
 		printk(KERN_DEBUG "%s: Wait for ready failed before probe !\n", hwif->name);
@@ -708,13 +707,8 @@ static int ide_probe_port(ide_hwif_t *hw
 			rc = 0;
 	}
 
-	/*
-	 * Use cached IRQ number. It might be (and is...) changed by probe
-	 * code above
-	 */
-	if (irqd)
-		enable_irq(irqd);
-
+	/* Reenable the interrupt line. */
+	enable_irq(hwif->irq);
 	return rc;
 }
 
@@ -847,13 +841,9 @@ static int init_irq (ide_hwif_t *hwif)
 {
 	struct ide_io_ports *io_ports = &hwif->io_ports;
 	struct ide_host *host = hwif->host;
-	irq_handler_t irq_handler = host->irq_handler;
 	int sa = host->irq_flags;
 
-	if (irq_handler == NULL)
-		irq_handler = ide_intr;
-
-	if (request_irq(hwif->irq, irq_handler, sa, hwif->name, hwif))
+	if (request_irq(hwif->irq, ide_intr, sa, hwif->name, hwif))
 		goto out_up;
 
 #if !defined(__mc68000__)
@@ -961,11 +951,6 @@ static void drive_release_dev (struct de
 
 static int hwif_init(ide_hwif_t *hwif)
 {
-	if (!hwif->irq) {
-		printk(KERN_ERR "%s: disabled, no IRQ\n", hwif->name);
-		return 0;
-	}
-
 	if (register_blkdev(hwif->major, hwif->name))
 		return 0;
 
@@ -980,12 +965,6 @@ static int hwif_init(ide_hwif_t *hwif)
 	}
 
 	sg_init_table(hwif->sg_table, hwif->sg_max_nents);
-	
-	if (init_irq(hwif)) {
-		printk(KERN_ERR "%s: disabled, unable to get IRQ %d\n",
-			hwif->name, hwif->irq);
-		goto out;
-	}
 
 	blk_register_region(MKDEV(hwif->major, 0), MAX_DRIVES << PARTN_BITS,
 			    THIS_MODULE, ata_probe, ata_lock, hwif);
@@ -1398,6 +1377,12 @@ int ide_host_register(struct ide_host *h
 	ide_host_for_each_port(i, hwif, host) {
 		if (hwif == NULL)
 			continue;
+		if (!hwif->irq || init_irq(hwif)) {
+			pr_err("%s: disabled, unable to request irq %d\n",
+			       hwif->name, hwif->irq);
+			ide_disable_port(hwif);
+			continue;
+		}
 
 		if (ide_probe_port(hwif) == 0)
 			hwif->present = 1;
@@ -1407,6 +1392,7 @@ int ide_host_register(struct ide_host *h
 		if ((hwif->host_flags & IDE_HFLAG_4DRIVES) == 0 ||
 		    hwif->mate == NULL || hwif->mate->present == 0) {
 			if (ide_register_port(hwif)) {
+				free_irq(hwif->irq, hwif);
 				ide_disable_port(hwif);
 				continue;
 			}
@@ -1425,10 +1411,12 @@ int ide_host_register(struct ide_host *h
 		if (hwif_init(hwif) == 0) {
 			printk(KERN_INFO "%s: failed to initialize IDE "
 					 "interface\n", hwif->name);
+			free_irq(hwif->irq, hwif);
 			device_unregister(&hwif->gendev);
 			ide_disable_port(hwif);
 			continue;
 		}
+		hwif->port_flags |= IDE_PFLAG_IRQENA;
 
 		if (hwif->present)
 			if (ide_port_setup_devices(hwif) == 0) {
Index: linux-2.6/include/linux/ide.h
===================================================================
--- linux-2.6.orig/include/linux/ide.h
+++ linux-2.6/include/linux/ide.h
@@ -660,6 +660,7 @@ struct ide_dma_ops {
 
 enum {
 	IDE_PFLAG_PROBING		= (1 << 0),
+	IDE_PFLAG_IRQENA		= (1 << 1),
 };
 
 struct ide_host;
@@ -782,8 +783,6 @@ struct ide_host {
 	void		(*get_lock)(irq_handler_t, void *);
 	void		(*release_lock)(void);
 
-	irq_handler_t	irq_handler;
-
 	unsigned long	host_flags;
 
 	int		irq_flags;

Re: [WARNING] at kernel/irq/manage.c:421 __enable_irq

[Steven Rostedt]

On Thu, 2012-05-17 at 00:35 +0200, Thomas Gleixner wrote:
> On Wed, 16 May 2012, Steven Rostedt wrote:
> > On Wed, 2012-05-16 at 13:27 +0200, Thomas Gleixner wrote:
> > > I have an idea how to fix that proper. Will send out patches later.
> > 
> > I'll test them, but it's a bit of a pain, as it would require me
> > shutting down evolution, xchat, firefox, chrome and all my emacs
> > windows :-)  This is why I don't reboot this box often.
> 
> Ok. Here you go. Compile tested only.

I booted it and I didn't see the warning. The system seems to be stable.
I'll keep it up and running over the weekend before I boot back into the
stable kernel. And then I'll give it a Tested-by tag.

-- Steve

> 
> --------------->
> Subject: ide: Request irq before calling irq_probe_port
> From: Thomas Gleixner <tglx@linutronix.de>
> Date: Wed, 16 May 2012 15:53:41 +0200
> 
> Steven reported that the warning in __enable_irq(), which yells about
> an unbalanced enable_irq() call, is triggered in context of
> ide_probe_port().
> 
> What happens is:
> 
> CPU0               CPU1
> disable_irq(X);
> ide_do_probe();    request_irq(X, ....);
> enable_irq(X)
> 
> request_irq() which happens on a non used interrupt undoes nested
> disables and enables the interrupt immediately. So the magic probe
> code in ide_probe_port() will trigger the unbalanced warning when
> enabling the irq at the end of the probe routine. A similar problem
> exists when a concurrent device init uses the irq auto probe
> functions.
> 
> The only solution for this is to request the interrupt _BEFORE_
> calling the probe code. That prevents a parallel request_irq for the
> same irq line to unconditionally undo the disabled state.
> 
> The code contains a few magics which are - as far as I understand the
> current code - simply leftovers of the historic ide implementation.
> 
> The following comment is completely bogus:
>  /*
>   * Use cached IRQ number. It might be (and is...) changed by probe
>   * code above
>   */
> 
> hwif->irq is set up _BEFORE_ the probe code is called. There is no
> function which modifies it in the context of the probe code.
> 
> Sigh, why can't people just clean up the mess when they change the
> code flow?
> 
> Also the check for hwif->irq != 0 there in the probe code is backwards
> as well. Why should we do probing first and then discard the hw
> interface because the function which installs the irq handler disables
> the interface when hwif->irq == 0 ???
> 
> There is nothing wrong with installing the interrupt handler before
> calling the probe code. All it takes is a check in the interrupt
> handler, so it can nicely coexist with another shared interrupt
> handler on the same irq line. 
> 
> Famous last words: This shouldn't break anything as the code needs to
> deal with shared interrupts anyway.
> 
> While at it remove the host.irq_handler member as it is unused and
> just adds extra confusion. TBH, I can't be bothered to split that into
> a separate patch. I wasted enough time already staring into that
> trainwreck.
> 
> Reported-by: Steven Rostedt <rostedt@goodmis.org>
> Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
> Link: http://lkml.kernel.org/r/1337131823.6724.11.camel@gandalf.stny.rr.com