登录
首页 >  数据库 >  MySQL

Node CPU 偶发100% 排查小结

来源:SegmentFault

时间:2023-02-23 08:42:30 225浏览 收藏

数据库小白一枚,正在不断学习积累知识,现将学习到的知识记录一下,也是将我的所得分享给大家!而今天这篇文章《Node CPU 偶发100% 排查小结》带大家来了解一下Node CPU 偶发100% 排查小结,希望对大家的知识积累有所帮助,从而弥补自己的不足,助力实战开发!

博文开始前,先贴下本文目录, 主要篇幅在第二部分:如何定位

NodeJs CPU 100%.png

前言(背景)

内部管理系统,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最高!
image.png

对于偶发场景,不可能一直开着终端,且出现问题了没有监控告警,无法知道出现问题的具体时间,不方便定位解决问题。

所以需要接入性能监控平台,具体可看 如何接入Node监控平台 - alinode , 我们内部服务器部署了类似aliNode的开源版 - Easy-Monitor 3.0,操作界面差不多。接入成功后,出现CPU过高时有以下图表:

DSP_001服务器CPU图表.jpg

当然也有其他 Node.js 插件能实现类似的监控,具体参考: NodeJs调试指南, 接入成功后主要看两项:

火焰图
GC Trace(垃圾回收跟踪)

image.png

火焰图

火焰图(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线上问题 - 之火焰图篇

image.png

理论上通过

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

然而,这边实践发现火焰图两问题:

1)时效性不够

例如 Node性能监控上 “抓取性能数据” - 生成火焰图, 生成的是 最近5分钟 的火焰图, 出现问题(看到钉钉告警)再上去“抓取”生成的 可能是正常运行代码的

火焰图
2)无法定位到具体代码

即使CPU过高问题持续很久, “抓取”的是异常运行状态下的

火焰图
,也有可能发现生成的图不对劲,无法与我们业务代码锲合,这边就遇到生成的
火焰图
无法定位到具体代码(-_-||。

不同项目不一样,或许

火焰图
能帮助大家定位到具体代码。

顺便说下,Node性能监控平台一般能导出

火焰图
文件, 导出的文件名如:
u-c3979add-7db3-4365-b1ed-9a2556b6a320-u-x-cpuprofile-4012-20210730-241648.cpuprofile
, 在 Chrome 上可导入:
image.png

image.png

image.png

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 应用故障排查手册, 考虑脱敏就不用内部监控系统截图。

!

image.png

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

image.png

此时点击 转储 即可上传到云端以供在线分析展示了,如下图所示:

image.png

最后点击这里的 分析 按钮,即可看到 AliNode 定制后的 GC 信息分析结果的展现:

image.png

结果展示中,可以比较方便的看到问题进程的 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%以上情况:

dsp_运行服务器尖刺.jpg

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

访问日志添加

为什么 域名只映射到这台新服务器?主要方便添加、查看日志, 多台服务器的话用户访问记录太分散,徒增分析、整理日志 时间成本。

EggJs日志 API 可记录 用户每次访问的页面, 或二级页面弹层时加载数据 等 API数据请求;

在 中间件 添加记录访问日志代码, 静态文件请求忽略。

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

添加成功后日志中,包含 “WARN”就是用户访问历史记录:

image.png

备注: 添加用户历史访问后,日志体积会增大,我们内部系统访问的人不多,每天大概产生 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  {
      // 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过高的业务代码,往往其请求时间也长, 可在Egg.js 最后的中间件添加以下代码 打印超时 的接口日志:

/* app -> middleware -> errCatch.ts  自定义中间件: 错误处理模块 */
import { Context } from 'egg';
'use strict';

export default function errHandler(): any {
  return async (ctx: Context, next: () => Promisenode进程cpu 100%问题排查
  • NodeJs调试指南
  • 唯快不破让NodeJs更快一些
  • 深入浅出Node(第五章内存控制) - 微信读书
  • V8 引擎垃圾回收与内存分配
  • 2019 - V8 引擎官方:GC算法更新
  • Node.js 应用故障排查手册
  • Easy-Monitor 3.0 使用指南
  • 今天关于《Node CPU 偶发100% 排查小结》的内容介绍就到此结束,如果有什么疑问或者建议,可以在golang学习网公众号下多多回复交流;文中若有不正之处,也希望回复留言以告知!

    声明:本文转载于:SegmentFault 如有侵犯,请联系study_golang@163.com删除
    相关阅读
    更多>
    最新阅读
    更多>
    课程推荐
    更多>