一个 Node 占用 CPU 过高的问题定位过程

抛砖引玉，希望能帮到大家

起因

有天晚上，负责人跟我说有台机器负载很高，在一众服务器中显得格格不入。 看起来在 20% 左右徘徊，但是这台机器上的业务流量很少，不仅如此，用来给这台机器上业务容灾的 fex00 CPU 负载也不低，13% 左右。

铺垫一下

Node 模块的行为

在 Node 中，模块分为两类：

1. Node 提供的模块，已经是编译后二进制文件，部分核心模块直接加载进内存，可以称为”核心模块“
2. 用户编写的模块，可以称为”文件模块“

Node 引入过的模块都会进行缓存，而且缓存的是编译和执行之后的对象。无论是核心模块还是文件模块，require的方式对相同模块的二次加载都一律采用缓存优先的方式。

// lib/internal/modules/cjs/loader.js
const module = new Module(filename, parent);
Module._cache[filename] = module;

在 makeRequireFunction 中将缓存的引用指到了 require 对象上。

// lib/internal/modules/cjs/helpers.js
function makeRequireFunction(mod, redirects) {
  require.cache = Module._cache;
}

所以这也是为什么 Node 每次代码更新都需要重启，那有办法热重载么？

重载

习惯了现代 JS 技术栈的同学基本都用过一个功能：当代码更新时，自动刷新或者重启。

这个功能在开发阶段节约了不少时间和操作成本，以至于成为开发环境的标配。

服务器上部署的老服务同样也拥有这个功能。最简单的思路就是根据上文提到的 require 的 cache 属性，只要监听代码文件的变动，然后删除掉对应模块的缓存即可。

// 老框架的代码
function onChg(prev, now) {
    if (prev.mtime == now.mtime) return;
    delete require.cache[file];
}

但是这里隐藏一些问题：

// lib/internal/modules/cjs/loader.js
function updateChildren(parent, child, scan) {
  const children = parent && parent.children;
  if (children && !(scan && children.includes(child)))
    children.push(child);
}

如果有 parent，因为没有 Module._cache，再次 require 会将自身的引用 push 到 parent.children 这个数组中，所以有泄漏的风险。

进行假设

开始定位问题。

因为这台服务器上服务是混部的，先 htop 一下，看一下是哪个进程占用资源。然后用 lsof 命令找到这个进程的路径，确定是哪个项目之后查看日志。

然而，这个老项目并没有日志。

又查了下进程的输出

tail -f /proc/<PID>/fd/1

emmm，连输出都没有。

看下系统调用

strace -p <PID>

