« 市町村変遷パラパラ地図を見やすくするグリモンParaParaMapZoomer | メイン | コミュニティに参加しはじめてから変わったこと »

profilerという処理速度計測用ライブラリ

IEでもFirebugについてくる処理時間計測用のProfileという機能が欲しくて作ってみた。
IE8からはFirebug相当のデバッグツールがついてくるのでいいけど、IE6,IE7あたりでは結構使えるかも。
他のBrowserでも使えるはず。
FirebugのProfileのように勝手に計測してくれるのではなく、計測部分にコードを埋め込まないといけないのはしかたがないと思って欲しい。
以下、ソースとその後に使い方。
profiler
/*
================================================================================
    Name            :   profiler
    In          :   [none]  
    Out         :   [none]  
    Note            :   処理時間を計測する
--------------------------------------------------------------------------------
    Version     :   Ver1.0.0        |   2009/02/07  |   新規作成
--------------------------------------------------------------------------------
    License     :   MIT license
    URL         :   www.kanasansoft.com
================================================================================
*/

var profiler=(
    function(){
        var timeRun={};
        var resultData={};
        var subResultData={};
        var startForMain=function(name){
            if((name in resultData)&&resultData.hasOwnProperty(name)){
            }else{
                timeRun[name]=[];
                resultData[name]={
                    "count":0,
                    "sum":0,
                    "min":Number.POSITIVE_INFINITY,
                    "max":Number.NEGATIVE_INFINITY
                };
                subResultData[name]={};
            }
            var body={
                "time":new Date().getTime(),
                "index":timeRun[name].length
            };
            timeRun[name].push(body);
            return getForChain(name,body);
        }
        var stopForMain=function(name,subname){
            if(timeRun[name].length==0){
                return false;
            }
            var timeCur=timeRun[name].pop();
            var passed=new Date().getTime()-timeCur.time;
            saveResult(name,subname,passed);
        }
        var stopForChain=function(name,body){
            return function(subname){
                var index=void(0);
                for(var i=Math.min(body.index,timeRun[name].length-1);i>=0;i--){
                    if(body==timeRun[name][i]){
                        index=i;
                        break;
                    }
                }
                if(index==void(0)){
                    return false;
                }
                var timeCur=timeRun[name].slice(index,index+1)[0];
                var passed=new Date().getTime()-timeCur.time;
                saveResult(name,subname,passed);
                timeRun[name]=timeRun[name].slice(0,index).concat(timeRun[name].slice(index+1));
            }
        };
        var getForChain=function(name,body){
            return {
                "stop":stopForChain(name,body),
                "dummy":function(){return this;}
            }
        }
        var saveResult=function(name,subname,passed){
            if(subname){
                if((subname in subResultData[name])&&subResultData[name].hasOwnProperty(subname)){
                }else{
                    subResultData[name][subname]={
                        "count":0,
                        "sum":0,
                        "min":Number.POSITIVE_INFINITY,
                        "max":Number.NEGATIVE_INFINITY
                    };
                }
                subResultData[name][subname].count++;
                subResultData[name][subname].sum+=passed;
                subResultData[name][subname].min=Math.min(subResultData[name][subname].min,passed);
                subResultData[name][subname].max=Math.max(subResultData[name][subname].max,passed);
            }else{
                resultData[name].count++;
                resultData[name].sum+=passed;
                resultData[name].min=Math.min(resultData[name].min,passed);
                resultData[name].max=Math.max(resultData[name].max,passed);
            }
        }
        var result=function(){
            var results=[];
            results.push(
                [
                    "start name",
                    "stop name",
                    "count",
                    "minimal time(ms)",
                    "maximum time(ms)",
                    "total time(ms)",
                    "average time(ms)"
                ].join("\t")
            );
            for(var name in resultData){
                if(resultData.hasOwnProperty(name)){
                    var running=[
                        "["+name+"]",
                        "(running)",
                        timeRun[name].length,
                        "-",
                        "-",
                        "-",
                        "-"
                    ].join("\t");
                    var buf={
                        "count":0,
                        "sum":0,
                        "min":Number.POSITIVE_INFINITY,
                        "max":Number.NEGATIVE_INFINITY
                    };
                    var subResults=[];
                    if(resultData[name].count!=0){
                        buf.count+=resultData[name].count;
                        buf.sum+=resultData[name].sum;
                        buf.min=Math.min(resultData[name].min,buf.min);
                        buf.max=Math.max(resultData[name].max,buf.max);
                        subResults.push(
                            [
                                "-",
                                "(no name)",
                                resultData[name].count,
                                resultData[name].min,
                                resultData[name].max,
                                resultData[name].sum,
                                resultData[name].sum/resultData[name].count
                            ].join("\t")
                        );
                    }
                    for(var subname in subResultData[name]){
                        if(subResultData[name].hasOwnProperty(subname)){
                            buf.count+=subResultData[name][subname].count;
                            buf.sum+=subResultData[name][subname].sum;
                            buf.min=Math.min(subResultData[name][subname].min,buf.min);
                            buf.max=Math.max(subResultData[name][subname].max,buf.max);
                            subResults.push(
                                [
                                    "-",
                                    "["+subname+"]",
                                    subResultData[name][subname].count,
                                    subResultData[name][subname].min,
                                    subResultData[name][subname].max,
                                    subResultData[name][subname].sum,
                                    subResultData[name][subname].sum/subResultData[name][subname].count
                                ].join("\t")
                            );
                        }
                    }
                    results.push(running);
                    if(buf.count!=0){
                        results.push(
                            [
                                "-",
                                "(all)",
                                buf.count,
                                buf.min,
                                buf.max,
                                buf.sum,
                                buf.sum/buf.count
                            ].join("\t")
                        );
                    }
                    results=results.concat(subResults);
                }
            }
            return results.join("\n");
        }
        return {
            "start":startForMain,
            "stop":stopForMain,
            "result":result
        }
    }
)();
一番単純な例
fnc1とfnc2の計測は以下のようにする。
profiler.start("fnc1");//計測開始に名前を指定
fnc1();//100msかかる処理
profiler.stop("fnc1");//名前を指定して計測終了
profiler.start("fnc2");
fnc2();//200msかかる処理
profiler.stop("fnc2");
alert(profiler.result());//tsvで処理結果がかえる。実際にはコピーしてexcelなんかにペーストがお勧め。

