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 應用阻塞在循環中。以前咱們就算知道是進程阻塞也難以方便的定位到具體的問題代碼以及產生問題的輸入，如今藉助於 Node.js 性能平臺 提供的核心轉儲分析能力，相信你們能夠比較容易地來解決這樣的問題。

---

本文做者：奕鈞

閱讀原文

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