~johan's blog
返回专辑
C++
·Johan·4 分钟阅读

日志级别与结构化字段：能搜才有用

结构化日志、级别策略与热路径里别 LOG_EVERY_N 误伤实时性。

#C++#工程#可观测性
日志级别与结构化字段：能搜才有用

1. 复盘三小时 grep，不如一个字段聚合

field 上 lidar timeout 一晚出现几百次，oncall 只能 regex 刮 timeout 和中文句子——无法按 sensor_id、error_code 计数，也无法和 metrics 对齐。根因是日志当散文写：RCLCPP_INFO("scan ok") 对人可读，对 Loki/ELK 不可算。

结构化日志的最小契约：固定 field 名 + 稳定 error_code 枚举 + 与文档/oncall playbook 同编号。否则每次事故都是人肉 grep 三小时，而不是五分钟聚合。

2. 级别纪律

ERROR：需人介入或触发 safe stop；不 throttle。WARN：降级仍运行，必须 throttle 防刷屏。DEBUG：默认关；dev 临时开完降回 INFO。级别不是「严重程度感觉」，是 运维动作触发器——ERROR 响 pager，WARN 进周报，DEBUG 不进生产 disk。

cpp
RCLCPP_ERROR_THROTTLE(logger, *clock, 5000,
  "event=lidar_timeout error_code=SLAM_001 sensor_id=%s seq=%u",
  sensor_id.c_str(), seq);

热路径禁止手写 if (debug) 仍构造大 string——用 RCLCPP_DEBUG 宏，级别关闭时不应求值昂贵参数。rclcpp 宏已处理，别自己 reinvent。

3. 结构化字段约定

key=value 或 JSON 行均可，关键是跨节点统一，别每节点自创 msg 格式：

cpp
RCLCPP_INFO(logger,
  "event=scan_drop reason=queue_full depth=%zu latency_ms=%.1f frame_id=%s",
  depth, latency_ms, frame_id.c_str());

spdlog 双写时 set_pattern("%v") + JSON sink；clock 源统一 rclcpp::Clock(RCL_ROS_TIME)，避免 sim time 与 wall time 混用。ERROR 以上同步 flush，防 crash 丢最后一行。error_code 用整数 enum，human readable 字符串只在展示层转换，方便 Loki metric 聚合。

4. 与 trace、topic 的分工

日志是稀疏事件。100Hz 以下状态变迁、错误、模式切换用 log；每帧 pose、点云统计走 topic/bag 或 trace span（Tracy/perfetto）。1000Hz IMU debug 用 RCLCPP_DEBUG_THROTTLE，不是每帧 INFO。把 megabyte 矩阵 dump 进 INFO 会拖垮 disk 与 executor——这是架构问题，不是「多打几行 log」能解决的。

与 trace 分工清楚：日志回答「发生了什么异常事件」，trace 回答「这一帧时间花在哪」。混用会导致 disk 满而 still 看不清 hotspot。

5. 运行时调级与录包

rcutils_logging_set_logger_level 可临时开 DEBUG，排障完必须收回。与 ros2 bag record /rosout 联用时确认 QoS compatible。事故袋应能还原关键 ERROR 的 error_code 与 frame_id——证据链分清算法还是配置。field 临时开 DEBUG 完忘记关，是 disk 满的常见根因之一。

rcutils_logging_set_logger_level 运行时调级；field 临时 DEBUG 完降回 INFO。review 禁止热路径字符串拼接 std::string msg = "a"+std::to_string(x)——用 format 或 Throttle。

6. 案例：同一错误码三处对齐

我们把 SLAM_001（lidar timeout）写进 error enum、Loki 告警规则、oncall playbook 同一页。以前 substring grep 中文「雷达超时」会漏掉英文节点日志；统一 error_code 后聚合从三小时缩到五分钟，且能直接对照 bag 里 sensor_id 字段。同一错误码在 log/metrics/文档三处同名，是 oncall 可检索的最低要求。

7. 与录包复盘

导航事故袋若没有结构化 ERROR 字段，只能猜当时哪个 sensor timeout。状态层录包应包含关键 log 或 /rosout 与 bag 时间对齐。证据链完整，才分得清是算法责任还是配置责任。error 日志固定字段 error_code/frame_id，便于 Loki 聚合告警。

8. Throttle 与 executor 占用

未 throttle 的 WARN 在传感器丢帧时一秒几百行，disk 与 executor 都被拖死——看起来像「节点卡了」，其实是 log I/O。RCLCPP_*_THROTTLE 要配合理窗口：太短仍刷屏，太长掩盖频率变化。ERROR 永不 throttle，但须防重复 ERROR 无新信息——同一根因应同一 error_code，便于聚合而非重复 pager。

9. 多 sink 与 sim time

sim 回放时 clock 源必须一致，否则 log 时间戳与 bag 对不齐，复盘像拼图。spdlog 与 rclcpp 双写时，JSON 行里 stamp 字段定义写进团队规范。生产默认 INFO；CI nightly 可开 DEBUG 抓泄漏路径，但别把 DEBUG volume 当性能基线。fleet 上 disk 告警阈值应与节点数、传感器频率联动——单节点 DEBUG 看似无害，百节点就是存储事故。

10. 与 metrics 的分工

log 记离散事件，metrics 记可聚合计数与 histogram。同一 timeout 既打 ERROR log 又 increment lidar_timeout_total，oncall 从 metrics 看趋势，从 log 看单次上下文（seq、frame_id）。只有 log 没有 metric，dashboard 空白；只有 metric 没有结构化 log，根因分析仍靠猜。

10. 验收

  • 同一 error_code 在 log、metrics、文档三处同名。
  • Loki 可按 error_code 聚合告警，不靠 substring grep 中文。
  • DEBUG 默认 off；disk 满与 log volume 可追踪。
  • 热路径无字符串拼接构造大 string。
  • ERROR 不 throttle；WARN 必须 throttle。

能搜的日志才有用。级别决定「谁该半夜起来」，字段决定「起来后五分钟内能否定位」——这是可观测性的地板，不是装饰。

← 全部文章

johan's blog