Node.js 應用故障排查手冊 —— 類死循環導緻程序阻塞

楔子

在實踐篇一中我們看到了兩個表象都是和 CPU 相關的生産問題，它們基本也是我們線上上可能遇到的這一類問題的典型案例，而實際上這兩個案例也存在一個共同點：我們可以通過 

Node.js 性能平台

 導出程序對應的 CPU Profile 資訊來進行分析定位問題，但是實際線上上的一些極端情況下，我們遇到的故障是沒有辦法通過輕量的 V8 引擎暴露的 CPU Profile 接口（僅部分定制的 AliNode runtime 版本支援，詳見下文）來擷取足夠的程序狀态資訊進行分析的，此時我們又回到了束手無策的狀态。

本章節将從一個生産環境下 Node.js 應用出現程序級别阻塞導緻的不再提供服務的問題場景來給大家展示下如何處理這類相對極端的應用故障。

本書首發在 Github，倉庫位址：

https://github.com/aliyun-node/Node.js-Troubleshooting-Guide

，雲栖社群會同步更新。

最小化複現代碼

這個例子稍微有些特殊，我們首先給出生産案例的最小化複現代碼，有興趣的同學可以親自運作一番，這樣結合下文的此類問題的排查過程，能更加清晰的看到我們面對這樣的問題時的排查思路，問題最小代碼如下，基于

Egg.js

：

'use strict';
const Controller = require('egg').Controller;

class RegexpController extends Controller {
  async long() {
    const { ctx } = this;
    // str 模拟使用者輸入的問題字元串
    let str = '<br/>                                             ' +
      '           早餐後自由活動，于指定時間集合自行辦理退房手續。';
    str += '<br/>                                      <br/>' +
      '                                        <br/>           ' +
      '                         <br/>';
    str += '                                    <br/>' +
      '                                                        ' +
      '                                                        ' +
      '        <br/>';
    str += '                                                <br/>                                                                                                                <br/>';
    str += '                                                     ' +
      '                                                        ' +
      '       根據船班時間，自行前往暹粒機場，傳回中國。<br/>';
    str += '如需送機服務，需增加280/每單。<br/>';
    const r = str.replace(/(^(\s*?<br[\s\/]*?>\*?)+|(\s*?<br[\s\/]*?>\s*?)+?$)/igm, '');
    ctx.body = r;
  }
}

module.exports = RegexpController;           

問題應用狀态

其實這個例子對應的問題場景可能很多 Node.js 開發者都遇到過，它非常有意思，我們首先來看下出現這類故障時我們的 Node.js 應用的狀态。當我們收到在平台配置的 CPU 告警資訊後，登入性能平台進入對應的告警應用找到出問題的 CPU 非常高的程序：然後點選 資料趨勢 按鈕檢視此程序目前的狀态資訊：

可以看到程序的 CPU 使用率曲線一直處于近乎 100% 的狀态，此時程序不再響應其餘的請求，而且我們通過跳闆機進入生産環境又可以看到程序其實是存活的，并沒有挂掉，此時基本上可以判斷：此 Node.js 程序因為在執行某個同步函數處于阻塞狀态，且一直卡在此同步函數的執行上。

Node.js 的設計運作模式就是單主線程，并發靠的是底層實作的一整套異步 I/O 和事件循環的排程。簡單的說，具體到事件循環中的某一次，如果我們在執行需要很長時間的同步函數（比如需要循環執行很久才能跳出的

while

 循環），那麼整個事件循環都會阻塞在這裡等待其結束後才能進入下一次，這就是不推薦大家在非初始化的邏輯中使用諸如

fs.readFileSync

 等同步方法的原因。

排查方法

這樣的問題其實非常難以排查，原因在于我們沒辦法知道什麼樣的使用者輸入造成了這樣的阻塞，是以本地幾乎無法複現問題。幸運的是，性能平台目前有不止一種解決辦法處理這種類死循環的問題，我們來詳細看下。

I. CPU Profile

