Node.js 應用故障排查手冊 —— 利用 CPU 分析調優吞吐量
楔子
在我們想要新上線一個 Node.js 應用之前，尤其是技術棧切換的第一個 Node.js 應用，由於擔心其在線上的吞吐量表現，肯定會想要進行效能壓測，以便對其在當前的叢集規模下能抗住多少流量有一個預估。本案例實際上正是在這樣的一個場景下，我們想要上線 Node.js 技術棧來做前後端分離，那麼刨開後端服務的響應 QPS，純使用 Node.js 進行的模板渲染能有怎麼樣的表現，這是大家非常關心的問題。
本書首發在 Github，倉庫地址：https://github.com/aliyun-node/Node.js-Troubleshooting-Guide，雲棲社群會同步更新。
優化過程
叢集在效能壓測下反映出來的整體能力其實由單機吞吐量就可以測算得知，因此這次的效能壓測採用的 4 核 8G 記憶體的伺服器進行壓測，並且頁面使用比較流行的 ejs 進行服務端渲染，程序數則按照核數使用 PM2 啟動了四個業務子程序來執行。
I. 開始壓測
完成這些準備後，使用阿里雲提供的 PTS 效能壓測工具進行壓力測試，此時大致單機 ejs 模板渲染的 QPS 在 200 左右，此時通過
II. 模板快取
因為是 CPU 達到了系統瓶頸導致整體 QPS 上不去，因此按照第二部分工具篇章節的方法，我們在平臺上抓了 壓測期間 的 3 分鐘的 CPU Profile，展現的結果如下圖所示：
這裡就看到了很奇怪的地方，因為壓測環境下我們已經打開了模板快取，按理來說不會再出現 ejs.compile 函式對應的模板編譯才對。仔細比對專案中的渲染邏輯程式碼，發現這部分採用了一個比較不常見的模組
瞭解到原因之後，首先我們將 koa-view 替換為更好用的 koa-ejs 模組，並且按照 koa-ejs 的文件正確開啟快取：
render(app, {
root: path.join(__dirname, 'view'),
viewExt: 'html',
cache: true
});再次進行壓測後，單機下的 QPS 提升到了 600 左右，雖然大約提升了三倍的效能，但是仍然達不到預期的目標。
III. include 編譯
為了繼續優化進一步提升伺服器的渲染效能，我們繼續在壓測期間抓取 3 分鐘的 CPU Profile 進行檢視：
可以看到，我們雖然已經確認使用 koa-ejs 模組且正確開啟了快取，但是壓測期間的 CPU Profile 裡面竟然還有 ejs 的 compile 動作！繼續展開這裡的 compile，發現是 includeFile 時引入的，繼續回到專案本身，觀察壓測的頁面模板，確實使用了 ejs 注入的 include 方法來引入其它模板：
<%- include("../xxx") %>對比 ejs 的原始碼後，這個注入的 include 函式呼叫鏈確實也是 include -> includeFile -> handleCache -> compile，與壓測得到的 CPU Profile 展示的內容一致。那麼下面紅框內的 replace 部分也是在 compile 過程中產生的。
到了這裡開始懷疑 koa-ejs 模組沒有正確地將 cache 引數傳遞給真正負責渲染地 ejs 模組，導致這個問題地發生，所以繼續去閱讀 koa-ejs 的快取設定，以下是簡化後的邏輯（[email protected] 版本）：
const cache = Object.create(null);
async function render(view, options) {
view += settings.viewExt;
const viewPath = path.join(settings.root, view);
// 如果有快取直接使用快取後的模板解析得到的函式進行渲染
if (settings.cache && cache[viewPath]) {
return cache[viewPath].call(options.scope, options);
}
// 沒有快取首次渲染呼叫 ejs.compile 進行編譯
const tpl = await fs.readFile(viewPath, 'utf8');
const fn = ejs.compile(tpl, {
filename: viewPath,
_with: settings._with,
compileDebug: settings.debug && settings.compileDebug,
debug: settings.debug,
delimiter: settings.delimiter
});
// 將 ejs.compile 得到的模板解析函式快取起來
if (settings.cache) {
cache[viewPath] = fn;
}
return fn.call(options.scope, options);
}顯然，koa-ejs 模板的模板快取是完全自己實現的，並沒有在呼叫 ejs.compile 方法時傳入的 option 引數內將使用者設定的 cache 引數傳遞過去而使用 ejs 模組提供的 cache 能力。但是偏偏專案在模板內又直接使用了 ejs 模組注入的 include 方法進行模板間的呼叫，產生的結果就是隻快取了主模板，而主模板使用 include 呼叫別的模板還是會重新進行編譯解析，進而造成壓測下還是存在大量重複的模板編譯動作導致 QPS 升不上去。
再次找到了問題的根源，為了驗證是否是 koa-ejs 模組本身的 bug，我們在專案中將其渲染邏輯稍作更改：
const fn = ejs.compile(tpl, {
filename: viewPath,
_with: settings._with,
compileDebug: settings.debug && settings.compileDebug,
debug: settings.debug,
delimiter: settings.delimiter,
// 將使用者設定的 cache 引數傳遞給 ejs 而使用到其提供的快取能力
cache: settings.cache
});然後打包後進行壓測，此時單機 QPS 從 600 提升至 4000 左右，基本達到了上線前的效能預期，為了確認壓測下是否還有模板的編譯動作，我們繼續在 Node.js 效能平臺 上抓取壓測期間 3 分鐘的 CPU Profile：
可以看到上述對 koa-ejs 模板進行優化後，ejs.compile 確實消失了，而壓測期間不再有大量重複且耗費 CPU 的編譯動作後，應用整體的效能比最開始有了 20 倍左右的提升。文中 koa-ejs 模組快取問題已經在 4.1.2 版本（包含）之後被修復了，詳情可以見 cache include file，如果大家使用的 koa-ejs 版本 >= 4.1.2 就可以放心使用。
結尾
CPU Profile 本質上以可讀的方式反映給開發者執行時的 JavaScript 程式碼執行頻繁程度，除了在線上程序出現負載很高時能夠用來定位問題程式碼之外，它在我們上線前進行效能壓測和對應的效能調優時也能提供巨大的幫助。這裡需要注意的是：僅當程序 CPU 負載非常高的時候去抓取得到的 CPU Profile 才能真正反饋給我們問題所在。
在這個源自真實生產的案例中，我們也可以看到，正確和不正確地去使用 Node.js 開發應用其前後執行效率能達到二十倍的差距，Node.js 作為一門服務端技術棧發展至今日，其本身能夠提供的效能是毋庸置疑的，絕大部分情況下執行效率不佳是由我們自身的業務程式碼或者三方庫本身的 Bug 引起的，Node.js 效能平臺 則可以幫助我們以比較方便的方式找出這些 Bug。
作者：奕鈞
本文為雲棲社群原創內容，未經