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 啓動了四個業務子進程來運行。

1. 開始壓測

完成這些準備後，使用阿里雲提供的 PTS 性能壓測工具進行壓力測試，此時大體單機 ejs 模板渲染的 QPS 在 200 左右，此時經過 Node.js 性能平臺 監控能夠看到四個子進程的 CPU 基本都在 100%，即 CPU 負載達到了瓶頸，可是區區 200 左右的 QPS 顯然系統總體渲染很是的不理想。

2. 模板緩存

由於是 CPU 達到了系統瓶頸致使總體 QPS 上不去，所以按照第二部分工具篇章節的方法，咱們在平臺上抓了 壓測期間 的 3 分鐘的 CPU Profile，展示的結果以下圖所示：

這裏就看到了很奇怪的地方，由於壓測環境下咱們已經打開了模板緩存，按理來講不會再出現 ejs.compile 函數對應的模板編譯纔對。仔細比對項目中的渲染邏輯代碼，發現這部分採用了一個比較不常見的模塊 koa-view，項目開發者想固然地用 ejs 模塊地入參方式傳入了 cache: true，可是實際上該模塊並無對 ejs 模板作更好的支持，所以實際壓測狀況下模板緩存並無生效，而模板地編譯動做本質上字符串處理，它偏偏是一個 CPU 密集地操做，這就致使了 QPS 達不到預期的情況。

瞭解到緣由以後，首先咱們將 koa-view 替換爲更好用的 koa-ejs 模塊，而且按照 koa-ejs 的文檔正確開啓緩存：

render(app, {
  root: path.join(__dirname, 'view'),
  viewExt: 'html',
  cache: true
});

再次進行壓測後，單機下的 QPS 提高到了 600 左右，雖然大約提高了三倍的性能，可是仍然達不到預期的目標。

3. 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 的緩存設置，如下是簡化後的邏輯（koa-ejs@4.1.1 版本）：

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。

---

本文做者：奕鈞

閱讀原文

本文爲雲棲社區原創內容，未經容許不得轉載。