Node.jsの heapの使用量が増加し続ける

heap dumpを取って解析してみましょう。

heap dumpの取り方

以下のように実装すると、シグナルを受け取った時にheap dumpを取れるようになります。
この例では SIGUSR1 を使ってハンドリングしてますが、他のシグナルでも良いです。

import v8 from 'v8';
import fs from 'fs';

process.on('SIGUSR1', () => {
    const fileName = `./heapdump_${Date.now()}.heapsnapshot`;
    const snapshotStream = v8.getHeapSnapshot();
    const fileStream = fs.createWriteStream(fileName);
    snapshotStream.pipe(fileStream);
});

※注意:
ググるとheapdumpというnpmモジュールが出てきますが、現在ではNode.jsに含まれるv8モジュールで上記の様にheap dumpが取れるのでheapdumpモジュールは不要です。

公式ドキュメント:
https://nodejs.org/dist/latest-v14.x/docs/api/v8.html

シグナルを送れば指定したpathにheap dumpが出力されます。

$ kill -USR1 <Node.jsのpid>

heap dumpの解析の仕方

取得したheap dumpは、Chrome DevToolsで解析ができます。
公式ドキュメントがあるのでそちらを参照してください。
https://github.com/GoogleChrome/devtools-docs/blob/master/docs/javascript-memory-profiling.md

Node.jsが突然スタックする

こういう状況の場合、コードのどの部分が実行されているのかを知りたいと思うでしょう。

core dumpを取ってllnodeというツールで解析すると、dumpを取った時点で実行中だった関数やその関数の引数などを見る事ができます。

https://github.com/nodejs/llnode

core dumpの取り方

core dumpはgcoreコマンドで取得するので、インストールしましょう。

e.g. Debian/Ubuntuの場合

$ apt update
$ apt install -y gdb

以下のようにするとcore dumpが取れます。

$ gcore <Node.jsのpid>

llnodeを使ってcore dumpを解析する

llnodeをインストールします。

$ apt update
$ apt install -y liblldb-9 liblldb-9-dev make g++
$ ln -s /usr/bin/lldb-9 /usr/bin/lldb
$ npm install -g llnode

注意点:

運用中のサーバではgcoreコマンドでcore dumpさえ取れればokで、そのサーバにはllnodeをインストールする必要はありません。llnodeでcore dumpを解析する環境は別に作った方が良いです
liblldbのバージョン(liblldb-9とliblldb-9-dev)は、使っているLinuxディストリビューションやバージョンによって違うので、適宜読み替えてください。僕はDebian bullseyeを使いました

llnodeでcore dumpを解析してみましょう。

core dumpの読み込み。

※ファイル名がcore.1190となっているのは、この時のNode.jsのpidが1190だったからです

# llnode $(which node) -c /app/core.1190
(lldb) target create "/usr/local/bin/node" --core "/app/core.1190"
Core file '/app/core.1190' (x86_64) was loaded.
(lldb) plugin load '/llnode/node_modules/llnode/llnode.so'
(lldb) settings set prompt '(llnode) '

v8 btで、core dumpを取った時点のコールスタックを確認できます。
(btはbacktraceという意味です)

(llnode) v8 bt
 * thread #1: tid = 1190, 0x00001d21df54a4b0, name = 'node', stop reason = signal SIGSTOP
  * frame #0: 0x00001d21df54a4b0 (anonymous)(this=0x21d2a68404b1:<undefined>) at /app/dist/bundle.js:7:243 fn=0x000030184bba2ab1
 ...

※このページに貼ると見にくかったので、gistに貼りました
https://gist.github.com/matsumana/bd9278747a62c4249f43f3b7743c7c2e

frame #0を見ると、/app/dist/bundle.jsの7行目のanonymous関数が実行中だったようです。

関数の引数の中身も見ることが出来ます。

frame #2の<Object: IncomingMessage>の中身を見てみましょう。

