TT Lab
开始
学习 学习路径 课程

从日志里找原因

没有偏移量的时间不算时间

在 TT Lab 中继续学习

一句话总结

日志中记录的时间是主张,而不是事实。没有偏移量,就无法知道是哪个地区的时钟;即使偏移量准确,只要那台主机的时钟本身错位了几秒,原因就会排到结果之后。

为什么需要它

无论把格式规范化得多好,只要时间是假的,建立在它之上的结论就全是假的。在故障调查中,最先要做的就是“什么先发生”,而确定这个先后顺序的依据,正是这些数字。

在现场收到的一批日志里,通常有三种情况同时存在。第一,完全没有偏移量的本地时间。应用日志器的默认值是 2026-03-08 15:04:57.200 这种形式,至今仍然很常见。RFC 3339 在第 4.4 节中明确指出:不带偏移量的本地时间,在地球上约 23/24 的地方无法解读,所以在互联网上因互操作性问题而不可接受。这一行是在首尔还是在法兰克福打的时间,行内并没有写。

第二,含义微妙不同的偏移量。同一份文档的第 4.3 节另行规定了 -00:00。当知道 UTC 时间,却不知道记录所在地的本地偏移量时,使用这种写法,它与 Z 或 +00:00 含义不同——后两者表示 UTC 是该时间的基准点。从数字上看,两者都是 0,所以计算结果相同,但给读者的信息不同。

第三,时钟本身的误差。没有接入 NTP 的主机,一天里会漂移好几秒。即使正确地带着偏移量,只要时钟超前 7 秒,这台主机打出的所有时间就都超前 7 秒。如果是响应在 1 秒内结束的请求,那么原因会比结果晚 6 秒被记录下来。只看日志,数据库就像是在收到请求之前就作出了回答。

工作原理

让不可信的时间变得可信的方法,是确定一个基准,并据此来测量。

找到基准事件。只要是能同时在多台主机上留下痕迹的东西都可以——部署标记、配置重新加载、运维调度器发出的探测信号。如果同一个标记出现在三个文件中,这三行的时间差,就是三个时钟之间的差。这种方法的精度不会超过该信号到达三台主机所用时间的离散程度——必须一并写明这一点,估计值才不会被夸大。

把差值拆成两部分。与基准的差值中,混有本地偏移量和时钟误差。IANA 的本地偏移量是 15 分钟的整数倍,所以把差值四舍五入到最近的 15 分钟,就得到本地偏移量,剩下的秒数就是时钟误差。8 小时 59 分 57 秒,要读作“9 小时偏移量 + 时钟慢了 3 秒”。这 3 秒不能四舍五入丢掉——颠倒因果顺序的,恰恰就是这 3 秒。

地区名称不是偏移量。地区是由 IANA 时区数据库管理的一组规则,同一地区的偏移量也会随季节变化。Python 用 zoneinfo 原样读取这些规则。在有夏令时的地区,不带偏移量的本地时间会有两次风险——春天会出现不存在的时间(America/New_York 的 2026-03-08 02:30),秋天会出现出现两次的时间。datetime 的 fold 就是用来指向后一个的旋钮。

最后固定为一种写法。正如 RFC 3339 第 5.1 节所写的性质,只要偏移量写法和小数位数相同,字符串排序就等同于按时间排序。如果处理的是 syslog,RFC 5424 第 6.2.3 节的要求更严——T 和 Z 必须是大写,不能使用闰秒,秒的小数不能超过六位。

在现场相遇的样子

原始时钟和观测时钟都要保留。OpenTelemetry 日志数据模型把 Timestamp 和 ObservedTimestamp 分开,原因就在这里。前者是事件发生时的原始时钟时间,也可能没有;后者是采集器看到该事件的时间。同时保留两者,当原始时钟可疑时,就有了可以对照的尺子。规范建议,把日志交给只接收一个时间的系统时,如果有 Timestamp 就用它,没有就用 ObservedTimestamp。

校正值不是数据,而是假设。“这台主机是 +09:00,并且慢了 3 秒”,是你根据基准事件推测出来的值。不要覆盖原始行,而要把校正后的时间和原始字符串并排保留。以后更换基准时,必须能够从头重新计算。

真正的解决办法在客户那边。推测只是挽救这批日志的应急处理。从下一批起,要求所有主机接入 NTP,让日志器必须带上偏移量,可能的话用 UTC 打时间,这才是真正的解决办法。提出这些要求的依据,就是你测出来的数字。

下一项实验要做什么

复现三台主机的日志并调查其写法,亲自测试在有夏令时的地区,本地时间是如何消失、又是如何出现两次的。然后用同时出现在三个文件中的探测信号,拆分并估计每台主机的本地偏移量和时钟误差,把所有行校正后排成一条时间线。最后统计校正之前原因比结果更晚被记录的请求有多少个,并以报告的形式写明改了什么、依据是什么。