LoginSignup
2
1
@awa2(Takanori Awatsu)

NodeJS: プロファイリング

Posted at

NodeJSとV8のチューニング

NodeJSの処理のほとんどはV8に依存しているため、V8の状態をプロファイリングすることでパフォーマンス上の問題などを特定できる場合があります。

JITプロファイリング

プロファイラの実行は次のとおりです。

$ NODE_ENV=puroduction node --prof app.js

これにより、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"

とはいえ、これではとても判ったものではないので、プロセッサを利用します。

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

すると、これらの状態をサマライズしてくれます。

Statistical profiling result from isolate-0xnnnnnnnnnnnn-21147-v8.log, (*** ticks, * unaccounted, 0 excluded).

 [Shared libraries]:
   ticks  total  nonlib   name
     11    2.0%          /usr/lib/system/libsystem_c.dylib
     11    2.0%          /usr/lib/libc++.1.dylib
     10    1.9%          /usr/lib/system/libsystem_malloc.dylib
      4    0.7%          /usr/lib/system/libsystem_platform.dylib
      2    0.4%          /usr/lib/system/libsystem_pthread.dylib
      2    0.4%          /usr/lib/system/libsystem_kernel.dylib
      1    0.2%          /usr/lib/system/libdyld.dylib

 [JavaScript]:
   ticks  total  nonlib   name
      1    0.2%    0.2%  RegExp: ^((?:@[^/\\%]+\/)?[^./\\%][^/\\%]*)(\/.*)?$
      1    0.2%    0.2%  Function: ^toRealPath node:internal/modules/cjs/loader:393:20
      :
      :
        

 [C++]:
   ticks  total  nonlib   name
    109   20.2%   21.9%  t auto node::options_parser::OptionsParser<node::EnvironmentOptions>::Convert<node::DebugOptions>(node::options_parser::OptionsParser<node::DebugOptions>::Implication, node::options_parser::OptionsParser<node::DebugOptions>* (node::EnvironmentOptions::*)())
     95   17.6%   19.1%  t node::fs::Read(v8::FunctionCallbackInfo<v8::Value> const&)
     83   15.4%   16.7%  T node::contextify::ContextifyContext::CompileFunction(v8::FunctionCallbackInfo<v8::Value> const&)
     59   10.9%   11.8%  t node::fs::InternalModuleStat(v8::FunctionCallbackInfo<v8::Value> const&)
      :
      :

 [Summary]:
   ticks  total  nonlib   name
      3    0.6%    0.6%  JavaScript
    492   91.3%   98.8%  C++
     22    4.1%    4.4%  GC
     41    7.6%          Shared libraries
      3    0.6%          Unaccounted
      :
      :

 [C++ entry points]:
   ticks    cpp   total   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
      :

 [Bottom up (heavy) profile]:
  Note: percentage shows a share of a particular caller in the total
  amount of its parent calls.
  Callers occupying less than 1.0% are not shown.

   ticks parent  name   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
      :
      :

これにより、CPUを何に使用しているのか、ある程度特定できます。ここでは、node::crypto::PBKDF2 の呼び出しが多くのCPUを利用していることがわかります。

また、このテキストの後半 [Bottom up (heavy) profile] は、関数の主な呼び出しもとを表しています。
ここでは、NodeJS公式のドキュメントからサンプルを抜粋していますが、 crypto.js における pdkdf2Syncが多くのリソースを消費していることがわかりますから、この部分にボトルネックがあると考えるわけです。

メモリプロファイリング

NodeJSそのものは、イベントモデルを最大限活かすことで、かなり少ないメモリで効率の良いIO関連処理を実装することができます。とはいえ、メモリを大きく利用するコードを書くことがあることもあるでしょう。
ここでは、メモリプロファイリングの方法を学びます。

ヒープダンプ

ヒープ領域の利用状況を確認する方法の１つに、ヒープダンプがあります。

NodeJSのヒープへのアクセスは、インスペクタ経由で簡単に確認することができます。

node --inspect some-app.js

インスペクトフラグでアプリケーションを起動したあと、Chromeの開発者ツールから、 chrome://inspect/#devices でインスペクタを開き「Devices」から「Open dedicated DevTools for Node」によって開くことができます。

image.png

（VSCodeやVisual Studioなどでも接続できますがここでは割愛します）

DevToolsからは、コンソール入出力の確認のほか、メモリプロファイリングができます。
image.png

ここで「Take snapshot」を選択することで、ヒープのスナップショットを得ることができます。

image.png

スナップショット比較

メモリリークの発見には、異なる時間で取得したスナップショット比較が有効です。
image.png

スナップショットでは「Comparison（比較）」によって、どのようにメモリが変化したかを確認することがD系ます。

ちょっと古いですが、具体的な演習ができるコードこちらに公開されているので、一度練習しておくとよいでしょう。

ヒーププロファイリング