v8 i -F <メモリアドレス>で見る事が出来ます。

(llnode) v8 i -F 0x3735bb9eab21
0x3735bb9eab21:<Object: IncomingMessage properties {
    ._readableState=0x3735bb9eac69:<Object: ReadableState>,
    .readable=0x21d2a6840639:<true>,
    ._events=0x3735bb9eae11:<Object: Object>,
    ._eventsCount=<Smi: 0>,
    ._maxListeners=0x21d2a68404b1:<undefined>,
    .Symbol('kCapture')=0x21d2a68406e9:<false>,
    .socket=0x3735bb9d7331:<Object: Socket>,
    .connection=0x3735bb9d7331:<Object: Socket>,
    .httpVersionMajor=<Smi: 1>,
    .httpVersionMinor=<Smi: 1>,
    .httpVersion=0x3735bb9eaf11:<String: "1.1">,
    .complete=0x21d2a68406e9:<false>,
    .headers=0x3735bb9eae29:<Object: Object>,
    .rawHeaders=0x3735bb9eaae1:<Array: length=28>,
    .trailers=0x3735bb9eae91:<Object: Object>,
    .rawTrailers=0x3735bb9eaec9:<Array: length=0>,
    .aborted=0x21d2a68406e9:<false>,
    .upgrade=0x21d2a68406e9:<false>,
    .url=0x3735bb9eab01:<String: "/busy-loop">,
    .method=0x8867f3182c1:<String: "GET">,
    .statusCode=0x21d2a68401b9:<null>,
    .statusMessage=0x21d2a68401b9:<null>,
    .client=0x3735bb9d7331:<Object: Socket>,
    ._consuming=0x21d2a68406e9:<false>,
    ._dumped=0x21d2a68406e9:<false>,
    .next=0x3735bb9ec2e9:<function: w at /app/dist/bundle.js:2:52407>,
    .baseUrl=0x21d2a6840731:<String: "">,
    .originalUrl=0x3735bb9eab01:<String: "/busy-loop">,
    ._parsedUrl=0x3735bb9ec6b9:<Object: Url>,
    .params=0x3735bb9ed5d9:<Object: Object>,
    .query=0x3735bb9ecab9:<Object: Object>,
    .res=0x3735bb9ebce9:<Object: ServerResponse>,
    .route=0x30184bba2ae9:<Object: p>}>

便利ですね。

llnodeのREADME.mdにDemo動画があるので、そちらも見てみてください。

Node.jsのDiagnostic report機能

上記のツール以外にも、Node.jsはDiagnostic report機能があるので、以下をNode.js起動時のコマンドラインオプションとして追加しておくのも良さそうです。

--report-uncaught-exception
--report-on-fatalerror
--report-on-signal

Uncaught exceptionやfatalerrorが発生した時にDiagnostic reportが出力されるようになります。
シグナル送った時に出力する事も出来ます。

Uncaught exceptionが発生した時のstack traceはこんな感じ。

"javascriptStack": {
  "message": "Error: *** test-exception.js: throwing uncaught Error",
  "stack": [
    "at myException (/path/to/test/report/test-exception.js:9:11)",
    "at Object.<anonymous> (/path/to/test/report/test-exception.js:12:3)",
    "at Module._compile (internal/modules/cjs/loader.js:718:30)",
    "at Object.Module._extensions..js (modules/cjs/loader.js:729:10)",
    "at Module.load (internal/modules/cjs/loader.js:617:32)",
    "at tryModuleLoad (internal/modules/cjs/loader.js:560:12)",
    "at Function.Module._load (internal/modules/cjs/loader.js:552:3)",
    "at Function.Module.runMain (internal/modules/cjs/loader.js:771:12)",
    "at executeUserCode (internal/bootstrap/node.js:332:15)"
  ]
},

公式ドキュメント:
https://nodejs.org/dist/latest-v14.x/docs/api/report.html

以上です。