Actions
Bug #86
openIRQ errors precede slow down of tape I/O, via SCSI and PCI/PCIe bridge
Start date:
12/12/2016
Due date:
% Done:
0%
Estimated time:
Affected versions:
Needs backport to:
Affected hardware:
Affected OS:
Description
On the KGPE-D16 with commit 4.5-566-geb9c639 there two IRQ errors that appear soon after boot and use of a SCSI tape device, which appear to cause a reduced tape speed. The tape library is connected via SCSI to a Symbios Logic 53c895 adapter, via an ASMedia ASM1083/1085 PCIe to PCI Bridge.
At first read speeds are about 60 MB/s, then the system may hang for a few seconds and IRQ errors appear on the screen. At this time, iotop shows that the speed reduces 10 MB/s. If not using microcode, the speed is reduced to 100 KB/s. This may also be the case when using the 20160907 libreboot config to build a recent upstream coreboot, with or without microcode, seemingly caused by use of static option tables.
I have attempted to boot with the irqpoll option, but this did not resolve the issue. I am using iommu=soft, as this is the only way that the tape device is being recognized by the system. Otherwise, dmesg logged the following:
# grep -i -e 07:00 -e sym0 < dmesg
[ 1.320378] pci 0000:07:00.0: [1000:000c] type 00 class 0x010000
[ 1.320396] pci 0000:07:00.0: reg 0x10: [io 0x3000-0x30ff]
[ 1.320408] pci 0000:07:00.0: reg 0x14: [mem 0xfcb11000-0xfcb110ff]
[ 1.320421] pci 0000:07:00.0: reg 0x18: [mem 0xfcb10000-0xfcb10fff]
[ 1.320465] pci 0000:07:00.0: reg 0x30: [mem 0xfcb00000-0xfcb0ffff pref]
[ 4.715481] AMD-Vi: Using IVRS reported alias 06:00.0 for device 0000:07:00.0[1000:000c], kernel reported alias 07:00.0
[ 4.726275] iommu: Adding device 0000:07:00.0 to group 12
[ 5.129228] pci 0000:07:00.0: Signaling PME through PCIe PME interrupt
[ 14.166969] sym0: <895> rev 0x2 at pci 0000:07:00.0 irq 38
[ 14.169181] sym0: Symbios NVRAM, ID 7, Fast-40, LVD, parity checking
[ 14.169182] sym0: open drain IRQ line driver, using on-chip SRAM
[ 14.169183] sym0: using LOAD/STORE-based firmware.
[ 14.169224] CACHE TEST FAILED: DMA error (dstat=0x81).sym0: CACHE INCORRECTLY CONFIGURED.
[ 14.169225] sym0: giving up ...
[ 14.169231] AMD-Vi: Event logged [IO_PAGE_FAULT device=07:00.0 domain=0x0000 address=0x0000000000001900 flags=0x0050]
[ 14.169233] AMD-Vi: Event logged [IO_PAGE_FAULT device=07:00.0 domain=0x0000 address=0x0000000000001940 flags=0x0050]
[ 14.169235] AMD-Vi: Event logged [IO_PAGE_FAULT device=07:00.0 domain=0x0000 address=0x0000000000001900 flags=0x0050]
[ 14.169237] AMD-Vi: Event logged [IO_PAGE_FAULT device=07:00.0 domain=0x0000 address=0x0000000000001940 flags=0x0050]
Here is the dmesg output when attempting to read from tape, when using iommu=soft:
[ 13.788004] sym0: <895> rev 0x2 at pci 0000:07:00.0 irq 36
[ 13.790154] sym0: Symbios NVRAM, ID 7, Fast-40, LVD, parity checking
[ 13.790154] sym0: open drain IRQ line driver, using on-chip SRAM
[ 13.790155] sym0: using LOAD/STORE-based firmware.
[ 13.796592] sym0: SCSI BUS has been reset.
...
[ 109.913335] irq 36: nobody cared (try booting with the "irqpoll" option)
[ 109.920562] CPU: 0 PID: 3 Comm: ksoftirqd/0 Not tainted 4.2.0-42-generic #49~14.04.1+7.0trisquel1
[ 109.920564] Hardware name: ASUS KGPE-D16/KGPE-D16, BIOS 4.5-566-geb9c639 12/09/2016
[ 109.920567] 0000000000000000 ffff88013bc03e08 ffffffff817c323d ffff8800bb8d3800
[ 109.920571] ffff8800bb8d38bc ffff88013bc03e38 ffffffff810d3406 ffff88013bc03e28
[ 109.920574] ffff8800bb8d3800 0000000000000024 0000000000000000 ffff88013bc03e88
[ 109.920577] Call Trace:
[ 109.920579] <IRQ> [<ffffffff817c323d>] dump_stack+0x63/0x81
[ 109.920591] [<ffffffff810d3406>] __report_bad_irq+0x36/0xd0
[ 109.920594] [<ffffffff810d3912>] note_interrupt+0x222/0x280
[ 109.920597] [<ffffffff810d0e14>] handle_irq_event_percpu+0xb4/0x1d0
[ 109.920600] [<ffffffff810d0f79>] handle_irq_event+0x49/0x70
[ 109.920603] [<ffffffff810d3d9a>] handle_fasteoi_irq+0x9a/0x150
[ 109.920606] [<ffffffff81018255>] handle_irq+0x25/0x40
[ 109.920609] [<ffffffff817cd2b1>] do_IRQ+0x51/0xe0
[ 109.920613] [<ffffffff817cb22b>] common_interrupt+0x6b/0x6b
[ 109.920614] <EOI> [<ffffffff8177209b>] ? ip6_pol_route.isra.38+0x29b/0x570
[ 109.920620] [<ffffffff81771ed2>] ? ip6_pol_route.isra.38+0xd2/0x570
[ 109.920623] [<ffffffff81772370>] ? ip6_pol_route.isra.38+0x570/0x570
[ 109.920626] [<ffffffff8177239b>] ip6_pol_route_input+0x2b/0x30
[ 109.920629] [<ffffffff8179a76f>] fib6_rule_action+0xaf/0x1e0
[ 109.920632] [<ffffffff816f23b5>] ? nf_hook_slow+0xa5/0xc0
[ 109.920636] [<ffffffff816dc4a0>] fib_rules_lookup+0xc0/0x160
[ 109.920638] [<ffffffff8179aa54>] fib6_rule_lookup+0x44/0x70
[ 109.920641] [<ffffffff81772370>] ? ip6_pol_route.isra.38+0x570/0x570
[ 109.920644] [<ffffffff81770b0a>] ip6_route_input_lookup.isra.39+0x4a/0x60
[ 109.920646] [<ffffffff817727fd>] ip6_route_input+0x9d/0xc0
[ 109.920650] [<ffffffff81764fd3>] ip6_rcv_finish+0x83/0xa0
[ 109.920653] [<ffffffff817657a6>] ipv6_rcv+0x2d6/0x500
[ 109.920656] [<ffffffff816f94c6>] ? ip_rcv+0x296/0x400
[ 109.920659] [<ffffffff816bebad>] __netif_receive_skb_core+0x65d/0x9c0
[ 109.920662] [<ffffffff817339c1>] ? inet_gro_receive+0x1e1/0x210
[ 109.920665] [<ffffffff816bef28>] __netif_receive_skb+0x18/0x60
[ 109.920668] [<ffffffff816bef93>] netif_receive_skb_internal+0x23/0x80
[ 109.920670] [<ffffffff816bfba3>] napi_gro_receive+0xd3/0x100
[ 109.920689] [<ffffffffc0812446>] e1000_receive_skb+0x86/0xe0 [e1000e]
[ 109.920698] [<ffffffffc08140b9>] e1000_clean_rx_irq+0x269/0x410 [e1000e]
[ 109.920707] [<ffffffffc081b200>] e1000e_poll+0x90/0x2a0 [e1000e]
[ 109.920710] [<ffffffff816bf3c4>] net_rx_action+0x164/0x350
[ 109.920713] [<ffffffff8107db3d>] __do_softirq+0xdd/0x290
[ 109.920716] [<ffffffff8107dd18>] run_ksoftirqd+0x28/0x50
[ 109.920719] [<ffffffff8109addf>] smpboot_thread_fn+0x10f/0x160
[ 109.920722] [<ffffffff8109acd0>] ? sort_range+0x30/0x30
[ 109.920725] [<ffffffff81097a99>] kthread+0xc9/0xe0
[ 109.920727] [<ffffffff810979d0>] ? kthread_create_on_node+0x1c0/0x1c0
[ 109.920730] [<ffffffff817caadf>] ret_from_fork+0x3f/0x70
[ 109.920733] [<ffffffff810979d0>] ? kthread_create_on_node+0x1c0/0x1c0
[ 109.920734] handlers:
[ 109.923566] [<ffffffffc02169d0>] sym53c8xx_intr [sym53c8xx]
[ 109.929719] Disabling IRQ #36
[ 124.269335] irq 20: nobody cared (try booting with the "irqpoll" option)
[ 124.276603] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.2.0-42-generic #49~14.04.1+7.0trisquel1
[ 124.276606] Hardware name: ASUS KGPE-D16/KGPE-D16, BIOS 4.5-566-geb9c639 12/09/2016
[ 124.276609] 0000000000000000 ffff88013bc03e08 ffffffff817c323d ffff8800368d4000
[ 124.276613] ffff8800368d40bc ffff88013bc03e38 ffffffff810d3406 ffff88013bc03e28
[ 124.276616] ffff8800368d4000 0000000000000014 0000000000000000 ffff88013bc03e88
[ 124.276619] Call Trace:
[ 124.276621] <IRQ> [<ffffffff817c323d>] dump_stack+0x63/0x81
[ 124.276633] [<ffffffff810d3406>] __report_bad_irq+0x36/0xd0
[ 124.276637] [<ffffffff810d3912>] note_interrupt+0x222/0x280
[ 124.276640] [<ffffffff810d0e14>] handle_irq_event_percpu+0xb4/0x1d0
[ 124.276643] [<ffffffff810d0f79>] handle_irq_event+0x49/0x70
[ 124.276645] [<ffffffff810d3d9a>] handle_fasteoi_irq+0x9a/0x150
[ 124.276649] [<ffffffff81018255>] handle_irq+0x25/0x40
[ 124.276652] [<ffffffff817cd2b1>] do_IRQ+0x51/0xe0
[ 124.276656] [<ffffffff817cb22b>] common_interrupt+0x6b/0x6b
[ 124.276657] <EOI> [<ffffffff8105f296>] ? native_safe_halt+0x6/0x10
[ 124.276665] [<ffffffff8101fd5e>] default_idle+0x1e/0xe0
[ 124.276668] [<ffffffff8102054f>] arch_cpu_idle+0xf/0x20
[ 124.276671] [<ffffffff810ba2f2>] default_idle_call+0x32/0x40
[ 124.276673] [<ffffffff810ba649>] cpu_startup_entry+0x2e9/0x360
[ 124.276676] [<ffffffff817b312c>] rest_init+0x7c/0x80
[ 124.276680] [<ffffffff81d5311f>] start_kernel+0x4b0/0x4bd
[ 124.276682] [<ffffffff81d52a54>] ? set_init_arg+0x57/0x57
[ 124.276686] [<ffffffff81d52120>] ? early_idt_handler_array+0x120/0x120
[ 124.276688] [<ffffffff81d525ee>] x86_64_start_reservations+0x2a/0x2c
[ 124.276690] [<ffffffff81d5272d>] x86_64_start_kernel+0x13d/0x14c
[ 124.276692] handlers:
[ 124.279478] [<ffffffffc0034d50>] irq_handler [firewire_ohci]
[ 124.285629] Disabling IRQ #20
Actions