//処理結果(説明用に整形)
start name  stop name   count   minimal time(ms)    maximum time(ms)    total time(ms)  average time(ms)
[fnc1]      (running)   0       -                   -                   -               -
-           (all)       1       100                 100                 100             100
-           (no name)   1       100                 100                 100             100
[fnc2]      (running)   0       -                   -                   -               -
-           (all)       1       200                 200                 200             200
-           (no name)   1       200                 200                 200             200
関数内部に記述
関数内に記述する場合は次のような感じで。
function fnc3(){
    profiler.start("fnc3");
    //何らかの処理
    profiler.stop("fnc3");
}
fnc3();
alert(profiler.result());
関数内の分岐にも対応
関数内を書き変えてまで計測計測するのは抵抗があるかもしれないけど、これは終了判定別に記録するため。
例えば、if文内でreturnを実行して関数を終わらせる場合に重宝するかと思う。
function fnc4(){
    profiler.start("fnc4");
    var num=Math.floor(Math.random()*10);//0から9までのランダムな値
    if(num==0){
        profiler.stop("fnc4","num==0");//処理終了に名前を指定
        return;
    }else if(num<5){
        profiler.stop("fnc4","num<5");//処理終了に名前を指定
        return;
    }else{
        profiler.stop("fnc4","other");//処理終了に名前を指定
        return;
    }
}
for(var i=0;i<1000;i++){
fnc4();
}
alert(profiler.result());

//処理結果(説明用に整形)
start name  stop name   count   minimal time(ms)    maximum time(ms)    total time(ms)  average time(ms)
[fnc4]      (running)   0       -                   -   -   -
-           (all)       1000    0                   1                   18              0.018
-           [num<5]     412     0                   1                   6               0.014563106796116505
-           [num==0]    84      0                   1                   2               0.023809523809523808
-           [other]     504     0                   1                   10              0.01984126984126984
profilerを変数に保存して使う
start実行時に戻り値を変数に入れておけば、stopの時に名前を指定しなくても止める事ができる。
これにより停止順を個別に指定できる。
下の例は交互に実行と停止を行なった場合。
変数を使わなければ(1)は(2)の約3倍の時間が測定されるけど、下の例であれば(1)と(2)はほぼ同じ時間になる。
var p5_1=profiler.start("fnc5");//(1)
fnc5();
var p5_2=profiler.start("fnc5");//(2)
fnc5();
p5_1.stop();//先に生成したprofilerを停止
fnc5();
p5_2.stop();//後で生成したprofilerを停止
alert(profiler.result());
マトリックス的に使う
以下のようにすると、マトリックスを生成可能。
これはprofilerを変数に保存できる機能と、変数に保持したprofilerのstop処理の引数に終了時の名前を指定できることを応用した例。
function fnc6(){
    var profiler6;
    var numstart=Math.floor(Math.random()*3)+1;//1から3までのランダムな値
    if(numstart==1){
        profiler6=profiler.start("first");
    }else if(numstart==2){
        profiler6=profiler.start("second");
    }else{
        profiler6=profiler.start("third");
    }
    var numstop=Math.floor(Math.random()*3)+1;//1から3までのランダムな値
    if(numstop==1){
        profiler6.stop("I");
    }else if(numstop==2){
        profiler6.stop("II");
    }else{
        profiler6.stop("III");
    }
}
for(var i=0;i<1000;i++){
    fnc6();
}
alert(profiler.result());

