技術探し

JavaScriptを中心に記事を書いていきます :;(∩´﹏`∩);:

トップ > Node > Node.jsのアプリケーションデバッグ・改善方法をおさらいする

Node.jsのアプリケーションデバッグ・改善方法をおさらいする

Node JavaScript

ステップ実行

--debugと--debug-brkはNode8の時点ですでに非推奨なので、使わないでください。

デバッグ方法

  • コンソール
  • Chrome devtools

または、VSCodeのようなIDEに任せる

今回は、エディタ依存の話は特にしないです。

共通的な手順

基本的には、debugger を止めたい場所に置いていくことになります。

例として、以下のコードで説明していきます。

'use strict';

const { readFile } = require('fs');
const { promisify } = require('util');

const readFileAsync = promisify(readFile);

(async () => {
  const data = await readFileAsync('hello.txt', 'utf8');

  debugger;

  console.log(data);
})();

コンソールでデバッグする

inspectというのを使います。

ᐅ node inspect index.js 
< Debugger listening on ws://127.0.0.1:9229/e1d19bde-2450-4d9b-9736-02fd
35038351
< For help, see: https://nodejs.org/en/docs/inspector
< Debugger attached.
Break on start in index.js:1
> 1 (function (exports, require, module, __filename, __dirname) { 'use s
trict';
  2
  3 const { readFile } = require('fs');
debug>

実行すると、一行目にbreakpointが置かれた状態で開始されます。
cont(or c)と入力することにより、次のbreakpointまで実行されます。

< Debugger listening on ws://127.0.0.1:9229/e1d19bde-2450-4d9b-9736-02fd
35038351
< For help, see: https://nodejs.org/en/docs/inspector
< Debugger attached.
Break on start in index.js:1
> 1 (function (exports, require, module, __filename, __dirname) { 'use s
trict';
  2
  3 const { readFile } = require('fs');
debug> cont
break in index.js:11  
  9   const data = await readFileAsync('hello.txt', 'utf8');
 10
>11   debugger;
 12
 13   console.log(data);
debug>

先程書いたdebuggerまで到達したことがわかります。
さて、ここでdataなどの値が見たいと思います。 そのようなときはreplというコマンドをdebugに対して打つことにより確認することができます。

...
 13   console.log(data);
debug> repl
Press Ctrl + C to leave debug repl
> data
'hello:)'
> typeof readFileAsync
'function'
>

Ctrl+Cを実行することにより、debugに戻ることが可能です。

もう一度、進めるともうdebuggerは存在しないため、終了となります。

  3 const { readFile } = require('fs');
debug>
debug> c
break in index.js:11
  9   const data = await readFileAsync('hello.txt', 'utf8');
 10
>11   debugger;
 12
 13   console.log(data);
debug> c
< hello:)
< Waiting for the debugger to disconnect...
debug>.exit

コマンド

  • cont, c
    • 実行を続ける
  • next, n
    • 次のステップに行きます
  • step, s
    • ステップイン(関数内の処理を実行)
  • out, o
    • ステップアウト(関数内から抜け出す)
  • pause
    • 起動コードを一時停止させる
  • setBreakpoint(), cb()
    • 引数が空の場合
      • 現在行にbreakpointを設置する
    • 引数が行番号の場合 (setBreakpoint(100))
      • 現在のファイルの指定された行にbreakpointを設置する
    • 引数が関数文字列の場合 (setBreakpoint('fn()'))
      • 関数本体の最初の文にbreakpointを設置する
    • 引数がファイル名 + 行の場合 (setBreakpoint('foo.js', 100))
      • そのファイルのその行にbreakpointを設置する
  • backtrace, br
    • 現在の実行フレームのバックトレースを表示する
  • repl
    • 評価するためのデバッガーを立ち上げる

基本的に上記だけで事足りると思います。(watchは個人的にはあまり使わない。。)

Chromeのdevtoolsを起動させる

Chrome DevTools Protocolを用いて、デバッグを行います。

基本的に起動しぱなっしのアプリケーション(e.g. http)などでは、--inspectを使い、終了するコードには--inspect-brkを使います。
--inspect-brkでは最初の行にbreakpointを自動的に配置します。(つまり、node inspect のコンソールがない版)

今回の例の場合は、すぐに終了してしまうため、--inspect-brkを使います。

ᐅ node --inspect-brk index.jsDebugger listening on ws://127.0.0.1:9229/b6e42f20-bbc5-4848-8c59-b25ccf
e0a454
For help, see: https://nodejs.org/en/docs/inspector

となるので、Chromeに chrome://inspect/ とURLバーに入力すると、devicesの部分にNodeがつながっていることが確認できます。

f:id:about_hiroppy:20180917010240p:plain

inspectがリンクになっているので、クリックをするとChromeのdevtoolsが別windowで起動します。

f:id:about_hiroppy:20180917010612p:plain

先程の、contは右ツールバーの一番左のボタンを押すことにより進めることができます。

f:id:about_hiroppy:20180917011008p:plain

進むと以下のようになります。 簡単にファイルから読み取った中身(data)が表示されました。

f:id:about_hiroppy:20180917011111p:plain

終了しないコードの値を見る

以下のコードをサンプルとします。

'use strict';

const http = require('http');

http.createServer((request, response) => {
  debugger;
  response.writeHead(200, { 'Content-Type': 'text/plain' });
  response.write('hello:)');
  response.end();
}).listen(8080);

このように、リクエストが来た時に内部の状態が見たいときは、inspect または --inspectを用いて起動させます。

ᐅ node --inspect server.js 
Debugger listening on ws://127.0.0.1:9229/61ea5e2c-6674-4a08-bd8a-f1cc1d8651bd
For help, see: https://nodejs.org/en/docs/inspector
Debugger attached.

あとは、上記と同じ方法で値の確認等が行なえます。
breakpoint前ではリクエストをまだ返してない状態であり、進めるとレスポンスを返します。

リモートデバッグ

パブリックIPをリッスンするのは問題なので、リモートデバッグを有効化する場合は、トンネリングする方法が推奨されています。

Debugging - Getting Started | Node.js

debuggerを書くのがめんどくさい場合

コンソールの場合

setBreakpoint(行番号) or sb(行番号)を使い、debug上で設定することが可能です。
importしている別ファイルに対しては、setBreakpoint('foo.js', 22)のように書くことによりbreakpointを置けます。

< Debugger listening on ws://127.0.0.1:9229/e0e85f75-c4c9-4d53-ab45-cc83d69ad9ba< For help, see: https://nodejs.org/en/docs/inspector< Debugger attached.
Break on start in index.js:1
> 1 (function (exports, require, module, __filename, __dirname) { 'use strict';
  2  
  3 const { readFile } = require('fs');
debug> setBreakpoint(10)
  6 const readFileAsync = promisify(readFile);  
  7
  8 (async () => {
  9   const data = await readFileAsync('hello.txt', 'utf8'); 
 10
>11   console.log(data); 
 12 })();
 13
debug> repl
Press Ctrl + C to leave debug repl
> data'hello:)'
debug
> c< hello:)
< Waiting for the debugger to disconnect...
debug> .exit

Chromeの場合

--inspect-brkを使い一旦起動させ、inspectorからbreakpointを設定していきます。
Node関係なく、行番号の部分をクリックすることにより、設置できます。
そうすると、右下のBreakpointsの枠に入ったのがわかります。

f:id:about_hiroppy:20180917012620p:plain

便利なツール

Node Inspector Managerを使うと簡単にchromeのインスペクタを開くことができます。
NIMの設定で自動でinspectorを開くに設定すると、--inspect-brk時やinspect時に勝手にChromeのInspectorが起動します。

chrome.google.com

使い分け

基本的に、サーバー内でどうしても確認したい時以外は、Webエンジニアは慣れているだろうし、Chromeで大丈夫かなって思っています。

CPU・メモリ等

便利なツール

node-report

もうすぐしたら、NodeのCoreへビルトインとして入ります。

github.com

オプションをつけることにより、ネイティブのスタックトレース、ヒープ統計情報、プラットフォーム情報、リソース使用状況などをファイルに出力します。

以下の情報が記載されます。

  • JavaScript Stack Trace
  • Native Stack Trace
  • JavaScript Heap and Garbage Collector
  • Resource Usage
  • Node.js libuv Handle Summary
  • System Information

将来的にはこれを使うことになると思います。

clinic

今回は、clinicを用いて説明する場合があります。
clinicを作っているのは、NearFormという会社で、JamesやAnna、MatteoなどのNode.jsのコミッターが所属する会社です。
dockerやflame、bubbleprofの機能を提供します。

github.com

CPU

負荷率を取る

V8内のプロファイラの実行をサンプリングします。
--profを使い、実行コードの負荷率をみることができます。

ᐅ node --prof index.js

と実行すると、isolate-0xNNNNNNNNN-v8.logみたいなファイルが生成されます。
次に、

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

と実行することにより、人間が読める形式になります。

 [JavaScript]:
   ticks  total  nonlib   name
      2    2.4%    2.5%  Builtin: KeyedStoreIC
      1    1.2%    1.3%  LazyCompile: ~NativeModule.require internal/bootstrap/loaders.js:138:34
      1    1.2%    1.3%  Builtin: CEntry_Return1_DontSaveFPRegs_ArgvOnStack_NoBuiltinExit

 [C++]:
   ticks  total  nonlib   name
     22   26.8%   27.5%  T node::contextify::ContextifyScript::New(v8::FunctionCallbackInfo<v8::Value> const&)
      6    7.3%    7.5%  T v8::internal::Log::MessageBuilder& v8::internal::Log::MessageBuilder::operator<<<char const*>(char const*)
      3    3.7%    3.8%  t node::GetBinding(v8::FunctionCallbackInfo<v8::Value> const&)
      3    3.7%    3.8%  T node::TTYWrap::New(v8::FunctionCallbackInfo<v8::Value> const&)

 [Summary]:
   ticks  total  nonlib   name
      4    4.9%    5.0%  JavaScript
     74   90.2%   92.5%  C++
      4    4.9%    5.0%  GC
      2    2.4%          Shared libraries
      2    2.4%          Unaccounted

各言語ごとにセクションが存在し、そこでどれだけ負荷がかかっているかが記載されます。

blog.hiroppy.me

JavaScript CPU Profileを取る

inspectで起動させ、Profilerタブから記録を取ります。(web開発同様)

f:id:about_hiroppy:20180917150242p:plain

フレームグラフを見る

頻繁なコードパスを可視化します。

$ clinic flame -- node index.js

f:id:about_hiroppy:20180917084446p:plain

x軸はサンプルが占める割合、y軸がstack traceを示します。
--profの表記と同様に、* は最適化済みを示し、~は非最適化を示します。
薄い赤色ほど、off-CPUであり、濃い赤であるほどon-CPUです。

以下を読むとわかりやすいです。

Hot/Cold Flame Graphs

メモリ

chromeのdevtoolsにあるmemoryからsnapshotを取得します。
そこから比較をしていきメモリリークなどの発見を行います。

f:id:about_hiroppy:20180917141337p:plain f:id:about_hiroppy:20180917143425p:plain

また、メモリリークを発見する手法として、--trace-gc, --expose-gc を使った方法もあります。

$ node --trace-gc test.js
[43929:0x102801c00]       39 ms: Scavenge 3.4 (6.3) -> 3.1 (7.3) MB, 0.9 / 0.0 ms  allocation failure
[43929:0x102801c00]       50 ms: Scavenge 3.6 (7.3) -> 3.5 (8.3) MB, 1.2 / 0.0 ms  allocation failure

$ node --optimize_for_size --max_old_space_size=4096 --gc_interval=100 #このようにV8のGCを操作することも可能

postd.cc

CPU・Memory・Event Loop Delay・Active Handles の推移を見る

clinic doctor -- node server.js

実行が短いプログラムには使えないことに注意してください。

f:id:about_hiroppy:20180917090239p:plain

イベントループの遅延が見えるのがありがたいです。

区間測定 及び 関数実行時間測定を行う

perf_hooksモジュールを使い、区間の実行時間、関数の実行時間、GCのコールされた種類等を検知し、改善に役立てます。

renderToString にかかる時間を計測する例です。

const { performance, PerformanceObserver } = require('perf_hooks');
const React = require('react');
const { renderToString } = require('react-dom/server');

const render = performance.timerify(renderToString);
const obs = new PerformanceObserver((list, observer) => {
  const data = list.getEntries();

  data.forEach((l) => {
    if (l.name === 'renderToString') console.log('duration', l.duration);
  });

  observer.disconnect();
});

obs.observe({ entryTypes: ['function'], buffered: true });

const Main = (props) => {
  return React.createElement(
    'ul',
    null,
    [...new Array(props.n)].map((_, i) => {
      return React.createElement('li', { key: i }, 'test');
    })
  );
};

render(Main(1000000));

slides.hiroppy.me

bubbleprofを見る

これはclinicが作った手法で、Nodeのプロセスを可視化します。
非同期処理を監視し、マッピングします。

f:id:about_hiroppy:20180918091455p:plain

userland, dependencies, Node Coreでそれぞれ処理にかかった時間がわかります。
また、非同期処理の実行回数と時間もわかります。

f:id:about_hiroppy:20180918091655p:plain

この場合だとファイル読み込みに6.8msかかったことになります。

clinicjs.org

Network

負荷試験

autocannon を使い、簡単に測定を行います。

github.com

$ node server.js
$ autocannon  localhost:8080 -c1000
Running 10s test @ http://localhost:8080
1000 connections

Stat         Avg     Stdev  Max
Latency (ms) 68.95   84.55  1594.74
Req/Sec      14454.7 5049.5 21068
Bytes/Sec    2.19 MB 769 kB 3.18 MB

145k requests in 10s, 21.8 MB read
1 errors (0 timeouts)
autocannon localhost:8080 -c1000  4.91s user 2.37s system 69% cpu 10.433 total

関連記事

github.com

blog.hiroppy.me

blog.hiroppy.me