デバッグし易くしよう！ 5: 処理時間を計測

プログラムを実行するサーバーによっては、ある一定時間以上連続して動作して動くプログラムが強制切断されてしまうようです。その意味で自分が作成したプログラムが処理にどれくらいかかるのか知りたいことが多いと思いますので、ここでは、プログラムの開始時間、終了時間、処理時間を表示させる例をご紹介します。

Step5 プログラムの処理時間を処理終了時に表示させてみる

現在時刻を取得する関数にはtime()関数(マニュアル)がありますが、timeでは、秒単位までしか分かりません。ここではマイクロ秒単位まで返してくれるmicrotime()関数(マニュアル)を利用します。

<?php
$start_time=microtime(true);
echo "開始時間： ".date('Y-m-d H:i:s',(int)$start_time)."<br>";

//メイン処理

$end_time=microtime(true);
echo "終了時間： ".date('Y-m-d H:i:s',(int)$end_time)."<br>";
$syori_zikan=$end_time - $start_time;
echo "処理時間：".sprintf('%0.5f',$syori_zikan)."秒<br>";
exit();
?>

開始、終了時刻をマイクロ秒で表示しても何が何だかわかりませんので実際にはdate()関数（マニュアル）を利用して'Y-m-d H:i:s'形式で表示させています。microtime(true)とした場合microtime()関数の戻り値はfloat型となりますが、date()関数の引数として利用できるのは、time()関数と同じint型のため、上の例では（int）でmicrotime関数の結果をcastしています。
処理時間については、sprintf()関数（マニュアル）で、小数点以下５桁表示にしています。

結果は以下のようになります。

開始時間： 2010-01-12 00:45:07
終了時間： 2010-01-12 00:45:07
処理時間：0.00012秒

開始、終了時刻もやはり詳細が見たいので、少し変更

<?php
$start_time=microtime(true);
echo "開始時間： ".formatMicrotime($start_time,'Y-m-d H:i:s')."<br>";

//メイン処理

$end_time=microtime(true);
echo "終了時間： ".formatMicrotime($end_time,'Y-m-d H:i:s')."<br>";
$syori_zikan=$end_time - $start_time;
echo "処理時間：".formatMicrotime($syori_zikan)."秒<br>";
exit();


function formatMicrotime ( $time, $format = null )
{
   if (is_string($format)) {
            $sec  = (int)$time;
         $msec = (int)(($time - $sec) * 100000);
            $formated = date($format, $sec). '.'. $msec;
     } else {
         $formated = sprintf('%0.5f', $time);
    }
    return $formated;
}
?>

処理結果は次になります。 なお上記の function formatMicrotime()は*1を参考にさせていただきました。

開始時間： 2010-01-12 00:51:40.54924
終了時間： 2010-01-12 00:51:40.54937
処理時間：0.00013秒

*1:http://www.sound-uz.jp/php/note/startDebug