Node.jsでプロファイルツールを使ってみる(--prof)

処理に時間がかかっている様子やどれ位メモリを使っているのかを調べる方法をプロファイルというらしい。

Node.js に組み込まれたプロファイルツール

node --prof (対象のプログラム).js

で、カレントに「isolate-0x424a810-v8.log」みたいなログファイルができる。
ここにプロファイルが載ってるんだけど、そのままみると

$ head -50 isolate-0x424a810-v8.log
v8-version,6,8,275,32,-node.45,0
shared-library,/home/vagrant/.nvm/versions/node/v10.14.2/bin/node,0x400000,0x2290000,0
shared-library,/lib/x86_64-linux-gnu/libc-2.27.so,0x7fad972e9000,0x7fad974d0000,0
shared-library,/lib/x86_64-linux-gnu/libpthread-2.27.so,0x7fad976da000,0x7fad976f4000,0
shared-library,/lib/x86_64-linux-gnu/libgcc_s.so.1,0x7fad978f9000,0x7fad97910000,0
.........

こんな感じでわけわからないから、nodeコマンドでわかりやすく表示する。

$ node --prof-process isolate-0x424a810-v8.log
Statistical profiling result from isolate-0x424a810-v8.log, (3359 ticks, 172 unaccounted, 0 excluded).

 [Shared libraries]:
   ticks  total  nonlib   name
    198    5.9%          /lib/x86_64-linux-gnu/libc-2.27.so
     72    2.1%          /home/vagrant/.nvm/versions/node/v10.14.2/bin/node
     25    0.7%          /lib/x86_64-linux-gnu/libpthread-2.27.so
      1    0.0%          /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.25

 [JavaScript]:
   ticks  total  nonlib   name
   2885   85.9%   94.2%  LazyCompile: *fib /home/vagrant/workspace/fibonacci/app.js:2:13
      1    0.0%    0.0%  LazyCompile: ~nextTick internal/process/next_tick.js:96:20
      1    0.0%    0.0%  LazyCompile: ~log console.js:196:37
      1    0.0%    0.0%  Builtin: LoadIC_Uninitialized
      1    0.0%    0.0%  Builtin: KeyedLoadIC_PolymorphicName
      1    0.0%    0.0%  Builtin: InterpreterEntryTrampoline
      1    0.0%    0.0%  Builtin: FastNewClosure

 [C++]:
   ticks  total  nonlib   name

 [Summary]:
   ticks  total  nonlib   name
   2891   86.1%   94.4%  JavaScript
      0    0.0%    0.0%  C++
      3    0.1%    0.1%  GC
    296    8.8%          Shared libraries
    172    5.1%          Unaccounted

 [C++ entry points]:
   ticks    cpp   total   name

 [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
   2885   85.9%  LazyCompile: *fib /home/vagrant/workspace/fibonacci/app.js:2:13
....................(以下プロファイル)

[Summary] という項目に、 プログラムの処理全体の概要、
[Bottom up (heavy) profile] という項目に、時間のかかった処理（一番左の ticks という列は、各処理にかかった イベントループ数）
などなど。
アルゴリズムの改善とかで、どの処理に時間かかったかを調べるときに便利ね！