区間内の経過時間をとる簡単なログ出力クラス

雑な1ファイルのPHPスクリプトの処理時間を計測したいと言われた。
既存ライブラリは古くて入らなかったり、
計測処理内容を引数に取る形だったり、
出力フォーマットがご満足いただけないようだったので、書捨てクラスを作った。

ご要望は

• 時刻はY年m月d日 H:i:s形式
• できれば1行で表示
• 作業ごとの開始時間と終了時間を記録する
• 作業ごとの経過時間を記録する(開始時間の差分が0sになるのは許容いただいた)
• 記録範囲全体の総経過時間を記録する
• ある作業を計測中に別作業の計測を開始してもなんとかなる
• 既存コードをできるだけ加工しない(間にロギング用コードを仕込む)
• 結果はファイルに出力する(特別なオーダー無し)

だったので、差分はmicrotime(true)の差分で出すとして、
スクリプトの最初にインスタンス生成、スクリプト終了のdestructで全体を取ることにした。
なのでクラス横断もできるstaticなまともなロガーには全然勝てない。
使い捨てでライブラリ入れるのが面倒なときとかに。

<?php

class SaveLog
{

    private $marks = array();

    public function __construct()
    {
        $this->start('ロギング');
    }

    public function __destruct()
    {
        $this->end('ロギング');
    }

    public function start($tag)
    {
        $this->marks[$tag] = microtime(true);

        $this->log($tag . '開始');

    }

    public function end($tag)
    {
        $this->log($tag . '完了', microtime(true) - $this->marks[$tag]);
    }

    private function log($tag, $diff = 0)
    {
        $now = new DateTime();
        $text = $now->format('Y年m月d日 H:i:s : ') . sprintf("(%.10f s)", $diff) . ' : ' . sprintf("%s\n", $tag);
        file_put_contents('./log', $text, FILE_APPEND);
    }
}

テストコード

<?php

$log = new SaveLog;

$log->start('sleep');
sleep(10);
$log->end('sleep');

$log->start('for');
for ($i = 0; $i < 5; ++$i) {
    $log->start('loop' . $i);
    sleep(1);
    // hogehoge
    $log->end('loop' . $i);
}
$log->end('for');

出力

2016年09月21日 10:27:25 : (0.0000000000 s) : ロギング開始
2016年09月21日 10:27:25 : (0.0000000000 s) : sleep開始
2016年09月21日 10:27:38 : (12.8896620274 s) : sleep完了
2016年09月21日 10:27:38 : (0.0000000000 s) : for開始
2016年09月21日 10:27:38 : (0.0000000000 s) : loop0開始
2016年09月21日 10:27:39 : (1.0011038780 s) : loop0完了
2016年09月21日 10:27:39 : (0.0000000000 s) : loop1開始
2016年09月21日 10:27:40 : (1.0008089542 s) : loop1完了
2016年09月21日 10:27:40 : (0.0000000000 s) : loop2開始
2016年09月21日 10:27:41 : (1.0008041859 s) : loop2完了
2016年09月21日 10:27:41 : (0.0000000000 s) : loop3開始
2016年09月21日 10:27:42 : (1.0007710457 s) : loop3完了
2016年09月21日 10:27:42 : (0.0000000000 s) : loop4開始
2016年09月21日 10:27:43 : (1.0009260178 s) : loop4完了
2016年09月21日 10:27:43 : (5.0053570271 s) : for完了
2016年09月21日 10:27:43 : (17.9945080280 s) : ロギング完了

秒数による位置ズレは許してもらえた。
横幅とりすぎると見づらくなるし…。
最初は作業名を頭に、と言われたが、半角・全角のズレが酷くて全部全角にする変換をかけたりしていた。
開始から終了までまとめて1行にしたり開始の差分は消したりした方がいいかもしれないけど、そこら辺は利用者に応じる。