[BUG 4.15-rc7] IRQ matrix management errors
From: Keith Busch
Date: Sun Jan 14 2018 - 22:00:01 EST
I hoped to have a better report before the weekend, but I've run out of
time and without my machine till next week, so sending what I have and
praying someone more in the know will have a better clue.
I've a few NVMe drives and occasionally the IRQ teardown and bring-up
is failing. Resetting the controllers to re-run interrupt allocation
results in device interrupts from not occuring at all.
It appears I need at least 2 NVMe drives for the problem. The NVMe
driver initializes controllers in parallel, and multiple threads calling
pci_alloc_irq_vectors and/or pci_free_vectors at about the same time
seems required to trigger the issue.
Here are the relavent warnings. I also have trace events from irq_matrix
and irq_vectors, but from a different run that won't match up to the
timestamps below, but can send if that's helpful.
[ 288.519216] WARNING: CPU: 28 PID: 1420 at kernel/irq/matrix.c:222 irq_matrix_remove_managed+0x10f/0x120
[ 288.519218] Modules linked in: nvme ip6t_rpfilter ip6t_REJECT nf_reject_ipv6 xt_conntrack ip_set nfnetlink ebtable_nat ebtable_broute bridge stp llc ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 ip6table_mangle ip6table_raw ip6table_security iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack iptable_mangle iptable_raw iptable_security ebtable_filter ebtables ip6table_filter ip6_tables sunrpc vfat fat intel_rapl x86_pkg_temp_thermal intel_powerclamp coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel intel_uncore intel_rapl_perf iTCO_wdt joydev iTCO_vendor_support ipmi_ssif ipmi_si mei_me mei shpchp i2c_i801 wmi lpc_ich ipmi_devintf ioatdma ipmi_msghandler dca acpi_pad acpi_power_meter xfs libcrc32c ast i2c_algo_bit drm_kms_helper ttm drm i40e crc32c_intel
[ 288.519286] ptp nvme_core pps_core [last unloaded: nvme]
[ 288.519294] CPU: 28 PID: 1420 Comm: kworker/u674:2 Not tainted 4.15.0-rc7+ #4
[ 288.519296] Hardware name: Intel Corporation S2600STB/S2600STB, BIOS SE5C620.86B.00.01.2001.062220170731 06/22/2017
[ 288.519305] Workqueue: nvme-wq nvme_reset_work [nvme]
[ 288.519310] RIP: 0010:irq_matrix_remove_managed+0x10f/0x120
[ 288.519312] RSP: 0018:ffffb01f0aec7a88 EFLAGS: 00010046
[ 288.519315] RAX: 00000000000000ee RBX: ffff9e387d824900 RCX: 0000000000000000
[ 288.519317] RDX: 0000000000000100 RSI: 00000000000000ee RDI: ffff9e387d410c50
[ 288.519319] RBP: 0000000000000000 R08: 0000000000000100 R09: 0000000000000000
[ 288.519320] R10: 0000000000000018 R11: 0000000000000003 R12: ffff9e387d410c00
[ 288.519322] R13: ffff9e387d410c30 R14: 00000000000000ee R15: 00000000000000ee
[ 288.519324] FS: 0000000000000000(0000) GS:ffff9e487cc00000(0000) knlGS:0000000000000000
[ 288.519326] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 288.519328] CR2: 00007fbc1c2321d4 CR3: 00000010f5209003 CR4: 00000000007606e0
[ 288.519330] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 288.519332] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 288.519333] PKRU: 55555554
[ 288.519334] Call Trace:
[ 288.519345] x86_vector_free_irqs+0xa1/0x180
[ 288.519349] x86_vector_alloc_irqs+0x1e4/0x3a0
[ 288.519354] msi_domain_alloc+0x62/0x130
[ 288.519363] ? kmem_cache_alloc_node_trace+0x1ac/0x1d0
[ 288.519366] __irq_domain_alloc_irqs+0x121/0x300
[ 288.519370] msi_domain_alloc_irqs+0x99/0x2e0
[ 288.519376] native_setup_msi_irqs+0x54/0x90
[ 288.519383] __pci_enable_msix+0xfb/0x4e0
[ 288.519389] pci_alloc_irq_vectors_affinity+0x8e/0x130
[ 288.519394] nvme_reset_work+0x919/0x153b [nvme]
[ 288.519404] ? sched_clock+0x5/0x10
[ 288.519407] ? sched_clock+0x5/0x10
[ 288.519414] ? sched_clock_cpu+0xc/0xb0
[ 288.519420] ? pick_next_task_fair+0x4d5/0x5f0
[ 288.519427] ? __switch_to+0xa2/0x430
[ 288.519431] ? put_prev_entity+0x1e/0xe0
[ 288.519438] process_one_work+0x182/0x370
[ 288.519441] worker_thread+0x2e/0x380
[ 288.519444] ? process_one_work+0x370/0x370
[ 288.519449] kthread+0x111/0x130
[ 288.519453] ? kthread_create_worker_on_cpu+0x70/0x70
[ 288.519460] ret_from_fork+0x1f/0x30
[ 288.519464] Code: 89 ea 44 89 f6 41 ff d1 4d 8b 0f 4d 85 c9 75 e2 e9 2a ff ff ff 48 83 c4 08 5b 5d 41 5c 41 5d 41 5e 41 5f c3 0f ff e9 14 ff ff ff <0f> ff e9 0d ff ff ff 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00
[ 288.519517] ---[ end trace 8fcc70570a780634 ]---
[ 310.959112] nvme nvme0: pci function 0000:5e:00.0
[ 310.959333] nvme nvme1: pci function 0000:60:00.0
[ 310.959675] nvme nvme2: pci function 0000:86:00.0
[ 311.167369] WARNING: CPU: 1 PID: 898 at kernel/irq/matrix.c:215 irq_matrix_remove_managed+0x108/0x120
[ 311.167371] Modules linked in: nvme ip6t_rpfilter ip6t_REJECT nf_reject_ipv6 xt_conntrack ip_set nfnetlink ebtable_nat ebtable_broute bridge stp llc ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 ip6table_mangle ip6table_raw ip6table_security iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack iptable_mangle iptable_raw iptable_security ebtable_filter ebtables ip6table_filter ip6_tables sunrpc vfat fat intel_rapl x86_pkg_temp_thermal intel_powerclamp coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel intel_uncore intel_rapl_perf iTCO_wdt joydev iTCO_vendor_support ipmi_ssif ipmi_si mei_me mei shpchp i2c_i801 wmi lpc_ich ipmi_devintf ioatdma ipmi_msghandler dca acpi_pad acpi_power_meter xfs libcrc32c ast i2c_algo_bit drm_kms_helper ttm drm i40e crc32c_intel
[ 311.167440] ptp nvme_core pps_core [last unloaded: nvme]
[ 311.167448] CPU: 1 PID: 898 Comm: kworker/u673:9 Tainted: G W 4.15.0-rc7+ #4
[ 311.167450] Hardware name: Intel Corporation S2600STB/S2600STB, BIOS SE5C620.86B.00.01.2001.062220170731 06/22/2017
[ 311.167459] Workqueue: nvme-wq nvme_reset_work [nvme]
[ 311.167464] RIP: 0010:irq_matrix_remove_managed+0x108/0x120
[ 311.167466] RSP: 0018:ffffb01f0f387a88 EFLAGS: 00010046
[ 311.167469] RAX: 0000000000000000 RBX: ffff9e387df24900 RCX: 0000000000000038
[ 311.167471] RDX: 0000000000000038 RSI: 0000000000000000 RDI: ffff9e3871bcd3c0
[ 311.167472] RBP: 0000000000000038 R08: fffffffffffffffc R09: 0300000000000003
[ 311.167474] R10: ffff9e387d402480 R11: ffff9e3838149d1c R12: ffff9e387d410c00
[ 311.167476] R13: ffff9e387d410c30 R14: 0000000000000021 R15: 00000000000000ee
[ 311.167478] FS: 0000000000000000(0000) GS:ffff9e387d840000(0000) knlGS:0000000000000000
[ 311.167481] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 311.167483] CR2: 00007fbe60000b20 CR3: 00000010f5209001 CR4: 00000000007606e0
[ 311.167486] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 311.167489] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 311.167490] PKRU: 55555554
[ 311.167491] Call Trace:
[ 311.167505] x86_vector_free_irqs+0xa1/0x180
[ 311.167515] ? cpumask_next+0x17/0x20
[ 311.167520] x86_vector_alloc_irqs+0x1e4/0x3a0
[ 311.167525] msi_domain_alloc+0x62/0x130
[ 311.167532] ? kmem_cache_alloc_node_trace+0x1ac/0x1d0
[ 311.167536] __irq_domain_alloc_irqs+0x121/0x300
[ 311.167540] msi_domain_alloc_irqs+0x99/0x2e0
[ 311.167547] native_setup_msi_irqs+0x54/0x90
[ 311.167556] __pci_enable_msix+0xfb/0x4e0
[ 311.167562] pci_alloc_irq_vectors_affinity+0x8e/0x130
[ 311.167568] nvme_reset_work+0x919/0x153b [nvme]
[ 311.167576] ? update_curr+0xe4/0x1d0
[ 311.167580] ? account_entity_dequeue+0xa4/0xd0
[ 311.167584] ? dequeue_entity+0xd5/0x430
[ 311.167589] ? pick_next_task_fair+0x14f/0x5f0
[ 311.167597] ? __switch_to+0xa2/0x430
[ 311.167603] ? sched_clock+0x5/0x10
[ 311.167607] ? put_prev_entity+0x1e/0xe0
[ 311.167612] process_one_work+0x182/0x370
[ 311.167616] worker_thread+0x2e/0x380
[ 311.167619] ? process_one_work+0x370/0x370
[ 311.167623] kthread+0x111/0x130
[ 311.167628] ? kthread_create_worker_on_cpu+0x70/0x70
[ 311.167633] ret_from_fork+0x1f/0x30
[ 311.167637] Code: 18 49 89 d8 4c 89 e1 89 ea 44 89 f6 41 ff d1 4d 8b 0f 4d 85 c9 75 e2 e9 2a ff ff ff 48 83 c4 08 5b 5d 41 5c 41 5d 41 5e 41 5f c3 <0f> ff e9 14 ff ff ff 0f ff e9 0d ff ff ff 66 2e 0f 1f 84 00 00
[ 311.167691] ---[ end trace 8fcc70570a780635 ]---
[ 311.172737] WARNING: CPU: 0 PID: 894 at arch/x86/kernel/apic/vector.c:404 x86_vector_activate+0x160/0x280
[ 311.172739] Modules linked in: nvme ip6t_rpfilter ip6t_REJECT nf_reject_ipv6 xt_conntrack ip_set nfnetlink ebtable_nat ebtable_broute bridge stp llc ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 ip6table_mangle ip6table_raw ip6table_security iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack iptable_mangle iptable_raw iptable_security ebtable_filter ebtables ip6table_filter ip6_tables sunrpc vfat fat intel_rapl x86_pkg_temp_thermal intel_powerclamp coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel intel_uncore intel_rapl_perf iTCO_wdt joydev iTCO_vendor_support ipmi_ssif ipmi_si mei_me mei shpchp i2c_i801 wmi lpc_ich ipmi_devintf ioatdma ipmi_msghandler dca acpi_pad acpi_power_meter xfs libcrc32c ast i2c_algo_bit drm_kms_helper ttm drm i40e crc32c_intel
[ 311.172801] ptp nvme_core pps_core [last unloaded: nvme]
[ 311.172808] CPU: 0 PID: 894 Comm: kworker/u673:5 Tainted: G W 4.15.0-rc7+ #4
[ 311.172809] Hardware name: Intel Corporation S2600STB/S2600STB, BIOS SE5C620.86B.00.01.2001.062220170731 06/22/2017
[ 311.172817] Workqueue: nvme-wq nvme_reset_work [nvme]
[ 311.172822] RIP: 0010:x86_vector_activate+0x160/0x280
[ 311.172824] RSP: 0018:ffffb01f0f367b88 EFLAGS: 00010086
[ 311.172827] RAX: 00000000ffffffe4 RBX: ffff9e386a90e380 RCX: 0000000000000000
[ 311.172829] RDX: 0000000000000100 RSI: 00000000000000ee RDI: ffff9e387d410c50
[ 311.172830] RBP: 0000000000000150 R08: 0000000000000100 R09: 0000000000000000
[ 311.172832] R10: 0000000000000018 R11: 0000000000000003 R12: 00000000ffffffe4
[ 311.172833] R13: 0000000000000000 R14: 0000000000000002 R15: ffff9e386a0b70a4
[ 311.172835] FS: 0000000000000000(0000) GS:ffff9e387d800000(0000) knlGS:0000000000000000
[ 311.172837] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 311.172839] CR2: 00007f268d3d5000 CR3: 00000010f5209001 CR4: 00000000007606f0
[ 311.172841] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 311.172842] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 311.172843] PKRU: 55555554
[ 311.172844] Call Trace:
[ 311.172855] ? kernfs_activate+0x63/0x80
[ 311.172864] __irq_domain_activate_irq+0x43/0x90
[ 311.172869] ? __kernfs_create_file+0x7d/0xb0
[ 311.172874] __irq_domain_activate_irq+0x7a/0x90
[ 311.172877] irq_domain_activate_irq+0x25/0x40
[ 311.172882] irq_startup+0xb2/0xe0
[ 311.172887] __setup_irq+0x66d/0x6e0
[ 311.172891] ? request_threaded_irq+0xad/0x160
[ 311.172894] request_threaded_irq+0xf5/0x160
[ 311.172900] ? nvme_del_cq_end+0x70/0x70 [nvme]
[ 311.172906] pci_request_irq+0x8f/0xd0
[ 311.172912] queue_request_irq+0x4d/0x70 [nvme]
[ 311.172917] nvme_reset_work+0x934/0x153b [nvme]
[ 311.172924] ? update_curr+0xe4/0x1d0
[ 311.172928] ? account_entity_dequeue+0xa4/0xd0
[ 311.172932] ? dequeue_entity+0xd5/0x430
[ 311.172937] ? pick_next_task_fair+0x14f/0x5f0
[ 311.172943] ? __switch_to+0xa2/0x430
[ 311.172947] ? sched_clock+0x5/0x10
[ 311.172951] ? put_prev_entity+0x1e/0xe0
[ 311.172956] process_one_work+0x182/0x370
[ 311.172959] worker_thread+0x2e/0x380
[ 311.172962] ? process_one_work+0x370/0x370
[ 311.172966] kthread+0x111/0x130
[ 311.172971] ? kthread_create_worker_on_cpu+0x70/0x70
[ 311.172975] ret_from_fork+0x1f/0x30
[ 311.172978] Code: 4b c2 3d 01 48 8b 3d a0 8a 9c 01 48 89 ee e8 88 33 3d 00 48 39 c5 0f 84 05 01 00 00 48 89 df e8 07 fd ff ff 85 c0 41 89 c4 79 a1 <0f> ff 8b 73 04 48 c7 c7 38 27 08 92 e8 f9 15 0b 00 eb 8e 45 31
[ 311.173032] ---[ end trace 8fcc70570a780636 ]---
[ 311.173034] Managed startup irq 41, no vector available
[ 311.173090] WARNING: CPU: 0 PID: 894 at kernel/irq/chip.c:226 irq_startup+0xd6/0xe0
[ 311.173090] Modules linked in: nvme ip6t_rpfilter ip6t_REJECT nf_reject_ipv6 xt_conntrack ip_set nfnetlink ebtable_nat ebtable_broute bridge stp llc ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 ip6table_mangle ip6table_raw ip6table_security iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack iptable_mangle iptable_raw iptable_security ebtable_filter ebtables ip6table_filter ip6_tables sunrpc vfat fat intel_rapl x86_pkg_temp_thermal intel_powerclamp coretemp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel intel_uncore intel_rapl_perf iTCO_wdt joydev iTCO_vendor_support ipmi_ssif ipmi_si mei_me mei shpchp i2c_i801 wmi lpc_ich ipmi_devintf ioatdma ipmi_msghandler dca acpi_pad acpi_power_meter xfs libcrc32c ast i2c_algo_bit drm_kms_helper ttm drm i40e crc32c_intel
[ 311.173140] ptp nvme_core pps_core [last unloaded: nvme]
[ 311.173145] CPU: 0 PID: 894 Comm: kworker/u673:5 Tainted: G W 4.15.0-rc7+ #4
[ 311.173147] Hardware name: Intel Corporation S2600STB/S2600STB, BIOS SE5C620.86B.00.01.2001.062220170731 06/22/2017
[ 311.173151] Workqueue: nvme-wq nvme_reset_work [nvme]
[ 311.173156] RIP: 0010:irq_startup+0xd6/0xe0
[ 311.173158] RSP: 0018:ffffb01f0f367c28 EFLAGS: 00010086
[ 311.173160] RAX: 00000000ffffffe4 RBX: ffff9e386a0b7000 RCX: 0000000000000006
[ 311.173162] RDX: 0000000000000000 RSI: 0000000000000002 RDI: 0000000000000000
[ 311.173163] RBP: ffff9e386a90e580 R08: 0000000000000720 R09: 0000000000000000
[ 311.173164] R10: 0000000000000018 R11: ffff9e386c83c790 R12: 0000000000000001
[ 311.173166] R13: ffff9e386a0b7028 R14: ffff9e386a0b7160 R15: ffff9e386a0b70a4
[ 311.173168] FS: 0000000000000000(0000) GS:ffff9e387d800000(0000) knlGS:0000000000000000
[ 311.173169] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 311.173171] CR2: 00007f268d3d5000 CR3: 00000010f5209001 CR4: 00000000007606f0
[ 311.173172] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 311.173174] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 311.173175] PKRU: 55555554
[ 311.173176] Call Trace:
[ 311.173180] __setup_irq+0x66d/0x6e0
[ 311.173183] ? request_threaded_irq+0xad/0x160
[ 311.173187] request_threaded_irq+0xf5/0x160
[ 311.173191] ? nvme_del_cq_end+0x70/0x70 [nvme]
[ 311.173194] pci_request_irq+0x8f/0xd0
[ 311.173199] queue_request_irq+0x4d/0x70 [nvme]
[ 311.173203] nvme_reset_work+0x934/0x153b [nvme]
[ 311.173207] ? update_curr+0xe4/0x1d0
[ 311.173211] ? account_entity_dequeue+0xa4/0xd0
[ 311.173215] ? dequeue_entity+0xd5/0x430
[ 311.173220] ? pick_next_task_fair+0x14f/0x5f0
[ 311.173223] ? __switch_to+0xa2/0x430
[ 311.173227] ? sched_clock+0x5/0x10
[ 311.173231] ? put_prev_entity+0x1e/0xe0
[ 311.173234] process_one_work+0x182/0x370
[ 311.173237] worker_thread+0x2e/0x380
[ 311.173240] ? process_one_work+0x370/0x370
[ 311.173243] kthread+0x111/0x130
[ 311.173248] ? kthread_create_worker_on_cpu+0x70/0x70
[ 311.173250] ret_from_fork+0x1f/0x30
[ 311.173253] Code: 89 ef e8 0e 2f 00 00 85 c0 75 20 48 89 ee 31 d2 4c 89 ef e8 ad da ff ff 48 89 df e8 d5 fe ff ff 89 c5 e9 65 ff ff ff 0f ff eb b9 <0f> ff eb b5 66 0f 1f 44 00 00 0f 1f 44 00 00 55 53 48 89 fd 48
[ 311.173306] ---[ end trace 8fcc70570a780637 ]---
[ 371.677929] nvme nvme0: I/O 21 QID 0 timeout, completion polled
[ 431.709906] nvme nvme0: I/O 21 QID 0 timeout, completion polled
[ 491.997931] nvme nvme0: I/O 5 QID 0 timeout, completion polled
[ 552.733905] nvme nvme0: I/O 25 QID 0 timeout, completion polled
[ 552.733990] Managed startup irq 43, no vector available