Node 20 里用 pino 打日志,我把 worker 的 stdout 弄丢了

跑在 Node 20.11 上的一个任务型服务,docker 里 4 个 worker 进程,每个进程用 pino 往 stdout 打 JSON 日志,再由 dockerd 的 json-file driver 收走。压测到每秒 3000 条左右时,发现日志条数对不上:程序里计数是 3000,docker logs 数出来只有 2600 上下,丢的都是 worker 进程的。

排查方向一开始跑偏了,以为是并发写同一个 fd 冲突。实际做法改成每个 worker 独立写文件,才看清问题:主进程用 pino.destination({ dest: 1, sync: false }) 时,pino 内部走的是 sonic-boom 的异步缓冲,进程被 SIGTERM 杀掉时缓冲区里还有没刷出去的数据。我们容器的 stop_grace_period 是 10s,但任务进程收到信号后自己 process.exit(0) 了,缓冲直接没了。

改法分两步。第一步给 pino 配同步写,代价是吞吐下降,实测单进程从 4.2 万条/秒掉到 1.1 万条/秒,我们这种量级够用:

const logger = pino(
  { level: process.env.LOG_LEVEL || 'info' },
  pino.destination({ dest: 1, sync: true })
)

第二步在退出路径上显式 flush,不要直接 exit:

async function shutdown(signal) {
  logger.info({ signal }, 'shutting down')
  await new Promise((resolve) => logger.flush(resolve))
  process.exit(0)
}
process.on('SIGTERM', () => shutdown('SIGTERM'))

为什么这样有效:sync: true 让每次 write 都落到 fd,logger.flush 则等异步队列排空。两者选一个其实就够,我两个都留是因为还有别的地方用异步 transport。

失效的地方也说清楚。sync 写在容器里遇到 stdout 是 pipe 而不是 tty 时,写阻塞会反压到业务代码,接口 P99 会抖;量再大就得换 pino.transport 把日志丢给单独进程。另外 logger.flush 的回调在极端情况下不保证被调用,我加了个 3 秒的 Promise.race 兜底,超时就硬退。还有一点,如果你用 cluster 且多个 worker 共写一个文件,sync: true 只保证单次 write 原子,不保证行不交错,超过 PIPE_BUF 的长日志还是可能撕裂。

现在的问题是:你们在生产里是接受 sync 写的延迟代价,还是宁可丢一点日志换吞吐?我这边两种都试过,还没找到特别舒服的中间点。

0
赞同度 100% · 0 条评论 · 1 阅读

0 条评论

支持 Markdown · 回复会实时推送给对方

还没有评论,写下第一条。