Node.js 进程偶现的 CPU 占用 100% 排查

image

问题背景

y 同学反映电脑换成 M2 后，使用 nopack 开发时经常会出现 CPU 占用 100% 的情况，已经严重影响到了开发效率

nopack: 公司内部的一个 bundless 工具，已支持 100+ 应用近 2年，相关分享见: 2021-10-14 凯多 巨石应用解决方案 nopack

相比于 webpack 这样的 bundler 📦 打包后产物只有少量的文件，Vite 与 nopack 这样的 bundless ⚡️ 工具不会在开发模式下打包应用的源代码。 这两者是基于浏览器 native ES Modules，这样的模式让热更新无比的快速，因为只需编译转换一个文件，不用像 bundler 那样从头开始打包

所以 bundless 工具开发模式下往往会出现大量的小文件请求，对于性能较差的电脑 Google Chrome 进程出现短暂的 CPU 占用 100% 的情况还是比较常见

该同学使用的是最强 M2，问题表现是 nopack 进程偶现 CPU 占用 100% 且不会下降，这属实让人一下难以接受

问题排查

一开始只能要 y 同学通过 node –cpu-prof 选项去启动 nopack，当程序退出时希望够从自动生成的 .cpuprofile 文件中找到突破口

–cpu-prof: Starts the V8 CPU profiler on start up, and writes the CPU profile to disk before exit.

image

遗憾的是如上图 .cpuprofile 文件中未能发现 🔍 有占用 CPU 过高的函数，没有发现较大价值的线索。另一个问题是 10次退出程序中大概只有 1次会生成 .cpuprofile 文件 🥲，分析文件的生成也不稳定 …

下一步的排查中我在 nopack 代码中加入了如下的心跳检测代码，确认进程是不是真瘫痪了

1
2
3
setInterval((){
    console.log('我还活着 ...')
}, 1000)

结果是当 CPU 占用到了 100% 时，setInterval 里面的 console 也停止了，此时基本确认了进程可能陷入了某种致命错误或者死循环中，这大概率是程序的 bug 了 🐛

最后只能寄希望于调试利器 lldb 了，来看看进程卡死后，最后运行的代码是什么

lldb: 是 macOS 和 iOS 平台下的一款命令行调试工具，它允许开发者在本地调试运行中的应用程序。lldb 使用了 gdb 的语法和命令，但是提供了更多的功能和本地调试器的支持，比如可以调试原生框架和 C++ 代码。

通过 lldb 线程的堆栈回溯，发现了最后堆栈的停留在了 node::http2::Http2Session::OnStreamClose 函数调用，这是一个很可疑的点

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
* thread #1, name = 'nopack', queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
  * frame #0: 0x0000000181249024 libsystem_malloc.dylib`tiny_malloc_should_clear + 56
    frame #1: 0x0000000181247cac libsystem_malloc.dylib`szone_malloc_should_clear + 92
    frame #2: 0x00000001813b88b0 libc++abi.dylib`operator new(unsigned long) + 32
    frame #3: 0x0000000102b59968 node`node::http2::Http2Session::OnStreamClose(nghttp2_session*, int, unsigned int, void*) + 300
    frame #4: 0x0000000102ae3af8 node`node::Environment::RunAndClearNativeImmediates(bool)::$_8::operator()(node::CallbackQueue<void, node::Environment*>*) const + 100
    frame #5: 0x0000000102ae3094 node`node::Environment::RunAndClearNativeImmediates(bool) + 404
    frame #6: 0x0000000102ae2a6c node`node::Environment::CheckImmediate(uv_check_s*) + 308
    frame #7: 0x00000001033a5850 node`uv__run_check + 152
    frame #8: 0x000000010339f5ac node`uv_run + 396
    frame #9: 0x0000000102a896d4 node`node::SpinEventLoop(node::Environment*) + 244
    frame #10: 0x0000000102b75138 node`node::NodeMainInstance::Run(int*, node::Environment*) + 120
    frame #11: 0x0000000102b74e18 node`node::NodeMainInstance::Run() + 112
    frame #12: 0x0000000102b0c994 node`node::Start(int, char**) + 224
    frame #13: 0x00000001810d3e50 dyld`start + 2544

因为对比一个正常运行的 nopack 进程的堆栈回溯时，已经运行结束的 node::http2::Http2Session::OnStreamClose 等函数就没有出现在如下的堆栈中

1
2
3
4
5
6
7
8
9
* thread #1, name = 'nopack', queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
  * frame #0: 0x00000001b7bab8cc libsystem_kernel.dylib`kevent + 8
    frame #1: 0x0000000104b17ea8 node`uv__io_poll + 764
    frame #2: 0x0000000104b066d0 node`uv_run + 380
    frame #3: 0x00000001041e2ccc node`node::SpinEventLoop(node::Environment*) + 244
    frame #4: 0x00000001042ce5b0 node`node::NodeMainInstance::Run(int*, node::Environment*) + 120
    frame #5: 0x00000001042ce27c node`node::NodeMainInstance::Run(node::EnvSerializeInfo const*) + 120
    frame #6: 0x0000000104267080 node`node::Start(int, char**) + 184
    frame #7: 0x0000000108e410f4 dyld`start + 520

前面说了 bundless 工具开发模式下往往会出现大量的小文件请求，所以 nopack 默认是 http2 协议启动，相比于 http1 协议能够大幅提升并发请求

而这里显示停留在了 Node.js http2 的 OnStreamClose 方法，如果尝试使用 http1 协议来启动没有问题就说明了 CPU 占用 100% 极有可能是 Node.js http2 在 M2 中的一个 bug

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
// src/node_http2.cc

int Http2Session::OnStreamClose(nghttp2_session* handle,
                                int32_t id,
                                uint32_t code,
                                void* user_data) {
  Http2Session* session = static_cast<Http2Session*>(user_data);
  Environment* env = session->env();
  Isolate* isolate = env->isolate();
  HandleScope scope(isolate);
  Local<Context> context = env->context();
  Context::Scope context_scope(context);
  Debug(session, "stream %d closed with code: %d", id, code);
  BaseObjectPtr<Http2Stream> stream = session->FindStream(id);
  // Intentionally ignore the callback if the stream does not exist or has
  // already been destroyed
  if (!stream || stream->is_destroyed())
    return 0;

  stream->Close(code);

  // It is possible for the stream close to occur before the stream is
  // ever passed on to the javascript side. If that happens, the callback
  // will return false.
  Local<Value> arg = Integer::NewFromUnsigned(isolate, code);
  MaybeLocal<Value> answer =
    stream->MakeCallback(env->http2session_on_stream_close_function(),
                          1, &arg);
  if (answer.IsEmpty() || answer.ToLocalChecked()->IsFalse()) {
    // Skip to destroy
    stream->Destroy();
  }
  return 0;
}

问题小结

使用 http1 协议后暂未能再复现 CPU 占用 100% 的问题，至于是不是 Node.js http2 的 bug，还需打个 Node.js debug 包来进行排查与确认，只能后续需求不忙再跟进了

image