乐趣区

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

jiezi

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

前言（背景）

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

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

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

如何定位

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

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 过高。

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

1）时效性不够

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

2）无奈定位到具体代码

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

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

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

GC Trace（垃圾回收跟踪）

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;

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

接入 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 调试指南
退出移动版