ＰＨＰでのログのとり方を考える

ＰＨＰでは記述ミスがあればエラー内容が画面表示されますし、警告も設定によりますが画面表示されるようになっています。なので特にデバッグツール類が必要になることはないでしょう。。
なので簡易的なログとり関数などを作っておけば充分です。

ＰＨＰにはログとり専用のerror_log()関数が用意されています。

書式　error_log("ログ書き込み内容をここに", 3, "/path/to/filename");

という書き方で実現できます。
恐らく実質fopen("/path/to/filename", "a")というアペンドモード（追加）書き込みが行われていると思います。

error_logという関数名ですが、エラーだけでなく開発時のデバッグ用にも大いに利用できると思います。

ということで早速使ってみましょう。

■ログとり（１）

<?php

$s= "foo";
error_log($s, 3, "error.log");

$s= "bar";
error_log($s, 3, "error.log");

?>

[error.log書き込み内容]

foobar

あれれ、１度目と２度目のログデータがつながってしまって切れ目がわかりません。
末尾改行が必要ですね。

■ログとり（２）

<?php

$s= "foo";
log2($s);

$s= "bar";
log2($s);

function log2($s)
{
    error_log(rtrim($s) . "\n", 3, "error.log");
}
?>

[error.log書き込み内容]

foo
bar

うまくいきました。
書き込み内容末尾に改行があるかどうかわからないので、改行があればrtrim()で削って"\n"を付加しています。これでログ末尾に必ず改行が付くことになります。

ところでログといえば必ず書き込んだ日付が付きものです。
日付を追加してみましょう。

■ログとり（３）

<?php

$s= "foo";
log3($s);

$s= "bar";
log3($s);

function log3($s)
{
    error_log(date("[Y/m/d H:i:s] ") . rtrim($s) . "\n", 3, "error.log");
}
?>

[error.log書き込み内容]

[2009/11/11 22:45:47] foo
[2009/11/11 22:45:47] bar

っぽいですね。ログって感じがプンプンしてきましたね。

では次はもっと欲を出してスカラー変数以外の配列などにも対応できるようにしてみます。

■ログとり（４）

<?php

$array= array("foo", "bar");
log4($array);

function log4($s)
{
    error_log(date("[Y/m/d H:i:s] ") . rtrim(print_r($s,true)) . "\n", 3, "error.log");
}
?>

[error.log書き込み内容]

[2009/11/11 23:23:32] Array
(
    [0] => foo
    [1] => bar
)

print_r()関数を使いました。この関数の第２引数を「true」にすると標準出力しないで文字列として返すようになります。

それでは更に欲を出して値の型も知ることができるようにprint_r()関数をvar_dump()関数に代えてみます。

■ログとり（５）

<?php

$array= array("foo", "bar", 5);
log5($array);

function log5($s)
{
    ob_start();
    var_dump($s);
    $log= ob_get_contents();
    ob_end_clean();
    error_log(date("[Y/m/d H:i:s] ") . rtrim($log) . "\n", 3, "error.log");
}
?>

[error.log書き込み内容]

[2009/11/11 23:28:35] array(3) {
    [0]=>
    string(3) "foo"
    [1]=>
    string(3) "bar"
    [2]=>
    int(5)
}

var_dump()関数にはprint_r()関数のような文字列を返すオプションは用意されていませんので、標準出力をバッファリングさせて捕まえないといけません。
そのためにob系関数を使っています。
これで値のデータ型まで知ることができるようになりました。

これくらいで終わりにしたいところですが、もし一度に複数の変数をログ書き込みしたい場合にも対応できたほうがいいので可変引数対応に書き替えます。

■ログとり（６）

<?php

$array= array("foo", "5", 5);
$s= "hoge";
log6($array, $s);

function log6()
{
    ob_start();
    foreach (func_get_args() as $argv){
        echo "\t";
        var_dump($argv);
    }
    $log= ob_get_contents();
    ob_end_clean();
    error_log(date("[Y/m/d H:i:s] ") . rtrim($log) . "\n", 3, "error.log");
}
?>

[error.log書き込み内容]

