こんにちは、「負荷テスト中の●●」シリーズでお馴染みの浅見です。
今回の●●は「アクセスログの解析」です。
過去記事はこちらです。
- 負荷テスト中のログを抽出をする方法
- 負荷テスト中のサーバリソース情報を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スタックを組んでしまうと便利です
