楔子
實踐篇一中我們也看到了一個比較典型的由于開發者不當使用第三方庫,而且在配置資訊中攜帶了三方庫本身使用不到的資訊,導緻了記憶體洩漏的案例,實際上類似這種相對緩慢的 Node.js 應用記憶體洩漏問題我們總是可以在合适的機會抓取堆快照進行分析,而且堆快照一般來說确實是分析記憶體洩漏問題的最佳手段。
但是還有一些問題場景下下應用的記憶體洩漏非常嚴重和迅速,甚至于在我們的告警系統感覺之前就已經造成應用的 OOM 了,這時我們來不及或者說根本沒辦法擷取到堆快照,是以就沒有辦法借助于之前的辦法來分析為什麼程序會記憶體洩漏到溢出進而 Crash 的原因了。這種問題場景實際上屬于線上 Node.js 應用記憶體問題的一個極端狀況,本節将同樣從源自真實生産的一個案例來來給大家講解下如何處理這類極端記憶體異常。
本書首發在 Github,倉庫位址:
https://github.com/aliyun-node/Node.js-Troubleshooting-Guide,雲栖社群會同步更新。
最小化複現代碼
同樣我們因為例子的特殊性,我們需要首先給出到大家生産案例的最小化複現代碼,建議讀者自行運作一番此代碼,這樣結合起來看下面的排查分析過程會更有收獲。最小複現代碼還是基于
Egg.js,如下所示:
'use strict';
const Controller = require('egg').Controller;
const fs = require('fs');
const path = require('path');
const util = require('util');
const readFile = util.promisify(fs.readFile);
class DatabaseError extends Error {
constructor(message, stack, sql) {
super();
this.name = 'SequelizeDatabaseError';
this.message = message;
this.stack = stack;
this.sql = sql;
}
}
class MemoryController extends Controller {
async oom() {
const { ctx } = this;
let bigErrorMessage = await readFile(path.join(__dirname, 'resource/error.txt'));
bigErrorMessage = bigErrorMessage.toString();
const error = new DatabaseError(bigErrorMessage, bigErrorMessage, bigErrorMessage);
ctx.logger.error(error);
ctx.body = { ok: false };
}
}
module.exports = MemoryController;
這裡我們還需要在
app/controller/
目錄下建立一個
resource
檔案夾,并且在這個檔案夾中添加一個
error.txt
,這個 TXT 内容随意,隻要是一個能超過 100M 的很大的字元串即可。
值得注意的是,其實這裡的問題已經在 egg-logger >= 1.7.1 的版本中修複了,是以要複現當時的狀況,你還需要在 Demo 的根目錄執行以下的三條指令以恢複當時的版本狀況:
rm -rf package-lock.json
rm -rf node_modules/egg/egg-logger
npm install [email protected]
最後使用
npm run dev
啟動這個問題最小化複現的 Demo。
感覺程序出現問題
這個案例下,實際上我們的線上 Node.js 應用幾乎是觸發了這個 Bug 後瞬間記憶體溢出然後 Crash 的,而平台預設的記憶體門檻值告警,實際上是由一個定時上報的邏輯構成,是以存在延時,也導緻了這個案例下我們無法像
備援配置傳遞引發的記憶體溢出問題那樣擷取到 Node.js 程序級别的記憶體超過預設門檻值的告警。
那麼我們如何來感覺到這裡的錯誤的呢?這裡我們的伺服器配置過了
ulimit -c unlimited
,是以 Node.js 應用 Crash 的時候核心會自動生成核心轉儲檔案,而且性能平台目前也支援核心轉儲檔案的生成預警,這一條規則目前也被放入了預設的快速添加告警規則中,可以參考工具篇中
Node.js 性能平台使用指南 - 配置合适的告警一節,詳細的規則内容如下所示:

這裡需要注意的是,核心轉儲檔案告警需要我們在伺服器上安裝的 Agenthub/Agentx 依賴的 Commandx 子產品的版本在 1.5.2 之上(包含),這一塊更詳細的資訊也可以看官方文檔
核心轉儲分析能力一節。
問題排查過程
I. 分析棧資訊
依靠上面提到的平台提供的核心轉儲檔案生成時給出的告警,我們在收到報警短信時登入控制台,可以看到 Coredump 檔案清單出現了新生成的核心轉儲檔案,繼續參照工具篇中
Node.js 性能平台使用指南 - 核心轉儲分析中給出的轉儲和 AliNode 定制分析的過程,我們可以看到如下的分析結果展示資訊:
同樣我們直接展開 JavaScript 棧資訊檢視應用 Crash 那一刻的棧資訊:
截圖中忽略掉了 Native C/C++ 代碼的棧資訊,這裡其實僅僅看 JavaScript 棧資訊就能得到結論了,通過翻閱比對出問題的
[email protected]中 lib/utils.js 的代碼内容:
function formatError(err) {
// ...
// 這裡對 Error 對象的 key 和 value 調用 inspect 方法進行序列化
const errProperties = Object.keys(err).map(key => inspect(key, err[key])).join('\n');
// ...
}
// inspect 方法實際上是調用 require('util').inspect 來對錯誤對象的 value 進行序列化
function inspect(key, value) {
return `${key}: ${util.inspect(value, { breakLength: Infinity })}`;
}
這樣我們就知道了線上 Node.js 應用在 Crash 的那一刻正在使用
require('util').inspect
對某個字元串進行序列化操作。
II. 可疑字元串
那麼這個序列化的動作究竟是不是造成程序 Crash 的元兇呢?我們接着來點選
inspect
函數的參數來展開檢視這個可疑的字元串的詳細資訊,如下圖所示:
點選紅框中的參數,得到字元串的詳情頁面連結,如下圖所示:
再次點選這裡的 detail 連結,既可在彈出的新頁面中看到這個可疑字元串的全部資訊:
這裡可以看到,這個正在被
util.inspect
的字元串大小高達 186.94 兆,顯然正是在序列化這麼大的字元串的時候,造成了線上 Node.js 應用的堆記憶體雪崩,幾乎在瞬間就記憶體溢出導緻 Crash。
值得一提的是,我們還可以點選上圖中的 + 号來在目前頁面展示更多的問題字元串内容:
也可以在頁面上點選 一鍵導出 按鈕下載下傳問題完整的字元串:
畢竟對于這樣的問題來說,如果能抓到産生問題的元兇參數,起碼能更友善地進行本地複現。
III. 修複問題
那麼知道了原因,其實修複此問題就比較簡單了,Egg-logger 官方是使用
circular-json來替換掉原生的
util.inspect
序列化動作,并且增加序列化後的字元串最大隻保留 10000 個字元的限制,這樣就解決這種包含大字元串的錯誤對象在 Egg-logger 子產品中的序列化問題。
結尾
本節的給大家展現了對于線上 Node.js 應用出現瞬間 Crash 問題時的排查思路,而在最小化複現 Demo 對應的那個真實線上故障中,實際上是拼接的 SQL 語句非常大,大小約為 120M,是以首先導緻資料庫操作失敗,接着資料庫操作失敗後輸出的 DatabaseError 對象執行個體上則原封不動地将問題 SQL 語句設定到屬性上,進而導緻了
ctx.logger.error(error)
時堆記憶體的雪崩。
在
Node.js 性能平台提供的 核心轉儲告警 + 線上分析能力 的幫助下,此類無法擷取到正常 CPU Profile 和堆快照等資訊的程序無故崩潰問題也變得有迹可循了,實際上它作為一種兜底分析手段,在很大程度上提升了開發者真正将 Node.js 運用到服務端生産環境中的信心。