Home > Webサイト開発日記 > レスポンスを返すまでの処理時間をアクセスログに記録する

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

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

※apacheの標準的なフォーマット
httpd.confには初期値で以下の4種類が標準的に定義されています。

PLAIN TEXT
CODE:
  1. <br />
  2. LogFormat "%h %l %u %t "%r" %&gt;s %b "%{Referer}i" "%{User-Agent}i"" combined<br />
  3. LogFormat "%h %l %u %t "%r" %&gt;s %b" common<br />
  4. LogFormat "%{Referer}i -&gt; %U" referer<br />
  5. LogFormat "%{User-agent}i" agent<br />

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

PLAIN TEXT
CODE:
  1. <br />
  2. CustomLog "|/usr/local/sbin/cronolog /etc/httpd/logs/access_log.%Y-%m-%d" combined<br />

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

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

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

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

-----------------------------------------------------------------------------------------------------------------

PLAIN TEXT
CODE:
  1. </p>
  2. <p>61.213.148.192 - - [23/Apr/2007:20:30:23 +0900] "GET /images/jk_11.gif HTTP/1.1" 200 314 "http://www.xxx.co.jp/Detail.do?cd=064895" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; .NET CLR 1.1.4322)"<br />
  3. 58.12.224.198 - - [23/Apr/2007:20:30:24 +0900] "GET /Detail.do?cd=064895 HTTP/1.1" 200 15110 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1; .NET CLR 1.1.4322)"</p>
  4. <p>

-----------------------------------------------------------------------------------------------------------------

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

変数 解説
%T リクエストを扱うのにかかった時間、秒単位
%D リクエストを処理するのにかかった時間、マイクロ秒単位

※apache1.3の場合は内部的に秒単位でしか記録が取られていないので、一工夫必要です。
参考:Apache1.3の処理経過時間をマイクロ秒で記録する

PLAIN TEXT
CODE:
  1. <br />
  2. LogFormat "%h %l %u %t "%r" %&gt;s %b "%{Referer}i" "%{User-Agent}i" %D" combined<br />

とすると
-----------------------------------------------------------------------------------------------------------------

PLAIN TEXT
CODE:
  1. </p>
  2. <p>61.213.148.192 - - [23/Apr/2007:20:30:23 +0900] "GET /images/jk_11.gif HTTP/1.1" 200 314 "http://www.xxx.co.jp/Detail.do?cd=064895" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; .NET CLR 1.1.4322)" 7216<br />
  3. 58.12.224.198 - - [23/Apr/2007:20:30:24 +0900] "GET /Detail.do?cd=064895 HTTP/1.1" 200 15110 "-" "Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1; .NET CLR 1.1.4322)" 169979</p>
  4. <p>

-----------------------------------------------------------------------------------------------------------------

という感じで最後尾にマイクロ行単位の処理時間が記録されます。
マイクロ秒で記録されていますから注意して下さい。

詳細は「Apacheモジュール mod_log_config」