如果一切同时变慢,说明只有一条道
一句话总结
在 Node 里,JavaScript 只在一条道上运行。所以“这个 API 很慢”和“全都很慢”,往往不是两件不同的事,而是同一件事的两副面孔,而这条道停顿了多久,不用分析器也能测出来。
为什么需要它
反馈总是指向一个地方。“支付确认 API 偶尔要花 3 秒。”我们打开这个 API 的代码,看查询、看索引、看外部调用,什么都不奇怪。这时该做的不是继续深挖这个 API,而是看看其他 API 的延迟是不是也一起上升了。
如果也一起上升了,元凶就不是这个 API。在 Node 进程里,执行 JavaScript 的道只有一条,在当前正在执行的回调自己交还之前,这条道不会交给任何人。这不是由操作系统把时间切片抢走的抢占式调度,而是由各自主动让出的协作式。所以只要某一个回调占着 CPU 300ms,在这期间到达的请求就全部要等 300ms。这些请求的代码并没有问题。它们只是在道上排队。
这种结构不是缺陷,而是一种选择。因为不为每个请求启动一个线程,所以能用很少的内存支撑几万个连接。代价是随之而来的一条规则:不能一次做耗时很长的事。要确认有没有守住这条规则,就得去测量,所以本课程的第一个工具不是分析器,而是尺子。
工作原理
事件循环每转一圈,会分成若干阶段。依次是:检查定时器(setTimeout、setInterval)是否到期的阶段,调用已完成的输入输出回调的阶段,等待新事件的 poll 阶段,以及调用 setImmediate 的 check 阶段,详细的顺序整理在官方指南事件循环、定时器与 process.nextTick()中。重要的不是阶段的名字,而是这样一个事实:要进入下一个阶段,当前的回调必须先结束。
测量的方法就由此而来。如果设置为每 20ms 响一次的定时器,实际上过了 320ms 才响,就说明在这期间的 300ms 里,事件循环被别的事情占住了。官方文档也写了同样的依据——“定时器的执行与 libuv 事件循环的生命周期绑在一起,所以循环的延迟会直接表现为定时器的延迟”(perf_hooks)。
let last = Date.now();
setInterval(() => {
const now = Date.now();
const lagMs = Math.max(0, now - last - 20); // 간격을 뺀 나머지가 지연이다
last = now;
}, 20);
Node 也提供做同样事情的内置工具。perf_hooks.monitorEventLoopDelay() 会生成直方图,使用时要知道两点。值的单位是纳秒,采样间隔(resolution)的默认值是 10ms。所以即使在什么事都没有的进程里,这个直方图的中位数也不是 0,而是在 10ms 附近——在实验镜像的 Node 22.11.0 上测量,安静状态下的 p50 是 10.5ms。如果把这个值理解成“我们的服务总是被拖慢 10ms”,就会去追一个并不存在的问题。亲手做一把尺子,就能切身体会到这个底数是从哪里来的。
在现场相遇的样子
这起事故最讨厌的性质是:平均值几乎不动。在 1.2 秒里以 20ms 间隔测得的 44 个样本中,超过 100ms 的只有一个,平均值是 7.7ms(Node 22.11.0、2 核环境下的实测)。画平均延迟的仪表盘,在这起事故发生期间也是平的。会动的只有最大值和 p99。
第二个性质是受害者有很多。在同样的条件下同时发出 10 个请求,只让其中第三个占着 CPU 300ms,结果除它自己之外的 7 个请求都一起花了超过 300ms。日志里会出现 8 个慢请求,其中真正的原因只有 1 个。无论怎么盯着其余 7 个请求的代码,也找不到答案。
所以,Node 服务的故障排查,应当不是从“找出慢的端点”开始,而是从“看同一时刻一起变慢的有什么”开始。如果是一起变慢的,就说明道只有一条,接下来的问题只有一个:“谁占住了这条道?”
下一项实验要做什么
亲手做出测量延迟分布的尺子。先把百分位的计数规则规定下来,把定时器晚了多少收集成样本,插入一次同步任务,确认只有长尾在动。然后一次性发出十个请求,数一数一个请求的停顿拖慢了多少个请求,最后把这些数字转换成“超出预算多少次”这样的判断。
评分器会把你写下的 p50、p99、max 从样本重新计算并对照,还会把你做的函数再运行一遍,看是否出现同样的性质。只把数字写得像模像样,是通不过的。