Apacheのログをカスタマイズ／重いログだけを抽出

Apacheのアクセスログに以下の情報を出力する方法と、取得したログから重いリクエストを取り出す例を示す。

• 処理にかかった時間
• ログイン中のユーザID
• ロードバランサ使用時の、実際のアクセス元のIP

##処理にかかった時間
LogFormatに%Dを付けるとリクエストにかかった時間がマイクロ秒単位で記録される。
%Tを付けるとリクエストを扱うのにかかった時間が秒単位で記録される。
ボトルネックの解析や、チューニング後の効果測定に便利だ。

出力可能な項目の一覧
https://httpd.apache.org/docs/2.2/ja/mod/mod_log_config.html

##ユーザIDなど
LogFormatに %{user_id}n login=%{login}n などと記述した上で、アプリケーション側からデータを渡す。

PHPであれば以下のように書けばよい。

apache_note('user_id', getUserID());
apache_note('login', getLogin());

##ロードバランサ使用時のアクセス元のIP
LogFormatに %{X-Forwarded-For} と記述すればよい。ロードバランサによってはフィールド名が異なる可能性もあるが、awsのELBではこれで動いているし、このフィールド名を使うことが推奨されているようだ。

##まとめ（コピペ用）
以下のような設定で、実行時間、ユーザID、ログインID、ロードバランサのIPアドレスを記録できます。

<IfModule log_config_module>
    LogFormat "%h %D %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\" user_id=%{user_id}n login=%{login}n \"%{X-Forwarded-For}i\" " combined
    CustomLog "logs/access_log" combined
</IfModule>

###ログの例（一部抜粋）
以下のログでは、user_id=123456　login=y-nishimuraのユーザがリクエストを送信しており、処理に10msかかった事が分かる。先頭に記録されているIPアドレスは（210.xxx.yyy.zzz）はロードバランサのもので、ユーザのIPは111.xxx.yyy.zzzです。

210.xxx.yyy.zzz 10157 - - [14/Oct/2016:10:09:15 +0900] "GET index.php?xxx=yyy HTTP/1.1" 200 8158 "http://example.com/index.php?xxx=zzz" "Mozilla/5.0 (Windows NT 6.1; Trident/7.0; rv:11.0) like Gecko" user_id=123456 login=y-nishimura "111.xxx.yyy.zzz"

###ログの解析（重いやつを抽出）
awkを使うとレスポンスタイムが大きな行だけを簡単に取り出せる。

awk '$2 >= 1000000' /var/log/httpd/access_log #1秒以上
awk '$2 >= 10000000' /var/log/httpd/access_log #10秒以上
awk '$2 >= 60000000' /var/log/httpd/access_log #1分以上