サイトチューニングの準備-アクセスログformat

まず始めにパフォーマンスを改善するための基本的な調査事項を洗い出して行きましょう。

一番助けになるのはWWWサーバーのアクセスログです。ここでは、どのようにアクセスログを収集すべきかを書いて行きます。

Tips#001

レスポンスを返すまでの処理時間をアクセスログに記録する

※apacheの標準的なフォーマット

httpd.confには初期値で以下の4種類が標準的に定義されています。



LogFormat "%h %l %u %t \"%r\" %>s %b
\"%{Referer}i\" \"%{User-Agent}i\"" combined

LogFormat "%h %l %u %t \"%r\" %>s %b" common

LogFormat "%{Referer}i -> %U" referer

LogFormat "%{User-agent}i" agent

CustomLog logs/access_log common

通常は以下のような感じで、

CustomLog
“|/usr/local/sbin/cronolog
/etc/httpd/logs/access_log.%Y-%m-%d” combined

でconbinedを指定して、かつ、ログファイルのローテートを指定することになります。

この場合収集される項目は  

border="1" cellpadding="2" cellspacing="2">


style="background-color: rgb(0, 102, 0); color: rgb(255, 255, 255);">変数
style="background-color: rgb(0, 102, 0); color: rgb(255, 255, 255);">解説

%h	リモート・ホスト名
%l	(identd からもし提供されていれば) リモートログ名。
%u	ユーザ認証によるリモート・ユーザ名
%t	アクセス日時
%r	HTTPリクエストヘッダー
%s	ステータスコード
%b	転送バイト数
%{STRING}i	リクエスト内のSTRING内容 ※STRINGに{Referer}と{User-Agent}を指定している

結果として以下のようなログになります。

61.25.152.161 - - [22/Apr/2007:00:00:05 +0900]
"GET　/images/btn_goto.gif HTTP/1.1" 304
-　"http://www.hogehoge.com/200000208/categoryb10-1000061717.html"
"Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1; .NET CLR
1.1.4322)"

61.25.152.161 - - [22/Apr/2007:00:00:05 +0900] "GET
/images/sidettl_base.gif HTTP/1.1" 304 -
"http://www.hogehoge.com/200000208/categoryb10-1000061717.html"
"Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1; .NET CLR
1.1.4322)"

218.110.154.161 - - [22/Apr/2007:00:00:05 +0900] "GET
/000000017/top5.html HTTP/1.1" 200 34509
"http://www.hogehoge.com/000000017/top4.html" "Mozilla/4.0 (compatible;
MSIE 6.0; Windows NT 5.1; SV1)"

通常はこれで問題ないのですが、チューニングをするためには、レスポンスにかかった処理時間を記録する必要があります。apche2以
上の場合は%Tで秒単位、%Dでマイクロ秒単位で記録できます。

cellpadding="2" cellspacing="2">


style="background-color: rgb(0, 102, 0); color: rgb(255, 255, 255);">変
数
style="background-color: rgb(0, 102, 0); color: rgb(255, 255, 255);">解
説

%T	リクエ ストを扱うのにかかった時間、秒単位
%D	リクエ ストを処理するのにかかった時間、ミリ秒単位

※apache1.3の場合は内部的に秒単位でしか記録が取られていないので、一工夫必要です。 href="http://module.jp/blog/millisecond_logging_with_ap13.htm">
「Apache1.3の処理経過時間をマイクロ秒で記録する」を参考にして下さい。



LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\"
\"%{User-Agent}i\" style="color: rgb(255, 0, 0); font-weight: bold;">%D"
combined



とすると

61.25.152.161 - -
[22/Apr/2007:00:00:05 +0900] “GET /images/sidettl_base.gif
HTTP/1.1″ 304 -
“http://www.hogehoge.com/200000208/categoryb10-1000061717.html”
“Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1; .NET
CLR 1.1.4322)” style="font-weight: bold; color: rgb(255, 0, 0);">17478

218.110.154.161 - - [22/Apr/2007:00:00:05 +0900] “GET
/000000017/top5.html HTTP/1.1″ 200 34509
“http://www.hogehoge.com/000000017/top4.html”
“Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1;
SV1)” style="font-weight: bold; color: rgb(255, 0, 0);">1206 style="color: rgb(255, 0, 0); font-weight: bold;">

という感じで最後尾にマイクロ行単位の処理時間が記録されます。

マイクロ秒で記録していますから

17478は0.017478秒

1206は0.001206秒

です。

ログフォーマットに関する詳細は
Apache
モジュール mod_log_config

を参照して下さい。