Re: system hang on start-up (mlx5?)

[Chuck Lever III <chuck.lever@oracle.com>]

> On May 7, 2023, at 1:31 AM, Eli Cohen <elic@nvidia.com> wrote:
> 
> Hi Thomas,
> 
> Do you have insights what could cause this?

Following up. I am not able to reproduce this problem with KASAN
enabled, so I sprinkled a few pr_info() call sites in
kernel/irq/matrix.c.

I can boot the system with mlx5_core deny-listed. I log in, remove
mlx5_core from the deny list, and then "modprobe mlx5_core" to
reproduce the issue while the system is running.

May 27 15:47:45 manet.1015granger.net kernel: mlx5_core 0000:81:00.0: firmware version: 16.35.2000
May 27 15:47:45 manet.1015granger.net kernel: mlx5_core 0000:81:00.0: 126.016 Gb/s available PCIe bandwidth (8.0 GT/s PCIe x16 link)
May 27 15:47:46 manet.1015granger.net kernel: mlx5_irq_alloc: pool=ffff9a3718e56180 i=0 af_desc=ffffb6c88493fc90
May 27 15:47:46 manet.1015granger.net kernel: matrix_alloc_area: m->scratch_map=ffff9a33801990b0 cm->managed_map=ffff9a3aefcf0f80 m->system_map=ffff9a33801990d0 end=236
May 27 15:47:46 manet.1015granger.net kernel: matrix_alloc_area: m->scratch_map=ffff9a33801990b0 cm->alloc_map=ffff9a3aefcf0f60 end=236
May 27 15:47:46 manet.1015granger.net kernel: mlx5_core 0000:81:00.0: Port module event: module 0, Cable plugged
May 27 15:47:46 manet.1015granger.net kernel: mlx5_irq_alloc: pool=ffff9a3718e56180 i=1 af_desc=ffffb6c88493fc60
May 27 15:47:46 manet.1015granger.net kernel: mlx5_core 0000:81:00.0: mlx5_pcie_event:301:(pid 10): PCIe slot advertised sufficient power (27W).
May 27 15:47:46 manet.1015granger.net kernel: matrix_alloc_area: m->scratch_map=ffff9a33801990b0 cm->managed_map=ffff9a36efcf0f80 m->system_map=ffff9a33801990d0 end=236
May 27 15:47:47 manet.1015granger.net kernel: matrix_alloc_area: m->scratch_map=ffff9a33801990b0 cm->alloc_map=ffff9a36efcf0f60 end=236
May 27 15:47:47 manet.1015granger.net kernel: matrix_alloc_area: m->scratch_map=ffff9a33801990b0 cm->managed_map=ffff9a36efd30f80 m->system_map=ffff9a33801990d0 end=236
May 27 15:47:47 manet.1015granger.net kernel: matrix_alloc_area: m->scratch_map=ffff9a33801990b0 cm->alloc_map=ffff9a36efd30f60 end=236
May 27 15:47:47 manet.1015granger.net kernel: matrix_alloc_area: m->scratch_map=ffff9a33801990b0 cm->managed_map=ffff9a3aefc30f80 m->system_map=ffff9a33801990d0 end=236
May 27 15:47:47 manet.1015granger.net kernel: matrix_alloc_area: m->scratch_map=ffff9a33801990b0 cm->alloc_map=ffff9a3aefc30f60 end=236
May 27 15:47:47 manet.1015granger.net kernel: matrix_alloc_area: m->scratch_map=ffff9a33801990b0 cm->managed_map=ffff9a3aefc70f80 m->system_map=ffff9a33801990d0 end=236
May 27 15:47:47 manet.1015granger.net kernel: matrix_alloc_area: m->scratch_map=ffff9a33801990b0 cm->alloc_map=ffff9a3aefc70f60 end=236
May 27 15:47:47 manet.1015granger.net kernel: matrix_alloc_area: m->scratch_map=ffff9a33801990b0 cm->managed_map=ffff9a3aefd30f80 m->system_map=ffff9a33801990d0 end=236
May 27 15:47:47 manet.1015granger.net kernel: matrix_alloc_area: m->scratch_map=ffff9a33801990b0 cm->alloc_map=ffff9a3aefd30f60 end=236
May 27 15:47:47 manet.1015granger.net kernel: matrix_alloc_area: m->scratch_map=ffff9a33801990b0 cm->managed_map=ffff9a3aefd70f80 m->system_map=ffff9a33801990d0 end=236
May 27 15:47:47 manet.1015granger.net kernel: matrix_alloc_area: m->scratch_map=ffff9a33801990b0 cm->alloc_map=ffff9a3aefd70f60 end=236
May 27 15:47:47 manet.1015granger.net kernel: matrix_alloc_area: m->scratch_map=ffff9a33801990b0 cm->managed_map=ffffffffb9ef3f80 m->system_map=ffff9a33801990d0 end=236
May 27 15:47:47 manet.1015granger.net kernel: BUG: unable to handle page fault for address: ffffffffb9ef3f80

