【草稿】Node Ninja で Flame Graph - Node.js profiling with DTrace on SmartOS

（まだ編集中の下書きです）

背景

2012/11/18 に実施された東京 Node 学園祭 2012 で、Node.js の開発を推進している Joyent の Isaac Schlueter が基調講演を行いました。その講演の終盤で「Flame Graph っつーもんがあるんだけど、まぁ詳しくはググってくれ」という発言がありましたが、参加者のツイッターやブログを見てもあまりそれに触れている人がいなかったので書いてみることにします。

今回は Node.js 本家のブログ記事とこの記事(http://dtrace.org/blogs/dap/2012/01/05/where-does-your-node-program-spend-its-time/)を参考にして進めます。

「Flame Graph」とは？

一言で言うと Node.js の処理をトレースしてプロファイルしたものを可視化したものです。トレースには DTrace、グラフ化には node-stackvis というツールを使います。

DTrace とは、Joyent 社の Bryan Cantrill らが開発したトレースツールです。その名の通り、処理をダイナミックにトレースします。カーネルを含めた処理のトレースが可能で、トレースしていない時はほとんどオーバーヘッドがないという優れものです。元々は Solaris 向けに開発されましたが、その有用性から FreeBSD（7.1 以降） や Mac（Leopard 以降）にも導入されています。

node-stackvis とは、Joyent 社の Brendan Gregg が開発した DTrace のトレース結果を可視化する「FlameGraph」を、これまた Joyent の David Pacheco が Node.js のモジュールとして起こしたものです。

この Flame Graph を見ることでざっくりとどの処理に時間を割いているかわかるので、アプリケーションのボトルネックを発見する手がかりになるでしょう。

それでは能書きはこの辺にして実際にやってみます。

実践

環境構築１　マシン調達編

上記の通り DTrace は様々な OS に導入されていますが、Mac は一部（ustack helper）動かない、FreeBSD はカーネルの再構築が必要、Linux は oracle-linux にしか採用されていないという状況なので、今回は本家の Solaris 系 OS を使います。Solaris は使い慣れないし環境構築が面倒という人もいると思いますが問題ありません。簡単に無料で使う方法があります。

Joyent は SmartOS という Solaris（Illmous）系の OS も開発しています。Illmous なり、その SmartOS なりを落としてきて自分で環境構築をしてもいいのですが、このご時世、こういうものはクラウドサービスでサクッと手に入れましょう。日本では Z Cloud という IaaS クラウドサービスで SmartOS を利用することができます（すてまｖ）。そしてその Z Cloud 上で Node Ninja という Node.js 専門の PaaS ホスティングサービスが動いているため、それを利用すれば おのずと SmartOS 上で動く Node.js の実行環境が手に入ります（すてまｖ）。

現在 Node Ninja はパブリックベータとして無料で利用できるため、その環境を使うことにします。サイトからユーザ登録をして、SSH公開鍵を登録し、マシンを作成して下さい。
※マシンは台数限定で提供されているので、マシンの空き在庫がない場合は @node_ninja に問い合わせてみましょう。

##環境構築２　ミドルウェア、モジュール編
Node.js を DTrace でトレースするためには、--with-dtraceオプションを指定して Node.js をコンパイルする必要がありますが、最近のバージョンではデフォルトで指定されており Node Ninja の環境では何もする必要はありません。DTrace も標準のままで OK。

node-stackvis だけ入れておきましょう。先ほど登録した鍵で作成したマシンに SSH でログインし、npm でつっこみます。「-g」でグローバル指定します。Node Ninja の標準ユーザは「node」です。下記の [IP Adress] は作成したマシンのIPアドレスに置き換えてください。

（stackvisのインストールサプルコマンド）

$ ssh node@[IP Address]   # node ユーザでマシンにログイン
[node@hostname ~]$ npm install -g stackvis  # npm で stackvis を グローバルにインストール

アプリケーションのデプロイ

Node Ninja は git でデプロイするとデプロイされたアプリが自動で起動する仕組みになっています。トレースしたいアプリをさきほどのマシンに git で push しましょう。
※ config.json というファイルで各種設定が可能です。動かない場合はここを参考にして設定します。

手元にアプリが無い場合は Node Ninja の管理画面からサンプルアプリをインストールすることもできますが、今回は下記のようなスクリプトを用意しました。

server.js

var http = require('http');

http.createServer(function httpService(req, res) {
  res.writeHead(200, {'Content-Type': 'text/plain'});

  function AAA(){
    setTimeout(function BBB(){}, 2000);
  };
  AAA();

  function XXX(){
    function YYY(){}
    for (var i=0; i < 100; i++){
      YYY();
    }
  };

  res.end( Date.now().toString() );
}).listen(8080);

上記 server.js を保存したディレクトリで下記コマンドを実行し、マシンにデプロイします。下記の [IP Adress] は作成したマシンのIPアドレスに置き換えてください。

（デプロイのサンプルコマンド）

$ git init    # 新規リポジトリの作成
$ git add server.js  # リポジトリに server.js というファイルを登録
$ git commit -n 'hogehoge'
$ git remote add node-ninja node@[IP Address]:repo  # デプロイ先のリモートリポジトリを登録
$ git push node-ninja master  # リモートリポジトリに反映

処理をトレース

それでは DTrace でトレースしましょう。DTrace は root 権限（又は dtrace の実行権限）が必要なため admin ユーザでログインします。今回は 97 ヘルツで「node」のプロセスをトレースし、呼びだされた関数ごとに数をカウントし、10sec(秒)後に「/tmp/stacks.out」というファイルに書き出して終了します。出力されるファイルはテキストファイルです。

（トレースのサンプルコマンド）

$ ssh admin@[IP Adress]  # admin ユーザでマシンに SSH 接続
[admin@hostname ~]$ dtrace -n 'profile-97/execname == "node" && 
  arg1/{ @[jstack(150, 8000)] = count(); }
  tick-10s { exit(0); }' > /tmp/stacks.out

※ jstack の二つの引数はバッファのサイズなのでトレース時間やコールスタックが深くなければ気にしなくてOK

上記コマンドを打つとトレースが開始するので、ブラウザや curl コマンド、AB 等で何度もアクセスしたり、apache bench などのツールを使ってトレース対象のアプリに処理をさせましょう。しっかり負荷をかけたほうが最終的に見やすいグラフになります。10 秒経つとファイルが作成され、プロンプトが戻ってきます。

（処理をさせるサンプルコマンド）

$ for i in {0..9} ; do curl http://[YourMachine].node-ninja.com:8080/ ; sleep 1; done

トレース結果をグラフ化

次に、さきほど admin ユーザで出力したトレース結果「/tmp/stacks.out」を svg 化し、「/tmp/stacks.svg」というファイルに書き出します。さきほど「node-stackvis」をインストールした「node」ユーザでログインします。出力されるファイルは xml フォーマットです。

（グラフ化のサンプルコマンド）

$ ssh node@[IP Adress]  # node ユーザでマシンに SSH 接続
[node@hostname ~]$ stackvis dtrace flamegraph-svg < /tmp/stacks.out > /tmp/stacks.svg

出力された svg ファイルはブラウザや Illustrator、Visio 等で開くことができます。私は下記のスクリプトをサーバ上で実行して chrome で見ました。

/tmp/hoge.js

var http = require('http');
var fs = require('fs');

http.createServer(function (req, res) {
  res.writeHead(200, {'Content-Type': 'image/svg+xml'});
  buf = fs.readFileSync('/tmp/stacks.svg');
  res.end(buf);
}).listen(80);

（上記svgファイル公開処理実行のサンプルコマンド）

[node@hostname ~]$ node /tmp/hoge.js

※ svg は xml なので Content-Type を 'image/svg+xml' としています。

Chromeで見てみましょう。
http://[YourMachine].node-ninja.com/

※私の実行した結果はこちらです。
http://vanx2.c.node-ninja.com/

y 軸に呼び出した function が積み上がり、ｘ軸が function ごとに費やされた時間の割合となっています。呼び出した function は時系列に並んでいるわけではありません。横に伸びている function がボトルネックになっている可能性があるので処理を見直してみましょう。

以上はサンプル通りの単純なトレースでしたが、トレース時に pid や function 名を指定することもできます。

pid の指定

トレース時に pid を指定します。下記の「12345」に pid を指定します。

（pidを指定するサンプルコマンド）

[admin@hostname ~]$ dtrace -n 'profile-97/pid == 12345 && arg1/{
    @[jstack(150, 8000)] = count(); } tick-60s { exit(0); }' > /tmp/stacks.out

