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 つあります。
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 "http://localhost:8080/newUser?username=matt&password=password"
ab -k -c 20 -n 250 "http://localhost: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 つのエントリがアプリケーションにどのように関与しているかは、すぐに明らかではない可能性があります（または、例として、そうであると仮定します）。これらの関数間の関係をよりよく理解するために、次に[ボトムアップ（重い）プロファイル]セクションを見ていきます。このセクションには、各関数の主要な呼び出し元に関する情報が提供されています。このセクションを調べると、次のようになります。
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', (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)やった！アプリケーションは、同期ハッシュ生成時よりも約 4 倍多い、1 秒あたり約 20 のリクエストを処理できるようになりました。さらに、平均レイテンシは、以前の 4 秒から 1 秒強に短縮されました。
この（確かに巧妙に考えられた）例のパフォーマンス調査を通じて、V8 ティックプロセッサが Node.js アプリケーションのパフォーマンスの理解を深めるのにどのように役立つかが理解できたことを願っています。
フレイムグラフの作成方法も役立つ場合があります。