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