# 输出
futex(0x24a7fa4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x24a7fa0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x24a7f60, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x24a7fa4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x24a7fa0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x24a7f60, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x24a7fa4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x24a7fa0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x24a7f60, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x24a7fa4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x24a7fa0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x24a7f60, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x24a7fa4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x24a7fa0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x24a7f60, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x24a7fa4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x24a7fa0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x24a7f60, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x24a7fa4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x24a7fa0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x24a7f60, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x24a7fa4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x24a7fa0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1

成吨的 futex，奈何本人才疏学浅，没法顺着这个思路追查下去。

没想到啥能在线上不停止进程的方式定位问题，于是开始看源码，因为这个服务的框架是老一辈革命家内部研发，公司分拆之后更是没了文档。

虽然之前把他从 Node 的 0.12 升级到了10.14，感觉核心模块都看烂了，但是其他的工具模块没太深入。

把重心放到之前没研究的代码上，果然发现了几行奇怪的代码。

//为了理解方便，在源码的基础上修改
if (ENVIRONMENT==='dev') {
  var watcher = require('./lib/watchNode.js')
  var absDir = __dirname.replace(/\\/g, '/')
  watcher.takeCare([APP_PATH])
}

看这个模块的意思，应该是开发环境监听文件变化然后重启的，难不成是因为这个？

然后找到了线上 ENVIRONMENT 的值，人傻了，竟然是 dev。

恍然大悟，一定是在线上服务监听文件变化导致的。但是仔细一想有不严谨，这个路径下应该没有新文件产生呀。想不明白，继续往下定位。

验证假设

因为这个服务流量很小，推测可能和调用方无关，索性搭了个测试环境开始 debug。

幸运的是搭建好了之后测试环境可以重现线上的 bug。

先是想到了使用 perf。

node --perf_basic_prof index.js

生成一个 /tmp/perf-<PID>.map 文件，然后用工具生成一个火焰图。 再次触及知识盲区。

再换个办法，用 Tick Processor 试试。

node --prof index.js

在执行命令后生成了一个文件 isolate-0x3c9c4d0-v8-<PID>.log

node --prof-process isolate-0x3c9c4d0-v8-<PID>.log

# 输出
[JavaScript]:
   ticks  total  nonlib   name
     72    2.6%    2.7%  LazyCompile: *resolve path.js:1073:28
     20    0.7%    0.7%  Builtin: StringSubstring
     20    0.7%    0.7%  Builtin: StringAdd_CheckNone_NotTenured
     13    0.5%    0.5%  LazyCompile: *<anonymous> fs.js:153:18
 [C++]:
   ticks  total  nonlib   name
    287   10.5%   10.6%  __pthread_cond_signal
    265    9.7%    9.8%  uv_timer_stop
    230    8.4%    8.5%  __lll_unlock_wake
    156    5.7%    5.7%  __lll_lock_wait
    123    4.5%    4.5%  epoll_pwait
    120    4.4%    4.4%  __GI___libc_malloc
     92    3.4%    3.4%  __pthread_mutex_lock
     82    3.0%    3.0%  node::contextify::ContextifyScript::New(v8::FunctionCallbackInfo<v8::Value> const&)
     79    2.9%    2.9%  uv_timer_start
     53    1.9%    2.0%  _int_free
     52    1.9%    1.9%  timer_cb
     52    1.9%    1.9%  node::StatWatcher::New(v8::FunctionCallbackInfo<v8::Value> const&)
     49    1.8%    1.8%  __GI___libc_free
     46    1.7%    1.7%  _int_malloc
     37    1.4%    1.4%  node::fs::NewFSReqWrap(v8::FunctionCallbackInfo<v8::Value> const&)
 [Bottom up (heavy) profile]:
  Note: percentage shows a share of a particular caller in the total
  amount of its parent calls.
  Callers occupying less than 1.0% are not shown.

   ticks parent  name
    287   10.5%  __pthread_cond_signal
     80   27.9%    LazyCompile: *<anonymous> /home/work/hornbill/nest/server/lib/watchNode.js:32:25
     80  100.0%      Builtin: ArrayForEach
     80  100.0%        LazyCompile: ~<anonymous> /home/work/hornbill/nest/server/lib/watchNode.js:29:26
     80  100.0%          LazyCompile: ~<anonymous> fs.js:140:18
     79   27.5%    LazyCompile: *<anonymous> /home/work/hornbill/nest/server/lib/watchNode.js:34:27
     79  100.0%      LazyCompile: *<anonymous> fs.js:153:18

被 watchNode.js 这个文件刷屏，感觉被我猜中了，开心。

仔细一看，咦，和我最开始预想的不太一样，怎么是大量的数组的 forEach 方法，看了下代码，难不成是因为监听的文件太多了？

跑了个小脚本算了下，懵了，5 万多个文件正在被监听，并且有 24 个进程在做同样的事情。

Using fs.watch() is more efficient than fs.watchFile and fs.unwatchFile. fs.watch should be used instead of fs.watchFile and fs.unwatchFile when possible.

虽然这个框架用的 fs.watchFile 来监听文件变化，并且 Node 文档也表示尽量使用 fs.watch，所以 fs.watchFile fs.watch 究竟做了什么，真的是他们导致系统大量调用 futex？

书到用时方恨少

fs.watchFile

在 Node 源码中，依次沿着 lib/fs.js → lib/internal/fs/watcher.js → src/node_stat_watcher.cc → deps/uv/src/fs-poll.c 找到 uv_fs_poll_start，然后是里面 uv_fs_stat 里的回调 poll_cb。

/* 一看注释就明白了 */
/* Reschedule timer, subtract the delay from doing the stat(). */
  interval = ctx->interval;
  interval -= (uv_now(ctx->loop) - ctx->start_time) % interval;

  if (uv_timer_start(&ctx->timer_handle, timer_cb, interval, 0))
    abort();

好家伙合着是一个定时轮询。

fs.watch

相比上一个 api 这个就好找一些

依次沿着 lib/fs.js → lib/internal/fs/watcher.js → src/fs_event_wrap.cc 里的 uv_fs_event_init。

好多文件都有着函数定义，Node 文档，找一下 linux 的，使用的操作系统的 inotify。

翻 Node 源码耗费了不少时间，但也不是无功而返。从上面的分析可以知道，因为这个框架用了 fs.watchFile 这个 API，这就可以解释，为什么火焰图里有大量的 fsstat 的调用：可能是一个定时器然后不断的按时查看文件的状态。

书到用时方恨少，至于为什么有大量的 futex，推测可能和海量的 fsstat 调用有关系吧。

总结

引发这次事故的原因是一个及其低级的失误：用错了配置文件。然而这个 bug 就这么运行了五六年，没有任何人注意到这个问题。

好在我们的基础架构组在不断地完善基础设施，让本来隐藏的问题重见天日。不仅如此，在过去 2 年，前端组一直在使用新的技术栈替换老项目，并引以为戒，花费大力气在文档、监控、发布部署流程等工程链路上。

虽然问题解决了，但是还有海量的相关知识要去了解，继续努力吧。

参考链接

linuxtools-rst.readthedocs.io/zh_CN/lates…

www.zhangyunling.com/448.html

tech.nitoyon.com/en/blog/201…

nodejs.org/api/fs.html

linuxtools-rst.readthedocs.io/zh_CN/lates…

groups.google.com/g/nodejs/c/…

stackoverflow.com/questions/5…

fex.baidu.com/blog/2015/0…

github.com/Kimi-Gao/Pr…

zhuanlan.zhihu.com/p/34702356

segmentfault.com/a/119000001…

www.spaghettiml.com/en/2019/01/…

blog.csdn.net/wuheshi/art…

www.cnblogs.com/sunsky303/p…

stackoverflow.com/questions/9…

github.com/nswbmw/node…