[2009/11/11 23:31:54] array(3) {
    [0]=>
    string(3) "foo"
    [1]=>
    string(1) "5"
    [2]=>
    int(5)
}
    string(4) "hoge"

その他、作成したこの関数を複数スクリプトで使う場合には書き込むログファイル名を分けるとか、一つのログファイルに書き込む場合には$_SERVER['SCRIPT_NAME']の値も併せて保存するといい感じになると思います。

できれば log6(__FILE__ . "(" . __LINE__ . ")". $message);のように記述したほうがよりわかり易いですが、面倒なんですよね。define()使っても置換できませんでした。

どっちのＰＨＰショー（３）時間ですよ

現在の時刻を取得するためにＵＮＩＸ秒を取得することはよくあることです。

簡単に$ts= time();とやるだけで取得することができます。

んで、マニュアル によるとＰＨＰ５．１．０以降から$_SERVER['REQUEST_TIME']という連想配列に実行時ＵＮＩＸ秒がセットされるようになっています。

このことから、現在のＵＮＩＸ秒を取得する方法として$_SERVER['REQUEST_TIME']を使う方が効率いいみたいなことがどこかに書いてあったのを見た記憶が・・・

ということで果たしてホントに効率（ここでは速さということにしておきましょう）がいいのはどっちか比較してみましょ

ただし、環境によって違う結果になるかも知れないということだけ言っておきます。
（計測環境　Windows Vista Home Premium 32bit SP2, CPU E5300 2.60GHz, RAM 4GB, xampplite 1.7.2[Apache2.2.12 PHP5.3.0]）

[ソースコード]

<?php

bench(1);
foreach (range(1, 1000000) as $i) $now= time();
printf("%.20f(time)<br />\n", bench());

bench(1);
foreach (range(1, 1000000) as $i) $now= $_SERVER['REQUEST_TIME'];
printf("%.20f(req)<br />\n", bench());

function bench($reset="")
{
    global $micro,$time;

    (!isset($time) or !empty($reset)) and list($micro, $time)= explode(' ', microtime());
    list($m, $t)= explode(' ', microtime());
    return $m-$micro+$t-$time;
}

?>

連想配列の場合、$_SERVER[REQUEST_TIME]と書くより$_SERVER['REQUEST_TIME']と書いたほうが速いことはよく知られていることです。

[出力結果]

0.71700596809387207031(time)
0.62918400764465332031(req)

0.72955703735351562500(time)
0.62026906013488769531(req)

0.70035099983215332031(time)
0.62803506851196289062(req)

１００万回ループを３回計測しました。

これだけループするとはっきりと$_SERVER['REQUEST_TIME']に分があることがわかります。
これは「システムコール直叩き」ｖｓ「メモリ上の連想配列値へのアクセス速度」の対決ということになるかと思いますが、なんら気にするほどの差はないということですね。

ということで、実行時刻として$_SERVER['REQUEST_TIME']を使うのが自然な場面ではこれを使うかも知れませんが、$_SERVER['REQUEST_TIME']は冗長なのでどんどんtime()関数を使っていくことを私の宗教とすることにします。

どっちのＰＨＰショー（２）ループ速度比較

ＰＨＰにはいくつかのループが用意されています。
一般的なforやwhileループ、配列値を順にセットするforeachループなどがそれです。
果たしてループにおいてそれぞれ速度差が出るものなのかを検証してみたいと思います。

■１０回ループを比較（３回繰り返す）

まずは１０回のループでfor、foreach、whileの３つのループを比較してみます。
当然各ループに特色があるのでできるだけ同じ条件に無理やりしてみます。

[ソースコード]

<?php

bench(1);
for ($i=0; $i++ < 10;) ;
printf("%.20f(for)<br />\n", bench());

bench(1);
foreach (range(1, 10) as $i) ;
printf("%.20f(foreach)<br />\n", bench());

bench(1);
$i= 0;
while ($i++ < 10) ;
printf("%.20f(while)<br />\n", bench());

function bench($reset="")
{
    global $micro,$time;

    (!isset($time) or !empty($reset)) and list($micro, $time)= explode(' ', microtime());
    list($m, $t)= explode(' ', microtime());
    return $m-$micro+$t-$time;
}
?>

