隠れていたNode.jsの4バイトメモリリーク、Walmart問題の解決

この記事は、 Node.js Advent Calendar 2013 - Adventar の12日目です。

1. ありがとう Ben

Nodeの情報に普段アンテナを張っている人は既にご存じでしょうが、Nodeコア開発の中心的エンジニア Ben Noordhuis がNodeのコアチームから離れました。Node.jsの公式ブログに「Ben Noordhuis's Departure」としてアナウンスされています。
なぜ彼がNodeの開発を止めなければならなかったのかその経緯をここで述べることは控えますが、彼のこれまでの貢献なしでは今のNodeは存在し得なかった、と言えるほど彼は重要な存在でした。Benは、Nodeやlibuvのコードの開発だけでなく、github の issue の回答やPRのレビュー、 MLの質問の返答などNodeコミュニティにも精力的に対応し、去年来日した isaacs 曰く「Ben is machine」と言われるぐらい常人離れした活動をした天才エンジニアでした。

私がこれまでに採用されたパッチも、ほとんど彼が丁寧にコードレビューし、コミットしてもらいました。ちょうど今Node-v0.12のリリースに向け、もうひと頑張りの段階で彼がいなくなるのは本当に痛手です。今回の出来事は非常に残念で悲しい事でしたが、これまでの Node/libuv における彼の多大な貢献に対して本当に感謝したいと思います。

2.WalmartのNodeシステム

最近、USの大手企業がNodeを使ったシステムを導入して成功したという事例発表をよく目にするようになりました。その中でGROUPON/PayPal/Walmartの3社がNodeの大規模導入事例の筆頭でしょう。ご存じの通りWalmartは、全米最大の小売り業者です。数年前からモバイルサイトのシステムにNodeの導入を進めています。そのチームリーダが OAuth1.x 仕様の発案者 Eran Hammer です。先日Joyentで行われたセミナーのビデオを見ると、WalmartのNodeシステム概要を知ることができます。プレゼンでは、WalmartのNodeシステムを豚の絵になぞらえていましたが、書き起こすと下図のような感じになるでしょう（色のついた部分がNode)。

プレゼンの内容を聞いてみると、このWalmartによるNodeシステムの特徴として、次のような項目が挙げられます。

FrontをNodeに変更、バックエンドは業務系(Java)のままで連携する。
モバイル用の proxyとして利用する。
プラグインシステムを開発し、機能に柔軟性を持たせる。
独自ミドルウェア(hapi)を開発する。
public NPM の前段に private NPMを設置する。

他の2社、Groupon/PaypalのNode導入レポートを見てみても、似ていて共通と思われる項目が数多くあり、こういった構成は、現時点でNode使ったシステムのベストプラクティスのような感じがします。このまま大規模なNodeの導入事例が続くと、近いうちにNodeの活用がもう一段上のステージに上がる何か転機が訪れるのではないかという期待が持てます。

3. Walmart問題とは

Eranらは、米国感謝祭後に購買ピークを迎えるブラックフライデー・サイバーマンデーの見据えて、数か月前からNodeを使ったモバイルサイトの負荷テストを行っていました。その結果、負荷をかけていくと次第にNodeのメモリ使用量が増大し、一日で数百メガにも増大し、数日毎にNodeプロセスを再起動せざる得ない問題の発生にぶちあたりました。

