JavaScriptのsetTimeoutをログに出す

setTimeoutは難しい。いつ呼ばれるかよく分からないし、ライブラリーを使うとそのライブラリーがsetTimeoutを使いすぎてしまう。よく分からなかったけどsetTimeoutすると動くからそうしていた、んだけど実はタイミングの関係で偶然うまく動いているように見えているだけだった、なんてこともよくある。

ウェブアプリケーションの描画が遅い。「なぜか遅い」が、処理を丁寧に追っていっても手がかりがつかめないということがある。色々な方法を駆使した後に、なぜかsetTimeoutの発火が遅いということにたどり着いた。どれくらい遅いか。

window.setTimeout = (function(setTimeout) {
  return function() {
    var handler = arguments[0];
    var wait = arguments[1] || 0;
    var log = function(action, color) {
      var d = new Date();
      console.log('%c%s%c [%c%d%c/%c%d%c] (%s %s) %s', 'color:' + color, action, '',
                  'color:blue', (Date.now() - registered), '', 'color:blue', wait, '',
                  d.toLocaleTimeString(), d.getMilliseconds(), handler.toString().slice(0, 100));
    };
    var args = [].slice.call(arguments, 2);
    var registered = Date.now();
    args.unshift(function() {
      log('FIRED', 'red');
      handler();
      log('DONE', 'blue');
    }, wait);
    log('REGISTERED', 'green');
    return setTimeout.apply(null, args);
  };
})(window.setTimeout);

setTimeoutをログに可視化してみた。コードの中で使っているあらゆるsetTimeoutのログが出力される。 [X/Y] みたいな表示がされるが、 Y がsetTimeoutの第二引数で、 X がsetTimeout登録からの経過時間を表している。

ああ、最悪だ。setTimeout 0のつもりが2秒も後に発火されている事がわかった。

本来ならば setTimeout(f, 500); → REGISTERED [0/500] → FIRED [500/500] → DONE [530/500] のようになるのが正しい (f()に30msかかる時)。ブラウザー描画処理が入る可能性があるので、setTimeout 0でもFIREDが [20/0] とかになることはある。しかし、上の画像のように2秒も遅れていると「何かがおかしい」ということが分かる。

setTimeoutが可視化されたのは良いが、実際の原因は別のところにあることが多い。setTimeoutが意図しているよりも遅れるということは、そこで別の重い処理が走っているということになる。その処理とは、自分の書いたJavaScriptの処理だったり、大きなDOMの挿入、ブラウザーのレンダリングだったりする。あとは、ブラウザーのTimelineやProfilesといった普通のデバッグ手法をとる。

console.logで時刻を出すというのは確かに原始的なやり方だ。printfデバッグと同じである。しかし、setTimeoutのタイミングが目に見えるのはとても便利だ。以前作ったsjspも同じように古典的な手法だが、今でも重宝している。

実行処理系のデバッガと、古典的な手法を行ったり来たりして原因を特定していくというのは、どの言語でもある気がする。どちらも良いところと悪いところがある。デバッグ技・プロファイル技は職人芸になりがちだが、文章にして伝えにくいところもあるので、どうしても特定の人にスキルが偏ってしまう。うまく伝えていきたい。