Node.js アプリケーションのプロファイリング
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', (req, res) => {
let username = req.query.username || '';
const password = req.query.password || '';
username = username.replace(/[!@#$%^&*]/g, '');
if (!username || !password || users[username]) {
return res.sendStatus(400);
}
const salt = crypto.randomBytes(128).toString('base64');
const hash = crypto.pbkdf2Sync(password, salt, 10000, 512, 'sha512');
users[username] = { salt, hash };
res.sendStatus(200);
});
もう1つは、ユーザー認証試行を検証するためのハンドラです。
app.get('/auth', (req, res) => {
let username = req.query.username || '';
const password = req.query.password || '';
username = username.replace(/[!@#$%^&*]/g, '');
if (!username || !password || !users[username]) {
return res.sendStatus(400);
}
const { salt, hash } = users[username];
const encryptHash = crypto.pbkdf2Sync(password, salt, 10000, 512, 'sha512');
if (crypto.timingSafeEqual(hash, encryptHash)) {
res.sendStatus(200);
} else {
res.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++ コードで発生したことを示しており、処理済み出力の他のセクションを表示する際には、C++ で行われている作業に最も注意を払う必要があることを示しています（JavaScript とは対照的です）。これを念頭に置いて、次に、どの 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つのエントリがアプリケーションにどのように関係しているかはすぐにはわからない場合があります（または、例のためにそうでないふりをします）。これらの関数の関係をよりよく理解するために、次に、各関数のプライマリ呼び出し元に関する情報
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
このセクションの解析は、上記のraw tick countsよりも少し手間がかかります。上記の各「コールスタック」内では、親カラムのパーセンテージは、上の行の関数が現在の行の関数によって呼び出されたサンプルのパーセンテージを示しています。たとえば、上記の_sha1_block_data_orderの中間の「コールスタック」では、_sha1_block_data_orderがサンプルの11.9%で発生したことがわかりますが、これは上記のraw countsからすでにわかっています。しかし、ここでは、Node.js cryptoモジュール内のpbkdf2関数によって常に呼び出されていたこともわかります。同様に、_malloc_zone_mallocがほぼ同じpbkdf2関数によって呼び出されていることもわかります。したがって、このビューの情報を使用すると、ユーザーのパスワードからのハッシュ計算が、上記の51.8%だけでなく、上位3つの最もサンプリングされた関数におけるすべてのCPU時間を占めていることがわかります。これは、_sha1_block_data_orderと_malloc_zone_mallocの呼び出しがpbkdf2関数のために実行されたためです。
この時点で、パスワードベースのハッシュ生成が最適化の対象となることは非常に明確です。幸いなことに、あなたは非同期プログラミングの利点を完全に理解しており、ユーザーのパスワードからハッシュを生成する作業が同期的に行われているため、イベントループをブロックしていることに気づいています。これにより、ハッシュを計算している間、他の受信リクエストを処理することができません。
この問題を解決するために、上記のハンドラをpbkdf2関数の非同期バージョンを使用するように少し変更します。
app.get('/auth', (req, res) => {
let username = req.query.username || '';
const password = req.query.password || '';
username = username.replace(/[!@#$%^&*]/g, '');
if (!username || !password || !users[username]) {
return res.sendStatus(400);
}
crypto.pbkdf2(
password,
users[username].salt,
10000,
512,
'sha512',
(err, hash) => {
if (users[username].hash.toString() === hash.toString()) {
res.sendStatus(200);
} else {
res.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)
やった！アプリケーションは現在、毎秒約20リクエストを処理しており、同期ハッシュ生成の場合の約4倍です。さらに、平均レイテンシは以前の4秒から1秒強に短縮されました。
この（確かに作為的な）例の性能調査を通して、V8 tickプロセッサがNode.jsアプリケーションの性能をより深く理解するのにどのように役立つかを理解していただけたことを願っています。
フレームグラフの作成方法も参考になるかもしれません。