解读 192 · 调试程序:打印、断言与日志
解读对象:概念课 · 以
duck-control/src/bus.rs的日志实例与robotd/src/main.rs的限流常量为教材
需要的前置:零基础可读;主循环背景见解读 191
新手调试靠"到处 printf",结果机器人一天打 400 万行日志,把真正有用的淹了。本篇用这只鸭子的真实代码,讲三件事:日志为什么限流、限流怎么写、断言怎么替你站岗。类比一个门卫的汇报守则:大事当场喊,小事记账本,喊过的一分钟内不重复喊。
先算账:每拍都打日志会发生什么
50 Hz 循环里哪怕每拍一行,main.rs:69 算过账:"每天约 430 万行。这不只是噪音:在日志有大小上限的系统里,它正是把支持人员需要的那几条挤掉的元凶"。所以主循环的常规摘要 300 秒才打一条(LOOP_SUMMARY_INTERVAL,main.rs:71)。调试的第一课不是"多打",而是"每行日志都要回答一个问题,并算得出它一天占多少行"。
三条真实限流规则:第 1 次、每 N 次、静默期
规则一(bus.rs):IMU 板"回答但内容没刷新"是总线外的故障,别人都不报,只能自己数。StaleImuTracker 记下连续相同块的次数,到 STALE_RUN_WARN = 25(bus.rs:72,50 Hz 下正好半秒)才开口,之后每 500 次提醒一次(bus.rs:451-456):
if run == STALE_RUN_WARN || (run > STALE_RUN_WARN && run.is_multiple_of(500)) {
tracing::warn!(
consecutive = run,
total = self.stale_imu.stale.total,
"imu board has returned the same sample {run} reads running — orientation is frozen"
);
}
注释里写着教训:"在最开始就告警,教会了所有人无视这条消息"——狼来了效应,限流就是防它。规则二(robotd):启动等舵机上线时,第 1 次失败和每第 30 次打日志(main.rs:1425、1533):const STARTUP_READ_LOG_EVERY: u32 = 30; 加上 if attempt == 1 || attempt.is_multiple_of(STARTUP_READ_LOG_EVERY)。规则三:偶发掉一次总线读是常态,连续错误计到 10 的倍数、或距上一条已满 60 秒(BUS_DROP_QUIET)才打(main.rs:2093-2095):
let a_run = n.is_multiple_of(10);
let due = last_bus_drop.is_none_or(|at| at.elapsed() >= BUS_DROP_QUIET);
if a_run || due {
注意计数器 consecutive_errors 在读到好数据时清零(main.rs:2080)——"连续"才是故障,孤立一次是生活。
断言:让"不该发生"当场爆炸
打印是事后查,断言是事前哨。最狠的一处在 model.rs:29:
const _: () = assert!(JOINT_NAMES.len() == NUM_JOINTS);
关节名表和关节数是两个来源,一旦不同步,观测维度就错了——所以用一条编译期断言:数字对不上,程序根本编译不出来。运行期的断言则在测试里,比如 io.rs:348 注入一次失败后 assert!(io.read().is_err());,把"必须报错"也钉成被验证的行为。调试工具箱由此齐了:打印看现场,日志限流地记历史,断言守不变量。
你带走的收获
- 先算日志账:50 Hz 每拍一行 = 430 万行/天,会把真正需要的记录挤掉。
- 限流三板斧:首次 + 每第 N 次(30)、连续计数 + 静默期(60 秒)、阈值 + 周期提醒(25/500)。
- "在最开始就告警,教会所有人无视它":日志要防狼来了,限流是尊重读者。
- 计数器是调试利器:孤立失败清零,"连续"才值得喊。
- 断言守不变量:能编译期查的绝不留到运行期,错误路径也要有断言。