Node CPU 偶發100% 排查小結

時間 2021-08-13

標籤 html 前端 node git github web 算法數據庫 segmentfault 後端欄目 HTML 简体版

原文原文鏈接

博文開始前，先貼下本文目錄，主要篇幅在第二部分：如何定位。html

前言（背景）

內部管理系統，Node.js項目線上運行一直穩定、正常，某天開始使用人員反饋系統訪問卡頓，同時對應服務器出現CPU 佔用 95% ~ 120%太高的釘釘告警，超過100%是由於對應Linux服務器是多核，出現後1~5分鐘後正常，偶發出現，此次問題持續時間較長，參考、閱讀了很多文章，寫個博文記錄、總結下。前端

問題出現 ~ 解決時間 2021.07.21 ~ 2021.08.01node

先說下內部系統技術架構，前端React，後端NodeJS框架Egg.js(Koa2封裝)。因此監控定位時有些 NodeJs 庫不適合接入，這個第二部分詳細講。git

如何定位

Node項目接入性能監控平臺

NodeJs項目出現CPU佔用100%以上時，登陸對應服務器命令行 top -c 查看當前服務器哪一個進程佔用CPU最高！
github

對於偶發場景，不可能一直開着終端，且出現問題了沒有監控告警，沒法知道出現問題的具體時間，不方便定位解決問題。web

因此須要接入性能監控平臺，具體可看如何接入Node監控平臺 - alinode ，咱們是內部服務器部署了aliNode，操做界面差很少。接入成功後，出現CPU太高時有如下圖表：算法

固然也有其餘 Node.js 插件能實現相似的監控，具體參考： NodeJs調試指南，接入成功後主要看兩項： 火焰圖 和 GC Trace（垃圾回收跟蹤）
數據庫

火焰圖

火焰圖（Flame Graph）你們應該聽過，它能夠將 CPU 的使用狀況可視化，使咱們直觀地瞭解到程序的性能瓶頸。咱們一般要結合操做系統的性能分析工具（profiling tracer）使用火焰圖，常見的操做系統的性能分析工具以下：segmentfault

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%狀況！

解決：定位到緣由解決就簡單多了，固然，改動的不是一個API路由，而是對應數據庫表關聯的全部業務代碼。歷史代碼太多，改動了近10個API路由。

解決的具體方案不展開了，簡述就是懶加載、MY SQL 語句優化相關：

問題：數據量大時，根據條件檢索特別慢
解決：1）給檢索字段添加索引；2）部分根據模糊匹配（LIKE '%${filterVar}%'）前端過濾。
前端過濾 是對當前頁數據進行過濾， 配合 pageSize 最大值調整，例如:調整爲當前頁最多顯示5000, 檢索效果、交互欠佳；後續考慮大數據檢索，新檢索條件最好經過新增字段 實現（方便添加索引）；

中臺系統列表項數據懶加載
問題：中臺系統列表項數據量過大（萬級別），致使性能、交互問題， 
解決：進入頁面 或 onFocus 請求 Top 100數據， 用戶輸入後 配合  抖動函數實時更新列表；