墨线与电路 INK & WIRE

Node.js · 2026.09.28

Node 的事件循环不是黑盒：一次 event loop lag 排查

接口 P99 从 40ms 涨到 900ms，CPU 却只有 15%。从 event loop lag 曲线出发，定位到一个被误用的同步读写和一个隐藏的深拷贝，以及它引发的连锁反应。

陈墨 4 分钟阅读 #Node.js#性能#排查

线上告警：某接口 P99 从 40ms 涨到 900ms，同机 CPU 使用率只有 15%，内存平稳，没有 GC 尖刺。看起来不像资源问题，更像是「有人在排队」。

Node 服务出现这类症状，第一反应应该是：事件循环被什么东西卡住了。

一、先量，别猜

事件循环延迟（event loop lag）是最直接的指标。原理很简单：定时器本该在 N 毫秒后触发，如果实际晚了 M 毫秒，那这 M 毫秒里循环就没能转完一圈。

js
// event-loop-lag.js
import { monitorEventLoopDelay } from 'node:perf_hooks';

const h = monitorEventLoopDelay({ resolution: 20 });
h.enable();

setInterval(() => {
  const p50 = (h.percentile(50) / 1e6).toFixed(1);
  const p99 = (h.percentile(99) / 1e6).toFixed(1);
  const max = (h.max / 1e6).toFixed(1);
  console.log(`lag p50=${p50}ms p99=${p99}ms max=${max}ms`);
  h.reset();
}, 5000).unref();

monitorEventLoopDelay 用的是高精度直方图，开销可以忽略（纳秒级采样），可以直接挂到生产环境。

我们加上埋点后看到：

text
lag p50=2.1ms  p99=3.4ms  max=8.0ms    # 正常时段
lag p50=118ms  p99=842ms  max=1310ms   # 故障时段

p50 就已经上百毫秒，说明不是偶发长任务，而是持续性的阻塞。CPU 只有 15% 说明阻塞不是「算得久」，而是「在等」。

同步 IO 是 Node 里最典型的「CPU 空闲但循环卡死」。

二、往同步 IO 方向找

fs.readFileSync、execSync、同步的压缩/加密调用，都会把整个循环挂住。但更隐蔽的是一类「看起来是内存操作，实际上是 IO」的调用。

排查顺序：

  1. --trace-sync-io 启动，任何同步 IO 都会打警告。
  2. 检查 require / import 的顶层是否有读文件。
  3. 检查模板渲染、配置热加载、日志格式化路径。
bash
node --trace-sync-io=1 server.js

警告长这样，直接指出调用栈：

text
(node:41273) WARNING: Detected use of sync API
  at Object.readFileSync (node:fs:453:3)
  at loadTranslations (/srv/app/i18n.js:88:20)
  at translate (/srv/app/render.js:31:14)
  at renderPage (/srv/app/render.js:64:5)

问题定位到了：一个 i18n 模块每次渲染页面都同步读一次语言包文件。

三、真正的元凶藏在第二层

修掉同步读取后，lag 从 842ms 降到 90ms，但仍然不对。继续看火焰图，发现一半时间在 JSON.parse。

这很有意思：JSON.parse 是纯 CPU 操作，不应该产生「CPU 空闲却排队」的现象。除非——它解析的字符串特别大，而且这个字符串是从一个巨大的对象上 JSON.stringify 出来的。

代码是这样的：

js
// 每个请求都会走这里
function snapshot(state) {
  return JSON.parse(JSON.stringify(state)); // 深拷贝
}

状态对象随着用户数据增长到了几 MB。每次请求深拷贝一个几 MB 的对象，单次耗时 20~40ms。QPS 50 的情况下，仅这一项就吃掉了整个循环的容量。

这解释了全部现象：CPU 分摊下来只有 15%（因为还有大量等待 IO 的空隙），但每个请求都要在循环里排一次 30ms 的队。

两个修法：

其一，别深拷贝。 结构化克隆在大多数场景下不是必需的，用不可变更新或者显式的浅拷贝更划算。

js
// 只拷贝需要改的层级
function update(state, patch) {
  return { ...state, ...patch };
}

其二，真要拷贝也别序列化。 Node 17+ 有 structuredClone，走的是原生实现，对大对象比 JSON.parse(JSON.stringify()) 快一个数量级，而且能正确处理 Date、Map、Set、RegExp。

js
const copy = structuredClone(state);

注意 structuredClone 不能克隆函数、Promise、DOM 节点，也不保留原型链。如果你的对象里有这些，得另做设计。

四、顺手确认一下 GC

排除同步阻塞之后，第二嫌疑是 GC。老生代回收会导致 stop-the-world，表现和事件循环阻塞几乎一样。

bash
node --trace-gc server.js | grep -E "Mark|Scavenge"

如果看到频繁的 Mark-Compact，说明对象存活时间过长或分配速率太高。常见原因是：

  • 长生命周期的数组被反复 push 却不清理。
  • 日志缓冲没有上限，只有在进程重启时才释放。
  • 缓存没有淘汰策略（Map 无界增长是最经典的泄漏）。

一个便宜的观测手段是给进程加内存阈值告警，并在堆超过阈值时打一次 heap snapshot 的 cue，而不是等到 OOM。

五、把「不阻塞」变成代码约束

修完这次问题后，我们在 CI 里加了三条规则：

  1. 禁用同步 API 的静态检查。 用 ESLint 规则禁掉 fs.*Sync、child_process.execSync（白名单注释放行，且要求说明理由）。
  2. 关键路径的 lag 预算。 每个服务的 event loop lag p99 有明确上限（比如 20ms），超了就告警，而不是等用户投诉。
  3. 大对象序列化的显式审查。 任何超过 100KB 的 JSON.stringify 都走一遍 code review，因为这类调用的成本随数据量增长而不随请求量。

六、把这次排查浓缩成一张表

现象可能原因验证方式
lag 高、CPU 低同步 IO / 锁等待--trace-sync-io
lag 高、CPU 满长计算任务CPU profile 火焰图
lag 周期性尖刺GC / 定时任务--trace-gc、任务日志
内存缓慢上涨无界缓存heap snapshot 对比
延迟高但 lag 正常下游依赖慢分布式 trace

Node 的并发模型是「单线程跑很多个任务」，它的性能上限不在 CPU 核数，而在一次循环能多快转完一圈。任何让单圈变长的东西，都会等比放大成全站的延迟。

所以下次看到「CPU 不高但就是慢」，别急着加机器，先量一圈 lag。