Bun 服务周期性 CPU 打满的排查：kafkajs 与 Bun 1.3.14 的叠加 bug
几天前，我们遇到了一个相当有趣的制作问题。Bun服务会定期将一个CPU核心绑定在三个pod上，每次正好10分钟，然后自己又会回归。服务本身还不错：请求正常，健康检查从未失败。CPU图表看起来非常糟糕。
结果发现是两个问题，各自都比较轻微，分别依赖于特定的内核版本和特定的 Bun 补丁发布。把它写下来。
环境：
- Bun 1.3.14（钉在 Dockerfile 中）
- 卡夫卡伊 2.2.4
- Kubernetes node kernel 5.10.134
复刻：布-埃波尔-计时-旋转-复制.我稍后会再谈这个。
一天内三个舱体都用到分钟级的CPU。底部的竖线是卡夫卡制作的;稍后会详细说明。有几点特别突出：
- 平台期核心数为0.99，且从未超过1.0。只有一个线程在忙。
- 每个拉伸时间都是600秒的倍数。它在一个刮擦间隔内跳动，而不是缓慢攀升。
- 这三个舱通常一起开始这段路。
- 几乎一夜之间没有什么变化。它追踪交通。
- 在峰值期间，用户大约是2/3，系统大约是1/3。网络、频率和记忆看起来和一段安静期一样。
最后一点已经排除了很多可能性。我们没有处理大量负载，也不是纯JS计算（系统不会那么高）。看起来像是忙碌的循环，还在做系统调用。
我最初怀疑是不是某个工人在某个工作中陷入了紧密的循环。但在24小时内，所有与作业超时、重试和心跳有关的日志都是零。繁忙时段和闲置时段产生的原木产量几乎相同。而且它也不是通过部署引入的：我们有的16天指标看起来都一样。
不能随便戳生产，容器里也没有穿孔，所以我kubectl exec读了/proc.那是完全只读的。
每个线程的差异utime/stime值/proc//task/*/stat超过3秒，找到最火的那个。在尖峰期（100刻=一个核心）：
tid comm d_utime d_stime
8 bun 197 100
95 HTTP 0 0
9 bun 0 0
16 Bun 0 0
15 Bun 0 0
14 Bun 0 0
13 Bun 0 0
12 HeapHelper 0 0
11 HeapHelper 0 0
10 HeapHelper 0 0热线是主线（tid等于PID的那个线）。然后我采样了/proc//task//syscall我尽快。第一列是线程当前所在的系统调用号，后面跟六个参数。当线程处于用户空间时，文件会说running:
i=0
while [ $i -lt 3000 ]; do
cat /proc/8/task/8/syscall >> /tmp/sc.txt
i=$((i+1))
done
# which syscall it is blocked on
awk '{print $1}' /tmp/sc.txt | sort | uniq -c | sort -rn
# epoll_pwait timeout (4th argument, i.e. column 5)
awk '$1 == 281 {print $5}' /tmp/sc.txt | sort | uniq -c | sort -rn系统调用号取决于架构。在x86_64上，桌子是syscall_64.tbl在核树中;如果盒子已经审计过，ausyscall x86_64 281也行。这些是后面出现的：
202 futex
281 epoll_pwait
441 epoll_pwait2关于arm64，epoll_pwait22岁。epoll_pwait2是较新的系统调用中，跨架构使用单一号码：441 everywhere。
怠速：
2969 281
29 running
2 202
1850 0x63
325 0x53
201 0x56
192 0x57
90 0x5d3000个样本中有2969个位于syscall 281，epoll_pwait，超时时间为数十到几百毫秒。正常。一个细节：441（epoll_pwait2）根本没出现。这点以后才重要。
在高峰期：
2979 running
21 281
21 0x1几乎完全是在用户空间里。那是极少数出现的时刻epoll_pwait，超时时间为1毫秒。
则/proc//net/tcp空闲时有4个连接（Redis、Postgres）。在一次尖峰期间，有两个额外连接连接到9095端口，Kafka经纪人。
该服务发布带有卡夫卡伊（kafkaj）的计量事件。我提取了48小时触发Kafka产物的日志，并将其对比到115个CPU区间：
- 每个区段起点都在距离最近的农产品-13秒到+1秒之间（在刮擦抖动范围内）
- 每段在该区段最后一次产物后，最后一次产物后都会在600秒到611秒之间结束
- 反过来：所有373个产物都位于某个区域内。没有一发失手。
600 是默认值connections.max.idle.ms在Kafka经纪人：经纪人在空闲10分钟后关闭连接。所以CPU伸延的长度就是一个Kafka连接的寿命。三个舱体突然聚集在一起，因为一个用户的批次任务分到三台机器上，每台机器几秒内都会发送消息。
卡夫卡 2.2.4，src/network/requestQueue/index.js:
checkPendingRequests() {
while (this.pending.length > 0 && this.canSendSocketRequestImmediately()) {
// ...
}
this.scheduleCheckPendingRequests()
}
scheduleCheckPendingRequests() {
let scheduleAt = this.throttledUntil - Date.now()
if (!this.throttleCheckTimeoutId) {
if (this.pending.length > 0) {
scheduleAt = scheduleAt > 0 ? scheduleAt : CHECK_PENDING_REQUESTS_INTERVAL
}
this.throttleCheckTimeoutId = setTimeout(() => {
this.throttleCheckTimeoutId = null
this.checkPendingRequests()
}, scheduleAt)
}
}checkPendingRequests总是打电话scheduleCheckPendingRequests.当待定状态是空的且没有油门时，仍然会启动setTimeout，其回拨呼叫checkPendingRequests又一次。throttledUntil从-1开始，所以scheduleAt是一个巨大的负数值。Node和Bun都把负延迟视为1毫秒。
所以从中介连接的第一个响应开始，该连接运行时间为1毫秒setTimeout循环直到destroy()被叫去。而且destroy()只有在连接断开时才会运行。
上游也有报道（卡夫卡伊斯#1556,Kafkajs#1704).修复PR已经放了很久（卡夫卡伊斯#1572）并且从未降落。我们已经在仓库里修补了，但补丁只用Math.max(1, scheduleAt || 1)这样1毫秒的循环就不会被杀死。
不过：1毫秒setTimeoutNode 循环大约占 2% CPU。为什么它会挂住整整一个核心？
事件循环。Bun 1.3.14，packages/bun-usockets/src/eventing/epoll_kqueue.c:
static int bun_epoll_pwait2(int epfd, struct epoll_event *events, int maxevents, const struct timespec *timeout) {
if (has_epoll_pwait2 != 0) {
// ... sys_epoll_pwait2(...)
}
int timeoutMs = -1;
if (timeout) {
timeoutMs = timeout->tv_sec * 1000 + timeout->tv_nsec / 1000000;
}
do {
ret = epoll_pwait(epfd, events, maxevents, timeoutMs, &mask);
} while (IS_EINTR(ret));
return ret;
}Bun 更喜欢epoll_pwait2，需要纳秒timespec.epoll_pwait2自 Linux 5.11 版本以来才存在;Bun 检查内核版本并退回到epoll_pwait还有一个毫秒的超时时间。这个漏洞是tv_nsec / 1000000：它会被截断到接近零。
1毫秒计时器会在自己的回调中重新激活。事件循环计算下一步等待时间：剩余0.9毫秒，截断为0，epoll_pwait(…, 0)立即返回，再次计算，仍为0，旋转直到计时器响起。然后回调触发新的1毫秒计时器，循环往复。
这很吻合/proc：主线程从未调用epoll_pwait2，因为我们的节点是5.10.134。该0x1峰值期间的采样是每轮唯一真正进入睡眠的呼叫。超时0的呼叫会立刻返回，所以你几乎抓不到。
截断自2011年3月1日起就存在。只有1.3.14会爆炸。区别在于面包#29806在1.3.14中：timespec.now()从中切换CLOCK_MONOTONIC_COARSE在Linux上精确到纳秒级hw_timer（RDTSC）。老式时钟是瞬间的，毫秒级。1毫秒计时器剩余的时间要么是完整的1毫秒，要么已经到期了。你从未见过0.9毫秒，所以截断也不会生成0。纳秒钟过后，那个老旧的截断终于被打破了。
上游修正了它兔子#34780（改为四舍五入）。那是1.4.0版本;1.3.14 之后，没有再有 1.3.x 版本。所以唯一受影响的版本是 1.3.14，而且只适用于epoll_pwait2.
你不需要5.10的机器。Docker seccomp 可以让系统调用返回 ENOSYS。当Bun看到epoll_pwait2返回ENOSYS，它采用相同的备用路径：
{
"defaultAction": "SCMP_ACT_ALLOW",
"syscalls": [
{ "names": ["epoll_pwait2"], "action": "SCMP_ACT_ERRNO", "errnoRet": 38 }
]
}完整复刻版已经发布布-埃波尔-计时-旋转-复制仅限 Docker ：
git clone https://github.com/BlackHole1/bun-epoll-timer-spin-repro.git
cd bun-epoll-timer-spin-repro
./run.sh它运行 Bun 1.3.13 / 1.3.14 / 1.4.0，带和不带epoll_pwait2，关于三计时器设置：一个普通setTimeout(fn, 1)，一片平原setTimeout(fn, 10)，以及构造卡夫卡伊的RequestQueue然后呼唤checkPendingRequests()只有一次（没有真正的卡夫卡）。每个箱子运行5秒，报告计时器射速加CPU：
bun epoll_pwait2 mode iter/s user% sys%
1.3.13 available timer1 330 1.2 1.4
1.3.13 available timer10 84 1.4 0.8
1.3.13 available kafkajs 327 2.2 0.9
1.3.13 blocked timer1 327 1.7 1.1
1.3.13 blocked timer10 84 1.5 1.2
1.3.13 blocked kafkajs 321 2.3 1.5
1.3.14 available timer1 336 1.2 0.7
1.3.14 available timer10 85 1 0.2
1.3.14 available kafkajs 335 2.3 0.7
1.3.14 blocked timer1 996 56 43.5
1.3.14 blocked timer10 92 2 0.7
1.3.14 blocked kafkajs 993 62.9 36.6
1.4.0 available timer1 334 1.3 1.6
1.4.0 available timer10 86 0.8 0.4
1.4.0 available kafkajs 337 2 1.3
1.4.0 blocked timer1 338 1 1.1
1.4.0 blocked timer10 85 0.7 0.5
1.4.0 blocked kafkajs 334 1.3 1.1只有1.3.14版本，syscall被阻挡，才会把核心绑定。所以这其实并不是关于卡夫卡伊。任何1毫秒setTimeoutLoop 在那个组合上也是同样的效果。
2秒内的追踪：148,000次epoll_pwait(4, [], 1024, 0, [], 8) = 0 <0.000001>，相距6到7微秒。那就是三分之二的用户+三分之一的系统。
补丁卡夫卡伊：如果待处理是空的且没有油门，就不要安排计时器。其他的都保留。
if (this.pending.length > 0) {
scheduleAt = scheduleAt > 0 ? scheduleAt : CHECK_PENDING_REQUESTS_INTERVAL
}
- // Prevent negative or invalid delays
- scheduleAt = Math.max(1, scheduleAt || 1)
+ if (scheduleAt <= 0) {
+ return
+ }
this.throttleCheckTimeoutId = setTimeout(() => {
复刻版的CPU从99%降到了0.2%。
我在那里时还有两件额外的事：
- 置顶的卡夫卡伊作品
^2.2.4以确定2.2.4.面包的patchedDependencies钥匙上的比赛kafkajs@2.2.4.如果锁文件解析了不同版本，Bun 会默默跳过补丁，bun install退出0，它一句话也没说。 - 新增了一个导入测试
kafkajs/src/network/requestQueue/index.js直接并断言空的待处理队列不会启动计时器。如果补丁消失，测试先失败。
补丁已经开始制作。周期性单芯峰值消失了。一旦我们升级到Bun 1.4.0，即使补丁发布，这个组合也不会再回来。
点赞
收藏
点踩
分享