lkml.org 
[lkml]   [2012]   [Apr]   [30]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
Patch in this message
/
Date
SubjectRe: Unhandled IRQs on AMD E-450
From
> I'd have to go back and look through all the bug reports.  Essentially,
> it wound up being "this used to work fine, now I get stuck in polling
> mode".  When we dropped the patch in those cases, it went back to
> working fine.

>>> + int unhandled_thresh = 999000;

>>> +       if (!irq_poll_and_retry)
>>> +               if (likely(desc->irq_count < 100000))
>>> +                       return;
>>> +       else
>>> +               if (likely(desc->irq_count < 10))
>>> +                       return;

Given these 2 bugs I wouldn't rule out that this code would have
malfunctioned, causing the problematic behaviour you describe. Are
these problematic machines still available ?

I have attached a patch for 3.2.16. It is essential that it is also
tested by people NOT having any problems. What the patch does:

- Detect stuck interrupts after a number (5) of consecutive unhandled
IRQs within a specified time frame (100ms).
- Start polling the handler for this interrupt at a preset (100Hz)
rate for a preset number of cycles (100).
- Retry and enable the interrupt line and start the cycle over.
- Report the first occurrences of this process for a preset number of times (5).
- Expose the state of stuck_count in /proc/irq/<irq>/spurious. It is
the number of times an interrupt was deemed stuck.
- Expose the state of stuck_level_max in /proc/irq/<irq>/spurious. It
indicates how many consecutive unhandled interrupts were detected
since the last reset (system startup or reenabling of the interrupt
line). It is intended for interrupt system diagnostics.

Using '$ cat /proc/irq/*/spurious' one can get a quick overview of the
operating state of the patch:

- Normal interrupts will have count=0 and level_max=0. Under some
circumstances, a driver may have already performed work belonging to a
later occurrence of an interrupt. In this case it may return reporting
an unhandled event so level_max = 1.
- The interrupts suffering from the problem allegedly caused by the
ASM1083 PCI bridge will have a count > 0, but not increasing more
rapidly than 1 / sec.
- The interrupts which are genuinely stuck will show a steady (1 /
sec) increase of count.

This patch does not include modifications to drivers/pci/quirks.c to
set the SATA interrupt mode of the Asus E450-M1 PRO to MSI. See
earlier patches for that.

Please test and/or comment.