function の指定

トレース後、svg 化する際に grep で抽出します。下記の「[function]」に function 名を指定します。

（function名で絞り込むサンプルコマンド）

[node@hostname ~]$ stackvis dtrace collapsed < /tmp/stacks.out | grep [function] > /tmp/collapsed.out
[node@hostname ~]$ stackvis collapsed flamegraph-svg < /tmp/collapsed.out > /tmp/stacks.svg

まとめ

Node.js でブロッキングな処理を書いてしまうと思わぬボトルネックで悩まされる場合があります。そんな時はこのグラフで手がかりを探ってみるのもいいでしょう。

DTrace は非常に強力なトレースツールです。D-Script や Probe を使いこなすことでもっと様々なトレースが可能です。
node-dtrace-provider というモジュールで Node.js の処理から DTrace を実行する方法もあります。
みなさんもいろいろ試してみてください。

おまけ

2013年に Joyent7 というものがリリースされる予定で、そこではさらに強力なNode.jsのデバッギングツールが提供される予定です。
http://www.joyent.com/company/press/joyent7-delivers-the-cloud-done-better

※その他の Node.js を DTrace するサンプル
http://mcavage.github.com/presentations/dtrace_conf_2012-04-03/#dtracenode
http://blog.nodeknockout.com/post/34710903021/restify
http://dtrace.org/blogs/dap/2012/01/05/where-does-your-node-program-spend-its-time/