NodeJs进程出现CPU100%解决方案

在此之前我们，我们尝试在Nodejs服务端增加接口访问日志以及去掉setTimeout超时请求，以及htop，pm2 monit，pref分析命令，并没有得到很有用的信息。
不过有意思的是 pref 将占用 cpu 的 v8 底层函数给暴露了出来，因为我只看得懂这个（node:internal/timers），它代表的时定时，而在prof 分析报告中也出现了它。如下是prof分析过程:

一旦nodejs进程出现cpu100% ，整个nodejs进程无法进行任何操作和试图获取cpu信息。

• 因为我们的js它是运行在v8中，且在使用额外的工具(pref 等其他对linux分析工具)获取Nodejs进程信息时看到的是v8的底层信息，对排查cpu没有实质性的帮助。
• 之前有装过一个easy-monitor2.0，其中的堆内存分析和cpu性能分析可在需要的情况下进行性能分析并生成分析报告，但是在cpu100%情况下是无法做任何处理，因为nodejs主进程已经完全爆了，所有状态都是死的情况。

在nodejs进程中如果遇到cpu100%，可使用如下方式去做cpu性能分析

官方地址：https://nodejs.org/en/docs/guides/simple-profiling/

// 启动nodejs进程，她会生成一个刻度文件，isolate-0xnnnnnnnnnnnn-v8.log（其中n是数字）。
node --prof index.js

//为了理解这个文件，我们需要使用与 Node.js 二进制文件捆绑在一起的滴答处理器。要运行处理器，请使用以下--prof-process
node --prof-process isolate-0xnnnnnnnnnnnn-v8.log > processed.txt

在使用prof时也要关切一下服务器内存情况，因为这次的事件需要在线运行24小时以上才出现cpu暴涨为100%，这时这个刻度文件达到了36GB，对是GB，然后我们分析这个刻度文件时，足足运行了将近5个小时才将这个刻度文件分析完成，所以我想说的时，如果刻度文件较大时，请耐心等待。

在您最喜欢的文本编辑器中打开 processes.txt 将为您提供几种不同类型的信息。该文件被分成多个部分，这些部分再次按语言分解。首先，我们看一下总结部分，看看：

 [Summary]:
   ticks  total  nonlib   name
  97957613   40.7%   98.1%  JavaScript
      0    0.0%    0.0%  C++
  10968298    4.6%   11.0%  GC
  141025140   58.6%          Shared libraries
  1851007    0.8%          Unaccounted

这告诉我们，收集到的所有样本中有 40.7% 发生在 JavaScript 代码中 及 58.6% 发生在 Shared libraries，并且在查看处理输出的其他部分时，我们应该最注意在 JavaScript，Shared libraries中完成的工作（C++）。考虑到这一点，我们接下来找到 [JavaScript，Shared libraries] 部分，其中包含有关哪些 [JavaScript，Shared libraries] 函数占用最多 CPU 时间的信息，并查看：

[Shared libraries]:
   ticks  total  nonlib   name
  136455210   56.7%          /usr/local/bin/node
  3967618    1.6%          /usr/lib64/libc-2.17.so
  244447    0.1%          /usr/lib64/libpthread-2.17.so
  194011    0.1%          [vdso]
  157122    0.1%          /usr/lib64/libstdc++.so.6.0.19
   6732    0.0%          /usr/lib64/libm-2.17.so

我们看到前 2 个条目占程序占用的 CPU 时间的 58.4%。从这个输出中，我们立即看到至少56.7% 的 CPU 时间被一个名为 /usr/local/bin/node 进程占用，接下来找到 JavaScript 部分CPU 时间的信息，并查看：

[JavaScript]:
   ticks  total  nonlib   name
  46484414   19.3%   46.6%  LazyCompile: *indexes /opt/apptrace/platform/fusion/node_modules/lru-cache/index.js:420:11
  35124819   14.6%   35.2%  LazyCompile: *<anonymous> /opt/apptrace/platform/fusion/src/common/memoryStore.js:37:26
  16263249    6.8%   16.3%  LazyCompile: *forEach /opt/apptrace/platform/fusion/node_modules/lru-cache/index.js:505:10
  44101    0.0%    0.0%  LazyCompile: *<anonymous> /usr/local/lib/node_modules/pm2/node_modules/@pm2/io/build/main/utils/metrics/histogram.js:55:28
   4444    0.0%    0.0%  LazyCompile: *handler /usr/local/lib/node_modules/pm2/node_modules/@pm2/io/build/main/metrics/httpMetrics.js:52:22
   4231    0.0%    0.0%  LazyCompile: *handler /usr/local/lib/node_modules/pm2/node_modules/@pm2/io/build/main/metrics/eventLoopMetrics.js:63:31
   1451    0.0%    0.0%  LazyCompile: *handler /usr/local/lib/node_modules/pm2/node_modules/@pm2/io/build/main/metrics/eventLoopMetrics.js:77:31
   1208    0.0%    0.0%  LazyCompile: *listOnTimeout node:internal/timers:507:25
   1153    0.0%    0.0%  LazyCompile: *next /opt/apptrace/platform/fusion/node_modules/express/lib/router/index.js:177:16
    953    0.0%    0.0%  LazyCompile: *handler /usr/local/lib/node_modules/pm2/node_modules/@pm2/io/build/main/metrics/httpMetrics.js:63:22