[出力結果]

0.00004291534423828125(for)
0.00003409385681152344(foreach)
0.00002288818359375000(while)

0.00004196166992187500(for)
0.00003409385681152344(foreach)
0.00002193450927734375(while)

0.00004196166992187500(for)
0.00003504753112792969(foreach)
0.00002288818359375000(while)

while速っ！なんで？思った以上に差が出た。。

よくわからないのでとりあえずループ回数を増やして計測してみます。

■１００万回ループを比較（３回繰り返す）

つづきまして先ほどと同じコードで１００万回ループの比較を行ってみました。

[出力結果]

0.11699891090393066406(for)
0.44337797164916992188(foreach)
0.04407906532287597656(while)

0.12270903587341308594(for)
0.47000908851623535156(foreach)
0.04393410682678222656(while)

0.12277793884277343750(for)
0.48631691932678222656(foreach)
0.04414606094360351562(while)

うぎゃぁ。。

foreachループ好きで今まで多用してきたのにぃ。。＞＜
やはりrange()の配列生成にそれなりのコストがかかってるようですな

でもこれだけのループ数を使うことは稀だし直感的に書きやすいからめげずに今後も使うかも

結論は、「while速っ！！」

もうこれ以上は何度比較しても無限ループですなぁ。。。

うわぁー、、うまいこと言ってしまった＾＾ｖ

■forループ内の関数使用による負荷（３回繰り返す）

気を取り直して次はよく言われるforループ内のループ条件部にcount($array)を使うとどれくらい遅くなるかを計ってみます。

[ソースコード]

<?php

$array= range(1, 10000); // １万要素の配列生成

bench(1);
for ($i=0,$max=count($array); $i < $max; $i++) ; // ループ前にセット
printf("%.20f(outer)<br />\n", bench());

bench(1);
for ($i=0; $i < count($array); $i++) ; // ループ条件にcount()使用
printf("%.20f(inner)<br />\n", bench());

function bench($reset="")
{
    global $micro,$time;

    (!isset($time) or !empty($reset)) and list($micro, $time)= explode(' ', microtime());
    list($m, $t)= explode(' ', microtime());
    return $m-$micro+$t-$time;
}

?>

[出力結果]

0.00142002105712890625(outer)
0.00653505325317382812(inner)

0.00143098831176757812(outer)
0.00645804405212402344(inner)

0.00141000747680664062(outer)
0.00650811195373535156(inner)

今回は配列要素数を１万でやってみましたが、まぁ確かに先にcount()値をセットしておいたほうが速いですね。

当たり前だけど・・

■ループ条件の評価タイミング

最後に各ループ条件の評価がどの段階で行われているかを調べてみます。

[ソースコード]

<?php

$i= 0;
for (; func("for", $i);){
    if (++$i > 2) break;
    echo "for<br />\n";
}

$i= 0;
foreach (func("foreach", $i) as $j){
    if (++$i > 2) break;
    echo "foreach<br />\n";
}

$i= 0;
while (func("while", $i)){
    if (++$i > 2) break;
    echo "while<br />\n";
}

function func($key, $i)
{
    echo "$key($i)<br />\n";
    return range(1, 10);
}

?>

[出力結果]

for(0)
for
for(1)
for
for(2)
foreach(0)
foreach
foreach
while(0)
while
while(1)
while
while(2)

これを見れば分かるように、forとwhileのループ条件に関数があればループのたびに評価されるが、foreachでは評価は最初の１回だけされています。

これを受けて一つ前に戻って
for ($i=0,$max=count($array); $i<$max; $i++)と
foreach (range(0, count($array)-1) as $i)は評価が最初だけなので似ているということになります。

ただしforeachループで注意しなければいけないのは
foreach (range(0, 0) as $i) では１回ループされ
foreach (range(0, -1) as $i) では２回ループされ
foreach (range(0, 1) as $i) では２回ループされる。
つまり必ず１回はループされることになる。

foreach ($array as $i) // $arrayが未定義なら警告が出て、
$array= array();
foreach ($array as $i) // $arrayが空っぽなら０ループ
という挙動になるので使う場合はこのことを知っておかないといけません。