Node.js アプリケーションのプロファイリング

Node.js アプリケーションのプロファイリングとは、アプリケーション実行中に CPU、メモリ、その他のランタイムメトリクスを分析することで、そのパフォーマンスを測定することです。これは、アプリケーションの効率、応答性、スケーラビリティに影響を与える可能性のあるボトルネック、高い CPU 使用率、メモリリーク、または遅い関数呼び出しを特定するのに役立ちます。

Node.js アプリケーションをプロファイリングするためのサードパーティ製ツールは多数ありますが、多くの場合、最も簡単な選択肢は Node.js の組み込みプロファイラを使用することです。組み込みプロファイラは、V8 内部のプロファイラを使用します。これは、プログラムの実行中に定期的にスタックをサンプリングします。これらのサンプルの結果を、JIT コンパイルなどの重要な最適化イベントとともに、一連のティックとして記録します。

code-creation,LazyCompile,0,0x2d5000a337a0,396,"bp native array.js:1153:16",0x289f644df68,~
code-creation,LazyCompile,0,0x2d5000a33940,716,"hasOwnProperty native v8natives.js:198:30",0x289f64438d0,~
code-creation,LazyCompile,0,0x2d5000a33c20,284,"ToName native runtime.js:549:16",0x289f643bb28,~
code-creation,Stub,2,0x2d5000a33d40,182,"DoubleToIStub"
code-creation,Stub,2,0x2d5000a33e00,507,"NumberToStringStub"

以前は、ティックを解釈するために V8 のソースコードが必要でした。幸いなことに、Node.js 4.4.0 以降、V8 をソースから別途ビルドすることなくこの情報を利用できるツールが導入されました。組み込みプロファイラがアプリケーションのパフォーマンスに関する洞察を提供するのにどのように役立つかを見てみましょう。

ティックプロファイラの使用を説明するために、簡単な Express アプリケーションを使用します。このアプリケーションには2つのハンドラがあります。1つはシステムに新しいユーザーを追加するためのものです。

app.get('/newUser', (, ) => {
  let  = .query.username || '';
  const  = .query.password || '';

   = .replace(/[^a-zA-Z0-9]/g, '');

  if (! || ! || users[]) {
    return .sendStatus(400);
  }

  const  = .randomBytes(128).toString('base64');
  const  = .pbkdf2Sync(, , 10000, 512, 'sha512');

  users[] = { ,  };

  .sendStatus(200);
});

もう1つはユーザー認証の試みを検証するためのものです。

app.get('/auth', (, ) => {
  let  = .query.username || '';
  const  = .query.password || '';

   = .replace(/[^a-zA-Z0-9]/g, '');

  if (! || ! || !users[]) {
    return .sendStatus(400);
  }

  const { ,  } = users[];
  const  = .pbkdf2Sync(, , 10000, 512, 'sha512');

  if (.timingSafeEqual(, )) {
    .sendStatus(200);
  } else {
    .sendStatus(401);
  }
});

これらは Node.js アプリケーションでユーザーを認証するための推奨されるハンドラではなく、純粋に説明のために使用されていることに注意してください。一般的に、独自の暗号認証メカニズムを設計しようとするべきではありません。既存の実証済みの認証ソリューションを使用する方がはるかに優れています。

さて、アプリケーションをデプロイし、ユーザーがリクエストのレイテンシが高いと不満を言っていると仮定します。組み込みプロファイラを使用してアプリを簡単に実行できます。

NODE_ENV=production node --prof app.js

そして ab (ApacheBench) を使ってサーバーに負荷をかけます。

curl -X GET "https://:8080/newUser?username=matt&password=password"
ab -k -c 20 -n 250 "https://:8080/auth?username=matt&password=password"

そして ab の出力を得ます。