這個分析方法可以說是我們的老朋友了，因為類死循環的問題本質上也是 CPU 高的問題，是以我們隻要對問題程序抓取 CPU Profile，就能看到目前卡在哪個函數了。需要注意的是，程序假死狀态下是無法直接使用 V8 引擎提供的抓取 CPU Profile 檔案的接口，是以工具篇章節的 

正确打開 Chrome devtools

一節中提到的 v8-profiler 這樣的第三方子產品是無法正常工作的。

不過定制過的 AliNode runtime 采用了一定的方法規避了這個問題，然而遺憾的是依舊并不是所有的 AliNode runtime 版本都支援在類死循環狀态下抓取 CPU Profile，這裡實際上對大家使用的 Runtime 版本有要求：

• AliNode V3 版本需要 >= v3.11.4
• AliNode V4 版本需要 >= v4.2.1
• AliNode V1 和 V2 版本不支援

如果你的線上 AliNode runtime 版本恰好符合需求，那麼可以按照前面

Node.js 性能平台使用指南

 提到的那樣，對問題程序抓取 3 分鐘的 CPU Profile，并且使用 AliNode 定制的火焰圖分析：

這裡可以看到，抓取到的問題程序 3 分鐘的 CPU 全部耗費在

long

 函數裡面的

replace

 方法上，這和我們提供的最小化複現代碼一緻，是以可以判斷

long

 函數内的正則存在問題進行修複。

II. 診斷報告

診斷報告也是 AliNode 定制的一項導出更多更詳細的 Node.js 程序目前狀态的能力，導出的資訊也包含目前的 JavaScript 代碼執行棧以及一些其它程序與系統資訊。它與 CPU Profile 的差別主要在兩個地方：

• 診斷報告主要針對此刻程序狀态的導出，CPU Profile 則是一段時間内的 JavaScript 代碼執行狀态
• 診斷報告除了此刻 JavaScript 調用棧資訊，還包含了 Native C/C++ 棧資訊、Libuv 句柄和部分作業系統資訊

當我們的程序處于假死狀态時，顯然不管是一段時間内還是此時此刻的 JavaScript 執行狀況，必然都是卡在我們代碼中的某個函數上，是以我們可以使用診斷報告來處理這樣的問題，當然診斷報告功能同樣也對 AliNode runtime 版本有所要求：

• AliNode V2 版本需要 >= v2.5.2
• AliNode V3 版本需要 >= v3.11.8
• AliNode V4 版本需要 >= v4.3.0
• AliNode V1 版本不支援
• 且要求：Agenthub/Egg-alinode 依賴的 Commandx 版本 >= v1.5.3

如果你使用的 AliNode runtime 版本符合要求，即可進入平台應用對應的執行個體資訊頁面，選中問題程序：

然後點選 診斷報告 即可生成此刻問題程序的狀态資訊報告：

診斷報告雖然包含了很多的程序和系統資訊，但是其本身是一個相對輕量的操作，故而很快就會結束，此時繼續點選 轉儲 按鈕将生成的診斷報告上傳至雲端以供線上分析展示：

繼續點選 分析 按鈕檢視 AliNode 定制的分析功能，展示結果如下：

結果頁面上面的概覽資訊比較簡單，我們來看下 JavaScript 棧 頁面的内容，這裡顯然也告訴我們目前的 JS 函數卡在

long

 方法裡面，并且比 CPU Profile 更加詳細的是還帶上了具體阻塞在

long

 方法的哪一行，對比我們提供給大家的最小複現代碼其實就是執行

str.replace

 這一行，也就是問題的正則比對操作所在的地方。

III. 核心轉儲分析

其實很多朋友看到這裡會有疑惑：既然 CPU Profile 分析和診斷報告已經能夠找到問題所在了，為什麼我們還要繼續介紹相對比較重的核心轉儲分析功能呢？

