nodetime が動いている仕組み

ちょうど昨日ですが、nodetime というなかなか面白いモジュールが公開されました。

npm で nodetime モジュールをインストールした後に自分のプログラムの先頭に、

require('nodetime').profile();

を付け加えて実行すると、標準出力に URL が出力されそこにアクセスすると、あらあら不思議実行したサイトのCPU負荷やメモリ使用量の時間系列やAPIで読み書きしたデータ量の推移などパフォーマンスチューニングに必要なデータがグラフや表で表示されてます。

ソースコードや node のライブラリに一切手を入れずにこんなデータが自動的に取得できるとはなんてステキな機能なんでしょう。そこで github で公開されているソースからこの nodetime という機能がどうやって実現できているかちょっと調べまてみました。

ちなみに、これって node で取得できるサーバのデータが外部のサイトに自動的に送られちゃうんですよね。10分しか見られないとアナウンスされているんですが、やっぱり心配。
ということで自分でサーバたててこのデータを取得できるようにパッチを送りました。
https://github.com/dmelikyan/nodetime/pull/3
しかしまだ時期尚早ということで作者から断られちゃいました。ローカルの閉じた環境で使えればガンガン使っていいものにできるんですがねぇ。残念。

実はオプションで {stdout: true} を指定するとデータは nodetime のサイトに送らずに標準出力に出すことができますが、取得しているデータの一部しかできません。以下のサンプルは hello world のコードでパフォーマンスデータの一部を標準出力に出すコードです。

// 標準出力にデータの一部を出力させる方法
require('nodetime').profile({stdout: true});
var http = require('http');
http.createServer(function (req, res) {
  res.writeHead(200, {'Content-Type': 'text/plain'});
  res.end('Hello World\n');
}).listen(1337);
console.log('Server running at http://127.0.0.1:1337/');

でも、この機能自体は非常に魅力的なのでどうやって実現しているか解説したいと思います。
この nodetime で肝となっている技術は、下記のような proxy オブジェクト（メソッド）を使っていることです。

// nodetime がやっていること簡易版 ここから
var proxy = {
  before: function(obj, method, hook) {
    var orig = obj[method];
    obj[method] = function() {
      hook(this, arguments);
      return orig.apply(this, arguments);
    };
  },
  after: function(obj, method, hook) {
    var orig = obj[method];
    obj[method] = function() {
      var ret = orig.apply(this, arguments);
      hook(obj, arguments, ret);
      return ret;
    };
  }
};

上の proxy オブジェクトは2つの関数 proxy.before(obj, method, hook) と proxy.after(obj, method, hook) を定義しています。これによって obj.method() の関数を実行する際に、その関数に変更を加えず、その前後に hook の関数を実行できるようになります。（いわゆるモンキーパッチの一種と言えるでしょう）

で、この proxy.before(), proxy,after() を使って net モジュールの connect メソッドの実行後、 socket.write() の前後で実行するような probe オブジェクトを下記のように作成します。

var probe = {
  net: function(obj) {
    proxy.after(obj,'connect', function(obj, args, ret){
      // net.connect() が実行された後に呼び出される
      var written_before, written_after;
      // client.write() が実行される前に呼び出すコールバック
      proxy.before(ret, 'write', function(obj, args) {
        written_before = obj.bytesWritten;
      });
      // client.write() が実行された後に呼び出すコールバック
      proxy.after(ret, 'write', function(obj, args) {
        written_after = obj.bytesWritten;
        // client.write() した後の書き込みバイト数を計算して表示
        var size = written_after-written_before;
        console.log(size + " bytes written");
      });
    });
  }
};

上記のオブジェクトを利用すると socket.write() の実行前に proxy.before() 、実行後に proxy.after() が呼び出されるので、書き込んだバイト数の差分を計算して標準出力に書き出すようにしています。

そして最後は require() の横取りです。

// module.require('net') を横取りして client = net.connect() の実行を
// probe.net(client) 関数に変えてしまう。
proxy.after(module.__proto__, 'require', function(obj, args, ret) {
  probe[args[0]](ret);
});
// nodetime がやっていること簡易版 ここまで

module の prototype オブジェクトの require メソッドの後に probe.after() の hook が呼び出されて probe.net(client) が実行されるように変えられちゃっています。これで require('net') は置き換えられました。

上記コードを下記の普通のプログラムの前に付ければなんちゃって nodetime が完成です。

// ここから普通のプログラム
var port = 8124;
var net = require('net');
var server = net.createServer();
server.listen(port, function() {
  var client = net.connect(port, function() {
    for (var i = 0; i < 10; i++) {
      client.write("hello");
    }
    client.end();
    client.on('end', function(){
      server.close();
    });
  });
});

実行結果

unixjp:~/tmp> node test.js
5 bytes written
5 bytes written
5 bytes written
5 bytes written
5 bytes written
5 bytes written
5 bytes written
5 bytes written
5 bytes written
5 bytes written

というようにコードに全く変更を加えることなく、 client.write() の前後の書き込みデータ量の取得ができるようになりました。

実際の nodetime では net/http/https/mongo/redis etc. といった各種の probe 関数が用意されており、そこで取得したデータを定期的に JSON でサイトにアップロードしているといった仕組みになっています。

このようなテクニックは、なかなか中身がいじれないコードのデバッグやパフォーマンスチューニングに使えるかもしれませんね。（やり方を間違えるとちょっと悲惨ですけど）

ぼちぼち日記

おそらくプロトコルネタを書いていることが多いんじゃないかと思います。

nodetime が動いている仕組み