Node.js の Event Loop ブロッキングを検出する

Node.jsを使ったWebサービスでは Event Loop をブロッキングしないことがパフォーマンス上とても重要ですが、blocked-atモジュールは性能のボトルネックになっているブロッキング処理部分を検出するのにとても重宝します。このモジュールは何ミリ秒間以上のブロッキングを検出するかの閾値thresholdもオプションで設定できます。

Node.js の Event Loop ブロッキングを検出する

実験コード
実行
結論

実験コード

fs.readFileSync(同期＝ブロッキング)とfs.readFile(非同期＝ノンブロッキング)を使い、指定された回数だけファイルを読み込むという処理でブロッキング検出実験をしてみましょう。

app.js

/*
 * Event Loop のブロッキングを検出する実験
 *
 * 引数で指定した回数だけファイルを読み込みます。
 *
 * # 使い方
 * $ node app.js <テキトーなファイルのパス> <ループ回数>
 *
 * 例)
 * $ node app.js ./package.json 10000
 */

/**
 * Event Loop ブロッキング情報を知るための blocked-at モジュール
 */
const blocked = require('blocked-at');
blocked((time, stack) => {
  console.log(`Blocked for ${time}ms, operation started here:`, stack)
}, {
  threshold: 10, // 検出ブロッキング時間(ミリ秒)の閾値。 デフォルトは 20 msec
});

const fs = require("fs");
// 何かテキトーなファイル（何でも良い）
const FILE = process.argv[2]; // NOTE: ファイルの存在確認は省略
// ループ回数 (各自マシンスペックに合わせて調整してください)
const COUNT = parseInt(process.argv[3]); // NOTE: 数字の妥当性はチェック省略
console.log(`${COUNT}回ループします ...`);

//
// ブロッキングするパターン
//
setImmediate(() => {
  console.time("block()");
  block();
  console.timeEnd("block()");
});

//
// ブロッキングしないパターン
//
setImmediate(() => {
  console.time("nonblock()");
  nonblock((err, ret) => {
    console.timeEnd("nonblock()");
  });
});

/** ブロッキングする関数 */
function block() {
  for (let len = COUNT, i = 0; i < len; i++) {
    fs.readFileSync(FILE);
  }
}

/** ブロッキングしない関数 */
function nonblock(cb) {
  // ループスタート！
  loop(0);

  function loop(i) {
    if (i >= COUNT) return cb && cb();
    fs.readFile(FILE, (err, res) => {
      loop(i + 1); // 関数を再帰呼び出し
      // setImmediate(loop.bind(null,i + 1)); // 関数を再帰呼び出し
    });
  }
}

実行

package.jsonファイルを10000回読み込んでみます:

$ node app.js ./package.json 10000

10000回ループします ...
block(): 54.689ms
Blocked for 55.12778699874878ms, operation started here: [ '    at new Immediate (timers.js:837:5)',
  '    at createImmediate (timers.js:879:19)',
  '    at setImmediate (timers.js:866:10)',
  '    at Object.<anonymous> (/<この実験コードのディレクトリ>/app.js:33:1)', // <= 33行目はブロッキングな関数の開始行
  ...
nonblock(): 1159.429ms

この実行結果を見ると、ブロッキングな関数block()は処理時間自体は 54.689ms と短いですが、55.12778699874878msも Event Loop をブロッキングしてしまっています。

一方のノンブロッキングな関数nonblock()は処理時間は 1159.429ms でblock()の20倍時間が掛かってますがEvent Loop をブロッキングしていません。

結論

blocked-at モジュールを使うとパフォーマンス改善が捗ります。自分のあずかり知らない箇所でブロッキング処理を使っている外部モジュールのあぶり出しにも使えそうです。

以上

追記2020/03/16: Node.jsアプリケーションのパフォーマンス改善のヒントにNode.jsでメモリリーク箇所を特定の記事も合わせてどうぞ。