PEARのLogでサーバ処理の性能測定

ログの出力にはいろいろとありますが、今回はPEARのパッケージ「Log」の活用例です。

Package Information: Log

PEARを利用することで、ログのファイルへの書き出しだけでなく、DBやメールでの出力もスムーズに行うことができます。

例えば、以下のようにするだけで、ファイルへログを出力することができます。

require_once('Log.php');
$log = &Log::factory('file', '/log/test.log', 'TEST');
$log->('テストログです');

これまで、CSV形式のファイルをオープンして、書き込んで保存したりしていましたが、こっちのほうが断然楽ですね。

このパッケージを活用して、サーバ処理の性能を測定します。

require_once('Log.php');
$conf = array('mode' => 0777, 'timeFormat' => '%H:%M:%S');
$date = date("Ymd");
$log_id = 'idとか';
$log = &Log::factory('file', '/log/' . $date . '.log', $log_id, $conf);
$log->log('処理○○');

Logの設定は配列で指定します。ここでは、日毎にログファイルを分けたいために、ファイル名をdate関数で取得します。「idとか」の部分には異なるセッションのログが混在しないように、セッション毎にIDをふります。そうすることで、後にログファイルを開いてIDで絞ることで、純粋にそのセッションだけのログを参照できるのです。そして、「$log->log(‘処理○○’);」を、プログラムの主な処理の間に入れていきます。テキスト部分はそれとわかるような内容で。

これでプログラムを実行すると、例えばファイル「20100101.log」で以下のような結果が得られます。これは任意のID「XXXX」で絞り込んだものと仮定します。

00:17:29 XXXX [info] Logging Start
00:17:29 XXXX [info] set A Start
00:17:29 XXXX [info] set A End
00:17:29 XXXX [info] set B Start
00:17:30 XXXX [info] set B End
00:17:30 XXXX [info] set C Start
00:17:30 XXXX [info] set C End
00:17:30 XXXX [info] set D Start
00:17:30 XXXX [info] set D End
00:17:30 XXXX [info] set E Start
00:17:33 XXXX [info] set E End
00:17:33 XXXX [info] set F Start
00:17:33 XXXX [info] set F End

これだけ見ると、処理「E」に時間がかかってるようなので、処理「E」を改善することが性能アップにつながると言えそうです。もちろん、他のセッションも見てみて、ある程度平均を見る必要があります。

本当はミリ秒単位で見たいんだけど。LogのtimeFormatをミリ秒まで指定するにはどうしたらいいんでしょう。どなたかご存知ですか？