Apacheのレスポンス分析に必要なスクリプトまとめ

最近、Apacheのログ解析をすることが多いので、備忘録を兼ねてまとめ。

 

とりあえず、超便利コマンドはawk, sed, grep, uniq, sortあたり。コレを駆使して色々解析する。そして、これを駆使して解析がツライ時は素直にperlruby, pythonに処理を渡すべきかなぁ。awkが結構なんでもできるので、awkだけでも基本的にはいいけれど。

あと、リアルタイム解析じゃなくて前日のログ解析だから基本はzgrepやzcatから始まります。

で、ポイントは可能な限りzgrepを使うこと。zcatは一度全部展開するので、トロいし、負荷もでかいです。

apacheのログフォーマットが違うと当然そのまま適用できないので、その辺は適当に変更する感じで。

やっぱ、CSV解析はこの辺がネックですね。全部JSONになれば良いのに...

 

平均レスポンスタイム

アクセスログの末尾がレスポンスタイム(マイクロ秒)なので、それをawkで取得して集計します。

マイクロ秒は直感的に理解しづらいので、1000で割ってミリ秒にしています。

zcat access_log.20121124.gz | awk '{sum += $NF; count++}; END{print (sum/count)/1000}'

 

最大レスポンスタイム Top 5

主に平均レスポンスとの差分を確認用。

単純にレスポンスタイムでsortしています。あと、どのリクエストが遅かったかは知りたいので、それも付けてます。

zcat access_log.20121124.gz | awk '{print $NF/1000, $7}'|sort|uniq -c|sort -rn|head -5

 

1秒以上のレスポンスタイム

1秒以上のアクセスが何件あったかを抽出。必要に応じて、遅かったアクセスの一覧を取得できるようにリクエスト名は一応取得しておく。

zcat access_log.20121124.gz | awk '$NF > 1000000 {print $NF/1000, $7}'|wc -l 

 

リクエスト毎の平均応答時間

各リクエストでの平均応答時間を求める。これで特定の処理だけ遅延しているかどうかが確認できる。

1回、リクエストの一覧を出して、それを元に集計をするスクリプトをawkで組み立てて出力。そして、最後にそれを実行するという手順にしてある。

'のエスケープの仕方が良く分からなかったので、一旦適当な文字列に変換してsedで置換するという荒業を実施w

zcat access_log.20121124.gz | awk '{print $NF, $7}'| sort | uniq | awk 'print "zgrep "$1" access_log.20121124.gz | awk _dot_{sum += $NF; count++}; END{print ¥""$1"¥", (sum) / 1000}_dot_"'|sed "s/_dot_/'/g"|sh

 

時間毎の応答時間とリクエスト数

MLの配信や、何らかのイベントベースで瞬間的に時間あたりのリクエスト数が急増するのは良くあることです。

で、単純にリクエストが伸びるだけじゃなくて、リクエストが伸びて負荷が上がりレスポンス時間が落ちる、という形になると、セッションの溜まり方が鰻上り!

というわけで、こいつも計測してやる必要があります。単位時間はなんでも良いのですが、個人的には分では意味が無いことが多いので、秒で出しています。

 

こいつはちょっとワンライナーでするのは厳しいので、単体のシェルスクリプトに。

ちなみに秒単位だと自分の環境では1ドメインあたり24時間くらい集計に掛かりそうだったので、1分単位で集計。

これでまずそうなところを必要に応じてさらにに秒で絞り込む感じかな?

#!/bin/sh

LANG=C
FILE=access_log.20121124.gz 

BASE_DATETIME=`echo $FILE|sed 's/.*access_log//g'|awk '{print substr($1, 0, 4)"/"substr($1, 5, 2)"/"substr($1, 7, 2)" 00:00:00"}'
MAX_TIME=`expr 60 ¥* 24`
for i in `seq 0 $MAX_TIME`
do
  DATETIME=`date -d "${BASE_DATETIME} ${i} minute" + '%d/%b/%Y:%H:%M'`
  AVG=`zgrep "${DATETIME}" $FILE | awk '{sum += $NF; count++}; END{if (count == 0){print "0","0"}else{print count, (sum/count) / 1000}}'`
  echo "${DATETIME} ${AVG}"
done

ファイルのフォーマットで日付がわかるので、それを抽出しています。入力値間違えで計測値が変というミスも減りますし。awkのsubstrは便利ですねー。

 

まとめ

とりあえず、この辺の解析結果を日次でレポートするようにしておけば、日々の監視としては良さそうです。

MTRGとかで取れる値もありますが、仕事だと管理の問題で自由にパラメータとかいじれないケースも多々あるのがネック。

これで集消したデータをメールで飛ばして、自動でMySQLあたりに放り込んで、OOoで解析というのが良いのかもしれないと思ったりもする今日このごろ。

まあ、MySQLに入れるなら最初から全ログ入れて全部SQLで書いたほうが速い気もしますけど、生データの扱いは要注意ですし、容量も考えるとサマリをぶち込むのも悪くは無いかと。

 

あと、一応書いときますが、この手のスクリプトを決してフロントサーバで行わないように! scpでログを集めて、多少負荷がかかっても問題がない、バックエンドサーバとか、場合によってはローカルマシンとかでやりましょー。

 

では、Happy Hacking