Apacheでプログラムを動かしていると、それがどの程度の速度でコンテンツを出力しているのかは開発者にとって興味のあるところだと思います。単一のページなら、スクリプトの最初と最後にmicrotime()でも仕込んでおけばいいのですが、サイト全体的に、継続的に、ってなるとなかなか面倒ですよね。でも、実はApacheの標準機能でできるんです。今回はそんなお話。

よく知られているのはこれ。

%T リクエストを扱うのにかかった時間、秒単位

引用元: mod_log_config – Apache HTTP サーバ バージョン 2.2
リクエストを扱うのにかかった時間を秒単位で計測してくれる。でも、秒単位ってちょっとね。分解能が低い。大体0か1になる。デジタルかよ、みたいな。デジタルだけどね。

で、実はこんなのもできてたみたいです。

%D リクエストを処理するのにかかった時間、マイクロ秒単位

引用元: mod_log_config – Apache HTTP サーバ バージョン 2.2
マイクロ秒で測ってくれる。マイクロって100万分の1なのでやり過ぎな感じもするけど、PHPでmicrotime()を最初と最後にやるのと同じようなもんだよね。なので採用。

後はページと紐付けるために%rなり%Uなり、好きなものと一緒にログに書き込んでください。自分はこうしてみた。

CustomLog /path/to/microtime_log "%D %U" env=!no_microtime_log

%Dを先にしたのは、%Uが半角スペースを含む可能性があるから。%rなら%Dが後でもいいかも。

そして最後の env=!no_microtime_log ってのはログするリクエストの制限です。この場合 no_microtime_log という環境変数が存在しない場合にログされる。こんなことをしておくんです。

SetEnvIf Request_URI "\.gif$" no_microtime_log

こうすればリクエストのURIが .gif で終わっていると環境変数が設定され、ログされなくなるんです。設定次第で色々できそうね。

そんな感じで数時間取ってみました。このサイトで一番時間食ってるURIは？

$ sort -nr /srv/imys.la/logs/microtime_log | head
120367284 /shun/wp-admin/admin-ajax.php
104168299 /shun/wp-admin/admin-ajax.php
60326889 /shun/index.php
4210766 /shun/wp-cron.php
2161329 /shun/wp-admin/post.php
1562175 /shun/wp-admin/admin-ajax.php
1547203 /shun/wp-admin/post.php
1399622 /shun/wp-admin/post.php
1055877 /shun/wp-admin/post-new.php
1053861 /shun/wp-admin/post.php

管理画面でした。まー、そうだよね。

ここまでできたら後は計算すればページごとの平均処理時間が分かりますね。チューニングの効果を測るのにもいいかも。