Nodejs監(jiān)控事件循環(huán)異常示例詳解

更新時間：2019年09月22日 11:30:56 作者：學而不思則廢

這篇文章主要給大家介紹了關于Nodejs監(jiān)控事件循環(huán)異常的相關資料，文中通過示例代碼介紹的非常詳細，對大家學習或者使用Nodejs具有一定的參考學習價值，需要的朋友們下面來一起學習學習吧

開場白

最近在學習 libuv，也了解了一些 Node.js 中使用 libuv 的例子。當然，這篇文章不會去介紹 event loop，畢竟這些東西在各個論壇、技術圈里都被介紹爛了。本文介紹如何正確使用 Event loop，以及即使發(fā)現(xiàn)程序是否異常 block。

基礎

event loop 的基礎想必各位讀者都比較熟悉了。這里我引用官方的圖，簡單介紹兩句，作為前置準備：

event loop是作為單線程實現(xiàn)異步的方式之一。簡而言之，就是在一個大的 while 循環(huán)中不斷遍歷這些 phase，執(zhí)行對應的 callbacks。這樣才實現(xiàn)了真正的異步調(diào)用：調(diào)用時不必等著響應，等調(diào)用的資源準備好了，回調(diào)我。
以上就是基礎，接下來進入正題：

問題提出

開門見山，我們提出以下問題：

js 既然是單線程，那么總有辦法 block 住整個程序，雖然用了 libuv，也可能會 block 住主程序。對嗎？
如何知道我們的程序 block 住了？

對于問題1，答案是肯定的。任何 io 密集計算都會 block 主進程，調(diào)用任何耗時的同步系統(tǒng) api（比如同步讀取大文件等），也會 block。

對于第2個問題，就需要對 libuv 有個基本認識了（想想我前面說的一個大 while）。event loop 既然是 loop，那么總有循環(huán)的概念吧？想到循環(huán)，能聯(lián)想到循環(huán)次數(shù)吧？對~解決方案就是使用循環(huán)次數(shù)。

方案

這里我提一個思路（并不是說不寫代碼😄）：如果我們正常邏輯下，一秒鐘能進行100W 次事件循環(huán)（數(shù)據(jù)基于我本機），那么如果有一段時間，我得到的1秒鐘時間循環(huán)次數(shù)只有50W，那么是不是說明程序中有哪些地方稍微 block 住了？或者夸張地說，由正常的100W 次變?yōu)榱藗€數(shù)次。這就很嚴重了。因此及時監(jiān)控event loop 非常重要。

第一版代碼

// 環(huán)境準備
const http = require('http');
const path = require('path');
const {execFile, execFileSync} = require('child_process');

const max = 9999;
const getComputedValueFromChildProcess = (max) => execFileSync('node', [path.join(__dirname, './childprocess.js'), max]);

http.createServer((req, res) => {
 const k = getComputedValueFromChildProcess(max);
 res.write('origin-text: ' + k);
 res.end();
}).listen(8888);


// 第一版實現(xiàn)
const MS_MULTI = 1000 * 1000;
const blockDelta = 10 * MS_MULTI;
let start;
function meature() {
 start = process.hrtime();
 setImmediate(function() {
  let seconds;
  [seconds, start] = process.hrtime(start);
  if (seconds * 1000 * MS_MULTI + start > blockDelta) {
   console.log(`node.eventloop_blocked for ${seconds}secs and ${(start / MS_MULTI).toFixed(2)}ms.`);
  }
  meature();
 });
}
meature();

// childprocess.js 文件
#!/use/env node
const args = Number(process.argv[2]);
function computeIo(args) {
 let k;
 for (let i = 0; i < args; ++i) {
  for (let j = 0; j < args; ++j) {
   k = i + j;
  } 
 }
 return k;
}
console.log(computeIo(args));

大環(huán)境是一個 web 服務器。我們選用了 check 這個 phase 來作為一個起點（這里不使用 timer phase的原因是，setTimeout 的 timeout 最低是1ms，在 event loop 空轉(zhuǎn)時，1ms 可以跑好多好多次循環(huán)了，本機數(shù)據(jù)大概是100K次/ms）。應用一開始就調(diào)用 meature 方法開始暴力測試。旨在測試這次 check 到下次 check 的時間是否大于10ms：