我们看到前 3 个条目占程序占用的 CPU 时间的 97%。从这个输出中，我们立即看到至少 62.8% 的 CPU 时间被一个名为 fusion/node_modules/lru-cache/index.js:420:11 的库占用，该库是做缓存用的。然而，较低的两个条目如何影响我们的应用程序可能不是很明显（或者如果是，我们将假装为其他示例）。为了更好地理解这些函数之间的关系，我们接下来将查看 [Bottom up (heavy) profile] 部分，该部分提供有关每个函数的主要调用者的信息。检查本节，我们发现：

 ticks parent  name
  136455210   56.7%  /usr/local/bin/node
  35960514   26.4%    LazyCompile: *indexes /opt/apptrace/platform/fusion/node_modules/lru-cache/index.js:420:11
  35960514  100.0%      /usr/local/bin/node
  35960514  100.0%        LazyCompile: *forEach /opt/apptrace/platform/fusion/node_modules/lru-cache/index.js:505:10
  35960514  100.0%          LazyCompile: ~prune /opt/apptrace/platform/fusion/src/common/memoryStore.js:35:15
  35960514  100.0%            LazyCompile: ~<anonymous> /opt/apptrace/platform/fusion/src/common/memoryStore.js:302:50
  32162757   23.6%    LazyCompile: *<anonymous> /opt/apptrace/platform/fusion/src/common/memoryStore.js:37:26
  32162757  100.0%      LazyCompile: *forEach /opt/apptrace/platform/fusion/node_modules/lru-cache/index.js:505:10
  32162757  100.0%        LazyCompile: ~prune /opt/apptrace/platform/fusion/src/common/memoryStore.js:35:15
  32162757  100.0%          LazyCompile: ~<anonymous> /opt/apptrace/platform/fusion/src/common/memoryStore.js:302:50
  32162757  100.0%            LazyCompile: *listOnTimeout node:internal/timers:507:25
  28583278   20.9%    /usr/local/bin/node
  13587234   47.5%      LazyCompile: *indexes /opt/apptrace/platform/fusion/node_modules/lru-cache/index.js:420:11
  13587234  100.0%        /usr/local/bin/node
  13587234  100.0%          LazyCompile: *forEach /opt/apptrace/platform/fusion/node_modules/lru-cache/index.js:505:10
  13587234  100.0%            LazyCompile: ~prune /opt/apptrace/platform/fusion/src/common/memoryStore.js:35:15
  12992671   45.5%      LazyCompile: *<anonymous> /opt/apptrace/platform/fusion/src/common/memoryStore.js:37:26
  12992671  100.0%        LazyCompile: *forEach /opt/apptrace/platform/fusion/node_modules/lru-cache/index.js:505:10
  12992671  100.0%          LazyCompile: ~prune /opt/apptrace/platform/fusion/src/common/memoryStore.js:35:15
  12992671  100.0%            LazyCompile: ~<anonymous> /opt/apptrace/platform/fusion/src

解析这部分比上面的原始滴答计数需要更多的工作。在上面的每个“调用堆栈”中，父列中的百分比告诉您上面行中的函数被当前行中的函数调用的样本的百分比。例如，在上面 indexes 的中间“调用堆栈”中，我们看到indexes发生在 19.3% 的样本中，这是我们从上面的原始计数中得知的。但是，在这里，我们也可以看出它总是由 Node.js lru-cache缓存模块中的 *forEach 函数调用,而 forEach 由 ~prune 调用。我们同样看到， 几乎完全由相同的 *forEach > ~prune 函数调用。因此，使用此视图中的信息，我们可以看出，我们使用的 lru-cache 模块不仅占了上面的 26.4%，而且还占了自调用 *indexes 和 * 进行以来前 3 个采样最多的函数中的所有 CPU 时间代表 *forEach 函数。我们查看：

// src/common/memoryStore.js
var LRU = require("lru-cache");
...
function prune(store) {
  debug("Pruning expired entries");
  store.forEach(function (value, key) {
    store.get(key);
  });
}
...
function MemoryStore(options) {
    ...
    this.store = new LRU(this.options);
    ...
 }
...

至此，很明显，以memoryStore.js 文件中的 ~prune 函数为起点，~prune > *forEch > *indexes(lru-cache)，~prune > *forEch > *(lru-cache) 应该是我们优化的目标。

根据我们的排查结果是：我们之前使用的lru-cache版本为5.1.1，而后续将 lru-cache 升级为7.14.0版本。
这时我们怀疑是版本的问题，所以我们将版本退回至5.1.1进行验证，果然问题得到了解决。

根据 lru-cache 的官网文档显示7.1版本之后内部的结构及程序比5.1.1版本有非常大的改变，我们便查看了源码，确实如此，如果要使用更高的版本我们得需要将memoryStore.js中的逻辑进行改造。

这次事件也反映处一个问题，我们在追求新版本的同时也要做足相应的研究和了解。