彼は当初よりNodeにメモリリークが存在するのではないかと考えていましたが、周りに賛同されず、いろいろ試行錯誤結果、メモリ増大がHTTPリクエストの数に依存することまで突き止めました(バックエンドとのJavaシステムとのつなぎで膨大なHTTPリクエストを送信しているようです）。そこでメモリ利用量の測定データと供にJoyentのNode コアチームに相談しに行きました(WalmartのシステムはJoyentのSmartOSの上で運用されています)。

4. Nodeに隠されたメモリリークを発見・解決

相談されたNodeコアチームの一人 Joyent の TJ Fontaine は、SmartOSで提供されている各種ツール(mdb,dtrace)等を駆使し、3週間かけてこのメモリリークの原因を特定し解決しました。その詳しい経緯は Joyent のブログ「「Walmart Node.js Memory Leak」に書かれています。この調査方法がすさまじく難易度が高く、SmartOSの専門家が揃っているJoyentメンバーの協力があったからこそできた技だと感心してしまいます。

彼が行ったNodeのメモリリークの原因を特定した流れを簡単に書くと、

メモリリークを再現するサーバ・クライアントコードを実行する。
1時間に1回、pmap 出力とコアダンプを取得、15時間継続してみる。
pmapデータから heapメモリが増加していることを確認。しかしV8のHeap利用量は変わらず。
SmartOSの mdb(modular debugger)を使い、4Kキャッシュ領域が過度に使用されているのを突き止める。
スタック情報を視覚化したフレームグラフとmdbのV8プラグインを使いV8のHandleScopeのスタック領域に Undefinedオブジェクトが大量に溜まっていることを発見。
別のコアチームメンバーの解析でmasterのsetImmediate実装にメモリリークがあることを発見。しかしnode-v0.10には関係なかった。
setImmediateのメモリリークの状況がWalmartのリークと全く同じだったのに気付き、同様のバグを dtrace を使って調査開始する。
dtrace の出力からHandleWrap::OnClose 関数が犯人であることを特定。HandleScopeの宣言の1行が無いことがメモリリークの原因であることを突き止める（1回のリーク量はわずか4バイト）。

これを受けて次の一行パッチ「src: add HandleScope in HandleWrap::OnClose」をNodeに適応し、 node-v0.10.22 と node-v0.11.9 を直ちにリリースしたということになりました。

なぜHandleScopeの宣言がないとメモリリークするのか？ V8のデザインに起因します。
V8では変数を扱うには、直接オブジェクトのポインターを扱わず、Handleを経由して利用します。Handleには PersistentとLocalの2種類があり、Persistent Handleは明示的に解放させないといけません。一方 Local Handleは、 HandleScope の変数を宣言しておくとそのスタック領域に格納され、デストラクターとともに自動的に LocalHandle が解放される仕組みになっています（パッと見るとHandleScopeの宣言がおまじないのように思えます）。

Nodeコアで非同期コールバックを呼び出す関数 MakeCallback 中に LocalHandle を使用していますが、今回それを実行する HandleWrap::OnClose 関数で HandleScope が宣言されていませんでした（おそらく node-v0.9.xの時代から）。これが原因で、例えば socketオブジェクトをクローズするような場合、libuv からこのOnClose が呼ばれてコールバックが実行されますが、その際 LocalHandle が解放されず Undefined オブジェクトが親（メインループ）の HandleScope スタックに溜まってしまっていたということです。

よってHTTPクライアントの接続切断毎に4バイトずつメモリリークしていた換算です。溜まっていたJSオブジェクトは全て同一の Undefined オブジェクトだったため、 V8のHeap領域の方は増加しなかったわけです。通常の利用ではそれほど目立たない状況でしょうが、Walmartのサービス負荷のレベルだと無視できないレベルになり致命的な状況を発生させるものでした。

実は今回のバグ発見のきっかけとなった setImmediate の関数は、私が node-v0.10で改変したところでした。自分が書いたところにメモリリークが見つかったと指摘された時は本当に肝を冷やしましたが、node-v0.11のマルチコンテキスト対応時に間違えて HandleScope を削除したことによるものでした。ホント焦りました。

5. Walmart問題を再現

では、Nodeメモリリークは実際どう見えるでしょうか？今回のWalmart問題を題材に試してみましょう。
TJが使った再現コードを簡略化して以下のコードを使ってみます。試験コードは、1秒間に並列で400のHTTPリクエストを送信し、ソケットハンドルを強制的に切断するものです。0.5秒毎に強制的にGCを起動し、Nodeのメモリ利用量を5秒毎に出力します。

// Walmartメモリリーク問題 再現コード
var http = require('http');
var port = 1331;
var server = http.createServer(function(req, res) {
  req.resume();
  res.end();
}).listen(port, function() {
  setInterval(function() {
    // 一秒毎に並列400リクエスト
    for(var i = 0; i < 400; i++) {
      http.get('http://localhost:' + port, function(res) {
        res.destroy(); // レスポンス受信したら強制切断
      });
    }
  }, 1000);
});

setInterval(function() {
  gc(); // 0.5秒毎に明示的にGC起動(要 --expose-gc オプション)
}, 500);

var start = Date.now();
setInterval(function () {
  var stats = process.memoryUsage();
  var now = Date.now();
  var elapsed = parseInt((now - start)/1000);
  // ５秒毎に RSS, Heap情報を出力
  console.log(elapsed + ',' + stats.rss + ',' + stats.heapTotal + ',' + stats.heapUsed);
}, 5000);

Nodeの実行時にV8向けのオプション --expose-gc と --always-compact の2つを指定します。前者はGCを起動する関数(gc)を有効にし、後者は heap領域の fragment を解消するためのものです。動作させると以下のように経過時間（秒）とメモリ利用量(RSS, heapTotal, heapUsed)が出力されます。

ohtsu:~/tmp/leak_test2$ ../node-v0.10.21/node --expose-gc --always-compact  leak.js
5,30396416,23927808,3508216
10,31281152,40705024,3516120
15,31334400,40705024,3534192
...

1000秒程度まで node-v0.10.21 と node-v0.10.22 でテストして、メモリ利用量の時間推移を以下に示します。

一回でわずか4バイトのリークですが、こうやって見比べるとRSS領域がリークで増加していることが一目でわかります。ただ単独で見た場合にはどう判断できるか。メモリリークの特定は本当に難しい作業です。

6. Nodeメモリリーク対策その後

これまで巷で「Nodeのメモリリークがあって大変だぁ」という話を聞くと、どうせGCされずにHeapが増加している現象を騒いでいるだけだろうと思うことが多かったのですが、こういったことがあるので、そういう考えを戒めなければなりません。今回の問題が解決したところ、実はうちも悩んでいた、問題だったという声がいくつも上がったようです。しかしNodeも最近かなり安定化し、すぐ目立つようなメモリリークが存在することは少なくなりました。あっても特殊な環境下での発生だったり、今回のような難易度の高いものだったりとかします。

一方 Walmartは時期的にはブラックフライデー直前でしたが、システムを修正されたnode-v0.10.22にバージョンアップし、無事高負荷を何事もなく乗り切りました。Walmartのサイトへのアクセスの58%がモバイル向けだったという高負荷下で、Nodeのプロセスは一つも再起動せずに済んだとのこと。 Eranは、#nodebb のハッシュタグでシステムの状況を随時実況していました（問題がなく退屈で仕方がないと）。

最近USで開催されたNodeSummit2013では、この騒動をLeek Seed(西洋にらの種)という童話にして発表しています。皮肉たっぷりな内容で一度ご覧になることをお勧めします（Leek は当然 Leak の言葉をかけています）。

http://hueniversedotcom.files.wordpress.com/2013/12/nodesummit2013.pdf
先日公開されたNodeUp56thでもWalmartチームが出演し、この話を含むWalmartのNodeの利用について解説しています。興味のある方は聞いてみたらいいでしょう（ただし英語ですけど）。