同步日志写入导致的 Node.js 性能上涨

[xiaoxiaojx]

背景

Q 同学反映自己负责的 SSR 项目线上环境 Node.js 性能指标「首字节 TTFB 」上涨了约 30ms, 而当次发布没有涉及配置的变更、基础包的升级等, 甚至同样的代码重新构建发布又恢复正常了...

问题排查

Cat 监控

首先查看了一下监控系统, 发现 SSR 项目涉及的渲染时延 Transaction , 后端接口时延 Transaction 等关键指标均没有明显波动

这里我们使用的 Cat 进行的数据采集, 下图为 Cat 监控示例图与本次无关

于是只能追加了更多的时延 Transaction 打点, 最终发现竟然是一行日志输出时而达到了 15ms 时而又小于 1ms 到可以忽略, 每个请求存在两条这样的日志输出故导致性能上涨了 30ms 🤯

// SSR

ctx.logger.info('[xxx] xxx success, ret: %o', ret)

pino 日志

对于上面一个小于 200 字符串的日志输出为什么会消耗了 15ms, 继续查看代码发现使用的 logger 其实是基于 pino 6.11.3 版本

// SSR

import pino from 'pino'

const logger = pino(opts, pino.destination())

然后再查看 pino.destination 的实现发现了比较刺眼的sync: true传参

// https://github.com/pinojs/pino/blob/v6.11.3/pino.js

module.exports.destination = (dest = process.stdout.fd) => {
  if (typeof dest === 'object') {
    dest.dest = dest.dest || process.stdout.fd
    return buildSafeSonicBoom(dest)
  } else {
    return buildSafeSonicBoom({ dest, minLength: 0, sync: true })
  }
}

继续深挖发现当传参是sync: true时会调用fs.writeSync(process.stdout.fd去写日志, 可以理解为等同于console.log

// https://github.com/pinojs/sonic-boom/blob/1.x/index.js

if (sonic.sync) {
    try {
        const written = fs.writeSync(sonic.fd, buf, 'utf8')
        release(null, written)
    } catch (err) {
        release(err)
    }
} else {
    fs.write(sonic.fd, buf, 'utf8', release)
}

k8s 支持

最后询问了 k8s 的同学, 为什么一行同步输出的日志时延波动这么大？ k8s 同学给出的回答是我们的 Pod 上的标准输出会落到云盘中, 网络抖动就可能造成这样的波动

ChatGPT 支持

当然 k8s 的同学不会忽悠我, 但本着学习的心理让我们继续向 ChatGPT 🤖️ 来探索一下这个问题。当 k8s 标准输出落到云盘的场景中, 同步日志输出是否会阻塞程序直到云盘写入成功?

ChatGPT 🤖️: 在默认情况下，程序的标准输出日志是通过标准输出流（stdout）输出的，而标准输出流通常是实时输出的，即时写入到日志文件或云盘中。因此，当你在程序中打印一条日志时，它不会被阻塞到写入云盘直到成功。相反，它会尽快地写入到标准输出流中。
然而，具体的日志写入到云盘的速度取决于多个因素，如磁盘性能、网络延迟等。如果写入到云盘的速度较慢，可能会导致一些日志消息在写入过程中被堆积。这可能会导致程序的标准输出流缓冲区填满，从而导致程序阻塞或出现其他问题。

问题解决

通过传入sync: false来进行异步写入日志即可解决本次的问题

import pino from 'pino'

const logger = pino(opts, pino.destination({ sync: false }))

问题探索

这里一个疑问是 ChatGPT 指出同步输入日志会先写入缓冲区, 所以不会阻塞, 那么实际情况我们还是被阻塞了 15ms 了?

对 Node.js 源码比较了解的同学应该知道 Node.js 程序刚开始运行的代码中就通过 setvbuf 系统调用把缓冲区给禁止掉了...

// https://github.com/nodejs/node/blob/main/src/node.cc#L486

int main(int argc, char* argv[]) {
  // ...

  // Disable stdio buffering, it interacts poorly with printf()
  // calls elsewhere in the program (e.g., any logging from V8.)
  setvbuf(stdout, nullptr, _IONBF, 0);
  setvbuf(stderr, nullptr, _IONBF, 0);
  return node::Start(argc, argv);
}

所以我们把传参改为sync: false时, 看看 sonic-boom 是如何实现

虽然 Node.js 禁止了系统输出流的缓冲行为, 不代表 JavaScript 层面不可以通过把数据缓存在内存中进行模拟实现, 实际 sonic-boom 就是这样去做的

// https://github.com/nodejs/node/blob/main/src/node.cc#L486

SonicBoom.prototype.write = function (data) {
  if (this.destroyed) {
    throw new Error('SonicBoom destroyed')
  }

  this._buf += data
  const len = this._buf.length
  if (!this._writing && len > this.minLength) {
    actualWrite(this)
  }
  return len < 16384
}

最后要说明的一点是当 sonic-boom 设置的缓存数据上限后, 开始进行 i/o 写入操作时会有一个请求会被阻塞？

其实是不会的, 当达到设置的上限值 sonic-boom 会调用fs.write去异步写入日志, 而写入这个操作是在子线程中进行的, 故不会阻塞主线程, 这部分内容见我之前写的【libuv 源码学习笔记】线程池与i/o

fs.write(sonic.fd, buf, 'utf8', release)