みんなのマーケットでwebエンジニアとして働いている高橋です。
前回の記事(http://tech.curama.jp/entry/2018/02/23/120000)で、弊社ではNode.jsを使用しているという話を簡単にしましたが、今回はその運用中に出てきたトラブルシューティングの話をしたいと思います。
弊社ではマイクロサービス用のBFF（Backends For Frontends）としてNode.jsを採用しています。 ところが最近、弊社SREから、「Nodeサーバーの再起動が多すぎます。メモリが増えた時に再起動で解決するんじゃなくて、ちゃんとリークしないように最適化してください」というお願いがありました。
また、こちらの記事には、
As leaks grow, V8 becomes increasingly aggressive about garbage collection, slowing your app down.
とありますので、メモリリークを再起動で回避し続けることには、問題がありそうです。というわけで、実際にヒープダンプを取ってメモリ周りの調査を行ってみることにしました。（対処法については、主に*1を参考にしました。）
サーバーのメトリクス
まずは本番サーバの状態を見てみます。弊社ではgrafanaを用いてcpu使用率やメモリ使用量を可視化しています。今回問題があるサーバの状態を見てみると、
のように、数十分おきにメモリ量が変動していることがわかります。定期的にメモリ使用量が減っているのは、Node.jsのプロセスマネージャであるPM2によって、メモリが増えた場合にプロセスの再起動を行うように設定していたためです。
ローカル環境で挙動の確認
次にローカル環境で挙動を確認してみます。PM2にはpm2 monitというモニタリング用のコマンドがあります。これを実行しながらリクエストを投げてみると、
1リクエストあたり数MBから数十MBメモリ使用量が増えることがわかりました。また、リクエストのない状態にしてからメモリ使用量のベースラインに戻るまで、30sから60s程かかりました。また、リクエストを繰り返すと、ベースラインが次第に上がっていくことも観測できました。
強制ガベージコレクションを行ってみる
Node.jsは、--expose-gcフラグを付けて起動することによって、global.gc()として、ガベージコレクションを手動で実行することができます。試しに手動でこれを実行してみました。
| 状態 | メモリ使用量 |
|---|---|
| ベースライン | 85MB |
| リクエスト10回実行 | 111MB |
| ガベージコレクション実行後 | 108MB |
ですが、ガベージコレクションによって、たった3MBしかメモリ使用量が減少していません。この時点で、メモリリークが発生している可能性が示唆されました。
メモリリークの調査をしてみる
リークの調査には、まずはじめにmemwatch-nextを使用しました。
npm install memwatch-next
した後、
import * as memwatch from "memwatch-next";
memwatch.on("leak", info => {
console.log("leak! ☔", info);
});
memwatch.on("stats", stats => {
console.log("stats! 📺", stats);
});
const hd = new memwatch.HeapDiff();
setInterval(() => {
const diff = hd.end();
console.log(diff);
}, 1000);
のようにして、ガベージコレクションのイベントが発生した場合にヒープのログを見ることができます。
この時点で手動でガベージコレクションを発生させると、
0|www | stats! 📺 { num_full_gc: 2,
0|www | num_inc_gc: 19,
0|www | heap_compactions: 2,
0|www | usage_trend: 0,
0|www | estimated_base: 75128928,
0|www | current_base: 75128928,
0|www | min: 0,
0|www | max: 0 }
のようなログをコンソールから見ることができます。
更に試しに、
class Fuga {
private foo: string[];
constructor() {
process.stdout.write("⏳");
this.foo = [];
for (let i = 0; i < 1000; i++) {
const data = Math.random().toString();
this.foo.push(data);
}
}
}
var leakyData: Fuga[] = [];
const hoge = () => {
leakyData.push(new Fuga());
};
setInterval(() => {
hoge();
}, 1);
のようにglobalから参照可能なオブジェクトに大量にデータを詰め込むと、
leak! ☔ { growth: 1374330784,
reason: 'heap growth over 5 consecutive GCs (1m 4s) - -2147483648 bytes/hr' }
というように、leak時の警告を見ることができます。
ここまで仕込んでから、ローカルのサ−バーに対して
while true; do curl localhost:3000; sleep 1s; done
として1sおきにリクエストを投げてみます。
しかし、ローカルサーバーではleakイベントが発生しませんでした。
次に、ヒープダンプのリクエスト毎のdiffを確認します。
ローカルのサーバーに対して数回リクエストを送り、new memwatch.HeapDiff();を利用したdiffを見てみると、
0|www | { what: 'Code',
0|www | size_bytes: 527632,
0|www | size: '515.27 kb',
0|www | '+': 2448,
0|www | '-': 1510 }
0|www | { what: 'Array',
0|www | size_bytes: 244784,
0|www | size: '239.05 kb',
0|www | '+': 8233,
0|www | '-': 6538 }
0|www | { what: 'String',
0|www | size_bytes: 52816,
0|www | size: '51.58 kb',
0|www | '+': 1030,
0|www | '-': 386 }
0|www | { what: 'Closure',
0|www | size_bytes: 11592,
0|www | size: '11.32 kb',
0|www | '+': 217,
0|www | '-': 55 }
0|www | { what: 'Object',
0|www | size_bytes: 7944,
0|www | size: '7.76 kb',
0|www | '+': 453,
0|www | '-': 279 }
Codeというオブジェクトが最もサイズが大きいことがわかりました。
これは、v8で定義されており、「コンパイル済みのコードに関連するすべてのオブジェクトです」ということです。
このオブジェクトはJITで生成されるものなので、アプリケーション固有のものではありません。ですので次に、より詳細なヒープの内容を追うことにしました。
詳細なヒープダンプを取得する
詳細なヒープダンプを取得するために、nodeを--inspectオプション付きで起動します。
すると、
chrome-devtools://devtools/remote/serve_file/xxxxx
というリンクがコンソールに表示されるので、chromeでそのURLにアクセスします。
その後、Profilesタブから、Take Heap Snapshotを選択すると、ヒープダンプが取得できます。
試しに、
a) 初期状態
b) 5回リクエスト
c) 5分後
としてダンプを取得してみました。ここから、Summary -> Comparisonと選択し、ヒープのdiffを取ることができます。
この結果、動かしていたアプリケーションのダンプの中で、リクエストに応じて増え、ガベージコレクトされないオブジェクトを特定することができました！ （具体的には、利用していたDependency Injection用のパッケージが原因でした）
最後に
以上のようにして、Node.jsのメモリ調査をしてみました。今までNode.jsのガベージコレクションの仕組みを意識することがなかったので、知見が溜まってよかったです。
（次回はアプリエンジニアのヤンさんの予定です！）