//処理結果(説明用に整形)
start name  stop name   count   minimal time(ms)    maximum time(ms)    total time(ms)  average time(ms)
[second]    (running)   0       -                   -                   -               -
-           (all)       342     0                   1                   9               0.02631578947368421
-           [I]         112     0                   1                   4               0.03571428571428571
-           [II]        109     0                   1                   1               0.009174311926605505
-           [III]       121     0                   1                   4               0.03305785123966942
[first]     (running)   0       -                   -                   -               -
-           (all)       319     0                   1                   4               0.012539184952978056
-           [II]        106     0                   1                   2               0.018867924528301886
-           [III]       117     0                   1                   1               0.008547008547008548
-           [I]         96      0                   1                   1               0.010416666666666666
[third]     (running)   0       -                   -                   -               -
-           (all)       339     0                   1                   7               0.02064896755162242
-           [I]         112     0                   1                   2               0.017857142857142856
-           [II]        109     0                   1                   3               0.027522935779816515
-           [III]       118     0                   1                   2               0.01694915254237288
処理をメソッドチェーンで
ここからはマニアックな機能。
こんな書き方も可能。
中間処理用にdummyというメソッドがある。
特に一時的な処理や後で削除したい処理を書く時に明示的に書く事もできる。
//一般的な書き方その1
profiler.start("fnc7");//後で消す
fnc7();//後で消す
profiler.stop("fnc7");//後で消す

//一般的な書き方その2
profiler.start("fnc7");fnc7();profiler.stop("fnc7");//後で消す

//この方がわかりやすい?
profiler.start("fnc7").dummy(fnc7()).stop();//後で消す
応用例
なんの役に立つかはわからないけど次のような書き方も可能。
var num=3;
function fnc8(){num--;if(num==0){alert(profiler.result());}}
function fnc8_1(){arguments.callee._profiler_.stop();fnc8();}
function fnc8_2(){arguments.callee._profiler_.stop();fnc8();}
function fnc8_3(){arguments.callee._profiler_.stop();fnc8();}
fnc8_1._profiler_=profiler.start("fnc8_1");
fnc8_2._profiler_=profiler.start("fnc8_2");
fnc8_3._profiler_=profiler.start("fnc8_3");
setTimeout(fnc8_1,Math.random()*10000);
setTimeout(fnc8_2,Math.random()*10000);
setTimeout(fnc8_3,Math.random()*10000);

//処理結果(説明用に整形)
start name  stop name   count   minimal time(ms)    maximum time(ms)    total time(ms)  average time(ms)
[fnc8_1]    (running)   0       -                   -                   -               -
-           (all)       1       8626                8626                8626            8626
-           (no name)   1       8626                8626                8626            8626
[fnc8_2]    (running)   0       -                   -                   -               -
-           (all)       1       1384                1384                1384            1384
-           (no name)   1       1384                1384                1384            1384
[fnc8_3]    (running)   0       -                   -                   -               -
-           (all)       1       9703                9703                9703            9703
-           (no name)   1       9703                9703                9703            9703
最後に
開始終了処理に名前が指定できる点、変数に保持できる点、メソッドチェーンが可能な点、この三点の機能があるので、ここにあげた方法だけでなくアイディア次第で色々な計測ができると思う。
しかし、処理結果生成の処理がどうも綺麗になっていなくて気持ち悪い。
functionでまとめたい場所も多々ある。
でも、functionを呼ぶのは処理コストが大きいらしい。
計測そのものに時間がかかると、計測結果に影響してしまうのでデータ収集時にはできるだけ複雑な処理をしないようにしている。
その影響でresultメソッド内が複雑になっている。
それでももうちょっとなんとかなかないかと思ってたり...。

タグ:

日時: 2009年02月07日 03:35 |

トラックバック

このエントリーのトラックバックURL:
http://www.kanasansoft.com/cgi/mt/mt-tb.cgi/195

コメントを投稿

(いままで、ここでコメントしたことがないときは、コメントを表示する前にこのブログのオーナーの承認が必要になることがあります。承認されるまではコメントは表示されません。そのときはしばらく待ってください。)

Google

タグ クラウド

アーカイブ