Concurrency Level:      20
Time taken for tests:   46.932 seconds
Complete requests:      250
Failed requests:        0
Keep-Alive requests:    250
Total transferred:      50250 bytes
HTML transferred:       500 bytes
Requests per second:    5.33 [#/sec] (mean)
Time per request:       3754.556 [ms] (mean)
Time per request:       187.728 [ms] (mean, across all concurrent requests)
Transfer rate:          1.05 [Kbytes/sec] received

...

Percentage of the requests served within a certain time (ms)
  50%   3755
  66%   3804
  75%   3818
  80%   3825
  90%   3845
  95%   3858
  98%   3874
  99%   3875
 100%   4225 (longest request)

この出力から、1秒あたり約5件のリクエストしか処理できておらず、平均リクエストのラウンドトリップに4秒近くかかっていることがわかります。実際の例では、ユーザーリクエストのために多くの関数で多くの処理を行っている可能性がありますが、この単純な例でさえ、正規表現のコンパイル、ランダムなソルトの生成、ユーザーパスワードからの一意なハッシュの生成、または Express フレームワーク自体の中で時間が失われている可能性があります。

--prof オプションを使用してアプリケーションを実行したため、アプリケーションをローカルで実行したのと同じディレクトリにティックファイルが生成されました。これは isolate-0xnnnnnnnnnnnn-v8.log (n は数字) のような形式のはずです。

このファイルを理解するためには、Node.js バイナリにバンドルされているティックプロセッサを使用する必要があります。プロセッサを実行するには、--prof-process フラグを使用します。

node --prof-process isolate-0xnnnnnnnnnnnn-v8.log > processed.txt

お気に入りのテキストエディタで processed.txt を開くと、いくつかの異なる種類の情報が表示されます。ファイルはセクションに分かれており、さらに言語ごとに分かれています。まず、サマリーセクションを見てみると、次のようになっています。

 [Summary]:
   ticks  total  nonlib   name
     79    0.2%    0.2%  JavaScript
  36703   97.2%   99.2%  C++
      7    0.0%    0.0%  GC
    767    2.0%          Shared libraries
    215    0.6%          Unaccounted

これは、収集された全サンプルの97%が C++ コードで発生したことを示しており、処理済み出力の他のセクションを見るときは、(JavaScript ではなく) C++ で行われている処理に最も注意を払うべきであることを意味します。これを念頭に置いて、次にどの C++ 関数が最も CPU 時間を消費しているかに関する情報を含む [C++] セクションを探し、見てみます。

 [C++]:
   ticks  total  nonlib   name
  19557   51.8%   52.9%  node::crypto::PBKDF2(v8::FunctionCallbackInfo<v8::Value> const&)
   4510   11.9%   12.2%  _sha1_block_data_order
   3165    8.4%    8.6%  _malloc_zone_malloc

上位3つのエントリがプログラムが消費した CPU 時間の 72.1% を占めていることがわかります。この出力から、CPU 時間の少なくとも 51.8% が、ユーザーのパスワードからのハッシュ生成に対応する PBKDF2 という関数によって占められていることがすぐにわかります。しかし、下位2つのエントリが我々のアプリケーションにどのように関与しているかはすぐには明らかではないかもしれません (あるいは、明らかであっても、例のためにそうでないふりをします)。これらの関数の関係をよりよく理解するために、次に [Bottom up (heavy) profile] セクションを見てみましょう。これは各関数の主要な呼び出し元に関する情報を提供します。このセクションを調べると、次のことがわかります。

   ticks parent  name
  19557   51.8%  node::crypto::PBKDF2(v8::FunctionCallbackInfo<v8::Value> const&)
  19557  100.0%    v8::internal::Builtins::~Builtins()
  19557  100.0%      LazyCompile: ~pbkdf2 crypto.js:557:16

   4510   11.9%  _sha1_block_data_order
   4510  100.0%    LazyCompile: *pbkdf2 crypto.js:557:16
   4510  100.0%      LazyCompile: *exports.pbkdf2Sync crypto.js:552:30

   3165    8.4%  _malloc_zone_malloc
   3161   99.9%    LazyCompile: *pbkdf2 crypto.js:557:16
   3161  100.0%      LazyCompile: *exports.pbkdf2Sync crypto.js:552:30

このセクションの解析は、上記の生のティック数よりも少し手間がかかります。上記の各「コールスタック」内で、親列のパーセンテージは、現在の行の関数が上の行の関数によって呼び出されたサンプルの割合を示しています。例えば、上記の中央の「コールスタック」の _sha1_block_data_order では、_sha1_block_data_order がサンプルの 11.9% で発生したことがわかります。これは上記の生のカウントからわかっていたことです。しかし、ここでは、それが常に Node.js の crypto モジュール内の pbkdf2 関数によって呼び出されていたこともわかります。同様に、_malloc_zone_malloc もほぼ排他的に同じ pbkdf2 関数によって呼び出されていたことがわかります。したがって、このビューの情報を使用することで、ユーザーのパスワードからのハッシュ計算が、上記からの 51.8% だけでなく、_sha1_block_data_order_malloc_zone_malloc への呼び出しが pbkdf2 関数に代わって行われたため、最もサンプリングされた上位3つの関数すべての CPU 時間を占めていることがわかります。

この時点で、パスワードベースのハッシュ生成が最適化の対象となるべきことは非常に明確です。幸いにも、あなたは非同期プログラミングの利点を完全に理解しており、ユーザーのパスワードからハッシュを生成する作業が同期的に行われているため、イベントループを拘束していることに気づきます。これにより、ハッシュを計算している間、他の着信リクエストの処理ができなくなります。

この問題を解決するために、上記のハンドラに少し変更を加えて、pbkdf2 関数の非同期バージョンを使用するようにします。

app.get('/auth', (, ) => {
  let  = .query.username || '';
  const  = .query.password || '';

   = .replace(/[^a-zA-Z0-9]/g, '');

  if (! || ! || !users[]) {
    return .sendStatus(400);
  }

  .pbkdf2(
    ,
    users[].salt,
    10000,
    512,
    'sha512',
    (, ) => {
      if (users[].hash.toString() === .toString()) {
        .sendStatus(200);
      } else {
        .sendStatus(401);
      }
    }
  );
});

非同期バージョンのアプリで上記の ab ベンチマークを再度実行すると、次のようになります。

Concurrency Level:      20
Time taken for tests:   12.846 seconds
Complete requests:      250
Failed requests:        0
Keep-Alive requests:    250
Total transferred:      50250 bytes
HTML transferred:       500 bytes
Requests per second:    19.46 [#/sec] (mean)
Time per request:       1027.689 [ms] (mean)
Time per request:       51.384 [ms] (mean, across all concurrent requests)
Transfer rate:          3.82 [Kbytes/sec] received

...

Percentage of the requests served within a certain time (ms)
  50%   1018
  66%   1035
  75%   1041
  80%   1043
  90%   1049
  95%   1063
  98%   1070
  99%   1071
 100%   1079 (longest request)

やりました!アプリは現在、1秒あたり約20件のリクエストを処理しており、同期的なハッシュ生成の場合の約4倍です。さらに、平均レイテンシは以前の4秒から1秒強に短縮されました。

この (意図的に作られた) 例のパフォーマンス調査を通して、V8 ティックプロセッサが Node.js アプリケーションのパフォーマンスをよりよく理解するのにどのように役立つかをお分かりいただけたことでしょう。

フレームグラフの作成方法も役立つかもしれません。

読了時間
7分
コントリビュート
このページを編集