其實道理也很簡單，不管是類死循環狀态下的 CPU Profile 抓取還是診斷報告功能的使用，都對問題程序的 AliNode runtime 版本有所要求，而且更重要的是，這兩種方法我們都隻能擷取到問題正則的代碼位置，但是我們無法知道什麼樣的使用者輸入在執行這樣的正則時會觸發程序阻塞的問題，這會給我們分析和給出針對性的處理造成困擾。是以，這裡最後給大家介紹對 AliNode runtime 版本沒有任何要求，且能拿到更精準資訊的核心轉儲分析功能。

首先按照預備章節的核心轉儲一節中提到的

手動生成 Core dump

檔案的方法，我們對問題程序進行

sudo gcore <pid>

 的方式擷取到核心轉儲檔案，然後在平台的詳情頁面，将滑鼠移動到左邊 Tab 欄目的 檔案 按鈕上，可以看到 Coredump 檔案 的按鈕：

點選後可以進入 Core dump 檔案清單頁，然後點選上方的 上傳 按鈕進行核心轉儲檔案的上傳操作：

這裡需要注意的是，請将 Core dump 檔案以 .core 結尾重命名，而對應的 Node 可執行檔案以 .node 結尾重命名，推薦的命名方式為 

<os info>-<alinode/node>-<version>.node

，友善以後回顧，比如 centos7-alinode-v4.7.2.node 這種。最後 Core dump 檔案和 Node 可執行檔案之間必須是 一一對應 的關系。這裡一一對應指的是：這份 Core dump 檔案必須是由這個 Node 可執行檔案啟動的程序生成的，如果這兩者沒有一一對應，分析結果往往是無效資訊。

因為 Core dump 檔案一般來說都比較大，是以上傳會比較慢，耐心等待至上傳完畢後，我們就可以使用 AliNode 定制的核心轉儲檔案分析功能進行分析了，點選 分析 按鈕即可：

此時我們在新打開的分析結果頁面可以看到如下的分析結果展示資訊：

這個頁面的各項含義在工具篇的 Node.js 性能平台使用指南的 [最佳實踐——核心轉儲分析]() 一節已經解釋過，這裡不再贅述，這裡直接展開 JavaScript 棧資訊：

這裡可以看到得到的結論和前面的 CPU Profile 分析以及診斷報告分析一緻，都能定位到提供的最小複現代碼中的

long

 方法中的異常正則比對，但是核心轉儲檔案分析比前面兩者多了導緻目前 Node.js 程序産生問題的異常字元串：  

"<br/> 早餐後自由活動，于指定時間集合自行辦理退房手續。<br/> <br/> <br/> <br/> <br/> <br/> <br/> <br/> 根據船班時間，自行前往暹粒機場，傳回中國。<br/>如需送機服務，需增加280/每單。<br/>"

 ，有了這個觸發正則執行異常的問題字元串，我們無論是構造本地複現樣例還是進一步分析都有了重要的資訊依靠。

分析問題

上一節中我們采用了 Node.js 性能平台提供的三種不同的方式分析定位到了線上應用處于假死狀态的原因，這裡來簡單的解釋下為什麼字元串的正則比對會造成類死循環的狀态，它實際上異常的使用者輸入觸發了 正規表達式災難性的回溯，會導緻執行時間要耗費幾年甚至幾十年，顯然不管是那種情況，單主工作線程的模型會導緻我們的 Node.js 應用處于假死狀态，即程序依舊存活，但是卻不再處理新的請求。

關于正則回溯的原因有興趣的同學可以參見

小心别落入正則回溯陷阱

 一文。

結尾

其實這類正則回溯引發的程序級别阻塞問題，本質上都是由于不可控的使用者輸入引發的，而 Node.js 應用又往往作為 Web 應用直接面向一線客戶，無時不刻地處理千奇百怪的使用者請求，是以更容易觸發這樣的問題。

相似的問題其實還有一些代碼邏輯中諸如

while

 循環的跳出條件在一些情況下失效，導緻 Node.js 應用阻塞在循環中。之前我們就算知道是程序阻塞也難以友善的定位到具體的問題代碼以及産生問題的輸入，現在借助于 

 提供的核心轉儲分析能力，相信大家可以比較容易地來解決這樣的問題。