消息调度框架日志刷屏

交流互助区
1

// 此模板仅供参考，如果不适用可以修改

问题描述

消息调度框架一直在刷屏打印：

2026-10-08 16:35:05.774237 redfish WARNING: init.lua(1131): Requestor Skynet message queue scheduling delay is 512 ms (threshold: 500 ms), service_name=:1.134, path=/bmc/kepler/MdbService, interface=bmc.kepler.Mdb, method_name=GetPath [repeated 3 times in 131s from 2026-10-08 16:25:25.717736 to 2026-10-08 16:27:36.654587][flush]
2026-10-08 16:35:05.775514 redfish WARNING: init.lua(1131): Requestor Skynet message queue scheduling delay is 510 ms (threshold: 500 ms), service_name=:1.134, path=/bmc/kepler/MdbService, interface=bmc.kepler.Mdb, method_name=GetPath [repeated 2 times in 200s from 2026-10-08 16:29:15.734948 to 2026-10-08 16:32:35.740495][flush]
2026-10-08 16:35:11.256387 general_hardware ERROR: retimer_agent_PT5161L_utils.lua(55): check heart beat failed. name=Retimer_PT5161L_2_010132
2026-10-08 16:35:27.064654 bmc_network NOTICE: dhcp_process.lua(1256): the field composed by dhcpv6 vendor class is empty string
2026-10-08 16:35:27.066035 bmc_network NOTICE: dhcp_process.lua(1020): eth2: no available prefix info, send_rs_and_parse_ra now
2026-10-08 16:35:30.767188 redfish WARNING: init.lua(1131): Requestor Skynet message queue scheduling delay is 523 ms (threshold: 500 ms), service_name=:1.134, path=/bmc/kepler/MdbService, interface=bmc.kepler.Mdb, method_name=GetPath
2026-10-08 16:35:50.783084 redfish WARNING: init.lua(1131): Requestor Skynet message queue scheduling delay is 546 ms (threshold: 500 ms), service_name=:1.134, path=/bmc/kepler/MdbService, interface=bmc.kepler.Mdb, method_name=GetPath
2026-10-08 16:35:55.756989 redfish WARNING: init.lua(1131): Requestor Skynet message queue scheduling delay is 555 ms (threshold: 500 ms), service_name=:1.134, path=/bmc/kepler/MdbService, interface=bmc.kepler.Mdb, method_name=GetPath
2026-10-08 16:35:57.353960 general_hardware ERROR: retimer_agent_PT5161L_utils.lua(55): check heart beat failed. name=Retimer_PT5161L_2_010132
2026-10-08 16:35:57.435289 bmc_network NOTICE: dhcp_process.lua(1256): the field composed by dhcpv6 vendor class is empty string
2026-10-08 16:35:57.435790 bmc_network NOTICE: dhcp_process.lua(1020): eth2: no available prefix info, send_rs_and_parse_ra now
2026-10-08 16:36:15.739391 redfish WARNING: init.lua(1131): Requestor Skynet message queue scheduling delay is 505 ms (threshold: 500 ms), service_name=:1.134, path=/bmc/kepler/MdbService, interface=bmc.kepler.Mdb, method_name=GetPath
2026-10-08 16:36:27.784716 bmc_network NOTICE: dhcp_process.lua(1256): the field composed by dhcpv6 vendor class is empty string
2026-10-08 16:36:27.786186 bmc_network NOTICE: dhcp_process.lua(1020): eth2: no available prefix info, send_rs_and_parse_ra now
2026-10-08 16:36:43.374130 general_hardware ERROR: retimer_agent_PT5161L_utils.lua(55): check heart beat failed. name=Retimer_PT5161L_2_010132
2026-10-08 16:36:45.809477 redfish WARNING: init.lua(1131): Requestor Skynet message queue scheduling delay is 508 ms (threshold: 500 ms), service_name=:1.134, path=/bmc/kepler/MdbService, interface=bmc.kepler.Mdb, method_name=GetPath
2026-10-08 16:36:58.151428 bmc_network NOTICE: dhcp_process.lua(1256): the field composed by dhcpv6 vendor class is empty string
2026-10-08 16:36:58.151988 bmc_network NOTICE: dhcp_process.lua(1020): eth2: no available prefix info, send_rs_and_parse_ra now
2026-10-08 16:37:10.699542 redfish WARNING: init.lua(1131): Requestor Skynet message queue scheduling delay is 514 ms (threshold: 500 ms), service_name=:1.134, path=/bmc/kepler/MdbService, interface=bmc.kepler.Mdb, method_name=GetPath
2026-10-08 16:37:20.731466 redfish WARNING: init.lua(1131): Requestor Skynet message queue scheduling delay is 504 ms (threshold: 500 ms), service_name=:1.134, path=/bmc/kepler/MdbService, interface=bmc.kepler.Mdb, method_name=GetPath
2026-10-08 16:37:28.465848 bmc_network NOTICE: dhcp_process.lua(1256): the field composed by dhcpv6 vendor class is empty string
2026-10-08 16:37:28.466482 bmc_network NOTICE: dhcp_process.lua(1020): eth2: no available prefix info, send_rs_and_parse_ra now
2026-10-08 16:37:29.408469 general_hardware ERROR: retimer_agent_PT5161L_utils.lua(55): check heart beat failed. name=Retimer_PT5161L_2_010132
2026-10-08 16:37:58.792913 bmc_network NOTICE: dhcp_process.lua(1256): the field composed by dhcpv6 vendor class is empty string
2026-10-08 16:37:58.793386 bmc_network NOTICE: dhcp_process.lua(1020): eth2: no available prefix info, send_rs_and_parse_ra now
2026-10-08 16:38:15.713443 general_hardware ERROR: retimer_agent_PT5161L_utils.lua(55): check heart beat failed. name=Retimer_PT5161L_2_010132
2026-10-08 16:38:29.098057 bmc_network NOTICE: dhcp_process.lua(1256): the field composed by dhcpv6 vendor class is empty string
2026-10-08 16:38:29.098741 bmc_network NOTICE: dhcp_process.lua(1020): eth2: no available prefix info, send_rs_and_parse_ra now
2026-10-08 16:38:46.854785 redfish WARNING: init.lua(1131): Requestor Skynet message queue scheduling delay is 545 ms (threshold: 500 ms), service_name=:1.134, path=/bmc/kepler/MdbService, interface=bmc.kepler.Mdb, method_name=GetPath [repeated 11 times in 421s from 2026-10-08 16:31:45.796474 to 2026-10-08 16:38:46.854785]

