楽に設置できる関数の実行時間計測器を作った

結論

やっぱ雑に設置できると肩肘張らずに作業できるのでモチベ上がる。

原理上事故が起きないので安心できるので楽。

その代償として、呼び出しコストが割と高いので大枠としての実行時間プロファイルを得る為に使う事が肝要。

売り

雑に設置してもいい感じに結果を得られる。

導入方法

Composerを使える環境の人

人は次のコマンドでインストールしてください。

composer require ickx/fw2

Composerを使えない環境の人

次のURLからzipファイルをダウンロードし、任意のフォルダに展開します。
https://codeload.github.com/ProjectICKX/fw2/zip/master

# wgetの場合
wget https://codeload.github.com/ProjectICKX/fw2/zip/master -O fw2.zip

unzip fw2.zip

呼び出し

PSR-0またはPSR-4互換のClassLoaderが使える場合

use ickx\fw2\basic\log\TimeProfiler;

PSR-4互換のClassLoaderが使えない場合

require_once '展開先のフォルダ/basic/log/TimeProfiler.php';
use ickx\fw2\basic\log\TimeProfiler;

基本的な使い方

TimeProfilerに対して任意の文字列で静的呼び出しを行うと、任意の文字列名での計測機を呼び出せます。
後は呼び出した計測器のlogメソッドを呼ぶだけで区間の時間計測を行ってくれます。

例

TimeProfiler::debug()->log();    //この場合、"debug"という名前で計測器を呼び出し、ログを残します。

TimeProfiler::info()->log();    //この場合、"info"という名前で計測器を呼び出し、ログを残します。

上記二つの呼び出しは並列して行え、独立したログ取得を行えます。

使用例

もっとも簡易な使い方

サンプルコード

test.php

TimeProfiler::debug()->log();
sleep(1);
TimeProfiler::debug()->log();
echo implode(\PHP_EOL, TimeProfiler::debug()->dump()), \PHP_EOL;

実行結果

[2017-09-03 10:34:34.2135] [debug] total:[split:  0.00000000, lap:  0.00000000] part:[split:  0.00000000, rap:  0.00000000] calltree:[main()] comment:[]
[2017-09-03 10:34:35.214 ] [debug] total:[split:  1.00050902, lap:  1.00050902] part:[split:  1.00050902, rap:  1.00050902] calltree:[main()] comment:[]

このように、同じ内容（TimeProfiler::debug()->log();）をコピペして回るだけで簡単にそれなりな区間計測を行うことが可能です。

もう少し実践的な例

それでは関数の呼び出しが階層構造の場合はどうでしょうか。

サンプルコード

test2.php

class SingletonArray {
    protected static $instance = null;

    protected $array = [];

    public static function getInstance () {
        TimeProfiler::debug()->log();
        static::$instance = static::$instance ?? new static();
        TimeProfiler::debug()->log();
        return static::$instance;
    }

    public function set ($name, $value) {
        $this->array[$name] = $value;
        return $this;
    }

    public function get ($name) {
        $ret = $value[$name] ?? null;
        return $ret;
    }

    public function length () {
        TimeProfiler::debug()->log();
        $count = 0;
        foreach ($this->array as $value) {
            $count++;
        }
        TimeProfiler::debug()->log();
        return $count;
    }
}

TimeProfiler::debug()->log('start');
$singletonArray = SingletonArray::getInstance()->set('a', 1)
->set('b', 2)
->set('c', 3);
TimeProfiler::debug()->log('set end');
$singletonArray->length();
TimeProfiler::debug()->log('length count end');

echo implode(\PHP_EOL, TimeProfiler::debug()->dump()), \PHP_EOL;

実行結果

[2017-09-03 11:05:02.4896] [debug] total:[split:  0.00000000, lap:  0.00000000] part:[split:  0.00000000, rap:  0.00000000] calltree:[main()] comment:[start]
[2017-09-03 11:05:02.4896] [debug] total:[split:  0.00003695, lap:  0.00003695] part:[split:  0.00000000, rap:  0.00000000] calltree:[main() => SingletonArray::getInstance()] comment:[]
[2017-09-03 11:05:02.4896] [debug] total:[split:  0.00004482, lap:  0.00000787] part:[split:  0.00000787, rap:  0.00000787] calltree:[main() => SingletonArray::getInstance()] comment:[]
[2017-09-03 11:05:02.4896] [debug] total:[split:  0.00005579, lap:  0.00001097] part:[split:  0.00005579, rap:  0.00005579] calltree:[main()] comment:[set end]
[2017-09-03 11:05:02.4896] [debug] total:[split:  0.00006390, lap:  0.00000811] part:[split:  0.00000000, rap:  0.00000000] calltree:[main() => SingletonArray->length()] comment:[]
[2017-09-03 11:05:02.4896] [debug] total:[split:  0.00006890, lap:  0.00000501] part:[split:  0.00000501, rap:  0.00000501] calltree:[main() => SingletonArray->length()] comment:[]
[2017-09-03 11:05:02.4896] [debug] total:[split:  0.00007391, lap:  0.00000501] part:[split:  0.00007391, rap:  0.00001812] calltree:[main()] comment:[length count end]

実行結果の5行目にあるcalltreeを見てみましょう。
[main() => SingletonArray->length()]
このように簡易的なスタックトレースが付与されます。

calltreeに注目すれば、いかなる階層であっても簡単に追跡を行うことが可能です。

明示的な開始地点と終了地点やチェックポイントを設置したい場合はlog methodの第一引数であるコメントを使ってみましょう。

意図を明確に残すことが可能です。

結び

"とりあえず作ってみた"版なので色々と至らない所はあると思います。
"こんな機能あったらいいな"などありましたら、コメントに残しておいてもらえるとうれしいです。
体力が許す範囲で対応を試みます。