スナップショットではなく、メモリ割り当てのタイムラインをプロファイリングすることもできます。
先ほどの画面で「Allocation instrumentation on timeline」を選択してください。

image.png

先ほどのスナップショットと異なり、リアルタイムの割り当て状況を理解することができます。

ただし、このプロファイリングは非常にオーバーヘッドが大きいため、実環境で実行することは推奨されていません。やむをえず本番環境でのプロファイリングが必要な場合、サンプリングする方法もあるので、そちらを代わりに使ってください。

ShallowSizeとRetainedSize

スナップショットやタイムラインで確認できるサイズには、シャローとリテインドの２つのメモリサイズの値があります。
シャローは、オブジェクト自体が保持する値で、大きな値はほとんどありません。文字列や配列は、生データを保持する場合があり、比較的大きくなる場合があります。それ以外の場合には、ほとんどはデータへの参照のみが保持されています。

一方、リテインドは、いわゆる値の実態のサイズです。GCによって解放されるメモリサイズは主にこちらになります。

GCのトレース

最後は、前回説明したV8のGCの状況をトレースする方法についてです。

$ node --trace-gc some-app.js

トレース付きで実行されたNodeJSは、次のような出力を返します。

[39067:0x158008000]     2297 ms: Scavenge 117.5 (135.8) -> 102.2 (135.8) MB, 0.8 / 0.0 ms  (average mu = 0.994, current mu = 0.994) allocation failure
[39067:0x158008000]     2375 ms: Scavenge 120.0 (138.3) -> 104.7 (138.3) MB, 0.9 / 0.0 ms  (average mu = 0.994, current mu = 0.994) allocation failure
[39067:0x158008000]     2453 ms: Scavenge 122.4 (140.8) -> 107.1 (140.8) MB, 0.7 / 0.0 ms  (average mu = 0.994, current mu = 0.994) allocation failure
[39067:0x158008000]     2531 ms: Scavenge 124.9 (143.3) -> 109.6 (143.3) MB, 0.7 / 0.0 ms  (average mu = 0.994, current mu = 0.994) allocation failure
[39067:0x158008000]     2610 ms: Scavenge 127.1 (145.5) -> 111.8 (145.5) MB, 0.7 / 0.0 ms  (average mu = 0.994, current mu = 0.994) allocation failure
[39067:0x158008000]     2688 ms: Scavenge 129.6 (148.0) -> 114.2 (148.0) MB, 0.8 / 0.0 ms  (average mu = 0.994, current mu = 0.994) allocation failure
[39067:0x158008000]     2766 ms: Scavenge 132.0 (150.5) -> 116.7 (150.5) MB, 1.1 / 0.0 ms  (average mu = 0.994, current mu = 0.994) allocation failure

この見方は、次のとおりです。

[39067:0x158008000]     2297 ms: Scavenge 117.5 (135.8) -> 102.2 (135.8) MB,
 ^^^^^ ^^^^^^^^^^^      ^^^^^^^  ^^^^^^^^ ^^^^^^^^^^^^^    ^^^^^^^^^^^^^
 PID   Heap Instance    経過時間  イベント   GC前ヒープ(合計)   GC後ヒープ(合計)
 
0.8 / 0.0 ms  (average mu = 0.994, current mu = 0.994) allocation failure
^^^^^^^^^^^^　                                         ^^^^^^^^^^^^^^^^^^
GC消費時間                                              割り当て失敗

各イベントについて

ScavengeとMark-sweepは、それぞれ、前回学んだGC対象のメモリ領域であるNewSpaceとOldSpaceで行われる操作イベントです。

  • Scavenge: メモリ上で新しいオブジェクトの割り当てのための必要な空間がない場合に、From領域とTo領域をスイッチし、生きているオブジェクトのみを新しい領域にコピーすることでGCが行われます。
  • Mark-sweep: 古くなったオブジェクトの到達性からオブジェクトの生死を判定して処理します

さて、Mark-sweep イベントが多数表示される場合、メモリリークが発生している可能性があります。何かの理由でオブジェクトが長く生き残り、OldSpaceを食い潰していってる可能性が高い場合には、OldSpaceのサイズは肥大化していき、最終的にOut of memoryエラーに到達してアプリケーションが停止します。

Linuxでのプロファイリング

さらにステージング環境などでは、Linux Perfを用いてプロファイリングを行うことができます。
NodeJSでは、２つのオプションがあります。

  • --perf-basic-profオプション：mapファイルに完全なプロファイリングを出力します
  • --perf-basic-prof-only-functions：関数のみにプロファイリングを行います。パフォーマンスへの影響が抑えられます。
# Launch the application an get the PID
$ node --perf-basic-prof-only-functions index.js &
[1] 3870

プロファイリングを実施すると tmpディレクトリにmap ファイルが出力されます。
ただし、生データは取り扱いづらいため、フレームグラフに変換します。

$ sudo perf script > perfs.out
2
1
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
2
1