博文開始前，先貼下本文目錄， 主要篇幅在第二部分：如何定位。
前言（背景）
內(nèi)部管理系統(tǒng)，Node.js項目線上運(yùn)行一直穩(wěn)定、正常， 某天開始使用人員反饋系統(tǒng)訪問卡頓，同時對應(yīng)服務(wù)器出現(xiàn)CPU 占用 95% ~ 120%過高的釘釘告警，超過100%是因為對應(yīng)Linux服務(wù)器是多核， 出現(xiàn)后1~5分鐘后正常，偶發(fā)出現(xiàn)，這次問題持續(xù)時間較長，參考、閱讀了不少文章，寫個博文記錄、總結(jié)下。
問題出現(xiàn) ~ 解決時間 2021.07.21 ~ 2021.08.01
先說下內(nèi)部系統(tǒng)技術(shù)架構(gòu)，前端React， 后端NodeJS框架Egg.js(Koa2封裝)。所以監(jiān)控定位時有些 NodeJs 庫不適合接入，這個第二部分詳細(xì)講。
如何定位
Node項目接入性能監(jiān)控平臺
NodeJs項目出現(xiàn)CPU占用100%以上時，登錄對應(yīng)服務(wù)器命令行 top -c 查看當(dāng)前服務(wù)器哪個進(jìn)程占用CPU最高！
對于偶發(fā)場景，不可能一直開著終端，且出現(xiàn)問題了沒有監(jiān)控告警，無法知道出現(xiàn)問題的具體時間，不方便定位解決問題。
所以需要接入性能監(jiān)控平臺，具體可看 如何接入Node監(jiān)控平臺 - alinode ， 我們內(nèi)部服務(wù)器部署了類似aliNode的開源版 - Easy-Monitor 3.0，操作界面差不多。接入成功后，出現(xiàn)CPU過高時有以下圖表：
當(dāng)然也有其他 Node.js 插件能實現(xiàn)類似的監(jiān)控，具體參考： NodeJs調(diào)試指南， 接入成功后主要看兩項： 火焰圖 和 GC Trace（垃圾回收跟蹤）
火焰圖
火焰圖（Flame Graph）大家應(yīng)該聽過，它可以將 CPU 的使用情況可視化，使我們直觀地了解到程序的性能瓶頸。我們通常要結(jié)合操作系統(tǒng)的性能分析工具（profiling tracer）使用火焰圖，常見的操作系統(tǒng)的性能分析工具如下：
Linux：perf, eBPF, SystemTap, and ktap。
Solaris, illumos, FreeBSD：DTrace。
Mac OS X：DTrace and Instruments。
Windows：Xperf.exe。
如果未接入NodeJs性能監(jiān)控， 得在服務(wù)器（一般是Linux）安裝以上分析工具；
接入NodeJs性能監(jiān)控后能一鍵導(dǎo)出 火焰圖， 理解火焰圖網(wǎng)上很多教程， 例如： 快速定位NodeJs線上問題 - 之火焰圖篇
理論上通過火焰圖能定位到具體是哪一行代碼導(dǎo)致CPU 過高。
然而，這邊實踐發(fā)現(xiàn)火焰圖兩問題：
1）時效性不夠
例如 Node性能監(jiān)控上 “抓取性能數(shù)據(jù)” - 生成火焰圖， 生成的是 最近5分鐘 的火焰圖， 出現(xiàn)問題（看到釘釘告警）再上去“抓取”生成的 可能是正常運(yùn)行代碼的火焰圖。
2）無法定位到具體代碼
即使CPU過高問題持續(xù)很久， “抓取”的是異常運(yùn)行狀態(tài)下的火焰圖，也有可能發(fā)現(xiàn)生成的圖不對勁，無法與我們業(yè)務(wù)代碼鍥合，這邊就遇到生成的火焰圖無法定位到具體代碼（-_-||。
不同項目不一樣，或許 火焰圖 能幫助大家定位到具體代碼。
順便說下，Node性能監(jiān)控平臺一般能導(dǎo)出 火焰圖文件， 導(dǎo)出的文件名如： u-c3979add-7db3-4365-b1ed-9a2556b6a320-u-x-cpuprofile-4012-20210730-241648.cpuprofile, 在 Chrome 上可導(dǎo)入：
GC Trace（垃圾回收跟蹤）
Node 底層V8引擎的垃圾回收一般跟內(nèi)存相關(guān)，為什么CPU過高要看 垃圾回收跟蹤數(shù)據(jù)？
因為 NodeJs 內(nèi)存泄露 會導(dǎo)致超過 V8引擎 垃圾回收最大內(nèi)存（1.4G），進(jìn)而重啟 V8 GC 導(dǎo)致 CPU 100%。
默認(rèn)情況下，32位系統(tǒng)新生代內(nèi)存大小為16MB，老生代內(nèi)存大小為700MB，64位系統(tǒng)下，新生代內(nèi)存大小為32MB，老生代內(nèi)存大小為1.4GB。
當(dāng)然可修改 V8 垃圾回收最大內(nèi)存上限值：
# node在啟動時可以傳遞參數(shù)來調(diào)整限制內(nèi)存大小。以下方式就調(diào)整了node的使用內(nèi)存
node --max-old-space-size=1700 // 單位是MB
node --max_semi_space_size=1024 // 單位是KB
以下截圖內(nèi)容 引自Node.js 應(yīng)用故障排查手冊， 考慮脫敏就不用內(nèi)部監(jiān)控系統(tǒng)截圖。
Node性能監(jiān)控平臺， 默認(rèn)會抓取 5 分鐘的對應(yīng)進(jìn)程的 GC 日志信息，等到結(jié)束后生成的文件會顯示在 文件 頁面：
此時點(diǎn)擊 轉(zhuǎn)儲 即可上傳到云端以供在線分析展示了，如下圖所示：
最后點(diǎn)擊這里的 分析 按鈕，即可看到 AliNode 定制后的 GC 信息分析結(jié)果的展現(xiàn)：
結(jié)果展示中，可以比較方便的看到問題進(jìn)程的 GC 具體次數(shù)，GC 類型以及每次 GC 的耗費(fèi)時間等信息，方便我們進(jìn)一步的分析定位。比如這次問題的 GC Trace 結(jié)果分析圖中，我們可以看到紅圈起來的幾個重要信息：
GC 總暫停時間高達(dá) 47.8s，大頭是 Scavenge
3min 的 GC 追蹤日志里面，總共進(jìn)行了 988 次的 Scavenge 回收
每次 Scavenge 耗時均值在 50 ~ 60ms 之間
從這些解困中我們可以看到此次 GC 案例的問題點(diǎn)集中在 Scavenge 回收階段，即新生代的內(nèi)存回收。那么通過翻閱 V8 的 Scavenge 回收邏輯可以知道，這個階段觸發(fā)回收的條件是：Semi space allocation failed。
這樣就可以推測，我們的應(yīng)用在壓測期間應(yīng)該是在新生代頻繁生成了大量的小對象，導(dǎo)致默認(rèn)的 Semi space 總是處于很快被填滿從而觸發(fā) Flip 的狀態(tài)，這才會出現(xiàn)在 GC 追蹤期間這么多的 Scavenge 回收和對應(yīng)的 CPU 耗費(fèi)，這樣這個問題就變?yōu)槿绾稳?yōu)化新生代的 GC 來提升應(yīng)用性能。
這里可能有同學(xué)看不懂 Scavenge GC 和 Mark-sweep GC 。
具體到業(yè)務(wù)代碼來說 Scavenge GC 就是一些占用內(nèi)存比較小的臨時變量 回收處理。
而 Mark-sweep GC 是占用內(nèi)存小的全局變量 或 占用內(nèi)存大的臨時變量 回收處理。
總的來說， 只要出現(xiàn) GC Trace（垃圾回收跟蹤）時間過長， 一般都是 內(nèi)存泄露 導(dǎo)致超過 V8引擎 垃圾回收最大內(nèi)存（1.4G）進(jìn)而重啟 V8 GC 導(dǎo)致 CPU 100%。
具體看 深入淺出Node(第五章內(nèi)存控制) - 微信讀書， 國內(nèi)最經(jīng)典的NodeJS書籍《深入淺出Node》雖然是2013年12月1日出版，但關(guān)于 V8引擎垃圾回收機(jī)制 內(nèi)容放現(xiàn)在也不過時，V8引擎 官方最近關(guān)于垃圾回收機(jī)制更新（2019 - V8 引擎官方：GC算法更新 ）內(nèi)容基本沒變，只是Mark-sweep GC 階段添加了三優(yōu)化機(jī)制。
這邊場景，觀察到 GC Trace 相關(guān)數(shù)據(jù)正常， 所以排除 內(nèi)存泄露 導(dǎo)致CPU過高。
單獨(dú)服務(wù)器部署
通過 火焰圖 和 GC Trace 還是無法定位到具體代碼怎么辦？每天都會出現(xiàn) 2 ~ 3次， 懷疑是服務(wù)器其他服務(wù)影響， 也考慮到需要 多臺服務(wù)器 來重現(xiàn)模擬問題。
所以跟運(yùn)維申請全新的一臺服務(wù)器，配置可以低一些， 主要用于排除干擾。
在新服務(wù)器部署代碼后， 將訪問域名 單獨(dú) 映射到新服務(wù)器， 然后繼續(xù)觀察 是否出現(xiàn) CPU 飆高情況。 結(jié)論是 新服務(wù)器運(yùn)行的代碼 還是出現(xiàn) CPU 占用 100%以上情況：
當(dāng)然單獨(dú)服務(wù)器的 CPU 趨勢 更加的直觀， 正常運(yùn)行CPU 占用率為 1 ~ 5%。
訪問日志添加
為什么 域名只映射到這臺新服務(wù)器？主要方便添加、查看日志， 多臺服務(wù)器的話用戶訪問記錄太分散，徒增分析、整理日志 時間成本。
EggJs日志 API 可記錄 用戶每次訪問的頁面， 或二級頁面彈層時加載數(shù)據(jù) 等 API數(shù)據(jù)請求；
在 中間件 添加記錄訪問日志代碼， 靜態(tài)文件請求忽略。
// app -> middleware -> init.ts
if (!reqPath.includes('/public/')) {
ctx.logger.warn('reqPath:', reqPath);
}
添加成功后日志中，包含 “WARN”就是用戶訪問歷史記錄：
備注： 添加用戶歷史訪問后，日志體積會增大，我們內(nèi)部系統(tǒng)訪問的人不多，每天大概產(chǎn)生 3M 日志數(shù)據(jù)， 可考慮添加定時清理日志腳本，每天定時清理。
egg 定時任務(wù)API，對應(yīng)清理日志腳本：
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', // 每臺機(jī)器，隨機(jī)指定某個進(jìn)程進(jìn)行執(zhí)行定時任務(wù)
// immediate: true, // 為true時,啟動時直接執(zhí)行
};
}
/**
* subscribe 是真正定時任務(wù)執(zhí)行時被運(yùn)行的函數(shù)
*/
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('子進(jìn)程已退出，退出碼 ' + 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('清理日志結(jié)束！');
}
}
module.exports = ClearLogs;
CPU趨勢、歷史記錄 分析和定位
接入NodeJS性能監(jiān)控后， CPU過高時有釘釘告警， 然后通過 CPU趨勢圖可定位到 CPU 占用過高前 分鐘 級別的細(xì)粒度信息， 例如：確定 2021.07.29 17:30 ~ 2021.07.29 17:32 這段時間內(nèi)CPU異常。
結(jié)合這段時間內(nèi)用戶訪問歷史， 可整理縮小范圍，知道訪問了哪些頁面、請求了哪些API接口導(dǎo)致CPU過高。
一次可能看不出，每次出現(xiàn)整理一份日志記錄， 多份數(shù)據(jù)對比可進(jìn)一步縮小訪問哪些頁面導(dǎo)致CPU過高問題范圍。
復(fù)現(xiàn)問題
有了日志對比，可模擬訪問頁面，同時登陸服務(wù)器運(yùn)行指令： top -c 觀察CPU運(yùn)行情況，訪問上述整理出現(xiàn)CPU過高時 1 ~ 2分鐘內(nèi)的每一路由 模擬復(fù)現(xiàn)問題。
備注： NodeJS 性能監(jiān)控平臺查看 CPU 運(yùn)行數(shù)據(jù)會有一定延時， 還是直接登錄服務(wù)器指令查看更實時！
通過模擬訪問定位到訪問某路由導(dǎo)致 CPU過高！
因為部署了多臺服務(wù)器， 確定訪問某路由能重現(xiàn)后， 可直接 IP 訪問舊服務(wù)器代碼，然后相同方式最終確認(rèn)！
訪問某路由時，其他服務(wù)器 NodeJs性能監(jiān)控平臺 CPU 情況。（幾個尖刺是調(diào)試確認(rèn)時的截圖）
定位思路小總結(jié)
總的來說定位問題 是以下四步驟：
- 分析
火焰圖， 試圖根據(jù)火焰圖定位到具體代碼； - 分析
GC Trace, 判斷是否 代碼 內(nèi)存泄露 導(dǎo)致CPU 過高； - 單獨(dú)服務(wù)器部署，排除干擾，確定是否業(yè)務(wù)代碼導(dǎo)致CPU占用率高， 添加每個路由（頁面路由、API請求路由）的日志（日志定時清理）；
- 通過對比 CPU 飆高前 2~ 3分鐘內(nèi)請求的頁面， 找出對應(yīng)頁面、二級頁面等 進(jìn)行訪問 觀察 對應(yīng)服務(wù)器CPU占用值。
解決問題
以上確定了具體路由后， 就能深入其業(yè)務(wù)代碼（100~200行）查看原因。
最終定位是某個二級彈層請求數(shù)據(jù)（API路由）時，如果該業(yè)務(wù)數(shù)據(jù)滿足某一條件時，會將做全表查詢， 對 十多萬數(shù)據(jù)進(jìn)行遍歷處理 導(dǎo)致CPU飆高！藏的很深！
原因： 歷史代碼沒考慮性能， 有全表查詢邏輯， 當(dāng)然一開始業(yè)務(wù)表數(shù)據(jù) 幾千條數(shù)據(jù) 不會觸發(fā)，隨著業(yè)務(wù)演進(jìn)，數(shù)據(jù)量增加至 十萬級別 就出現(xiàn)CPU飆升100%情況！
解決： 定位到原因解決就簡單多了，當(dāng)然，改動的不是一個API路由，而是對應(yīng)數(shù)據(jù)庫表關(guān)聯(lián)的所有業(yè)務(wù)代碼。歷史代碼太多，改動了近10個API路由。
解決的具體方案不展開了， 簡述就是 懶加載、MY SQL 語句優(yōu)化相關(guān)：
問題：數(shù)據(jù)量大時，根據(jù)條件檢索特別慢
解決：1）給檢索字段添加索引；2）部分根據(jù)模糊匹配（LIKE '%${filterVar}%'）前端過濾。
前端過濾 是對當(dāng)前頁數(shù)據(jù)進(jìn)行過濾， 配合 pageSize 最大值調(diào)整，例如:調(diào)整為當(dāng)前頁最多顯示5000, 檢索效果、交互欠佳；后續(xù)考慮大數(shù)據(jù)檢索，新檢索條件最好通過新增字段 實現(xiàn)（方便添加索引）；
中臺系統(tǒng)列表項數(shù)據(jù)懶加載
問題：中臺系統(tǒng)列表項數(shù)據(jù)量過大（萬級別），導(dǎo)致性能、交互問題，
解決：進(jìn)入頁面 或 onFocus 請求 Top 100數(shù)據(jù)， 用戶輸入后 配合 抖動函數(shù)實時更新列表；
小總結(jié)
本文主要分享 Node.js 項目運(yùn)行時出現(xiàn) CPU 飆升 100% 時， 排查、定位 到具體業(yè)務(wù)代碼的思路。偶發(fā)的線上Node.js問題排查需要各種工具輔助，推薦 alinode 、 Easy-Monitor 這類集成了多種工具的應(yīng)用性能監(jiān)控與線上故障定位解決方案。當(dāng)然網(wǎng)上各種總結(jié)帖， CPU 過高問題原因很多，本文提供一種定位思路。有其他更好方法請評論區(qū)補(bǔ)充~
