我写这封信是为了就影响运行 AlmaLinux 8.9(内核 4.18.0-513.9.1.el8_9.x86_64)的 ThinkSystem SR630 V2 服务器的关键问题寻求您的专家建议。它在相同的操作系统和内核版本上托管两个虚拟机。
问题:
跨不同区域(MySQL、Java、QXL/VRAM)的多个进程正在经历异常终止(僵尸状态)和卡住状态(D 状态)。缺乏一致的模式使得查明根本原因具有挑战性,这表明系统不稳定,而不是个别应用程序问题。
采取的故障排除步骤:
- 已验证最新的 UEFI 固件,并将与 Lenovo 检查 RAID 适配器更新。
- BMC 和 XClarity Provision Manager 更新似乎不太可能有贡献,但也经过了检查。
- 考虑在所有服务器上升级可用的内核和软件包。
问题:
- 已知内核错误:内核 4.18.0-513.9.1.el8_9 中是否存在已知错误或 SR630 V2 内核模块的兼容性问题?
- 僵尸进程分析:我可以使用哪些工具/方法来确定堆栈跟踪之外的僵尸进程的原因(进程已经终止)?
- D 状态进程分析:如何克服阻止 strace 和 gdb 用于 D 状态进程的权限问题?有哪些替代调试方法可用?
- 内存转储:有没有办法提取 D 状态进程的内存转储?
- 硬件测试:有人因内存或磁盘问题遇到类似问题吗?您能推荐具体的硬件测试吗?
附加信息:
- 我目前正在通过 nmon 收集统计数据。
- 系统日志 (/var/log/messages) 中没有出现新错误。
我在下面提供了事件详细信息的摘要,但可以根据要求提供更多信息。
事件1
- 问题:
- Web 应用程序变得无响应,可能是由于内核工作线程 (kworker/6:24+ev) 卡在 D 状态。
- 细节:
- 受影响的线程负责各种后台任务,例如 I/O、计时器和进程管理。
- 尝试使用 gdb 或 strace 调试线程未成功。
- 对线程堆栈跟踪的分析表明它正在等待 QXL 图形设备栅栏。
- 系统日志确认 QXL 图形驱动程序在视频 RAM (VRAM) 中分配缓冲区对象 (BO) 失败。
- 关键点:
- 虽然该事件似乎与 QXL 图形驱动程序有关,但之前的事件并未涉及它,这表明存在更深层次的潜在问题。
# cat /proc/719494/stack
[<0>] qxl_fence_wait+0x109/0x160 [qxl]
[<0>] dma_fence_wait_timeout+0x4e/0x120
[<0>] dma_resv_wait_timeout+0x67/0xc0
[<0>] ttm_bo_wait_ctx+0x39/0x50 [ttm]
[<0>] qxl_bo_move+0x32/0xa0 [qxl]
[<0>] ttm_bo_handle_move_mem+0xb9/0x140 [ttm]
[<0>] ttm_mem_evict_first+0x2bb/0x500 [ttm]
[<0>] ttm_bo_mem_space+0x1d1/0x220 [ttm]
[<0>] ttm_bo_validate+0xa0/0x120 [ttm]
[<0>] ttm_bo_init_reserved+0x147/0x170 [ttm]
[<0>] qxl_bo_create+0x158/0x200 [qxl]
[<0>] qxl_alloc_bo_reserved+0x3e/0xb0 [qxl]
[<0>] qxl_image_alloc_objects+0x69/0x120 [qxl]
[<0>] qxl_draw_dirty_fb+0x178/0x450 [qxl]
[<0>] qxl_framebuffer_surface_dirty+0xf8/0x1d0 [qxl]
[<0>] drm_fbdev_fb_dirty+0x125/0x350 [drm_kms_helper]
[<0>] drm_fb_helper_damage_work+0x86/0x160 [drm_kms_helper]
[<0>] process_one_work+0x1d3/0x390
[<0>] worker_thread+0x1f9/0x390
[<0>] kthread+0x134/0x150
[<0>] ret_from_fork+0x1f/0x40
dmesg | grep qxl
[831639.144553] [drm:qxl_alloc_bo_reserved [qxl]] *ERROR* failed to allocate VRAM BO
[831654.501399] qxl 0000:00:01.0: object_init failed for (4096, 0x00000001)
[831654.502061] [drm:qxl_alloc_bo_reserved [qxl]] *ERROR* failed to allocate VRAM BO
[831669.861572] qxl 0000:00:01.0: object_init failed for (4096, 0x00000001)
[831669.862240] [drm:qxl_alloc_bo_reserved [qxl]] *ERROR* failed to allocate VRAM BO
[831685.221761] qxl 0000:00:01.0: object_init failed for (4096, 0x00000001)
[831685.222435] [drm:qxl_alloc_bo_reserved [qxl]] *ERROR* failed to allocate VRAM BO
[831700.581990] qxl 0000:00:01.0: object_init failed for (4096, 0x00000001)
[831700.582679] [drm:qxl_alloc_bo_reserved [qxl]] *ERROR* failed to allocate VRAM BO
[831715.942106] qxl 0000:00:01.0: object_init failed for (4096, 0x00000001)
[831715.942783] [drm:qxl_alloc_bo_reserved [qxl]] *ERROR* failed to allocate VRAM BO
[831731.302242] qxl 0000:00:01.0: object_init failed for (4096, 0x00000001)
[831731.302909] [drm:qxl_alloc_bo_reserved [qxl]] *ERROR* failed to allocate VRAM BO
[831746.662426] qxl 0000:00:01.0: object_init failed for (4096, 0x00000001)
perf record -g -p 719494
perf report
Samples: 55 of event 'cpu-clock:pppH', Event count (approx.): 13750000
Children Self Command Shared Object Symbol
+ 100.00% 0.00% kworker/6:24+ev [kernel.kallsyms] [k] ret_from_fork
+ 100.00% 0.00% kworker/6:24+ev [kernel.kallsyms] [k] kthread
+ 100.00% 0.00% kworker/6:24+ev [kernel.kallsyms] [k] worker_thread
+ 100.00% 0.00% kworker/6:24+ev [kernel.kallsyms] [k] process_one_work
+ 100.00% 0.00% kworker/6:24+ev [kernel.kallsyms] [k] drm_fb_helper_damage_work
+ 100.00% 0.00% kworker/6:24+ev [kernel.kallsyms] [k] drm_fbdev_fb_dirty
+ 52.73% 52.73% kworker/6:24+ev [kernel.kallsyms] [k] memcpy_erms
+ 47.27% 0.00% kworker/6:24+ev [kernel.kallsyms] [k] qxl_framebuffer_surface_dirty
+ 47.27% 0.00% kworker/6:24+ev [kernel.kallsyms] [k] qxl_draw_dirty_fb
+ 47.27% 0.00% kworker/6:24+ev [kernel.kallsyms] [k] qxl_alloc_bo_reserved
+ 45.45% 0.00% kworker/6:24+ev [kernel.kallsyms] [k] qxl_image_alloc_objects
+ 25.45% 1.82% kworker/6:24+ev [kernel.kallsyms] [k] vprintk_emit
+ 23.64% 21.82% kworker/6:24+ev [kernel.kallsyms] [k] console_unlock
+ 20.00% 0.00% kworker/6:24+ev [kernel.kallsyms] [k] qxl_bo_create
+ 20.00% 0.00% kworker/6:24+ev [kernel.kallsyms] [k] ttm_bo_init_reserved
+ 16.36% 1.82% kworker/6:24+ev [kernel.kallsyms] [k] __drm_err
+ 14.55% 0.00% kworker/6:24+ev [kernel.kallsyms] [k] printk
+ 12.73% 0.00% kworker/6:24+ev [kernel.kallsyms] [k] ttm_bo_validate
+ 12.73% 0.00% kworker/6:24+ev [kernel.kallsyms] [k] ttm_bo_mem_space
+ 12.73% 0.00% kworker/6:24+ev [kernel.kallsyms] [k] ttm_mem_evict_first
+ 12.73% 0.00% kworker/6:24+ev [kernel.kallsyms] [k] ttm_bo_handle_move_mem
+ 12.73% 0.00% kworker/6:24+ev [kernel.kallsyms] [k] qxl_bo_move
+ 12.73% 0.00% kworker/6:24+ev [kernel.kallsyms] [k] ttm_bo_wait_ctx
+ 12.73% 0.00% kworker/6:24+ev [kernel.kallsyms] [k] dma_resv_wait_timeout
+ 12.73% 0.00% kworker/6:24+ev [kernel.kallsyms] [k] dma_fence_wait_timeout
+ 12.73% 0.00% kworker/6:24+ev [kernel.kallsyms] [k] qxl_fence_wait
+ 10.91% 0.00% kworker/6:24+ev [kernel.kallsyms] [k] qxl_bo_create.cold.9
事件2
- 问题:
- Web 应用程序变得无响应,最初归因于 MySQL 中的表锁。
- 重新启动 MySQL 会导致僵尸进程。
- MySQL 备份也被困在一个零字节文件中,这表明存在资源访问问题。
- 技术细节(供参考):
- MySQL 进程(PID 1282)处于失效僵尸状态。
- 另一个服务进程(PID 604275)也是僵尸进程。
- 尝试使用 SIGCHLD 杀死僵尸进程未成功
- 要点:进一步的调查对表锁作为唯一原因提出了怀疑,指出了更广泛的资源访问问题。
事件3
- 问题:
- Web 应用程序无响应,Java 进程陷入 D 状态,没有可用的堆栈跟踪,表明存在潜在的内核级或进程损坏问题。
- 关键点:
- 内存访问问题:错误消息“Unable to access opcode bytes at RIP 0x7fdd7e72a432”表示内核无法读取指定内存地址处的指令字节,表明与内存相关的问题。
- 内核函数参与:日志中与进程调度和退出相关的内核函数的存在暗示了系统调用或进程终止期间的潜在问题。
dmesg 日志
[Thu Jan 18 08:49:42 2024] RIP: 0033:0x7fdd7e72a45c
[Thu Jan 18 08:49:42 2024] Code: Unable to access opcode bytes at RIP 0x7fdd7e72a432.
[Thu Jan 18 08:49:42 2024] RSP: 002b:00007fdd663113e0 EFLAGS: 00000246 ORIG_RAX: 00000000000000ca
[Thu Jan 18 08:49:42 2024] RAX: fffffffffffffe00 RBX: 00007fdd30000b60 RCX: 00007fdd7e72a45c
[Thu Jan 18 08:49:42 2024] RDX: 0000000000000000 RSI: 0000000000000080 RDI: 00007fdd30000b8c
[Thu Jan 18 08:49:42 2024] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
[Thu Jan 18 08:49:42 2024] R10: 0000000000000000 R11: 0000000000000246 R12: 00007fdd78ded828
[Thu Jan 18 08:49:42 2024] R13: 0000000000000003 R14: 0000000000000000 R15: 00007fdd30000b8c
[Thu Jan 18 08:49:42 2024] task:java state:D stack:0 pid:2527 ppid:1 flags:0x80004084
[Thu Jan 18 08:49:42 2024] Call Trace:
[Thu Jan 18 08:49:42 2024] __schedule+0x2d1/0x870
[Thu Jan 18 08:49:42 2024] schedule+0x55/0xf0
[Thu Jan 18 08:49:42 2024] do_exit+0x250/0xb10
[Thu Jan 18 08:49:42 2024] do_group_exit+0x3a/0xa0
[Thu Jan 18 08:49:42 2024] get_signal+0x141/0x880
[Thu Jan 18 08:49:42 2024] ? do_futex+0x143/0x4e0
[Thu Jan 18 08:49:42 2024] do_signal+0x36/0x690
[Thu Jan 18 08:49:42 2024] ? __x64_sys_futex+0x14e/0x200
[Thu Jan 18 08:49:42 2024] ? syscall_trace_enter+0x1ff/0x2d0
[Thu Jan 18 08:49:42 2024] ? __x64_sys_futex+0x14e/0x200
[Thu Jan 18 08:49:42 2024] exit_to_usermode_loop+0x89/0x100
[Thu Jan 18 08:49:42 2024] do_syscall_64+0x19c/0x1b0
[Thu Jan 18 08:49:42 2024] entry_SYSCALL_64_after_hwframe+0x61/0xc6
[Thu Jan 18 08:49:42 2024] RIP: 0033:0x7fdd7e72a45c
[Thu Jan 18 08:49:42 2024] Code: Unable to access opcode bytes at RIP 0x7fdd7e72a432.
事件4
- 问题:
- Web 应用程序变得无响应,并且发现两个进程处于失效(僵尸)状态,这表明异常终止,而其父进程没有进行适当的清理。
- 技术细节(供参考):
- 这两个进程均标识为“[service_process]”(进程 ID 261224 和 950658),由于其父进程未收集其退出状态而陷入失效状态。
- 这表明进程管理或父进程和子进程之间的通信存在潜在问题。