1.服务器环境以及配置
| 物理机/虚拟机/云/容器 | 物理机 |
| 外网/私有网络/无网络 | 私有网络 |
| 处理器： | PHYTIUM FT2000PLUS 2200 MHz |
| 内存： | 128 GiB |
| 整机类型/架构： | HIKVISION DS-V |
| BIOS版本： | HK 601FBE02HK |
| 网卡： | mlx5_core v5.0-0 / fw 14.29.2002 (MT_2420110004) |
| 具体操作系统版本 | (7860) Kylin-Server-V10-SP3-General-Release-2303-arm64 |
| 内核版本 | 4.19.90-52.22.v2207.ky10.aarch64 |
2.问题现象描述
服务器开机之后反复重启，用户现场已经收集了日志，需要分析日志。
3.问题分析
3.1 查看系统环境
| cat ./sos_commands/networking/ethtool_-i_enp6s0f1
driver: mlx5_core
version: 5.0-0
firmware-version: 14.29.2002 (MT_2420110004)
expansion-rom-version:
bus-info: 0000:06:00.1
supports-statistics: yes
supports-test: yes
supports-eeprom-access: no
supports-register-dump: no
supports-priv-flags: yes |
3.2 vmcore-dmesg分析
分析127.0.0.1-2023-09-19-07:58:37的vmcore-dmesg
| [1865270.773139] mlx5_core 0000:06:00.0: cmd_work_handler:906:(pid 1026764): failed to allocate command entry
[1865271.773142] mlx5_core 0000:06:00.0: cmd_work_handler:906:(pid 1026764): failed to allocate command entry
[1865272.773093] mlx5_core 0000:06:00.0: cmd_work_handler:906:(pid 1026764): failed to allocate command entry
[1865273.773195] mlx5_core 0000:06:00.0: cmd_work_handler:906:(pid 1026764): failed to allocate command entry
[1865274.773168] mlx5_core 0000:06:00.0: cmd_work_handler:906:(pid 1026764): failed to allocate command entry
[1865275.773147] mlx5_core 0000:06:00.0: cmd_work_handler:906:(pid 1026764): failed to allocate command entry
[1865276.773151] mlx5_core 0000:06:00.0: cmd_work_handler:906:(pid 1026764): failed to allocate command entry
[1865277.773127] mlx5_core 0000:06:00.0: cmd_work_handler:906:(pid 1026764): failed to allocate command entry
[1865278.773147] mlx5_core 0000:06:00.0: cmd_work_handler:906:(pid 1026764): failed to allocate command entry
[1865279.773174] mlx5_core 0000:06:00.0: cmd_work_handler:906:(pid 1026764): failed to allocate command entry
[1865280.773149] mlx5_core 0000:06:00.0: cmd_work_handler:906:(pid 1026764): failed to allocate command entry
[1865281.773120] mlx5_core 0000:06:00.0: cmd_work_handler:906:(pid 1026764): failed to allocate command entry
[1865282.773112] mlx5_core 0000:06:00.0: cmd_work_handler:906:(pid 1026764): failed to allocate command entry
[1865283.773139] mlx5_core 0000:06:00.0: cmd_work_handler:906:(pid 1026764): failed to allocate command entry
[1865284.773150] mlx5_core 0000:06:00.0: cmd_work_handler:906:(pid 1026764): failed to allocate command entry
[1865285.773097] mlx5_core 0000:06:00.0: cmd_work_handler:906:(pid 1026764): failed to allocate command entry
[1865286.773067] mlx5_core 0000:06:00.0: cmd_work_handler:906:(pid 1026764): failed to allocate command entry
[1865287.773095] mlx5_core 0000:06:00.0: cmd_work_handler:906:(pid 1026764): failed to allocate command entry |
分析127.0.0.1-2023-10-29-14:17:27的vmcore-dmesg
| [3478639.193325] mlx5_core 0000:06:00.0: wait_func:1034:(pid 4068733): MODIFY_CQ(0x403) timeout. Will cause a leak of a command resource
[3478639.193333] mlx5_core 0000:06:00.0: wait_func:1034:(pid 4166044): MODIFY_CQ(0x403) timeout. Will cause a leak of a command resource
[3478639.193334] mlx5_core 0000:06:00.0: wait_func:1034:(pid 2812292): MODIFY_CQ(0x403) timeout. Will cause a leak of a command resource
[3478639.193342] mlx5_core 0000:06:00.0: wait_func:1034:(pid 3401828): MODIFY_CQ(0x403) timeout. Will cause a leak of a command resource
[3478639.193344] mlx5_core 0000:06:00.0: wait_func:1034:(pid 3822606): MODIFY_CQ(0x403) timeout. Will cause a leak of a command resource
[3478639.193354] mlx5_core 0000:06:00.0: wait_func:1034:(pid 188898): MODIFY_CQ(0x403) timeout. Will cause a leak of a command resource
[3478639.193363] mlx5_core 0000:06:00.0: wait_func:1034:(pid 3288787): MODIFY_CQ(0x403) timeout. Will cause a leak of a command resource
[3478639.194469] mlx5_core 0000:06:00.0: wait_func:1038:(pid 192618): MODIFY_CQ(0x403) canceled on out of queue timeout.
[3478639.194487] mlx5_core 0000:06:00.0: wait_func:1038:(pid 192616): MODIFY_CQ(0x403) canceled on out of queue timeout.
[3478639.194495] mlx5_core 0000:06:00.0: wait_func:1038:(pid 192615): MODIFY_CQ(0x403) canceled on out of queue timeout.
[3478639.194505] mlx5_core 0000:06:00.0: wait_func:1038:(pid 192613): MODIFY_CQ(0x403) canceled on out of queue timeout.
[3478639.194515] mlx5_core 0000:06:00.0: wait_func:1038:(pid 192610): MODIFY_CQ(0x403) canceled on out of queue timeout.
[3478640.183135] mlx5_core 0000:06:00.0: cmd_work_handler:906:(pid 1268656): failed to allocate command entry |
从日志可见，不断打印failed to allocate command entry，可见该打印来自于drivers/net/ethernet/mellanox/mlx5/core/cmd.c文件的cmd_work_handler函数。
分析异常打印时的函数调用流程如下所示：
| -> mlx5_cmd_exec
-> cmd_exec
-> mlx5_cmd_invoke
-> cmd_work_handler
-> alloc_ent
-> find_first_bit |
| static int alloc_ent(struct mlx5_cmd *cmd)
{
unsigned long flags;
int ret;
spin_lock_irqsave(&cmd->alloc_lock, flags);
ret = find_first_bit(&cmd->bitmask, cmd->max_reg_cmds);
if (ret < cmd->max_reg_cmds)
clear_bit(ret, &cmd->bitmask);
spin_unlock_irqrestore(&cmd->alloc_lock, flags);
return ret < cmd->max_reg_cmds ? ret : -ENOMEM;
} |
| /*
* Find the first set bit in a memory region.
*/
unsigned long find_first_bit(const unsigned long *addr, unsigned long size)
{
unsigned long idx;
for (idx = 0; idx * BITS_PER_LONG < size; idx++) {
if (addr[idx])
return min(idx * BITS_PER_LONG + __ffs(addr[idx]), size);
}
return size;
} |
| static void free_ent(struct mlx5_cmd *cmd, int idx)
{
unsigned long flags;
spin_lock_irqsave(&cmd->alloc_lock, flags);
set_bit(idx, &cmd->bitmask);
spin_unlock_irqrestore(&cmd->alloc_lock, flags);
} |
从上述代码可见，通过cmd->bitmask进行标记是否有还可以申请，cmd->bitmask的初始化如下，假设获取出来的cmd->log_sz=0x80，则cmd->max_reg_cmds=0xFF，cmd->bitmask=0x1FD。应该是cmd->bitmask初始化的时候有多少bit位为1，就可以alloc_ent多少次。
| int mlx5_cmd_init(struct mlx5_core_dev *dev)
{
int size = sizeof(struct mlx5_cmd_prot_block);
int align = roundup_pow_of_two(size);
struct mlx5_cmd *cmd = &dev->cmd;
u32 cmd_h, cmd_l;
u16 cmd_if_rev;
int err;
int i;
memset(cmd, 0, sizeof(*cmd));
cmd_if_rev = cmdif_rev(dev);
if (cmd_if_rev != CMD_IF_REV) {
dev_err(&dev->pdev->dev,
"Driver cmdif rev(%d) differs from firmware's(%d)\n",
CMD_IF_REV, cmd_if_rev);
return -EINVAL;
}
cmd->pool = dma_pool_create("mlx5_cmd", &dev->pdev->dev, size, align, 0);
if (!cmd->pool)
return -ENOMEM;
err = alloc_cmd_page(dev, cmd);
if (err)
goto err_free_pool;
cmd_l = ioread32be(&dev->iseg->cmdq_addr_l_sz) & 0xff;
cmd->log_sz = cmd_l >> 4 & 0xf;
cmd->log_stride = cmd_l & 0xf;
if (1 << cmd->log_sz > MLX5_MAX_COMMANDS) {
dev_err(&dev->pdev->dev, "firmware reports too many outstanding commands %d\n",
1 << cmd->log_sz);
err = -EINVAL;
goto err_free_page;
}
if (cmd->log_sz + cmd->log_stride > MLX5_ADAPTER_PAGE_SHIFT) {
dev_err(&dev->pdev->dev, "command queue size overflow\n");
err = -EINVAL;
goto err_free_page;
}
cmd->checksum_disabled = 1;
cmd->max_reg_cmds = (1 << cmd->log_sz) - 1;
cmd->bitmask = (1UL << cmd->max_reg_cmds) - 1; |
执行cmd_exec的时候，会去调用alloc_ent，找到cmd->bitmask中最近为1的位，并调用clear_bit清除为0；cmd传到固件执行完以后，要去释放command entry，调用free_ent，将对应位重新标志为1。所以出现问题，有两种可能性：
1、当cmd在传到固件，一直未能执行完，而一直有cmd_exec执行，被积压，导致cmd->bitmask的位使用完，cmd->bitmask所有位被置为了0。alloc_ent无法申请到cmd->bitmask中的标识位。
2、cmd_exec执行完后，由于某种原因，没能调用free_ent，导致cmd->bitmask的所有位被使用完。
3.3 vmcore分析
日志中提示Internal error: SP/PC alignment exception，PC寄存器出现了未对齐的打印。
| [3478640.184122] Internal error: SP/PC alignment exception: 8a000000 [#1] SMP
[3478640.184720] Modules linked in: fuse tun bridge stp llc fccore(POE) fchook(OE) bonding ip_set_hash_ip ip_set nfnetlink rfkill ipmi_ssif vfat fat rpcrdma sunrpc rdma_ucm ib_srpt ib_isert iscsi_target_mod target_core_mod ib_iser rdma_cm ib_umad iw_cm ib_ipoib libiscsi scsi_transport_iscsi ib_cm mlx5_ib joydev ib_uverbs ib_core ipmi_si ipmi_devintf ipmi_msghandler sch_fq_codel mlx5_core megaraid_sas igb ast mlxfw dm_mirror dm_region_hash dm_log [last unloaded: ip_tables]
[3478640.188127] Process kworker/u128:0 (pid: 1268656, stack limit = 0x0000000074e0af67)
[3478640.188820] CPU: 15 PID: 1268656 Comm: kworker/u128:0 Kdump: loaded Tainted: P OE 4.19.90-52.22.v2207.ky10.aarch64 #1
[3478640.189835] Source Version: 52f32c50138f4eec54ab90ce9775f0d75e1d6968
[3478640.190505] Hardware name: HIKVISION DS-V/N/A, BIOS 601FBE02HK 2020/04/20
[3478640.191173] Workqueue: mlx5_cmd_0000:06:00.0 cmd_work_handler [mlx5_core]
[3478640.191790] pstate: 40000005 (nZcv daif -PAN -UAO)
[3478640.192235] pc : 0x42
[3478640.192539] lr : cmd_work_handler+0x434/0x578 [mlx5_core]
[3478640.193029] sp : ffffda857e113d20
[3478640.193348] x29: ffffda857e113d20 x28: ffffda8553b4c400
[3478640.193838] x27: 0000000000000000 x26: ffff5607dffd1000
[3478640.194341] x25: 0000000000000000 x24: ffffda8511e001c8
[3478640.194830] x23: ffffda8511e000e0 x22: ffffda8511e00160
[3478640.195345] x21: ffffda8553b4c548 x20: 0000000000000001
[3478640.195840] x19: ffffda8511e001d8 x18: 0000000000000001
[3478640.196332] x17: 0000fffc58585308 x16: ffff5607def87070
[3478640.196812] x15: ffffffffffffffff x14: 742064656c696166
[3478640.197283] x13: 203a293635363836 x12: 323120646970283a
[3478640.197769] x11: 3630393a72656c64 x10: ffff5607dffd5b70
[3478640.198278] x9 : 5f646d63203a302e x8 : ffff5607deee95d8
[3478640.198769] x7 : ffff5607e07230f8 x6 : 000000000000056b
[3478640.199307] x5 : 0000000000000000 x4 : 0000000000000000
[3478640.199801] x3 : 0000000000000000 x2 : 0000000000000042
[3478640.200358] x1 : 0000000000000000 x0 : 00000000fffffff5
[3478640.200835] Call trace:
[3478640.201084] 0x42
[3478640.201307] process_one_work+0x1fc/0x4a8
[3478640.201705] worker_thread+0x50/0x4d8
[3478640.202068] kthread+0x134/0x138
[3478640.202386] ret_from_fork+0x10/0x18
[3478640.202781] Code: bad PC value
[3478640.203165] SMP: stopping secondary CPUs
[3478640.205196] Starting crashdump kernel... |
crash /usr/lib/debug/lib/modules/4.19.90-52.22.v2207.ky10.aarch64/vmlinux vmcore分析vmcore
| LOAD AVERAGE: 102.08, 41.38, 22.56
TASKS: 7790
NODENAME: localhost.localdomain
RELEASE: 4.19.90-52.22.v2207.ky10.aarch64
VERSION: #1 SMP Tue Mar 14 11:52:45 CST 2023
MACHINE: aarch64 (unknown Mhz)
MEMORY: 126.4 GB
PANIC: ""
PID: 1268656
COMMAND: "kworker/u128:0"
TASK: ffffdc8435076a00 [THREAD_INFO: ffffdc8435076a00]
CPU: 15
STATE: TASK_RUNNING (PANIC)
crash> bt
PID: 1268656 TASK: ffffdc8435076a00 CPU: 15 COMMAND: "kworker/u128:0"
#0 [ffffda857e1138c0] machine_kexec at ffff5607de7b2e8c
#1 [ffffda857e113920] __crash_kexec at ffff5607de8ca148
#2 [ffffda857e113a90] crash_kexec at ffff5607de8ca258
#3 [ffffda857e113ac0] die at ffff5607de79f65c
#4 [ffffda857e113b00] arm64_notify_die at ffff5607de79f964
#5 [ffffda857e113b30] do_sp_pc_abort at ffff5607de7914f8
#6 [ffffda857e113d10] el1_pc at ffff5607de792f94
#7 [ffffda857e113d20] (null) at 3e
#8 [ffffda857e113db0] process_one_work at ffff5607de8226f8
#9 [ffffda857e113e00] worker_thread at ffff5607de8229f4
#10 [ffffda857e113e70] kthread at ffff5607de82a1e0 |
根据vmcore-dmesg中，pc : 0x42 lr : cmd_work_handler+0x434/0x578 [mlx5_core]，查看lr寄存器执行的位置可见执行 blr x2的时候触发了空指针。从而可知问题发生在drivers/net/ethernet/mellanox/mlx5/core/cmd.c: 908
| crash> mod -s mlx5_core
crash> dis -rl cmd_work_handler+0x434 |tail -n 20
0xffff56077bcf6808 <cmd_work_handler+1016>: mrs x1, sp_el0
/usr/src/debug/kernel-4.19.90/linux-4.19.90-52.22.v2207.ky10.aarch64/drivers/net/ethernet/mellanox/mlx5/core/cmd.c: 906
0xffff56077bcf680c <cmd_work_handler+1020>: ldr x0, [x22,#-128]
0xffff56077bcf6810 <cmd_work_handler+1024>: adrp x2, 0xffff56077bd70000
0xffff56077bcf6814 <cmd_work_handler+1028>: ldr w4, [x1,#1712]
0xffff56077bcf6818 <cmd_work_handler+1032>: add x2, x2, #0xe50
0xffff56077bcf681c <cmd_work_handler+1036>: add x2, x2, #0x7c0
0xffff56077bcf6820 <cmd_work_handler+1040>: mov w3, #0x38a // #906
0xffff56077bcf6824 <cmd_work_handler+1044>: adrp x1, 0xffff56077bd7e000
0xffff56077bcf6828 <cmd_work_handler+1048>: add x1, x1, #0xcb0
0xffff56077bcf682c <cmd_work_handler+1052>: bl 0xffff56077bd65e60 <plt:_dev_err>
/usr/src/debug/kernel-4.19.90/linux-4.19.90-52.22.v2207.ky10.aarch64/drivers/net/ethernet/mellanox/mlx5/core/cmd.c: 907
0xffff56077bcf6830 <cmd_work_handler+1056>: ldr x2, [x28,#40]
0xffff56077bcf6834 <cmd_work_handler+1060>: cbz x2, 0xffff56077bcf6970 <cmd_work_handler+1376>
/usr/src/debug/kernel-4.19.90/linux-4.19.90-52.22.v2207.ky10.aarch64/drivers/net/ethernet/mellanox/mlx5/core/cmd.c: 908
0xffff56077bcf6838 <cmd_work_handler+1064>: ldr x1, [x21,#-88]
0xffff56077bcf683c <cmd_work_handler+1068>: mov w0, #0xfffffff5 // #-11
0xffff56077bcf6840 <cmd_work_handler+1072>: blr x2
/usr/src/debug/kernel-4.19.90/linux-4.19.90-52.22.v2207.ky10.aarch64/drivers/net/ethernet/mellanox/mlx5/core/cmd.c: 909
0xffff56077bcf6844 <cmd_work_handler+1076>: ldr x1, [x28,#16]
crash> |
struct mlx5_cmd_work_ent是一个自定义的结构体，它包含了额外的字段和数据，用于处理MLX5驱动程序中的命令工作项。可见callback是一个有问题的值，该值出现问题应是网卡固件导致。
| crash> struct mlx5_cmd_work_ent 0xffffda8553b4c400
struct mlx5_cmd_work_ent {
state = 1,
in = 0x383ef300000001,
out = 0x1,
uout = 0x0,
uout_size = 0,
callback = 0x42,
cb_timeout_work = {
work = {
data = {
counter = 0
}, |
4.问题分析结果
通过上述分析，同时查看相关资料https://bugzilla.redhat.com/show_bug.cgi?id=1767678和https://forums.developer.nvidia.com/t/occure-mlx5-core-failed-to-allocate-command-entry-with-mcx4421a-acan-in-ubtuntu-18-04-1/206943，该问题更可能是网卡固件原因。可以尝试升级网卡固件，进行观察。
经查找有新的网卡固件版本为v14.32.1010。
Firmware for ConnectX®-4 Lx EN
具体的OPN号需要联系整机或网卡厂商获取，再找到对应的OPN网卡固件驱动由硬件厂商进行升级
5.参考资料
1767678 – [mlx5_core] OVS offload: mlx5_core 0000:04:00.0: cmd_work_handler:855:(pid 87647): failed to allocate command entry
RHEL8: Mellanox driver [mlx5_core] causing kernel stack overflow. - Red Hat Customer Portal
Occure mlx5_core :" failed to allocate command entry" with MCX4421A-ACAN in Ubtuntu 18.04.1 - Software And Drivers - NVIDIA Developer Forums
https://www.mellanox.com/downloads/MFT/mft-4.21.0-99-x86_64-rpm.tgz
https://www.mellanox.com/downloads/firmware/fw-ConnectX4Lx-rel-14_32_1010-MCX4121A-ACA_Ax-UEFI-14.25.17-FlexBoot-3.6.502.bin.zip
Bug Fixes History - NVIDIA Docs
