日志来自未来

一句话总结

时间戳不是事实，而是那台机器当时看着自己的时钟做出的主张。把许多这样的主张收集起来按时间顺序排列，事件的先后顺序就会悄悄颠倒。

为什么需要它

在故障复盘中，最常用的工具是把日志按时间顺序合并。把四台服务器的日志汇总到一个画面里，从上往下读，去找“原来是从这里开始的”。这个方法在大多数日子里都很管用。所以，它不管用的那些日子，才格外难以察觉。

它不管用的日子是这样的：worker 的“收到请求”排在 API 的“发出请求”上面。这等于处理了一个没收到过的东西。人看到这个画面后得出的结论几乎是固定的——“worker 好像重放了重复请求”“消息队列打乱了顺序”“有人错误地配置了重试”。这三个假设都很合理，而三个都错了。其实只是 worker 的时钟慢了 12 秒而已。

反方向的情况更糟。时钟超前的机器，它那一行日志会像来自未来一样。往返响应时间被记成 4 分 37 秒，仪表板上的延迟曲线在那个时刻飙升。明明没有变慢，却留下了变慢的证据。而且这份证据不会消失。

工作原理

这里重要的是，误差并不只出现在一行上。时钟错位的机器，它的每一行日志都错位相同的大小。所以，如果只有一行异常，那不是时钟问题，而是别的问题；如果某台主机的整批日志都被整体推移了一个固定的量，那几乎就是时钟问题。这个区分是排查的第一个分岔口。

误差的大小不靠猜，而是测量。之所以能测量，是因为一个请求会留下四个时间点：发送方发出的时间（T1）、接收方收到的时间（T2）、接收方答复的时间（T3）、发送方收到答复的时间（T4）。NTP 三十年来一直在用的正是这个计算，RFC 5905 第 8 节是这样写的。

theta = T(B) - T(A) = 1/2 * [(T2-T1) + (T3-T4)]      두 시계의 차이
delta = T(ABA)      = (T4-T1) - (T3-T2)              왕복에 걸린 시간

该代码块中的韩文注释依次说明：第一个式子表示两个时钟的差，第二个式子表示往返所花的时间。

为什么要把两项相加再除以二，这就是这个式子的全部。(T2-T1) 中混着两样东西：真正的时钟差，以及去程的网络延迟。(T3-T4) 中也包含时钟差，但这次回程的延迟是以相反的符号包含进去的。把两者相加，延迟相互抵消，只剩下两倍的时钟差。所以要再除以二。

只有去程和回程的延迟相等时，抵消才是完美的。在真实的网络中两者并不相等，所以测一次得到的值，会错 (去程延迟 - 回程延迟) 的一半。因此要用的不是一个样本，而是多个样本的中位数。如果再一并观察样本的离散幅度，就能同时得知这个估计有多大的可信度。如果离散幅度只有几十毫秒，而误差是 277 秒，结论就毫无动摇的余地。

实际工作中校准时钟的事，由 chrony 这样的守护进程来做。误差较小时，守护进程会微调时钟的速度，慢慢追上（slew）；误差较大时，则让时间一次性跳变（step）。这两种方式的差别，会引出接下来的内容。

在现场相遇的样子

在容器环境中，这个问题尤其常见。容器没有自己的时钟，直接使用宿主机内核的时钟。所以一旦某个节点的 NTP 挂了，运行在该节点上的 Pod 会一起错位，而其他节点的 Pod 则完全正常。症状不是“某个服务有问题”，而是“只有运行在某个节点上的东西有问题”，而由于习惯按服务名称汇总日志，这个模式很难被看出来。

留下记录时有两点要遵守。一是时间始终连同偏移量一起写。RFC 3339 格式之所以有用，就是这个原因。2025-11-01T18:30:00.694+09:00 无论在哪台机器上读取，指向的都是同一个时刻，而 2025-11-01 18:30:00 则依赖于读者的猜测。另一点是不要把顺序只交给时间。如果同时保留请求 ID 和因果链（什么产生了什么），即使时钟错位，顺序也能还原。分布式追踪做的正是这件事。

还有排查时的顺序。如果发现了时钟错位，不要删除或重新生成日志，而要记录下误差，读取时再进行校正。原始记录是这台机器当时相信什么的证据，而这种相信可能正是事故的原因。

下一项测验要确认什么

确认如何区分单独一行的异常和整台主机的整体偏移，用四个时间点测量误差的式子为什么能抵消延迟，以及为什么使用的不是一个样本而是多个样本的中位数。