Signed-off-by: Jeroen Van den Keybus <jeroen.vandenkeybus@gmail.com>
---
diff -upr linux-3.2.16.orig/include/linux/irqdesc.h
linux-3.2.16.new/include/linux/irqdesc.h
--- linux-3.2.16.orig/include/linux/irqdesc.h 2012-04-23
00:31:32.000000000 +0200
+++ linux-3.2.16.new/include/linux/irqdesc.h 2012-04-29 16:33:48.142332693 +0200
@@ -14,28 +14,29 @@ struct timer_rand_state;
struct module;
/**
* struct irq_desc - interrupt descriptor
- * @irq_data: per irq and chip data passed down to chip functions
- * @timer_rand_state: pointer to timer rand state struct
- * @kstat_irqs: irq stats per cpu
- * @handle_irq: highlevel irq-events handler
- * @preflow_handler: handler called before the flow handler
(currently used by sparc)
- * @action: the irq action chain
- * @status: status information
- * @core_internal_state__do_not_mess_with_it: core internal status information
- * @depth: disable-depth, for nested irq_disable() calls
- * @wake_depth: enable depth, for multiple irq_set_irq_wake() callers
- * @irq_count: stats field to detect stalled irqs
- * @last_unhandled: aging timer for unhandled count
- * @irqs_unhandled: stats field for spurious unhandled interrupts
- * @lock: locking for SMP
- * @affinity_hint: hint to user space for preferred irq affinity
- * @affinity_notify: context for notification of affinity changes
- * @pending_mask: pending rebalanced interrupts
- * @threads_oneshot: bitfield to handle shared oneshot threads
- * @threads_active: number of irqaction threads currently running
- * @wait_for_threads: wait queue for sync_irq to wait for threaded handlers
- * @dir: /proc/irq/ procfs entry
- * @name: flow handler name for /proc/interrupts output
+ * @irq_data: per irq and chip data passed down to chip functions
+ * @timer_rand_state: pointer to timer rand state struct
+ * @kstat_irqs: irq stats per cpu
+ * @handle_irq: highlevel irq-events handler
+ * @preflow_handler: handler called before the flow handler
(currently used by sparc)
+ * @action: the irq action chain
+ * @status: status information
+ * @istate: core internal status information
+ * @depth: disable-depth, for nested irq_disable() calls
+ * @wake_depth: enable depth, for multiple irq_set_irq_wake() callers
+ * @irqs_stuck_count: stuck interrupt occurrence counter
+ * @irqs_stuck_level: used for stuck interrupt line detection and
tracking poll cycle count
+ * @irqs_stuck_level_max: indicates the maximum irqs_stuck_level
since last stuck interrupt occurrence
+ * @irqs_stuck_timeout: deadline for resetting irqs_stuck_level
+ * @lock: locking for SMP
+ * @affinity_hint: hint to user space for preferred irq affinity
+ * @affinity_notify: context for notification of affinity changes
+ * @pending_mask: pending rebalanced interrupts
+ * @threads_oneshot: bitfield to handle shared oneshot threads
+ * @threads_active: number of irqaction threads currently running
+ * @wait_for_threads: wait queue for sync_irq to wait for threaded handlers
+ * @dir: /proc/irq/ procfs entry
+ * @name: flow handler name for /proc/interrupts output
*/
struct irq_desc {
struct irq_data irq_data;
@@ -47,12 +48,13 @@ struct irq_desc {
#endif
struct irqaction *action; /* IRQ action list */
unsigned int status_use_accessors;
- unsigned int core_internal_state__do_not_mess_with_it;
+ unsigned int istate;
unsigned int depth; /* nested irq disables */
unsigned int wake_depth; /* nested wake enables */
- unsigned int irq_count; /* For detecting broken IRQs */
- unsigned long last_unhandled; /* Aging timer for unhandled count */
- unsigned int irqs_unhandled;
+ unsigned int irqs_stuck_count;
+ unsigned int irqs_stuck_level;
+ unsigned int irqs_stuck_level_max;
+ unsigned long irqs_stuck_timeout;
raw_spinlock_t lock;
struct cpumask *percpu_enabled;
#ifdef CONFIG_SMP
diff -upr linux-3.2.16.orig/kernel/irq/debug.h
linux-3.2.16.new/kernel/irq/debug.h
--- linux-3.2.16.orig/kernel/irq/debug.h 2012-04-23 00:31:32.000000000 +0200
+++ linux-3.2.16.new/kernel/irq/debug.h 2012-04-29 16:35:33.782919592 +0200
@@ -11,8 +11,9 @@

static inline void print_irq_desc(unsigned int irq, struct irq_desc *desc)
{
- printk("irq %d, desc: %p, depth: %d, count: %d, unhandled: %d\n",
- irq, desc, desc->depth, desc->irq_count, desc->irqs_unhandled);
+ printk("irq %d, desc: %p, depth: %d, stuck_count: %d, stuck_level:
%d, stuck_level_max: %d, stuck_timeout: %lu\n",
+ irq, desc, desc->depth, desc->irqs_stuck_count,
desc->irqs_stuck_level, desc->irqs_stuck_level_max,
+ desc->irqs_stuck_timeout);
printk("->handle_irq(): %p, ", desc->handle_irq);
print_symbol("%s\n", (unsigned long)desc->handle_irq);
printk("->irq_data.chip(): %p, ", desc->irq_data.chip);
diff -upr linux-3.2.16.orig/kernel/irq/internals.h
linux-3.2.16.new/kernel/irq/internals.h
--- linux-3.2.16.orig/kernel/irq/internals.h 2012-04-23 00:31:32.000000000 +0200
+++ linux-3.2.16.new/kernel/irq/internals.h 2012-04-28 22:01:15.124279391 +0200
@@ -13,9 +13,7 @@
# define IRQ_BITMAP_BITS NR_IRQS
#endif

-#define istate core_internal_state__do_not_mess_with_it
-
-extern int noirqdebug;
+extern bool noirqdebug;

/*
* Bits used by threaded handlers:
diff -upr linux-3.2.16.orig/kernel/irq/irqdesc.c
linux-3.2.16.new/kernel/irq/irqdesc.c
--- linux-3.2.16.orig/kernel/irq/irqdesc.c 2012-04-23 00:31:32.000000000 +0200
+++ linux-3.2.16.new/kernel/irq/irqdesc.c 2012-04-29 16:00:01.792104426 +0200
@@ -84,8 +84,10 @@ static void desc_set_defaults(unsigned i
irqd_set(&desc->irq_data, IRQD_IRQ_DISABLED);
desc->handle_irq = handle_bad_irq;
desc->depth = 1;
- desc->irq_count = 0;
- desc->irqs_unhandled = 0;
+ desc->irqs_stuck_count = 0;
+ desc->irqs_stuck_level = 0;
+ desc->irqs_stuck_level_max = 0;
+ desc->irqs_stuck_timeout = jiffies;
desc->name = NULL;
desc->owner = owner;
for_each_possible_cpu(cpu)
diff -upr linux-3.2.16.orig/kernel/irq/manage.c
linux-3.2.16.new/kernel/irq/manage.c
--- linux-3.2.16.orig/kernel/irq/manage.c 2012-04-23 00:31:32.000000000 +0200
+++ linux-3.2.16.new/kernel/irq/manage.c 2012-04-30 09:26:26.395627416 +0200
@@ -1087,8 +1087,10 @@ __setup_irq(unsigned int irq, struct irq
*old_ptr = new;

/* Reset broken irq detection when installing new handler */
- desc->irq_count = 0;
- desc->irqs_unhandled = 0;
+ desc->irqs_stuck_count = 0;
+ desc->irqs_stuck_level = 0;
+ desc->irqs_stuck_level_max = 0;
+ desc->irqs_stuck_timeout = jiffies;

/*
* Check whether we disabled the irq via the spurious handler
diff -upr linux-3.2.16.orig/kernel/irq/proc.c linux-3.2.16.new/kernel/irq/proc.c
--- linux-3.2.16.orig/kernel/irq/proc.c 2012-04-23 00:31:32.000000000 +0200
+++ linux-3.2.16.new/kernel/irq/proc.c 2012-04-29 16:34:17.642434577 +0200
@@ -248,9 +248,9 @@ static int irq_spurious_proc_show(struct
{
struct irq_desc *desc = irq_to_desc((long) m->private);

- seq_printf(m, "count %u\n" "unhandled %u\n" "last_unhandled %u ms\n",
- desc->irq_count, desc->irqs_unhandled,
- jiffies_to_msecs(desc->last_unhandled));
+ seq_printf(m, "irq=%3d stuck_count=%3u stuck_level_max=%3u\n",
+ desc->irq_data.irq,
+ desc->irqs_stuck_count, desc->irqs_stuck_level_max);
return 0;
}

diff -upr linux-3.2.16.orig/kernel/irq/spurious.c
linux-3.2.16.new/kernel/irq/spurious.c
--- linux-3.2.16.orig/kernel/irq/spurious.c 2012-04-23 00:31:32.000000000 +0200
+++ linux-3.2.16.new/kernel/irq/spurious.c 2012-04-29 18:26:59.848127250 +0200
@@ -18,7 +18,12 @@

static int irqfixup __read_mostly;

-#define POLL_SPURIOUS_IRQ_INTERVAL (HZ/10)
+#define SPURIOUS_IRQ_TIMEOUT_INTERVAL (HZ/10)
+#define SPURIOUS_IRQ_TRIGGER 5
+#define SPURIOUS_IRQ_REPORT_COUNT 5
+#define SPURIOUS_IRQ_POLL_CYCLES 100
+#define SPURIOUS_IRQ_POLL_INTERVAL (HZ/100)
+
static void poll_spurious_irqs(unsigned long dummy);
static DEFINE_TIMER(poll_spurious_irq_timer, poll_spurious_irqs, 0, 0);
static int irq_poll_cpu;
@@ -141,14 +146,15 @@ out:
static void poll_spurious_irqs(unsigned long dummy)
{
struct irq_desc *desc;
- int i;
+ int i, poll_again;

if (atomic_inc_return(&irq_poll_active) != 1)
goto out;
irq_poll_cpu = smp_processor_id();

+ poll_again = 0; /* Will stay false as long as no polling candidate is found */
for_each_irq_desc(i, desc) {
- unsigned int state;
+ unsigned int state, irq;

if (!i)
continue;
@@ -158,15 +164,38 @@ static void poll_spurious_irqs(unsigned
barrier();
if (!(state & IRQS_SPURIOUS_DISABLED))
continue;
-
- local_irq_disable();
- try_one_irq(i, desc, true);
- local_irq_enable();
+
+ /* We end up here with a disabled stuck interrupt.
+ desc->irqs_stuck_level now tracks the number of times
+ the interrupt has been polled */
+
+ irq = desc->irq_data.irq;
+ if (unlikely(desc->irqs_stuck_level == 1))
+ if (desc->irqs_stuck_count <= SPURIOUS_IRQ_REPORT_COUNT)
+ printk(KERN_EMERG "Polling handlers for IRQ %d.\n", irq);
+ if (desc->irqs_stuck_level < SPURIOUS_IRQ_POLL_CYCLES) {
+ local_irq_disable();
+ try_one_irq(i, desc, true);
+ local_irq_enable();
+ desc->irqs_stuck_level++;
+ poll_again = 1;
+ } else {
+ if (unlikely(desc->irqs_stuck_count <= SPURIOUS_IRQ_REPORT_COUNT)) {
+ printk(KERN_EMERG "Reenabling IRQ %d.\n", irq);
+ if (desc->irqs_stuck_count >= SPURIOUS_IRQ_REPORT_COUNT)
+ printk(KERN_EMERG "No more stuck interrupt reports for IRQ %d.\n", irq);
+ }
+ irq_enable(desc); /* Reenable the interrupt line */
+ desc->depth--;
+ desc->istate &= (~IRQS_SPURIOUS_DISABLED);
+ desc->irqs_stuck_level = 0;
+ }
}
+ if (poll_again)
+ mod_timer(&poll_spurious_irq_timer,
+ jiffies + SPURIOUS_IRQ_POLL_INTERVAL);
out:
atomic_dec(&irq_poll_active);
- mod_timer(&poll_spurious_irq_timer,
- jiffies + POLL_SPURIOUS_IRQ_INTERVAL);
}

static inline int bad_action_ret(irqreturn_t action_ret)
@@ -176,14 +205,6 @@ static inline int bad_action_ret(irqretu
return 1;
}

-/*
- * If 99,900 of the previous 100,000 interrupts have not been handled
- * then assume that the IRQ is stuck in some manner. Drop a diagnostic
- * and try to turn the IRQ off.
- *
- * (The other 100-of-100,000 interrupts may have been a correctly
- * functioning device sharing an IRQ with the failing one)
- */
static void
__report_bad_irq(unsigned int irq, struct irq_desc *desc,
irqreturn_t action_ret)
@@ -272,7 +293,6 @@ void note_interrupt(unsigned int irq, st
if (desc->istate & IRQS_POLL_INPROGRESS)
return;

- /* we get here again via the threaded handler */
if (action_ret == IRQ_WAKE_THREAD)
return;

@@ -281,55 +301,47 @@ void note_interrupt(unsigned int irq, st
return;
}

- if (unlikely(action_ret == IRQ_NONE)) {
- /*
- * If we are seeing only the odd spurious IRQ caused by
- * bus asynchronicity then don't eventually trigger an error,
- * otherwise the counter becomes a doomsday timer for otherwise
- * working systems
- */
- if (time_after(jiffies, desc->last_unhandled + HZ/10))
- desc->irqs_unhandled = 1;
- else
- desc->irqs_unhandled++;
- desc->last_unhandled = jiffies;
- }
-
- if (unlikely(try_misrouted_irq(irq, desc, action_ret))) {
- int ok = misrouted_irq(irq);
- if (action_ret == IRQ_NONE)
- desc->irqs_unhandled -= ok;
+ /* Adjust action_ret if an optional poll was successful.
+ (See inlined try_misrouted_irq() for conditions (depending
+ on 'irqfixup' and 'irqpoll'), and 'noirqdebug' must not
+ be set, since we wouldn't be here (note_interrupt())
+ at all in that case.) */
+ if (unlikely(try_misrouted_irq(irq, desc, action_ret)))
+ if (misrouted_irq(irq))
+ action_ret = IRQ_HANDLED;
+
+ if (unlikely(action_ret == IRQ_NONE) && time_before(jiffies,
desc->irqs_stuck_timeout)) {
+ desc->irqs_stuck_level++;
+ if (desc->irqs_stuck_level > desc->irqs_stuck_level_max)
+ desc->irqs_stuck_level_max = desc->irqs_stuck_level;
+ if (desc->irqs_stuck_level >= SPURIOUS_IRQ_TRIGGER) { /* The
interrupt is stuck */
+ desc->irqs_stuck_count++; /* TODO: Prevent hypothetical overflow */
+ if (desc->irqs_stuck_count <= SPURIOUS_IRQ_REPORT_COUNT) {
+ __report_bad_irq(irq, desc, action_ret);
+ printk(KERN_EMERG "Disabling IRQ %d.\n", irq);
+ }
+ desc->istate |= IRQS_SPURIOUS_DISABLED;
+ desc->depth++;
+ irq_disable(desc);
+ /* TODO: Do a safe access to the timer. Now we may be extending a deadline
+ for a polling system already running for another interrupt. */
+ mod_timer(&poll_spurious_irq_timer,
+ jiffies + SPURIOUS_IRQ_POLL_INTERVAL); /* Schedule a poll cycle */
+ desc->irqs_stuck_level = 1;
+ desc->irqs_stuck_level_max = 0;
+ }
}
-
- desc->irq_count++;
- if (likely(desc->irq_count < 100000))
- return;
-
- desc->irq_count = 0;
- if (unlikely(desc->irqs_unhandled > 99900)) {
- /*
- * The interrupt is stuck
- */
- __report_bad_irq(irq, desc, action_ret);
- /*
- * Now kill the IRQ
- */
- printk(KERN_EMERG "Disabling IRQ #%d\n", irq);
- desc->istate |= IRQS_SPURIOUS_DISABLED;
- desc->depth++;
- irq_disable(desc);
-
- mod_timer(&poll_spurious_irq_timer,
- jiffies + POLL_SPURIOUS_IRQ_INTERVAL);
+ else {
+ desc->irqs_stuck_timeout = jiffies + SPURIOUS_IRQ_TIMEOUT_INTERVAL;
+ desc->irqs_stuck_level = 0;
}
- desc->irqs_unhandled = 0;
}

-int noirqdebug __read_mostly;
+bool noirqdebug __read_mostly;

int noirqdebug_setup(char *str)
{
- noirqdebug = 1;
+ noirqdebug = true;
printk(KERN_INFO "IRQ lockup detection disabled\n");

return 1;
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
\
 
 \ /
  Last update: 2012-04-30 11:01    [W:0.158 / U:0.168 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site