环境信息

  • 软件版本：OpenUBMC260630

诉求

  1. 有没有什么办法确认超时原因？例如为什么GetPath方法会超时
  2. 日志能否关闭？
2

答案内容由AI生成，仅供参考：
（未检测到明确的“总结”、“解决方案”或“结论”章节，返回空内容。）

点击此处查看详细分析解答

根据您提供的信息，我对“消息调度框架日志刷屏”问题进行了分析。以下是针对您诉求的回答：

一、关于确认超时原因（GetPath方法超时）

根据知识库中的信息，您日志中出现的 “Requestor Skynet message queue scheduling delay” 警告，其根本原因可以从以下几个方面进行排查：

  1. 系统整体负载过高：知识库中明确指出，“Skynet message queue scheduling delay” 是一个性能指标，用于指示消息处理中的延迟。日志中显示延迟超过500ms阈值，且您在环境信息中看到的 framework 进程CPU占用率很高（在日志片段中显示 framework 进程CPU使用率接近60%），这强烈表明系统可能处于过载状态。当系统负载过高时，消息队列中的消息无法被及时调度处理，从而导致请求方（Requestor）等待时间过长。

  2. 消息队列积压：知识库中提到了“message queue length”这一概念，它衡量系统中待处理消息的数量，是潜在系统瓶颈的指标。如果消息队列长度过高（例如达到1222），则表明存在过载。虽然您的日志中没有直接给出队列长度，但高延迟现象通常与队列积压有关。

  3. 特定服务处理延迟：日志中明确提到了服务 bmc.kepler.maca 也出现了类似的调度延迟。此外，文档资料也指出，诸如遍历性能问题（如传感器/Fan数量较多）可能导致单个接口超时，即使单个接口超时不超过100ms，但累计起来也会超过阈值并触发日志。

  4. 日志中其他错误佐证：您的日志中同时出现了 general_hardware ERROR: retimer_agent... check heart beat failed 错误。这表明硬件组件（如Retimer）的心跳检查失败，这可能是由于系统繁忙导致未能及时响应，也可能是硬件本身存在问题，但也可能是系统整体负载过高的一个表现。

排查建议：

  • 观察系统资源：在问题发生时，通过 top 命令确认CPU、内存占用情况，特别是 framework、skynet 等关键进程的资源占用，以判断是否存在过载。
  • 确认传感器/Fan数量：根据知识库中“看起来就是单纯的遍历性能问题”的排查思路，确认现场环境的传感器和风扇数量是否较多，导致遍历查询耗时过长。
  • 分析慢接口日志：知识库建议查看详细的后半截日志，确定具体是哪个接口、哪个环节耗时较长。

二、关于关闭日志

知识库中提供了关闭日志的方法，但这并非直接针对“消息调度延迟”日志，而是通用的日志限流功能。如果您希望减少此类刷屏日志的干扰，可以考虑以下方法：

方法1：使用调试命令关闭日志限流

  • 可以参考 mdbctl dloglimit 命令的相关介绍来关闭日志限流功能。但请注意，关闭限流可能反而会导致日志量更大。

方法2：通过环境变量关闭日志限流

  • 在 /dev/shm/dbus/.dbus 文件中添加一行 MCC_DEBUG=1。
  • 然后使用 systemctl restart framework 命令重启框架进程。

重要提示：

  • 上述方法关闭的是日志限流功能，并不会消除产生该延迟的根本原因。从根本上解决问题，需要结合第一部分的分析来定位并优化系统性能瓶颈。
  • 知识库中也提到了通过调整日志级别来避免日志刷屏的案例。对于 retimer_agent 心跳检查失败这类循环打印的错误日志，若该日志仅用于协助定位，可以考虑将日志级别从 error 降级为 debug，以减少刷屏影响。

综上所述，建议您首先通过资源监控和日志分析来定位导致 GetPath 方法超时的系统瓶颈，这通常是解决刷屏问题的关键。关闭日志只是治标不治本的临时措施。

3
  1. 没法直接确认超时原因，可以参考机器人答复。一般是看日志有没有异常报错以及CPU等资源占用情况。
  2. 这个日志是用于增强可定位性的，没法直接关闭。日志里超时打印已有日志限流措施。设置系统环境变量 RPC_DELAY_LOG_THRESHOLD 超过500（默认500ms超时）可以临时减少该打印。