負荷テスト中のアクセスログを解析する

こんにちは、「負荷テスト中の●●」シリーズでお馴染みの浅見です。

今回の●●は「アクセスログの解析」です。

過去記事はこちらです。

• 負荷テスト中のログを抽出をする方法
• 負荷テスト中のサーバリソース情報を1秒間隔で確認する方法
• インフラ視点で、負荷テストについて考えてみる

こんなお悩みありませんか？

WEBサーバのアクセスが偏っている気がする。

実際どれくらい偏っているのかを調べようとすると、意外と頭を悩ませることになります。

この記事ではお手軽なシェルを使って、アクセスログから「PVっぽいアクセス件数」と「応答速度」の推移を確認してみます。

なお、アクセスログは、combinedD形式（※）で出力されているものとします。

※combinedログの末尾に処理時間を表す「%D」を付けたものです

# combinedDログ
LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\" %D" combinedD

アクセスログの解析方法

手順は次のとおりです。

• １. PVっぽいアクセスを抜き出す
• ２. サマリしたい時間リスト取得
• ３. 分単位のアクセス件数および平均応答速度取得

それでは詳細を確認していきます。

PVっぽいアクセスを抜き出す

まずはじめに、アクセスログからPVっぽいアクセスを抜き出します。

「っぽい」と表現したのは、アクセスログからPVを特定することは困難なためです。

ここでは、明らかにPVとは異なる拡張子を持ったファイルへのアクセスを除外していきます。

実際に除外したらファイルの中を目視して不要なものがないかを確認してみるとよいでしょう。

# PVっぽいアクセスを抜き出す
cat access_log|egrep -v "\.svg|\.css|\.js|\.class|\.gif|\.jpg|\.jpeg|\.png|\.bmp|\.ico|\.swf|/js/|\.cur|healthcheck.txt|\.xml">access_log.pv

サマリしたい時間リスト取得

PVっぽいアクセスを抽出したあとは、アクセスログに記録された時間（時分）のリストを作成します。

この時間のリストを使って、後続の分単位の件数取得や平均応答速度の取得を行います。

# 時間リストを作成する
cat access_log.pv |awk -F: '{print $2 ":" $3 ":"}'|sort|uniq|sort -n>time.list

こんな感じでアクセスログから時分のみ抜き出すことが可能です。

# cat time.list
10:33:
10:34:
10:35:
10:36:
10:37:

分単位のアクセス件数および平均応答速度取得

最後に時分ごとに平均応答速度および件数を算出し、結果ファイルへ出力していきます。

# 時間リストごとに平均応答速度と件数を取得する
while read time
  do
    # 平均応答速度を取得する
    responsetime=`grep $time access_log.pv|awk '{m+=$NF} END{print m/NR/1000000;}'`

    # 件数を取得する
    count=`grep -c $time access_log.pv`

    # 結果をファイル出力
    echo $time $responsetime $count >> result.txt
done < time.list

結果を確認

次のような結果が出力されたかと思います。

左から「時刻」「平均応答速度」「件数」となります。

# cat result.txt
10:33   0.124048    1454
10:34   0.105191    833
10:35   0.0431748   331
10:36   0.159945    2230
10:37   0.141889    1042

結果はExcel等でグラフ化するとパッと見わかりやすいものにできますのでご自由に加工してみてください。

まとめ

シェルでアクセスログを解析する方法についてまとめてみました。

負荷テストというよりも、実際に運用中のサーバの状態を確認するときに覚えておくと役に立つかもしれません。

PVっぽいアクセスだけでなく、具体的なURLを絞り込んで確認することで特定アクセスの応答推移の確認ができ、全体が遅いのか特定アクセスのみ遅延しているかの切り分けも可能です。

アクセスログは情報の宝庫なので、色々解析してみると面白いと思います。

追伸．負荷テスト中にリアルタイムでログ解析したい場合は、ELKスタックを組んでしまうと便利です