关于node.js:Node-CPU-偶发100-排查小结

博文开始前，先贴下本文目录，次要篇幅在第二局部：如何定位。

外部管理系统，Node.js 我的项目线上运行始终稳固、失常，某天开始应用人员反馈系统拜访卡顿，同时对应服务器呈现 CPU 占用 95% ~ 120% 过高的钉钉告警，超过 100% 是因为对应 Linux 服务器是多核，呈现后 1~5 分钟后失常，偶发呈现，这次问题持续时间较长，参考、浏览了不少文章，写个博文记录、总结下。

问题呈现 ~ 解决工夫 2021.07.21 ~ 2021.08.01

先说下外部零碎技术架构，前端 React，后端 NodeJS 框架 Egg.js(Koa2 封装)。所以监控定位时有些 NodeJs 库不适宜接入，这个第二局部具体讲。

NodeJs 我的项目呈现 CPU 占用 100% 以上时，登录对应服务器命令行 top -c 查看以后服务器哪个过程占用 CPU 最高！

对于偶发场景，不可能始终开着终端，且呈现问题了没有监控告警，无奈晓得呈现问题的具体工夫，不不便定位解决问题。

所以须要接入性能监控平台，具体可看如何接入 Node 监控平台 – alinode，咱们是外部服务器部署了 aliNode，操作界面差不多。接入胜利后，呈现 CPU 过高时有以下图表：

当然也有其余 Node.js 插件能实现相似的监控，具体参考：NodeJs 调试指南，接入胜利后次要看两项：火焰图 和 GC Trace（垃圾回收跟踪）

火焰图（Flame Graph）大家应该听过，它能够将 CPU 的应用状况可视化，使咱们直观地理解到程序的性能瓶颈。咱们通常要联合操作系统的性能剖析工具（profiling tracer）应用火焰图，常见的操作系统的性能剖析工具如下：

Linux：perf, eBPF, SystemTap, and ktap。Solaris, illumos, FreeBSD：DTrace。Mac OS X：DTrace and Instruments。Windows：Xperf.exe。

如果未接入 NodeJs 性能监控，得在服务器（个别是 Linux）装置以上剖析工具；

接入 NodeJs 性能监控后能一键导出 火焰图，了解火焰图网上很多教程，例如：疾速定位 NodeJs 线上问题 – 之火焰图篇

实践上通过 火焰图 能具体定位到具体是哪一行代码导致 CPU 过高。

然而，这边实际发现火焰图两问题：

例如 Node 性能监控上“抓取性能数据”– 生成火焰图，生成的是 最近 5 分钟 的火焰图，呈现问题（看到钉钉告警）再下来“抓取”生成的可能是失常运行代码的 火焰图。

即便 CPU 过高问题继续很久，“抓取”的是异样运行状态下的 火焰图 ，也有可能发现生成的图不对劲，无奈与咱们业务代码锲合，这边就遇到生成的 火焰图 无奈定位到具体代码（-_-||。

不同我的项目不一样，或者 火焰图 能帮忙大家定位到具体代码。

顺便说下，Node 性能监控平台个别能导出 火焰图 文件，导出的文件名如：u-c3979add-7db3-4365-b1ed-9a2556b6a320-u-x-cpuprofile-4012-20210730-241648.cpuprofile, 在 Chrome 上可导入：

Node 底层 V8 引擎的垃圾回收个别跟内存相干，为什么 CPU 过高要看垃圾回收跟踪数据？

因为 NodeJs 内存泄露 会导致超过 V8 引擎垃圾回收最大内存（1.4G），进而重启 V8 GC 导致 CPU 100%。

默认状况下，32 位零碎新生代内存大小为 16MB，老生代内存大小为 700MB，64 位零碎下，新生代内存大小为 32MB，老生代内存大小为 1.4GB。

当然可批改 V8 垃圾回收最大内存上限值：

# node 在启动时能够传递参数来调整限度内存大小。以下形式就调整了 node 的应用内存
node --max-old-space-size=1700 // 单位是 MB
node --max_semi_space_size=1024 // 单位是 KB

以下截图内容引自 Node.js 利用故障排查手册，思考脱敏就不必外部监控零碎截图。

Node 性能监控平台，默认会抓取 5 分钟的对应过程的 GC 日志信息，等到完结后生成的文件会显示在文件页面：

此时点击转储即可上传到云端以供在线剖析展现了，如下图所示：

最初点击这里的剖析按钮，即可看到 AliNode 定制后的 GC 信息剖析后果的展示：

后果展现中，能够比拟不便的看到问题过程的 GC 具体次数，GC 类型以及每次 GC 的消耗工夫等信息，不便咱们进一步的剖析定位。比方这次问题的 GC Trace 后果剖析图中，咱们能够看到红圈起来的几个重要信息：

