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

初心者向 PHP Twitter bot デバッグ

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

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

デバッグし易くしよう！ 6: 　ログファイルに処理記録を残す

初心者向 PHP Twitter bot デバッグ

ここまでは、処理の進行状況や、変数の値などを表示する方法を紹介してきましたが、実際に本番サーバー上で、botの運用を開始してしまうと、毎回の処理状況を付きっきりで目視できる訳ではありません。
PHPのerror_log関数（マニュアル）を利用すると、ログとして任意のエラーメッセージをファイルに書きだすことができます。
これを利用して、処理のログをファイルに書き出してみることにします。*1

Step6 ログファイルに処理記録を残す

error_log関数を利用してログをファイルに書き出す方法は簡単です。例えば、syori.txtというファイルに"プログラムを実行しました”というメッセージを書き出したいのであれば、下記のように書くだけでOKです。

<?php

error_log("プログラムを実行しました",3,'syori.txt');

?>

これを今までも利用しているサンプルコードに埋め込むんで、step1で追加した、echo文をログファイルに出力するようにしてみると例えば、次のようになります。

*1:error_log ( string $message [, int $message_type = 0 [, string $destination [, string $extra_headers ]]] )関数
エラーメッセージを Web サーバのエラーログ、 TCP ポート、あるいはファイルに送ります
第2引数$mesage_typeに"3"をセットした場合に、第3引数Rdestinationで指定したログファイルに第1引数で指定したエラーメッセージが書き出されます。

続きを読む

デバッグし易くしよう！ 7: 　デバッグ用のClass

初心者向 PHP Twitter bot デバッグ

特にStep6のログファイルの出力のことを書きましたが、
毎回error_log...で、ログファイルの出力先等を記載するのは面倒臭い。
ログファイルに出力したいことと、画面に表示したいことは同じ場合も多い。
どのプログラムでもデバッグ用にやりたい作業はだいたい同じ
ということで、実際の自分のプログラムではデバッグ処理用のClassを作成して使い回しています。本当に使っているものはもっと複雑というかラーメンかスパゲッティか的な物なのですが、少し単純化してみたものをご参考までに載せて説明させて頂きたいと思います。*1

Step7: デバッグ用Classを使う

仮に testLogと名付けたClassを作成しました。
このClassを利用してできることは以下の通りとなります。

1.任意のテキスト文字列を表示/ログファイルに出力する。
2.ログファイルへの出力に際しては、以下の内容も追加した状態で出力される。
　　a.処理が行われた時間
b.プログラム名
3.ログファイルに、
　　プログラムの開始、終了時刻および処理時間を出力することも可能
4.文字列の表示、非表示は切り替え可能

プログラム側でのこのClassの利用例は次のようになります。

<?php
require_once("test_log.php");  //testLog class
testLog::setLogfile('./logfile/test_log.txt'); //ログファイル名の指定
testLog::setProgname( 'testprogram_name' ); // プログラム名
testLog::setdispLogF( TRUE ); //  ログを画面表示するか？ TRUE/FALSE

testLog::save_msg('処理スタート','====['.__FILE__.']==');

// メインの処理

testLog::save_msg('処理終了','=================================');
testLog::keikazikanLog();　　
?>

上のようなコードを含むプログラムを実行した場合。
./logfile/test_log.txtには、以下のような形式でログを出力することができます。

"2010-01-12 01:13:48","0.8619","testprogram_name","処理スタート","====[C:\(中略)\testprogram.php]=="

"2010-01-12 01:13:48","0.72220","testprogram_name","処理終了","================================="
"2010-01-12 01:13:48","0.72433","testprogram_name","[ 2010-01-12 01:13:48.8614 ]-[ 2010-01-12 01:13:48.72419 ]","  開始からの処理時間= [0.63805]sec"

画面の表示は下記のようになります。

testLog: 処理スタート,====[C:\(中略)\testprogram.php]==

testLog: 処理終了,=================================
testLog: [ 2010-01-12 01:13:48.8614 ]-[ 2010-01-12 01:13:48.72419 ],  開始からの処理時間= [0.63805]sec

見ておわかり頂けると思いますが、最初に出力対象のログファイル名、プログラム名、画面表示の有無を設定してしまえば後は、

testLog::save_msg('text1','text2');

のように、表示、出力したい情報を文字列形式にしてセットするだけです。なお、２つ目の項目は省略も可能です。

以下、実際のtestLog Class となります。

*1:http://www.sound-uz.jp/php/note/startDebug のdebugクラスを物凄く参考にさせていただいております。

続きを読む

デバッグし易くしよう！（おまけ）　testLog Class をサンプルコードに適用した例

初心者向 PHP Twitter bot デバッグ

前回のデバッグ用Class testLogをサンプルコードに組み込んでみた例です。

開発時、運用時などの状況により、表示の有無、出力範囲の制御を次の二つの定義を組み合わせで制御できます。

//DEBUG処理の切り替え 本番運用時にはFALSEに変更すること
define('DEBUG', TRUE); //デバッグ時
//define('DEBUG', FALSE); //本番運用時

testLog::setdispLogF( TRUE ); // ログを画面表示するか？ TRUE/FALSE

また、メインプログラム側で、ログファイル名に日付を加え、日付ごとにログファイルが分かれるようにしています。

//ログ処理準備
$Kyou=date("Ymd",time());

$logDir='./log/'; //ログディレクトリ
$logFname=$logDir.'test_syori_log'.$Kyou.'.txt';//ログファイル名
require_once("test_log.php"); //test class
testLog::setLogfile($logFname); //ログファイル名の指定

続きを読む