先量事件循环延迟再怪 CPU

追踪定时器计划与实际执行的滞后，把尖峰与请求日志对齐，找出肇事同步代码。

目标

一段同步的报告渲染会冻结它身后所有的请求，而 CPU 曲线却舒服地停在 30%。事件循环延迟——定时器“本该触发”与“实际触发”之间的滞后——是唯一能看穿这类问题的指标：采集几乎零成本，与请求日志按时间戳对齐后还能精确归因。先把延迟量出来，再谈调优。

步骤要点

在一切 import 之前启用 monitorEventLoopDelay 直方图，每 5 秒检查 p99，超过 100ms 就输出带时间戳的 loop-lag 日志行。
把每条 loop-lag 的时间戳与请求日志做 200ms 窗口交集，按路由计数排名，每个尖峰窗口都出现的重路由就是头号嫌疑。
尖峰期间给进程发 SIGUSR1 抓 CPU profile，或用 –prof 分析，热帧里独占 tick 的同步函数即为阻塞元凶。
把阻塞工作挪出主循环：重渲染与序列化交给 worker_threads 或子进程，主线程只做流式转发。
把直方图固化为常驻指标（p99 与 max），仪表盘上与 CPU、内存并列，100ms 告警能在部署当天抓住这类回归。

排错提示

没有 loop-lag 行但延迟仍尖刺，说明卡顿在循环之外，查 GC 暂停、内核 IO 等待或下游依赖的外部请求日志；尖刺呈精确周期出现是定时任务、缓存清扫或指标抓取在同步跑，用时间戳算术对上 cron 表再挪去 worker；启动期数值巨大属正常的模块加载与 JIT 预热，告警要跳过启动后 30 秒或单独放宽阈值。

适用边界

直方图只测循环滞后，重度异步 IO 排队仍需请求级计时来诊断；20ms 分辨率看不见亚毫秒抖动，更细粒度要以更高开销为代价。

代码示例

# The log line that names the freeze
grep "loop-lag" app.log | tail -3
# {"evt":"loop-lag","p99ms":812,"at":"2026-10-22T14:03:11Z"}

# Which routes were live in that window?
jq -r 'select(.at >= "14:03:10" and .at <= "14:03:12") | .route' \
  requests.json | sort | uniq -c
#    41  /api/items
#     2  /report      <-- the only heavy route: culprit

# After moving /report to a worker thread
# loop-lag lines: gone. p99 latency: 1.9s -> 240ms