GC 总暂停工夫高达 47.8s，大头是 Scavenge
3min 的 GC 追踪日志外面，总共进行了 988 次的 Scavenge 回收
每次 Scavenge 耗时均值在 50 ~ 60ms 之间
从这些解困中咱们能够看到此次 GC 案例的问题点集中在 Scavenge 回收阶段，即新生代的内存回收。那么通过翻阅 V8 的 Scavenge 回收逻辑能够晓得，这个阶段触发回收的条件是：Semi space allocation failed。

这样就能够揣测，咱们的利用在压测期间应该是在新生代频繁生成了大量的小对象，导致默认的 Semi space 总是处于很快被填满从而触发 Flip 的状态，这才会呈现在 GC 追踪期间这么多的 Scavenge 回收和对应的 CPU 消耗，这样这个问题就变为如何去优化新生代的 GC 来晋升利用性能。

这里可能有同学看不懂 Scavenge GC 和 Mark-sweep GC。
具体到业务代码来说 Scavenge GC 就是一些占用内存比拟小的长期变量回收解决。
而 Mark-sweep GC 是占用内存小的全局变量或占用内存大的长期变量回收解决。

总的来说，只有呈现 GC Trace（垃圾回收跟踪）工夫过长，个别都是 内存泄露 导致超过 V8 引擎垃圾回收最大内存（1.4G）进而重启 V8 GC 导致 CPU 100%。

具体看深入浅出 Node(第五章内存管制) – 微信读书，国内最经典的 NodeJS 书籍《深入浅出 Node》尽管是 2013 年 12 月 1 日出版，但对于 V8 引擎垃圾回收机制内容放当初也不过时，V8 引擎官网最近对于垃圾回收机制更新（2019 – V8 引擎官网：GC 算法更新）内容根本没变，只是Mark-sweep GC 阶段增加了三优化机制。

这边场景，察看到 GC Trace 相干数据失常，所以排除 内存泄露 导致 CPU 过高。

通过 火焰图 和 GC Trace 还是无奈定位到具体代码怎么办？每天都会呈现 2 ~ 3 次，狐疑是服务器其余服务影响，也思考到须要多台服务器来重现模仿问题。

所以跟运维申请全新的一台服务器，配置能够低一些，次要用于排除烦扰。

在新服务器部署代码后，将拜访域名独自映射到新服务器，而后持续察看是否呈现 CPU 飙高状况。论断是新服务器运行的代码还是呈现 CPU 占用 100% 以上状况：

当然独自服务器的 CPU 趋势更加的直观，失常运行 CPU 占用率为 1 ~ 5%。

为什么域名只映射到这台新服务器？次要不便增加、查看日志，多台服务器的话用户拜访记录太扩散，徒增剖析、整顿日志工夫老本。

EggJs 日志 API 可记录用户每次拜访的页面，或二级页面弹层时加载数据等 API 数据申请；

在中间件增加记录拜访日志代码，动态文件申请疏忽。

// app -> middleware -> init.ts 
if (!reqPath.includes('/public/')) {ctx.logger.warn('reqPath:', reqPath);
}

增加胜利后日志中，蕴含“WARN”就是用户拜访历史记录：

备注：增加用户历史拜访后，日志体积会增大，咱们外部零碎拜访的人不多，每天大略产生 3M 日志数据，可思考增加定时清理日志脚本，每天定时清理。

egg 定时工作 API，对应清理日志脚本：

import {Subscription} from 'egg';
import * as fs from 'fs';
import * as child_process from 'child_process';

const CLEAR_WHITE_LIST = ['common-error.log', 'my_app-web.log']; // 保留日志白名单
class ClearLogs extends Subscription {static get schedule() {
    return {
      cron: '0 30 7 * * *', // 每天查看一次
      type: 'worker', // 每台机器，随机指定某个过程进行执行定时工作
      // immediate: true,  // 为 true 时, 启动时间接执行
    };
  }
  /**
   * subscribe 是真正定时工作执行时被运行的函数
   */
  async subscribe() {const { ctx} = this;
    ctx.logger.info('开始清理日志！');
    this.clearLog();}
  async clearLog() {const { ctx} = this;
    const loggerPath = ctx.app.config.logger.dir; // eg: /home/webserver/logs/logger/flat_cms/prod
    ctx.logger.info('loggerPath:', loggerPath);
    const twoCount = (count: number) => {return count < 10 ? '0' + count : count.toString();
    };

    // 删除文件、文件夹
    const unlinkFile = (logNameList: string[], subDirPath: string) => {// console.log('保留文件列表 - logNameList:', logNameList);
      const subFiles = fs.readdirSync(subDirPath);
      subFiles.forEach(fileName => {const filePath = `${subDirPath}/${fileName}`;
        const state = fs.statSync(filePath);
        if (state.isFile()) {if (!logNameList.includes(fileName)) {fs.unlinkSync(filePath);
            // console.log('删除文件：', fileName);
          }
        } else if (state.isDirectory()) {const workerProcess = child_process.exec(`rm -rf ${filePath}`, 
            (error:any) => {if (error) {ctx.logger.info('删除文件夹异样 Error code:' + error.code)
              }
            });
          workerProcess.on('exit', function (code) {ctx.logger.info('子过程已退出，退出码' + code);
          })
        }
      });
    };
    // 获取最近三天 日志文件
    const logNameList: string[] = []; 
    CLEAR_WHITE_LIST.forEach((logPath)=> {logNameList.push(logPath); // eg: common-error.log
    });
    [new Date(Date.now() - 3600 * 1000 * 24 * 2), new Date(Date.now() - 3600 * 1000 * 24), new Date()].forEach(timeObj => {const logSuffix = `${timeObj.getFullYear()}-${twoCount(timeObj.getMonth() + 1)}-${twoCount(timeObj.getDate())}`; // 简略日期解决, 不必 moment 模块
      CLEAR_WHITE_LIST.forEach((logPath)=> {const logName = `${logPath}.${logSuffix}`; // eg: common-error.log.2021-03-06
        logNameList.push(logName);
      });
    });

    unlinkFile(logNameList, loggerPath);
    ctx.logger.info('清理日志完结！');
  }
}

