環境
CodeIgniter:Version 2.1.0
前置き
表題にCodeIgniterと書きましたが、概念的にはこのフレームワークだからという話ではないです。前回の続きと言うことで。
デフォルトでログは以下のように吐かれます。
DEBUG - 2012-02-18 23:30:43 --> Controller Class Initialized
INFO - 2012-02-18 23:30:43 --> start
INFO - 2012-02-18 23:30:43 --> valid id:hogehoge
INFO - 2012-02-18 23:30:43 --> end
まあ、ざっくりこのログが何を表しているかというと、土曜の夜だというのにデバッグしてるMVCモデルのControllerの部分に要求がきて、その中のメソッドを開始し、idの値判定して結果をログへ出力。正常にメソッドを抜けてendといった感じを表しています。
自分で作り込んでいれば、上記では割愛した前後のログでおよその見当は付くでしょうが、ぱっと見どこの処理かわからないですね。
これにクラス名やメソッド名、行番号が表示されていれば、前後を確認しなくとも１発でどこの処理か判断する事ができるのではないでしょうか。
クラス名やメソッド名、行番号などの情報を取得する方法
PHPには便利な関数があるようで、
・PHP: debug_backtrace - Manual
http://www.php.net/manual/ja/function.debug-backtrace.php
この関数を叩けば、呼び出し元のクラス名やら行番号が参照できます。という事で、前回社畜仕様にカスタマイズしたファイルに埋め込めばＯＫ。はい解決！と行きたいところですが、少し挙動を見てみましょう。
debug_backtrace関数の戻り値を表示させるには、
var_dump(debug_backtrace());
という記述をしてやります。これを前回で言うところのMY_Log.phpのwrite_logメソッド内に記述し、
呼び出し元となる、テスト用のControllerを作成してやります。
<?php if ( ! defined('BASEPATH')) exit('No direct script access allowed');
class Testcontroller extends CI_Controller {
public function index() {
log_message('debug', 'Hello world');
}
}ブラウザから呼んで、１回の処理でどれだけ戻り値があるか実験してみます。
こんな感じでたくさんの配列の中身が表示されます。これらをコピーしてテキストに保存してサイズを見ると、
160KBなかなか大きいサイズじゃないですか。たかだかControllerからHello worldとログに出力するだけでこのサイズの戻り値の文字があるわけです。これが、何行もログを出力し、同時に複数のアクセスがある事を考えると、脇役のログが結構な負荷になるのではないでしょうか？そんなにアクセスないから安心しろ。 とは言え、160KBと言われても、戻り値の配列を文字で表示したサイズですし、PHPの中身がどうなっててメモリをどう使ってるのかわからないので”大きいサイズ”と言いましたが感覚的なものです。。。ブラウザに表示すると重くなるデータサイズはちと見逃せねーなーといった感じです。
パフォーマンス重視で言えば、以下の定数を１個１個Hello worldの部分へ埋め込めば良いでしょう。
・PHP: 自動的に定義される定数 - Manual
http://php.benscom.com/manual/ja/language.constants.predefined.php
しかし、捕らぬアクセスのレスポンス算用を今のうちにして、パフォーマンス重視の見づらいコードになるくらいなら、バグを埋め込まないためにもスッキリさせておきたいので、仲介の関数（ラッパー関数）を間に挟んでみます。
ロガーを仲介する関数を作成する
メソッドからロガーを呼ぶにあたり、以下のようなコードの見栄えでどこからでも直接関数を呼べるよう、
log_message('debug', 'Hello world');CodeIgniterのヘルパー関数として実装します。
・ヘルパー関数 : CodeIgniter ユーザガイド 日本語版
http://codeigniter.jp/user_guide_ja/general/helpers.html
まず、ヘルパー関数を記述するファイルを作成します。ファイル名の末尾は「_helper.php」となるようにします。
- application/helpers/mylogwrap_helper.php
<?php
function logger_debug($msg) {
print_r(debug_backtrace());
log_message('debug', $msg);
}
?>
まずは、上記のMY_Log.phpと比較できるよう、print_r(debug_backtrace());を実装しておきます。これをどこからでも呼べるよう、「application/config/autoload.php」に登録します。こちらでは、ファイル名の「_helper.php」は必要ありません。
$autoload['helper'] = array('mylogwrap');これで先ほどのControllerでこの関数を呼ぶようにして実験をしてみます。
<?php if ( ! defined('BASEPATH')) exit('No direct script access allowed');
class Testcontroller extends CI_Controller {
public function index() {
logger_debug('Hello world');
}
}
約27KBで仲介させた関数の方が約1/6小さい！ということで明らかに効果がありますね。まあ、フレームワーク自体のログが出なくなる事もあり、当たり前ですが。できればByte単位にしたいところですが、コレでいきたいと思います。
で、これを表題の通りに表示させるべく、debug_backtrace関数の戻り値から必要な情報を取得し、関数を修正・整理してみたのが以下です。ただし、クラス名を表示させるので呼び出し元はクラス限定という縛りで。
<?php
function logger_info($msg) {
logger('info', $msg);
}
function logger_debug($msg) {
logger('debug', $msg);
}
function logger_error($msg) {
logger('error', $msg);
}
function logger($level, $msg) {
$arr = debug_backtrace();
// この関数が直接呼ばれた場合と、同ファイル内から呼ばれた場合でバックトレースの取得位置を分岐。
if(stristr($arr[0]['file'], 'mylogwrap_helper') === FALSE) {
// ヘルパーとして呼び出された場合
$filename = $arr[1]['class'] ."::".$arr[1]['function'];
$msg = $filename."[".$arr[0]['line']."] ".$msg;
}
else {
// 同ファイル内からの呼び出された場合
$filename = $arr[2]['class'] ."::".$arr[2]['function'];
$msg = $filename."[".$arr[1]['line']."] ".$msg;
}
// 本家ロガーへ (;_;)/~~~
log_message($level, $msg);
}
?>
パラメータとして記述していたdebugやerrorというレベル値は、その分対応する関数としました。これならNetBeansとかのIDEなら実行前にエラーだとわかるのではないでしょうか？試してないのでわかりませんが。そして、共通的に処理するloggerを設けてます。本当はloggerはプライベートな関数としたいところですが、そうもいかないので、直接呼ばれた場合と同ファイルから呼ばれた場合で分岐させましました。
これを先ほどのControllerから呼ぶと、
DEBUG - 2012-02-19 01:32:45 Controller Class Initialized
DEBUG - 2012-02-19 01:32:45 Testcontroller::index[6] Hello world
これで、どこのHello worldさんか一目瞭然ですね！
コメント
コメントを投稿