现场出问题之后,日志往往是唯一的线索。但翻过的日志里,能真正回答问题的其实不多:通常只有一行“超时了”,既不知道当时在做什么任务,也不知道超时前最后一条有效反馈是什么。
后来我改了个做法——先写下复盘时要回答哪几个问题,再倒推该记什么字段。这比事后加日志有效得多。
先列问题
要回答的问题大概这几类:这次任务从哪台设备、哪个请求开始;在哪一步超时;超时前最后一条有效反馈是什么;同一时刻还有没有别的错误;这个问题在这台设备上出现过几次。
字段是这些问题推出来的,不是反过来。先写日志再想用途,很容易得到一堆“进入函数”“离开函数”,关键判断点反而没有信息。
身份字段比详细描述更管用
只有时间和文本的日志,跨进程的同一件事串不起来。加上这几个字段,可检索性会明显不一样:
1 | ts=2026-09-14T09:30:12.481+08:00 |
关键是 task_id 和 request_id 要贯穿所有层。上层任务、设备命令和设备侧反馈都带同一个标识,事后就能按时间排成一条链,不用在文本里猜哪条相关。
时间基准要说清楚
不同进程用不同时钟,排出来的顺序就没意义了。至少要明确时间戳来自哪个时钟、有没有和外部时间同步、单位是什么。
有超时逻辑的系统,记单调时钟差值比记墙上时间靠谱,因为墙上时间可能被对时调整。需要跨机器比的时候再记同步后的墙上时间,并标注同步状态。
只记墙上时间不记单调时间,“时钟跳变导致误判超时”这类问题就发现不了。
状态转换比错误字符串有用
只记“ack 超时”只能说明发生了什么,记状态转换才能说明系统当时怎么理解这件事。上面例子里的 from、to 和 reason 三项合起来,既能做统计也能重建流程。
原因码建议用可枚举的集合,自由文本适合补充细节,不适合聚合。一个稳定的原因码集合,能直接支持“这台设备最近两周最常出现哪种停止原因”这种问题。
高频路径上的日志得限流
有一类日志出现在高频路径上,比如每个控制周期或者每帧。在这些位置无差别打印会改变时序,让原本要观察的性能问题被日志本身盖住。
分层是个可行做法:正常路径只在状态变化时记,异常路径按原因码记并限流,详细跟踪用运行时开关控制。限流要在日志里显式写“已丢弃 N 条”,否则事后没法判断记录是否完整。
日志和可复现不是一回事
日志让问题可解释,但不一定让问题可复现。要复现,得记录输入和环境:当时的配置、软件版本,以及关键输入数据有没有存下来。
一次超时如果和某个传感器输入相关,而输入没存,日志只能说明超时发生了,没法重放。这时候补数据录制比加日志更有效。两者是互补的:日志说发生了什么,录制数据说为什么发生。
参考资料
证据边界:本文不含任何具体系统的日志样例数据。字段集合要按你要回答的问题裁剪。日志能证明系统当时如何判断,证明不了物理世界发生了什么——涉及执行器行为的结论还得靠设备侧反馈或独立测量。