# 沒有請求前
# 等了很久出現(xiàn)一個15ms
➜ test node blocked.js
node.eventloop_blocked for 0secs and 15.71ms.

# 當我執(zhí)行幾次
curl http://localhost:8888
# 出現(xiàn)：
node.eventloop_blocked for 0secs and 175.60ms.
node.eventloop_blocked for 0secs and 149.92ms.
node.eventloop_blocked for 0secs and 147.25ms.

是的，基本雛形出來了。可以根據(jù)這些數(shù)值進行數(shù)據(jù)上報、排查問題等。但是！

如果讀者有嘗試了上面這個例子的話，會發(fā)現(xiàn)一個問題：電腦發(fā)燙，風扇不停轉(zhuǎn)！

我看了任務管理器，發(fā)現(xiàn) Node 進程的 cpu 占用率是100%左右！當我把 meature 邏輯注釋掉，cpu 占用率恢復到了0%左右?？磥磉@個版本不行。我們來修改一下~具體原因是不斷地執(zhí)行 setImmediate 代碼，不斷添加 callback，導致 cpu 一直 run！

第二版代碼

我們增加一個采樣的概念：每10秒，采樣一個至少2秒的循環(huán)數(shù)（為什么是至少2秒？因為 setTimeout 的 timeout 的定義本來也就是至少鴨，哈哈哈哈😏）

const EVERY_SEC_MIN_LOOPS = 1000000; // 定義每秒最小循環(huán)數(shù)
let times = 0; // 一次采樣中的循環(huán)數(shù)
let nowShowIncreaseTimes = false; // 當前是否應該增加 times
let start = Date.now();
const CD = 10 * 1000; // 間隔
function meature(callback = () => {}) {
 setTimeout(function() {
  start = Date.now();
  nowShowIncreaseTimes = true;
  _inter();
  setTimeout(() => {
   endMeature();
   meature(); // 開始預約下次采樣
  }, 2000);
 }, CD);
}
function _inter() {
 setImmediate(() => {
  if (nowShowIncreaseTimes) {
   ++times;
   return _inter();
  }
 });
}

function endMeature() {
 
 const now = Date.now();
 nowShowIncreaseTimes = false;
 const totalMsSpan = now - start;
 const everySecLoops = (times / (totalMsSpan / 1000)).toFixed(0);
 if (everySecLoops < EVERY_SEC_MIN_LOOPS) {
  console.log(`當前每秒循環(huán)數(shù)${everySecLoops}`);
 }
 times = 0;
 return everySecLoops
}
meature();

測試結果：

# 當我不斷：
curl http://localhost:8888
# 出現(xiàn)
➜ test node blocked.js
當前每秒循環(huán)數(shù)777574
當前每秒循環(huán)數(shù)890565
# 當我們搞事情時：
ab -c 10 -n 200 http://localhost:8888/

# 結果是這樣的：
➜ test node blocked.js
當前每秒循環(huán)數(shù)843594
當前每秒循環(huán)數(shù)913329
當前每秒循環(huán)數(shù)2
當前每秒循環(huán)數(shù)2

修改為了第2版后，電腦不再燙了，風扇不再轉(zhuǎn)了。cpu 只有在采樣時會上升到30、40樣子，不錯。

但同時也發(fā)現(xiàn)了問題：一秒才2次循環(huán)?。∵@時基本處于拉閘了。為什么呢？

因為我們的請求處理是同步的！同步地生成一個子進程，并且等到子進程運行完了，才把結果返回?？梢姡?server 項目中啟用耗時的同步操作，風險是多么大??！

我們把同步換為異步試試：

// non-blocked.js
const max = 9999;
const getComputedValueFromChildProcess = (max) => new Promise((res, rej) => {
 execFile('node', [path.join(__dirname, './childprocess.js'), max], (err, stdout) => {
  const valueFromChildProcess = Number(stdout);
  res(valueFromChildProcess);
 });
});

http.createServer(async (req, res) => {
 const k = await getComputedValueFromChildProcess(max);
 res.write('origin-text: ' + k);
 res.end();
}).listen(8888);

PS: 為了示范同步、異步的區(qū)別，本文用的是子進程這種方式。其實更好的應該是用 worker_thread 的方式、或者分片計算等。讓我們用相同的 ab 進行測試，得到結果：