JavaScript でプロファイリング

JavaScript

追記 [20061103]:
ライブラリ非依存なバージョンも書いてみました。id:reinyannyan:20061103:p1 でご覧下さい。



最近自分で書いた JS プログラムが驚くほど重かったので、どこに原因があるか調べたいと思いました。

その方法として、怪しいと思う箇所に (あるいは思わない箇所にも) 手作業でタイマーを仕掛けて、部分部分の実行時間を計測するのも手だと思うんですが、クラスのどのメソッドでどのくらい時間が掛かっているのかが自動的に分かる、というのが理想的かなと思いました。

(以下、prototype.js 的な (OO 的な) コーディングを対象とした話になります)

まず思いついたのは、プロファイルしたいクラス (function オブジェクト) を受け取って、メソッドを動的に書き換えるという方法です:

for (var m in klass.prototype) {
  if (typeof klass.prototype[m] == "function")  // メソッドであれば
    (function(method){
      var orig = klass.prototype[method];
      klass.prototype[method] = function() {    // 書き換え
        var started = new Date - 0;

        var result = orig.apply(this, arguments); // オリジナルを実行

        // 経過時間を記録 (どこかに蓄積していく)
        var elapsed = (new Date - 0) - started;
        return result;
      };
    })(m);
}

ただ、この方法には問題がありました: クラスが Mix-in によって動的に拡張される場合、補足できないメソッドが生じてしまうのです。

そこでインスタンスを受け取る方法に切り替えなければならないわけですが、インスタンスを生成して、それを手でプロファイリング関数なりオブジェクトに渡す、というのでは理想に反します。

ということで、あまり使いたくない手ではあるんですが、クラス作成メソッド (Class.create) を書き換える方法を考えました。つまり、インスタンスが作成されると自動的にそれをプロファイリング・オブジェクトに渡すように仕掛けるわけです。

ではまず、弄る前のクラス作成メソッド (とその周辺) をお見せしておきます (Prototype の Class.create 周りを独自に拡張したものです):

次に、プロファイラの仕組みですが、クラスとしては実装しないことにします (と言うかプロファイラのインスタンス生成時に永久ループが生じるため出来ません)。そして、生成される全てのインスタンスを調査するのではなく、あらかじめ調べたいクラス名を登録しておき、そのクラスのインスタンスだけを調べるようにしましょう。

また、あまり複雑に考えず、メソッドの累積実行時間と呼び出し回数を記録する程度のもので良いかなと思います。

こんな感じになりました:

var Profiler = {
  klasses: [],  // class names
  _klasses: [], // classes (used for class -> class-name conversion)
  times: {},

  watch: function() {
    this.klasses = $A(arguments);
    this._klasses = this.klasses.map(function(k){return eval(k)});
  },

  profile: function(klass, instance) {
    if (klass = this.klasses[this._klasses.indexOf(klass)]) {
      this.times[klass] = {};
      for (var m in instance)
        if (typeof instance[m] == "function" && m != "supra")
          (function(method, m) {
            var orig = instance[method];
            instance[method] = function() {
              // (this == instance)
              var time= m.time || 0;
              var now = new Date - 0;

              var result = orig.apply(instance, arguments);

              m.time = time + (new Date - 0) - now;
              m.cnt  = (m.cnt || 0) + 1;
              return result;
            };
          })(m, this.times[klass][m] = {});
    }
  },

  report: function() {
    var div = document.body.appendChild(document.createElement("div"));
    var table = [
      "<table>", "<thead>", "<th>count</th>", "<th>time</th>",
      "<th>class</th>", "<th>method</th>", "</thead>", "<tbody>"
    ];
    for (var k in this.times) {
      var t = this.times[k];
      for (var m in t) {
        if (!t[m].cnt) continue;
        table.push([ "<tr><td>", t[m].cnt, "</td>" ].join(""));
        table.push([ "<td>", t[m].time/1000, "</td>" ].join(""));
        table.push([ "<td>", k, "</td>" ].join(""));
        table.push([ "<td>", m, "</td></tr>" ].join(""));
      }
    }
    table.push("</tbody></table>");
    div.innerHTML = table.join("");
  }
};

Profiler.watch() で調べたいクラス名のリストを受け取ります。レポート出力を考慮し、文字列として受け取るようにします。そして、後でクラスを受け取った時に名前に変換できるよう、クラス名に対応するクラスの配列を用意しておきます。

さらに、Class.create の、initialize メソッドの呼び出しの後に以下を追加します*1:

      Profiler && Profiler.profile(klass, this);

Profiler.profile 内では以下の式で調査対象のクラスかどうかがチェックされます。

    if (klass = this.klasses[this._klasses.indexOf(klass)])

右辺の klass はクラス (への参照)、左辺にはそれがクラス名に変換されたもの (または undefined) が代入されるわけです。

これが、該当するクラスのインスタンス生成時のみプロファイリングが行われる仕組みとなります。

そして、結果は Profiler.report で出力したいわけなんですが、テーブルを作ったりするのが苦手なのでまだ出来てません(笑。


最後に、利用の流れを示しておきましょう。以下のようになると思います:

var ClassToTest = Class.create(...);

Profiler.watch("ClassToTest");

var c = new ClassToTest;
// areyakoreya

Profiler.report();

元のソースコードを弄る必要があるかどうかはコーディング次第だと思います。プログラムの定義を .js ファイルに、実行部を .html 側に置いている様な場合は、.html の方に２行を書き足すだけで済むかも知れません。


Update [20060619]:

Profiler.report を書きました。

このような体裁で出力されます:

(冒頭で「重い」と言っていたものではなく、Ajax 版フォトライフデスクトップをしばらく走らせておいた状態のレポートです。ちなみに以前 XP で動かないと言っていましたが、MSXML 3.0 を使えば正常動作することがわかりました)

メソッド間の呼び出し関係をトレースしたり、などということはおそらく無理なので、呼び出し回数と時間を手がかりに探ることになりますね。この場合だと "collect_fotos" が "renew_catalog" から呼ばれているメソッドの中で最も時間が掛かっている、ということが推測できます。

ちなみに、この表からは分かりませんが、一つのクラスに関して最後に生成されたインスタンスの情報が報告されるようになってます。ただ、少し弄れば全インスタンスのデータを蓄積することも可能ではあります。


Update [20060620]:

いちおう組み込みクラスでも以下のようにすればプロファイリング可能ですね:

Profiler.watch("Array");
var arr = [];
Profiler.profile(Array, arr);

試しに上述の『Ajax〜』(現在 Not Available) で、写真を保持している配列を調べてみました:

count time  class method
2     1.7   Array dharma
287   1.16  Array remove_at
4     0.17  Array remove
4     0     Array random
4     0     Array empty

(dharma は達磨落としメソッド (配列の要素をランダムに落としていって一定サイズにするメソッド) です)

*1:initialize 内での Mixin 実行を考慮し、initialize の「後」に埋め込みます。したがって initialize メソッド自体はプロファイリングの対象からは外れてしまいます