Node.js 读取 Error.stack 属性耗时过长导致的性能问题

image

问题背景

最近其他团队交接过来一个 Node.js 服务, 在完成该服务的技术架构迁移后发现了一个奇怪的现象, 表现是代码发布上线后第一次请求该服务 100% 会超时 (延时超过 2000ms), 第二次及以后的请求恢复正常 (延时稳定在 600ms 左右)。

问题排查

Cat Transaction

首先查看 Cat 延时监控来确认是上游依赖的接口超时还是 Node.js 代码运行卡住导致的超时。插曲是第一次请求超时的记录却丢失了, 花了一些时间先排查解决了基础上报库的 bug。
image

非真实监控图, 示例图来自 cat/wiki/transaction

记录丢失问题修复后发现上游依赖的接口的第一次耗时也就 600ms 左右, 那超时的原因只能是 Node.js 的某些代码存在严重的性能问题, 卡住了 JS 的主线程 1400ms +。

Error.stack

接着对大量可疑的代码进行了埋点, 最终定位到如下仅一行代码 ❌ this.stack = new Error().stack; 运行耗时约 1600ms

1
2
3
4
5
6
export function TestError(message = 'TestError') {
  this.name = 'TestError';
  this.message = message;
  this.errorCode = 100;
  this.stack = new Error().stack;
}

当我给出这个排查结果时大家都是不敢相信, 确实读取一个 Error 对象的 stack 属性能有这么大的能量 ?

紧接着我本地运行该 Node.js 服务来复现, 发现自己的 M1 电脑第一次运行这行代码也花费了约 1200ms, 第二次及以后基本就是 1ms 或者 0.x ms 可以忽略不计了。

Performance

定位 JS 代码性能比较好用的就是火焰图了, 我们可以使用下面的命令通过调试模式启动该服务

1
node --inspect you-app.js

image

随着调用堆栈的展示, Error.stack 的真相才慢慢浮出水面

Call Tree

从调用堆栈我们发现了当运行 Error.stack 这行代码时,

  1. 首先会运行 Node.js 源码中的 prepareStackTrace 函数, prepareStackTrace 函数会判断是否有全局被复写的实现, 如果有则调用

    image

  2. 而该项目依赖的 source-map-support 库正好复写了 Error.prepareStackTrace 的值

    image

  3. source-map-support 库的 prepareStackTrace 函数则会读取报错的文件获取到该文件的 sourceMap 的地址最后把错误堆栈反解指向原始文件 (通常 js 文件的最后一行是 sourceMap 的地址)。比如代码打包后报错文件名是 dist/app.js 则可以把报错堆栈文件名改为 src/app.ts

    image

  4. 好家伙这个报错的文件有 11MB 使得文件的同步读取操作以及后续的 sourceMap 反解操作一下把耗时怼上去了, 在性能差电脑上尤其明显。注意上图代码 fileContentsCache 等缓存使得第二次及以后运行性能不受影响
    image

问题探索

最后我们再说一下运行 Error.stack 代码后为什么会先运行 Node.js 源码中的 prepareStackTrace 函数 ?

  1. Node.js 源码启动时中调用了 setPrepareStackTraceCallback 函数, 参数是 prepareStackTrace 函数

    1
    2
    3
    // https://github.com/nodejs/node/blob/v12.13.1/lib/internal/bootstrap/node.js#L314C3-L314C51

    setPrepareStackTraceCallback(prepareStackTrace);

  2. SetPrepareStackTraceCallback 函数内部会调用 set_prepare_stack_trace_callback 函数把传入的参数 prepareStackTrace 函数保存下来

    1
    2
    3
    4
    5
    6
    7
    // https://github.com/nodejs/node/blob/v12.13.1/src/node_errors.cc#L819

    void SetPrepareStackTraceCallback(const FunctionCallbackInfo<Value>& args) {
      Environment* env = Environment::GetCurrent(args);
      CHECK(args[0]->IsFunction());
      env->set_prepare_stack_trace_callback(args[0].As<Function>());
    }

  3. Node.js 源码启动时会调用 v8 的 SetPrepareStackTraceCallback API 设置当读取 Error.stack 时的回调函数为 PrepareStackTraceCallback, PrepareStackTraceCallback 内部则会调用步骤 2 与 步骤 1 中传入的 prepareStackTrace 函数

    1
    2
    3
    // https://github.com/nodejs/node/blob/v12.13.1/src/api/environment.cc#L199

    isolate->SetPrepareStackTraceCallback(PrepareStackTraceCallback);
    image

问题结论

由于 v8 的 SetPrepareStackTraceCallback API 提供的底层能力让用户可以设置读取 Error.stack 属性时的回调, 相当于 JS Object 设置 getter 函数, 使得一些库比如 source-map-support 复写了 Error.prepareStackTrace 的值将可能导致预期外的性能问题。

更多关于 v8 Stack trace API 的内容见: Customizing stack traces