latest log

酩酊状態で書いたエンジニアポエムです。酩酊状態で読んでください。

コンソールに階層構造付きで呼び出し履歴(トレース)を出してみる。出来るだけダーティーな実装で

階層付きのトレース出力をこのような感じで実装します。

(function(global) {
    function console_q() {

        function begin() {
            console.log(repeat("|", nest) + "+- " + fname + "(" +
                            slice.call(args).join(",") + ")");
        }
        function q() {
            console.log(repeat("|", nest) + "|  " + fname + "(" +
                            slice.call(arguments).join(",") + ")");
        }
        function end() {
            console.log(repeat("|", nest) + "`- " + fname);
            return --console.q.nest;
        }

        function repeat(str, num) {
            return Array(num + 1).join(str);
        }
        function nickname(fn) {
            return fn.name ||
                  (fn + "").split("(")[0].trim().slice(9); // )
        }

        var args = arguments,
            fname = nickname(args.callee.caller),
            slice = Array.prototype.slice,
            nest = console.q.nest++;

        begin();
        q.valueOf = end;
        return q;
    }

    console.q = console_q
    console.q.nest = 0;
})(this);


使いかたはこんな感じに

function one() {
    var q = console.q("関数の引数とか");

    q("途中経過とか");
    two();
    -q; // デストラクタ代わり
}

function two() {
    var q = console.q("関数の引数とか");

    q("途中経過とか");
    three();
    -q; // デストラクタ代わり
}


function three() {
    var q = console.q("関数の引数とか");

    q("途中経過とか", "色々だしてみたり", 123);
    -q; // デストラクタ代わり
}


one() を実行すると、

+- one(関数の引数とか)
|  one(途中経過とか)
|+- two(関数の引数とか)
||  two(途中経過とか)
||+- three(関数の引数とか)
|||  three(途中経過とか,色々だしてみたり,123)
||`- three
|`- two
`- one

とコンソールに階層構造付きで出力されます。
時刻ぐらい出せばいいのにね!

おまけ

13年ほど前にC++で同じようなログ/トレースを実装してたのを思い出して、js で出来るだけ邪悪に実装してみました。

JavaScript にはデストラクタが無いので、

-q; // デストラクタ代わり

のように、デストラクタをわざわざ書かなきゃならないのが面倒ですね。

デストラクタを呼び出すには、-q; としなくても --q; や +q; でもOKです。valueOf が呼ばれればいいので。

C++ で実装する場合は

デストラクタに --nest と ログを吐くコードを書いておけば、スコープアウトで勝手にログがでるので、
らくちんなんです。

C++でマルチスレッドな環境で、この形式のログをスレッド番号付きで出しておくと、
リソース開放漏れや、スレッドが何処で何時死んだのかがログに残るので、
大変分かりやすいログが取れます。

気に入ったら真似するといいですよ~

追記

mofmof.js の console.q の実装は、割とクリーンな感じに。

var q = console.q(関数名); // トレース開始

q(引数とか、トレースに残したい何か); // 何かだすよ

q.end(); // 終わり
// console.q
function console_q(/* var_args */) { // @param Mix: var_args
                                     // @return Function:
                                     // @desc: quick trace

    function begin(fn) { // @param Function/String(= ""): function or function name
        fnName = (Type.isString(fn) ? fn : fn.nickname()) || "unknown";

        console.log("|".repeat(nest) + "+- " + fnName + "(now:" + (+now) + ")");
    }
    function trace(/* var_args */) { // @param Mix: var_args
        console.log("|".repeat(nest) + "|  " + fnName + "[" +
                        Array.toArray(arguments).join(",") + "]");
    }
    function end() {
        var time = Date.now() - (+now);
        console.log("|".repeat(nest) + "`- " + fnName + "(time:+" + time + ")");
        --console.q.nest;
    }

    console_q.nest === void 0 && (console_q.nest = 0);

    var args = arguments, fnName = "", now = new Date,
        nest = console.q.nest++;

    begin();
    trace.end = end;
    return trace;
}
function one(arg1, arg2) {
    var q = console.q("one");
    q(arg1, arg2);

    two(arg1, arg2);

    q.end();
}

function two(arg1, arg2) {
    var q = console.q("two");
    q(arg1, arg2);

    three(arg1, arg2);

    q.end();
}

function three(arg1, arg2) {
    var q = console.q("three");

    q(arg1, arg2);
    for (var i = 0; i < 3; ++i) {
        q("loop", i);
    }

    q.end();
}

これを、one("a", "z") として実行すると(↓)こんな感じに。

+- one(now:1326954199430)
|  one[a,z]
|+- two(now:1326954199433)
||  two[a,z]
||+- three(now:1326954199437)
|||  three[a,z]
|||  three[loop,0]
|||  three[loop,1]
|||  three[loop,2]
||`- three(time:+3)
|`- two(time:+8)
`- one(time:+11)

関数の開始時間(now:...)と、経過時間(time:...)も出すようにしています。
arguments.callee.caller とか valueOf はどこいったのー って感じですね。ハイ