###

The fault address is the cm->managed_map for one of the CPUs.

###

May 27 15:47:47 manet.1015granger.net kernel: #PF: supervisor read access in kernel mode
May 27 15:47:47 manet.1015granger.net kernel: #PF: error_code(0x0000) - not-present page
May 27 15:47:47 manet.1015granger.net kernel: PGD 54ec19067 P4D 54ec19067 PUD 54ec1a063 PMD 482b83063 PTE 800ffffab110c062
May 27 15:47:47 manet.1015granger.net kernel: Oops: 0000 [#1] PREEMPT SMP PTI
May 27 15:47:47 manet.1015granger.net kernel: CPU: 6 PID: 364 Comm: kworker/6:3 Tainted: G S                 6.4.0-rc3-00014-g7d5f9d35c255 #2 fde923d833042649d4022091376d234db2fe0900
May 27 15:47:47 manet.1015granger.net kernel: Hardware name: Supermicro SYS-6028R-T/X10DRi, BIOS 1.1a 10/16/2015
May 27 15:47:47 manet.1015granger.net kernel: Workqueue: events work_for_cpu_fn
May 27 15:47:47 manet.1015granger.net kernel: RIP: 0010:__bitmap_or+0x11/0x30
May 27 15:47:47 manet.1015granger.net kernel: Code: c6 48 85 f6 0f 95 c0 c3 31 f6 eb cf 66 66 2e 0f 1f 84 00 00 00 00 00 66 90 89 c9 49 89 f8 48 83 c1 3f 48 c1 e9 06 74 17 31 c0 <48> 8b 3c c6 48 0b 3c c2 49 89 3c c0 48 83 c0 01 48 39 c1 75 eb c3
May 27 15:47:47 manet.1015granger.net kernel: RSP: 0018:ffffb6c88493f798 EFLAGS: 00010046
May 27 15:47:47 manet.1015granger.net kernel: RAX: 0000000000000000 RBX: ffff9a33801990b0 RCX: 0000000000000004
May 27 15:47:47 manet.1015granger.net kernel: RDX: ffff9a33801990d0 RSI: ffffffffb9ef3f80 RDI: ffff9a33801990b0
May 27 15:47:47 manet.1015granger.net kernel: RBP: ffffb6c88493f7d8 R08: ffff9a33801990b0 R09: ffffb6c88493f628
May 27 15:47:47 manet.1015granger.net kernel: R10: 0000000000000003 R11: ffffffffb9d30748 R12: ffffffffb9ef3f60
May 27 15:47:47 manet.1015granger.net kernel: R13: 00000000000000ec R14: 0000000000000020 R15: ffffffffb9ef3f80
May 27 15:47:47 manet.1015granger.net kernel: FS:  0000000000000000(0000) GS:ffff9a3aefc00000(0000) knlGS:0000000000000000
May 27 15:47:47 manet.1015granger.net kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
May 27 15:47:47 manet.1015granger.net kernel: CR2: ffffffffb9ef3f80 CR3: 000000054ec16005 CR4: 00000000001706e0
May 27 15:47:47 manet.1015granger.net kernel: Call Trace:
May 27 15:47:47 manet.1015granger.net kernel:  <TASK>
May 27 15:47:47 manet.1015granger.net kernel:  ? matrix_alloc_area.constprop.0+0x66/0xe0
May 27 15:47:47 manet.1015granger.net kernel:  ? unpack_to_rootfs+0x178/0x380
May 27 15:47:47 manet.1015granger.net kernel:  irq_matrix_reserve_managed+0x55/0x170
May 27 15:47:47 manet.1015granger.net kernel:  x86_vector_alloc_irqs.part.0+0x2bb/0x3a0
May 27 15:47:47 manet.1015granger.net kernel:  x86_vector_alloc_irqs+0x23/0x40
May 27 15:47:47 manet.1015granger.net kernel:  irq_domain_alloc_irqs_parent+0x24/0x50
May 27 15:47:47 manet.1015granger.net kernel:  intel_irq_remapping_alloc+0x59/0x650
May 27 15:47:47 manet.1015granger.net kernel:  irq_domain_alloc_irqs_parent+0x24/0x50
May 27 15:47:47 manet.1015granger.net kernel:  msi_domain_alloc+0x74/0x130
May 27 15:47:47 manet.1015granger.net kernel:  irq_domain_alloc_irqs_hierarchy+0x18/0x40
May 27 15:47:47 manet.1015granger.net kernel:  irq_domain_alloc_irqs_locked+0xce/0x370
May 27 15:47:47 manet.1015granger.net kernel:  __irq_domain_alloc_irqs+0x57/0xa0
May 27 15:47:47 manet.1015granger.net kernel:  __msi_domain_alloc_irqs+0x1ca/0x3f0
May 27 15:47:47 manet.1015granger.net kernel:  msi_domain_alloc_irq_at+0xef/0x140
May 27 15:47:47 manet.1015granger.net kernel:  ? vprintk+0x4b/0x60
May 27 15:47:47 manet.1015granger.net kernel:  pci_msix_alloc_irq_at+0x5c/0x70
May 27 15:47:47 manet.1015granger.net kernel:  mlx5_irq_alloc+0x22f/0x3d0 [mlx5_core 11229579f576884e9585dbff83cf9d4f8d975d71]

[ snip ]


>> -----Original Message-----
>> From: Chuck Lever III <chuck.lever@oracle.com>
>> Sent: Thursday, 4 May 2023 22:03
>> To: Leon Romanovsky <leon@kernel.org>; Eli Cohen <elic@nvidia.com>
>> Cc: Saeed Mahameed <saeedm@nvidia.com>; linux-rdma <linux-
>> rdma@vger.kernel.org>; open list:NETWORKING [GENERAL]
>> <netdev@vger.kernel.org>
>> Subject: Re: system hang on start-up (mlx5?)
>> 
>> 
>> 
>>> On May 4, 2023, at 3:29 AM, Leon Romanovsky <leon@kernel.org> wrote:
>>> 
>>> On Wed, May 03, 2023 at 02:02:33PM +0000, Chuck Lever III wrote:
>>>> 
>>>> 
>>>>> On May 3, 2023, at 2:34 AM, Eli Cohen <elic@nvidia.com> wrote:
>>>>> 
>>>>> Hi Chuck,
>>>>> 
>>>>> Just verifying, could you make sure your server and card firmware are up
>> to date?
>>>> 
>>>> Device firmware updated to 16.35.2000; no change.
>>>> 
>>>> System firmware is dated September 2016. I'll see if I can get
>>>> something more recent installed.
>>> 
>>> We are trying to reproduce this issue internally.
>> 
>> More information. I captured the serial console during boot.
>> Here are the last messages:
>> 
>> [    9.837087] mlx5_core 0000:02:00.0: firmware version: 16.35.2000
>> [    9.843126] mlx5_core 0000:02:00.0: 126.016 Gb/s available PCIe
>> bandwidth (8.0 GT/s PCIe x16 link)
>> [   10.311515] mlx5_core 0000:02:00.0: Rate limit: 127 rates are supported,
>> range: 0Mbps to 97656Mbps
>> [   10.321948] mlx5_core 0000:02:00.0: E-Switch: Total vports 2, per vport:
>> max uc(128) max mc(2048)
>> [   10.344324] mlx5_core 0000:02:00.0: mlx5_pcie_event:301:(pid 88): PCIe
>> slot advertised sufficient power (27W).
>> [   10.354339] BUG: unable to handle page fault for address: ffffffff8ff0ade0
>> [   10.361206] #PF: supervisor read access in kernel mode
>> [   10.366335] #PF: error_code(0x0000) - not-present page
>> [   10.371467] PGD 81ec39067 P4D 81ec39067 PUD 81ec3a063 PMD
>> 114b07063 PTE 800ffff7e10f5062
>> [   10.379544] Oops: 0000 [#1] PREEMPT SMP PTI
>> [   10.383721] CPU: 0 PID: 117 Comm: kworker/0:6 Not tainted 6.3.0-13028-
>> g7222f123c983 #1
>> [   10.391625] Hardware name: Supermicro X10SRA-F/X10SRA-F, BIOS 2.0b
>> 06/12/2017
>> [   10.398750] Workqueue: events work_for_cpu_fn
>> [   10.403108] RIP: 0010:__bitmap_or+0x10/0x26
>> [   10.407286] Code: 85 c0 0f 95 c0 c3 cc cc cc cc 90 90 90 90 90 90 90 90 90
>> 90 90 90 90 90 90 90 89 c9 31 c0 48 83 c1 3f 48 c1 e9 06 39 c8 73 11 <4c>
>> 8b 04 c6 4c 0b 04 c2 4c 89 04 c7 48 ff c0 eb eb c3 cc cc cc cc
>> [   10.426024] RSP: 0000:ffffb45a0078f7b0 EFLAGS: 00010097
>> [   10.431240] RAX: 0000000000000000 RBX: ffffffff8ff0adc0 RCX:
>> 0000000000000004
>> [   10.438365] RDX: ffff9156801967d0 RSI: ffffffff8ff0ade0 RDI:
>> ffff9156801967b0
>> [   10.445489] RBP: ffffb45a0078f7e8 R08: 0000000000000030 R09:
>> 0000000000000000
>> [   10.452613] R10: 0000000000000000 R11: 0000000000000000 R12:
>> 00000000000000ec
>> [   10.459737] R13: ffffffff8ff0ade0 R14: 0000000000000001 R15:
>> 0000000000000020
>> [   10.466862] FS:  0000000000000000(0000) GS:ffff9165bfc00000(0000)
>> knlGS:0000000000000000
>> [   10.474936] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>> [   10.480674] CR2: ffffffff8ff0ade0 CR3: 00000001011ae003 CR4:
>> 00000000003706f0
>> [   10.487800] DR0: 0000000000000000 DR1: 0000000000000000 DR2:
>> 0000000000000000
>> [   10.494922] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7:
>> 0000000000000400
>> [   10.502046] Call Trace:
>> [   10.504493]  <TASK>
>> [   10.506589]  ? matrix_alloc_area.constprop.0+0x43/0x9a
>> [   10.511729]  ? prepare_namespace+0x84/0x174
>> [   10.515914]  irq_matrix_reserve_managed+0x56/0x10c
>> [   10.520699]  x86_vector_alloc_irqs+0x1d2/0x31e
>> [   10.525146]  irq_domain_alloc_irqs_hierarchy+0x39/0x3f
>> [   10.530284]  irq_domain_alloc_irqs_parent+0x1a/0x2a
>> [   10.535155]  intel_irq_remapping_alloc+0x59/0x5e9
>> [   10.539859]  ? kmem_cache_debug_flags+0x11/0x26
>> [   10.544383]  ? __radix_tree_lookup+0x39/0xb9
>> [   10.548649]  irq_domain_alloc_irqs_hierarchy+0x39/0x3f
>> [   10.553779]  irq_domain_alloc_irqs_parent+0x1a/0x2a
>> [   10.558650]  msi_domain_alloc+0x8c/0x120
>> [ rqs_hierarchy+0x39/0x3f
>> [   10.567697]  irq_domain_alloc_irqs_locked+0x11d/0x286
>> [   10.572741]  __irq_domain_alloc_irqs+0x72/0x93
>> [   10.577179]  __msi_domain_alloc_irqs+0x193/0x3f1
>> [   10.581789]  ? __xa_alloc+0xcf/0xe2
>> [   10.585273]  msi_domain_alloc_irq_at+0xa8/0xfe
>> [   10.589711]  pci_msix_alloc_irq_at+0x47/0x5c
>> [   10.593987]  mlx5_irq_alloc+0x99/0x319 [mlx5_core]
>> [   10.598881]  ? xa_load+0x5e/0x68
>> [   10.602112]  irq_pool_request_vector+0x60/0x7d [mlx5_core]
>> [   10.607668]  mlx5_irq_request+0x26/0x98 [mlx5_core]
>> [   10.612617]  mlx5_irqs_request_vectors+0x52/0x82 [mlx5_core]
>> [   10.618345]  mlx5_eq_table_create+0x613/0x8d3 [mlx5_core]
>> [   10.623806]  ? kmalloc_trace+0x46/0x57
>> [   10.627549]  mlx5_load+0xb1/0x33e [mlx5_core]
>> [   10.631971]  mlx5_init_one+0x497/0x514 [mlx5_core]
>> [   10.636824]  probe_one+0x2fa/0x3f6 [mlx5_core]
>> [   10.641330]  local_pci_probe+0x47/0x8b
>> [   10.645073]  work_for_cpu_fn+0x1a/0x25
>> [   10.648817]  process_one_work+0x1e0/0x2e0
>> [   10.652822]  process_scheduled_works+0x2c/0x37
>> [   10.657258]  worker_thread+0x1e2/0x25e
>> [   10.661003]  ? __pfx_worker_thread+0x10/0x10
>> [   10.665267]  kthread+0x10d/0x115
>> [   10.668501]  ? __pfx_kthread+0x10/0x10
>> [   10.672244]  ret_from_fork+0x2c/0x50
>> [   10.675824]  </TASK>
>> [   10.678007] Modules linked in: mlx5_core(+) ast drm_kms_helper
>> crct10dif_pclmul crc32_pclmul drm_shmem_helper crc32c_intel drm
>> ghash_clmulni_intel sha512_ssse3 igb dca i2c_algo_bit mlxfw pci_hyperv_intf
>> pkcs8_key_parser
>> [   10.697447] CR2: ffffffff8ff0ade0
>> [   10.700758] ---[ end trace 0000000000000000 ]---
>> [   10.707706] pstore: backend (erst) writing error (-28)
>> [   10.712838] RIP: 0010:__bitmap_or+0x10/0x26
>> [   10.717014] Code: 85 c0 0f 95 c0 c3 cc cc cc cc 90 90 90 90 90 90 90 90 90
>> 90 90 90 90 90 90 90 89 c9 31 c0 48 83 c1 3f 48 c1 e9 06 39 c8 73 11 <4c>
>> 8b 04 c6 4c 0b 04 c2 4c 89 04 c7 48 ff c0 eb eb c3 cc cc cc cc
>> [   10.735752] RSP: 0000:ffffb45a0078f7b0 EFLAGS: 00010097
>> [   10.740969] RAX: 0000000000000000 RBX: ffffffff8ff0adc0 RCX:
>> 0000000000000004
>> [   10.748093] RDX: ffff9156801967d0 RSI: ffffffff8ff0ade0 RDI:
>> ffff9156801967b0
>> [   10.755218] RBP: ffffb45a0078f7e8 R08: 0000000000000030 R09:
>> 0000000000000000
>> [   10.762341] R10: 0000000000000000 R11: 0000000000000000 R12:
>> 00000000000000ec
>> [   10.769467] R13: ffffffff8ff0ade0 R14: 0000000000000001 R15:
>> 0000000000000020
>> [   10.776590] FS:  0000000000000000(0000) GS:ffff9165bfc00000(0000)
>> knlGS:0000000000000000
>> [   10.784666] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>> [   10.790405] CR2: ffffffff8ff0ade0 CR3: 00000001011ae003 CR4:
>> 00000000003706f0
>> [   10.797529] DR0: 0000000000000000 DR1: 0000000000000000 DR2:
>> 0000000000000000
>> [   10.804651] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7:
>> 0000000000000400
>> [   10.811775] note: kworker/0:6[117] exited with irqs disabled
>> [   10.817444] note: kworker/0:6[117] exited with preempt_count 1
>> 
>> HTH
>> 
>> --
>> Chuck Lever
>> 
> 

--
Chuck Lever