Messages in this thread Patch in this message | | | Date | Mon, 30 Apr 2012 10:29:19 +0200 | Subject | Re: Unhandled IRQs on AMD E-450 | From | Jeroen Van den Keybus <> |
| |
> 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/
| |