module.exports = ClearLogs;

接入 NodeJS 性能监控后，CPU 过高时有钉钉告警，而后通过 CPU 趋势图可定位到 CPU 占用过高前分钟级别的细粒度信息，例如：确定 2021.07.29 17:30 ~ 2021.07.29 17:32 这段时间内 CPU 异样。

联合这段时间内用户拜访历史，可整顿放大范畴，晓得拜访了哪些页面、申请了哪些 API 接口导致 CPU 过高。

一次可能看不出，每次呈现整顿一份日志记录，多份数据比照可进一步放大拜访哪些页面导致 CPU 过高问题范畴。

有了日志比照，可模仿拜访页面，同时登陆服务器运行指令：top -c 察看 CPU 运行状况，拜访上述整顿呈现 CPU 过高时 1 ~ 2 分钟内的每一路由模仿复现问题。

备注：NodeJS 性能监控平台查看 CPU 运行数据会有肯定延时，还是间接登录服务器指令查看更实时！

通过模仿拜访定位到拜访某路由导致 CPU 过高！

因为部署了多台服务器，确定拜访某路由能重现后，可间接 IP 拜访旧服务器代码，而后雷同形式最终确认！

拜访某路由时，其余服务器 NodeJs 性能监控平台 CPU 状况。（几个尖刺是调试确认时的截图）

总的来说定位问题是以下四步骤：

剖析 火焰图 ，试图依据 火焰图 定位到具体代码；
剖析 GC Trace, 判断是否代码 内存泄露 导致 CPU 过高；
独自服务器部署，排除烦扰，确定是否业务代码导致 CPU 占用率高，增加每个路由（页面路由、API 申请路由）的日志（日志定时清理）；
通过比照 CPU 飙高前 2~ 3 分钟内申请的页面，找出对应页面、二级页面等进行拜访察看对应服务器 CPU 占用值。

以上确定了具体路由后，就能深刻其业务代码（100~200 行）查看起因。

最终定位是某个二级弹层申请数据（API 路由）时，如果该业务数据满足某一条件时，会将做全表查问，对 十多万数据进行遍历解决 导致 CPU 飙高！藏的很深！

起因：历史代码没思考性能，有全表查问逻辑，当然一开始业务表数据 几千条数据 不会触发，随着业务演进，数据量减少至 十万级别 就呈现 CPU 飙升 100% 状况！

本文次要分享 Node.js 我的项目运行时呈现 CPU 飙升 100% 时，排查、定位到具体业务代码的思路。比照网上各种总结帖，CPU 过高问题起因很多，本文提供一种定位思路。有其余更好办法请评论区补充~

node 过程 cpu 100% 问题排查
NodeJs 调试指南
唯快不破让 NodeJs 更快一些
深入浅出 Node(第五章内存管制) – 微信读书
V8 引擎垃圾回收与内存调配
2019 – V8 引擎官网：GC 算法更新
Node.js 利用故障排查手册
Node.js 调试指南

关于node.js:Node-CPU-偶发100-排查小结

前言（背景）

如何定位

Node 我的项目接入性能监控平台

火焰图

1）时效性不够

2）无奈定位到具体代码

GC Trace（垃圾回收跟踪）

独自服务器部署

拜访日志增加

CPU 趋势、历史记录剖析和定位

复现问题

定位思路小总结

解决问题

小总结

参考博文

Just My Socks（注册教程内含优惠码）

关于node.js:Node-CPU-偶发100-排查小结

前言（背景）

如何定位

Node 我的项目接入性能监控平台

火焰图

1）时效性不够

2）无奈定位到具体代码

GC Trace（垃圾回收跟踪）

独自服务器部署

拜访日志增加

CPU 趋势、历史记录 剖析和定位

复现问题

定位思路小总结

解决问题

小总结

参考博文

Just My Socks（注册教程 内含优惠码）

CPU 趋势、历史记录剖析和定位

Just My Socks（注册教程内含优惠码）