Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]
Groups > linux.kernel > #1537252 > unrolled thread
| Started by | Prarit Bhargava <prarit@redhat.com> |
|---|---|
| First post | 2016-12-06 21:00 +0100 |
| Last post | 2016-12-08 23:50 +0100 |
| Articles | 2 — 2 participants |
Back to article view | Back to linux.kernel
[PATCH v2] x86/irq: Add additional unhandled IRQ debug information Prarit Bhargava <prarit@redhat.com> - 2016-12-06 21:00 +0100
Re: [PATCH v2] x86/irq: Add additional unhandled IRQ debug information Thomas Gleixner <tglx@linutronix.de> - 2016-12-08 23:50 +0100
| From | Prarit Bhargava <prarit@redhat.com> |
|---|---|
| Date | 2016-12-06 21:00 +0100 |
| Subject | [PATCH v2] x86/irq: Add additional unhandled IRQ debug information |
| Message-ID | <sLu49-6lz-9@gated-at.bofh.it> |
The current unhandled IRQ warning doesn't output enough information on x86 to
determine which device issued an interrupt. For example,
irq 16: nobody cared (try booting with the "irqpoll" option)
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.9.0-rc6+ #19
Hardware name: Hewlett-Packard HP Z820 Workstation/158B, BIOS J63 v03.90 06/01/2016
ffff88041f803eb0 ffffffff81337a95 ffff880418607200 ffff88041860729c
ffff88041f803ed8 ffffffff810db845 ffff880418607200 0000000000000000
0000000000000010 ffff88041f803f10 ffffffff810dbb9f ffff880418607200
Call Trace:
<IRQ> [<ffffffff81337a95>] dump_stack+0x63/0x8e
[<ffffffff810db845>] __report_bad_irq+0x35/0xd0
[<ffffffff810dbb9f>] note_interrupt+0x20f/0x260
[<ffffffff810d8f05>] handle_irq_event_percpu+0x45/0x60
[<ffffffff810d8f4c>] handle_irq_event+0x2c/0x50
[<ffffffff810dc8ca>] handle_fasteoi_irq+0x8a/0x150
[<ffffffff8102ee0b>] handle_irq+0xab/0x130
[<ffffffff8109de6a>] ? atomic_notifier_call_chain+0x1a/0x20
[<ffffffff8103631d>] ? __exit_idle+0x2d/0x30
[<ffffffff81715bad>] do_IRQ+0x4d/0xd0
[<ffffffff81713c02>] common_interrupt+0x82/0x82
<EOI> [<ffffffff815e3931>] ? cpuidle_enter_state+0xc1/0x280
[<ffffffff815e3924>] ? cpuidle_enter_state+0xb4/0x280
[<ffffffff815e3b27>] cpuidle_enter+0x17/0x20
[<ffffffff810c1813>] call_cpuidle+0x23/0x40
[<ffffffff810c1a79>] cpu_startup_entry+0x149/0x240
[<ffffffff81705fe7>] rest_init+0x77/0x80
[<ffffffff81d8a147>] start_kernel+0x495/0x4a2
[<ffffffff81d89aa0>] ? set_init_arg+0x55/0x55
[<ffffffff81d89120>] ? early_idt_handler_array+0x120/0x120
[<ffffffff81d895d6>] x86_64_start_reservations+0x2a/0x2c
[<ffffffff81d89715>] x86_64_start_kernel+0x13d/0x14c
handlers:
[<ffffffff8155b050>] usb_hcd_irq
Disabling IRQ #16
The unhandled interrupt is issued against IRQ 16, however, in many cases the
handlers listed do not have anything to do with the device that has issued the
interrupt.
This patch adds weak function arch_irq_debug(), and adds an x86 specific
definition. The x86 version dumps the following information: the status
of the IO APIC pin line associated with the IRQ, the state of the CPU's
LAPIC, and the PCI devices which have their interrupt set.
This information is output:
Additional x86 information on IRQ #16 ...
IRQ16 maps to APIC0 PIN16 : pin10, enabled , level, low , V(10), IRR(1), S(1), remapped, I(98013), Z(0)
This CPU APIC ID is 0, and cpu id is 0.
CPU 0 LAPIC IRR dump:
APIC IRR 7 (IRQs 255 to 224) = 0x20008000 [ 239 253 ]
APIC IRR 6 (IRQs 223 to 192) = 0x0
APIC IRR 5 (IRQs 191 to 160) = 0x0
APIC IRR 4 (IRQs 159 to 128) = 0x0
APIC IRR 3 (IRQs 127 to 96) = 0x0
APIC IRR 2 (IRQs 95 to 64) = 0x0
APIC IRR 1 (IRQs 63 to 32) = 0x0
APIC IRR 0 (IRQs 31 to 0) = 0x0
Disabling IRQ #16
PCI devices with INTERRUPT STATUS set (bit 3 of PCI_STATUS register):
possible unhandled irq source 0000:00:16.0: pin = 1
possible unhandled irq source 0000:05:00.0: pin = 1
[v2]: Fixed kbuild auto test warning for i386
Signed-off-by: Prarit Bhargava <prarit@redhat.com>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Ingo Molnar <mingo@redhat.com>
Cc: "H. Peter Anvin" <hpa@zytor.com>
Cc: x86@kernel.org
Cc: Rui Wang <rui.y.wang@intel.com>
Cc: Paul Gortmaker <paul.gortmaker@windriver.com>
Cc: Denys Vlasenko <dvlasenk@redhat.com>
Cc: Borislav Petkov <bp@suse.de>
Cc: Aaron Lu <aaron.lu@intel.com>
---
arch/x86/include/asm/io_apic.h | 2 ++
arch/x86/kernel/apic/io_apic.c | 70 ++++++++++++++++++++++++--------------
arch/x86/kernel/irq.c | 72 ++++++++++++++++++++++++++++++++++++++++
kernel/irq/spurious.c | 9 +++++
4 files changed, 129 insertions(+), 24 deletions(-)
diff --git a/arch/x86/include/asm/io_apic.h b/arch/x86/include/asm/io_apic.h
index 6cbf2cfb3f8a..88b9819e6198 100644
--- a/arch/x86/include/asm/io_apic.h
+++ b/arch/x86/include/asm/io_apic.h
@@ -195,6 +195,7 @@ static inline unsigned int io_apic_read(unsigned int apic, unsigned int reg)
extern void setup_ioapic_dest(void);
extern int IO_APIC_get_PCI_irq_vector(int bus, int devfn, int pin);
extern void print_IO_APICs(void);
+extern void print_IRQ_to_pin_mapping(unsigned int irq);
#else /* !CONFIG_X86_IO_APIC */
#define IO_APIC_IRQ(x) 0
@@ -203,6 +204,7 @@ static inline unsigned int io_apic_read(unsigned int apic, unsigned int reg)
static inline void ioapic_insert_resources(void) { }
static inline int arch_early_ioapic_init(void) { return 0; }
static inline void print_IO_APICs(void) {}
+static inline void print_IRQ_to_pin_mapping(unsigned int irq) {}
#define gsi_top (NR_IRQS_LEGACY)
static inline int mp_find_ioapic(u32 gsi) { return 0; }
static inline int mp_map_gsi_to_irq(u32 gsi, unsigned int flags,
diff --git a/arch/x86/kernel/apic/io_apic.c b/arch/x86/kernel/apic/io_apic.c
index 48e6d84f173e..ff86bd140d18 100644
--- a/arch/x86/kernel/apic/io_apic.c
+++ b/arch/x86/kernel/apic/io_apic.c
@@ -1247,34 +1247,30 @@ void ioapic_zap_locks(void)
raw_spin_lock_init(&ioapic_lock);
}
-static void io_apic_print_entries(unsigned int apic, unsigned int nr_entries)
+static void io_apic_print_entry(unsigned int apic, int entry_no)
{
- int i;
char buf[256];
struct IO_APIC_route_entry entry;
struct IR_IO_APIC_route_entry *ir_entry = (void *)&entry;
- printk(KERN_DEBUG "IOAPIC %d:\n", apic);
- for (i = 0; i <= nr_entries; i++) {
- entry = ioapic_read_entry(apic, i);
- snprintf(buf, sizeof(buf),
- " pin%02x, %s, %s, %s, V(%02X), IRR(%1d), S(%1d)",
- i,
- entry.mask == IOAPIC_MASKED ? "disabled" : "enabled ",
- entry.trigger == IOAPIC_LEVEL ? "level" : "edge ",
- entry.polarity == IOAPIC_POL_LOW ? "low " : "high",
- entry.vector, entry.irr, entry.delivery_status);
- if (ir_entry->format)
- printk(KERN_DEBUG "%s, remapped, I(%04X), Z(%X)\n",
- buf, (ir_entry->index << 15) | ir_entry->index,
- ir_entry->zero);
- else
- printk(KERN_DEBUG "%s, %s, D(%02X), M(%1d)\n",
- buf,
- entry.dest_mode == IOAPIC_DEST_MODE_LOGICAL ?
- "logical " : "physical",
- entry.dest, entry.delivery_mode);
- }
+ entry = ioapic_read_entry(apic, entry_no);
+ snprintf(buf, sizeof(buf),
+ " pin%02x, %s, %s, %s, V(%02X), IRR(%1d), S(%1d)",
+ entry_no,
+ entry.mask == IOAPIC_MASKED ? "disabled" : "enabled ",
+ entry.trigger == IOAPIC_LEVEL ? "level" : "edge ",
+ entry.polarity == IOAPIC_POL_LOW ? "low " : "high",
+ entry.vector, entry.irr, entry.delivery_status);
+ if (ir_entry->format)
+ pr_debug("%s, remapped, I(%04X), Z(%X)\n",
+ buf, (ir_entry->index << 15) | ir_entry->index,
+ ir_entry->zero);
+ else
+ pr_debug("%s, %s, D(%02X), M(%1d)\n",
+ buf,
+ entry.dest_mode == IOAPIC_DEST_MODE_LOGICAL ?
+ "logical " : "physical",
+ entry.dest, entry.delivery_mode);
}
static void __init print_IO_APIC(int ioapic_idx)
@@ -1284,6 +1280,7 @@ static void __init print_IO_APIC(int ioapic_idx)
union IO_APIC_reg_02 reg_02;
union IO_APIC_reg_03 reg_03;
unsigned long flags;
+ int i;
raw_spin_lock_irqsave(&ioapic_lock, flags);
reg_00.raw = io_apic_read(ioapic_idx, 0);
@@ -1330,7 +1327,32 @@ static void __init print_IO_APIC(int ioapic_idx)
}
printk(KERN_DEBUG ".... IRQ redirection table:\n");
- io_apic_print_entries(ioapic_idx, reg_01.bits.entries);
+ pr_debug("IOAPIC %d:\n", ioapic_idx);
+ for (i = 0; i <= reg_01.bits.entries; i++)
+ io_apic_print_entry(ioapic_idx, i);
+}
+
+void print_IRQ_to_pin_mapping(unsigned int irq)
+{
+ struct irq_pin_list *entry;
+ struct irq_chip *chip;
+ struct mp_chip_data *data;
+
+ chip = irq_get_chip(irq);
+ if (chip != &ioapic_chip && chip != &ioapic_ir_chip)
+ return;
+ data = irq_get_chip_data(irq);
+ if (!data)
+ return;
+ if (list_empty(&data->irq_2_pin))
+ return;
+
+ pr_emerg("IRQ%d ", irq);
+ for_each_irq_pin(entry, data->irq_2_pin) {
+ pr_cont("maps to APIC%d PIN%d :", entry->apic, entry->pin);
+ io_apic_print_entry(entry->apic, entry->pin);
+ }
+ pr_cont("\n");
}
void __init print_IO_APICs(void)
diff --git a/arch/x86/kernel/irq.c b/arch/x86/kernel/irq.c
index 9f669fdd2010..e692f1b4ecab 100644
--- a/arch/x86/kernel/irq.c
+++ b/arch/x86/kernel/irq.c
@@ -10,6 +10,7 @@
#include <linux/ftrace.h>
#include <linux/delay.h>
#include <linux/export.h>
+#include <linux/pci.h>
#include <asm/apic.h>
#include <asm/io_apic.h>
@@ -547,3 +548,74 @@ void fixup_irqs(void)
}
}
#endif
+
+/* Unhandled Interrupt Debug */
+
+static struct work_struct x86_unhandled_irq_work;
+static void x86_unhandled_irq_work_fn(struct work_struct *work)
+{
+#ifdef CONFIG_PCI
+ struct pci_dev *dev = NULL;
+ u32 reg;
+ int irq_pending;
+
+ pr_emerg("PCI devices with INTERRUPT STATUS set (bit 3 of PCI_STATUS register):\n");
+ for_each_pci_dev(dev) {
+ if (!dev || !dev->pin)
+ continue;
+
+ pci_read_config_dword(dev, PCI_COMMAND, ®);
+ irq_pending = !!((reg >> 16) & PCI_STATUS_INTERRUPT);
+ if (irq_pending)
+ pr_emerg("possible unhandled irq source %s: pin = %d\n",
+ pci_name(dev), dev->pin);
+ }
+#endif
+}
+
+static void lapic_dump_irr(void)
+{
+#ifdef CONFIG_X86_LOCAL_APIC
+ int irr, bit;
+ u32 reg;
+
+ pr_emerg("This CPU APIC ID is %d, and cpu id is %d.\n",
+ hard_smp_processor_id(), smp_processor_id());
+ pr_emerg("CPU %d LAPIC IRR dump:\n", smp_processor_id());
+ /*
+ * Since this CPU is handling the interrupt, dump its LAPIC IRR to see
+ * which line is asserted.
+ */
+ for (irr = APIC_ISR_NR - 1; irr >= 0; irr--) {
+ reg = apic_read(APIC_IRR + irr*0x10);
+ pr_emerg("APIC IRR %d (IRQs %d to %d) = 0x%0x ", irr,
+ (irr + 1) * 32 - 1, irr * 32, reg);
+ if (reg) {
+ pr_cont(" [ ");
+ for (bit = 0; bit < 32; bit++) {
+ if ((reg >> bit) & 0x01)
+ pr_cont("%d ", bit + (irr * 32));
+ }
+ pr_cont("]");
+ }
+ pr_cont("\n");
+ }
+#endif
+}
+
+void arch_irq_debug(unsigned int irq)
+{
+ pr_emerg("Additional x86 information on IRQ #%d ...\n", irq);
+
+ /* PCI information cannot be dumped in interrupt context */
+ INIT_WORK(&x86_unhandled_irq_work, x86_unhandled_irq_work_fn);
+ schedule_work_on(smp_processor_id(), &x86_unhandled_irq_work);
+
+#ifdef CONFIG_X86_IO_APIC
+ /* Dump the IOAPIC irq mapping */
+ print_IRQ_to_pin_mapping(irq);
+#endif
+
+ /* Dump this CPU's IRR to determine which bits are set */
+ lapic_dump_irr();
+}
diff --git a/kernel/irq/spurious.c b/kernel/irq/spurious.c
index 5707f97a3e6a..fac67b799974 100644
--- a/kernel/irq/spurious.c
+++ b/kernel/irq/spurious.c
@@ -180,6 +180,14 @@ static inline int bad_action_ret(irqreturn_t action_ret)
return 1;
}
+void __weak arch_irq_debug(unsigned int irq)
+{
+ /*
+ * This weak function provides a method to dump arch-specific
+ * data to further debug unhandled IRQs or IRQ storms.
+ */
+}
+
/*
* 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
@@ -218,6 +226,7 @@ static void __report_bad_irq(struct irq_desc *desc, irqreturn_t action_ret)
action->thread_fn, action->thread_fn);
printk(KERN_CONT "\n");
}
+ arch_irq_debug(irq);
raw_spin_unlock_irqrestore(&desc->lock, flags);
}
--
1.7.9.3
[toc] | [next] | [standalone]
| From | Thomas Gleixner <tglx@linutronix.de> |
|---|---|
| Date | 2016-12-08 23:50 +0100 |
| Subject | Re: [PATCH v2] x86/irq: Add additional unhandled IRQ debug information |
| Message-ID | <sMfFL-3xP-3@gated-at.bofh.it> |
| In reply to | #1537252 |
On Tue, 6 Dec 2016, Prarit Bhargava wrote:
> The current unhandled IRQ warning doesn't output enough information on x86 to
> determine which device issued an interrupt. For example,
>
> irq 16: nobody cared (try booting with the "irqpoll" option)
> CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.9.0-rc6+ #19
> Hardware name: Hewlett-Packard HP Z820 Workstation/158B, BIOS J63 v03.90 06/01/2016
> ffff88041f803eb0 ffffffff81337a95 ffff880418607200 ffff88041860729c
> ffff88041f803ed8 ffffffff810db845 ffff880418607200 0000000000000000
> 0000000000000010 ffff88041f803f10 ffffffff810dbb9f ffff880418607200
> Call Trace:
> <IRQ> [<ffffffff81337a95>] dump_stack+0x63/0x8e
> [<ffffffff810db845>] __report_bad_irq+0x35/0xd0
> [<ffffffff810dbb9f>] note_interrupt+0x20f/0x260
> [<ffffffff810d8f05>] handle_irq_event_percpu+0x45/0x60
> [<ffffffff810d8f4c>] handle_irq_event+0x2c/0x50
> [<ffffffff810dc8ca>] handle_fasteoi_irq+0x8a/0x150
> [<ffffffff8102ee0b>] handle_irq+0xab/0x130
> [<ffffffff8109de6a>] ? atomic_notifier_call_chain+0x1a/0x20
> [<ffffffff8103631d>] ? __exit_idle+0x2d/0x30
> [<ffffffff81715bad>] do_IRQ+0x4d/0xd0
> [<ffffffff81713c02>] common_interrupt+0x82/0x82
> <EOI> [<ffffffff815e3931>] ? cpuidle_enter_state+0xc1/0x280
> [<ffffffff815e3924>] ? cpuidle_enter_state+0xb4/0x280
> [<ffffffff815e3b27>] cpuidle_enter+0x17/0x20
> [<ffffffff810c1813>] call_cpuidle+0x23/0x40
> [<ffffffff810c1a79>] cpu_startup_entry+0x149/0x240
> [<ffffffff81705fe7>] rest_init+0x77/0x80
> [<ffffffff81d8a147>] start_kernel+0x495/0x4a2
> [<ffffffff81d89aa0>] ? set_init_arg+0x55/0x55
> [<ffffffff81d89120>] ? early_idt_handler_array+0x120/0x120
> [<ffffffff81d895d6>] x86_64_start_reservations+0x2a/0x2c
> [<ffffffff81d89715>] x86_64_start_kernel+0x13d/0x14c
Quoting the full backtrace adds which value to this changelog?
> handlers:
> [<ffffffff8155b050>] usb_hcd_irq
> Disabling IRQ #16
>
> The unhandled interrupt is issued against IRQ 16, however, in many cases the
> handlers listed do not have anything to do with the device that has issued the
> interrupt.
>
> This patch
Please read and finally understand Documentation/SubmittingPatches. Hint:
Search for: 'This patch'
> adds weak function arch_irq_debug(), and adds an x86 specific
> definition. The x86 version dumps the following information: the status
> of the IO APIC pin line associated with the IRQ, the state of the CPU's
> LAPIC, and the PCI devices which have their interrupt set.
Again: You are telling what the patch does, but not WHY. Why is all of this
useful and necessary to debug such a problem?
> This information is output:
>
> Additional x86 information on IRQ #16 ...
> IRQ16 maps to APIC0 PIN16 : pin10, enabled , level, low , V(10), IRR(1), S(1), remapped, I(98013), Z(0)
So PIN16 is pin10? Very intuitive.
It's enabled, which we already know because otherwise we would not have
seen that interrupt.
It's level and low, which can be retrieved from /proc/interrupts as well
I can figure out what IRR and remapped means, but V, S, I and Z are telling
us what and in which way are they helpful?
> This CPU APIC ID is 0, and cpu id is 0.
We already know that we are on CPU 0. And the APIC Id is known as well.
> CPU 0 LAPIC IRR dump:
> APIC IRR 7 (IRQs 255 to 224) = 0x20008000 [ 239 253 ]
> APIC IRR 6 (IRQs 223 to 192) = 0x0
> APIC IRR 5 (IRQs 191 to 160) = 0x0
> APIC IRR 4 (IRQs 159 to 128) = 0x0
> APIC IRR 3 (IRQs 127 to 96) = 0x0
> APIC IRR 2 (IRQs 95 to 64) = 0x0
> APIC IRR 1 (IRQs 63 to 32) = 0x0
> APIC IRR 0 (IRQs 31 to 0) = 0x0
And the full IRR state is useful because this interrupt is connected to
IRR(1), right?
> Disabling IRQ #16
> PCI devices with INTERRUPT STATUS set (bit 3 of PCI_STATUS register):
> possible unhandled irq source 0000:00:16.0: pin = 1
> possible unhandled irq source 0000:05:00.0: pin = 1
You are looking at that way after the trouble happened. What guarantees
that the interrupt status bit is still set?
And aside of that, if we know that usb_hcd_irq is an installed handler on
that line, then figuring out which other PCI devices are using the same
line is a very trivial excercise:
lspci -vvv
contains all the required information.
> - printk(KERN_DEBUG "%s, remapped, I(%04X), Z(%X)\n",
> + pr_debug("%s, remapped, I(%04X), Z(%X)\n",
While the original code prints always (with DEBUG level) your change makes
it depend on either
- DEBUG being defined in that file
or
- CONFIG_DYNAMIC_DEBUG being set and the APIC/IOAPIC pr_debugs being
enabled via the kernel command line or the debugfs interface.
That's a real achievement as it breaks apic=debug and apic=verbose !
The only benefit is that it prints less useless information in your dump
with the downside that it just dumps even more useless emergency level
messages around the void.
Congratulations for following checkpatch.pl advice blindly!
So in order to use this one has either to recompile the kernel or reboot
with magic command line options, or hope that the wreckage only happens
after enabling magic bits in debugfs or a combination of that.
Of course you went a great length to document all of this and explain how a
sysadmin is supposed to enable it and then interpret the valuable extra
information.
Maybe you can provide a real coherent explanation why we need to break
existing debug facilities and when we unbreak them dump lots of useless
information instead of using easily to access useful information.
The time to cobble this together would have been better spent to document
how this can be debugged with existing tools and existing command line
options, if further information about pin association is really required.
Thanks,
tglx
[toc] | [prev] | [standalone]
Back to top | Article view | linux.kernel
csiph-web