負荷テスト中のログを抽出をする方法

こんにちは。先日こちらの記事で負荷テストマニア認定されてしまった浅見です。

せっかくなので、「負荷テスト中の●●」というシリーズでお送りしようと思います。

過去記事はこちらです。

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

今回の●●は、「ログの抽出方法」です。

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

大量のログから必要なログだけ抜き出すのって地味に大変ですよね？

ボトルネックを調査するときは、サーバリソースの状況から全体を把握し、ログの確認をしていくことが多いと思います。

確認対象としては、httpdのアクセスログやMySQLのスロークエリログなど様々なものがあります。

追記型のものが多く、放っておくと様々なテストケースの情報が混在していきます。ローテーションをしていたとしても、日次やファイルサイズの単位となり、負荷テストとの紐付けができません。

毎回ログを退避させて初期化してもよいですが、初期化できないシチュエーションもあったりします。

そんなときに、オリジナルのログは変更せずに、負荷テスト中に出力された部分だけを抜き出す方法を紹介します。

ログの抽出方法概要

図のように負荷テスト実行前と実行後の差分のログを取りたい！というのが今回の内容です。

こう書くと簡単ですね。で、実際にやることも簡単です。

フローチャートに描くとこんな感じ。負荷テスト前に対象ログファイルの行数を取得しておき、テスト後にさきほど取得した行数以降のログを取得するだけです。

ログの抽出方法

では、実際にログの取得方法をご紹介します。

ログは次のような構成を想定しています

• 対象ファイル:access_log
• 一時ファイル:access_log.pos
• 取得ファイル:日時accesslog

早速いってみましょう。

1. テスト前のログ行数取得

まずログの行数を取得します。

wc -l access_log|awk '{print $1}'>access_log.pos

2. 負荷テスト実行

行数を取得したら負荷テストを実施しましょう。

3. テスト前の行数以降のログ取得

1で取得したログ行数と、負荷テスト実行後のログ行数の差分を取得しtailコマンドでログの抽出を行います。

# 取得するtail行数を算出
START_POS=`cat access_log.pos`
END_POS=`wc -l access_log|awk '{print $1}'`
TAIL_CNT=`expr ${END_POS} - ${START_POS}`

# ログファイル取得
tail -n ${TAIL_CNT} access_log>`date +%Y%m%d-%k%M`_access_log

テスト実行中のログだけ取得できましたか？

まとめ

負荷テスト中のログ抽出方法についてまとめてみました。

今回はコマンドレベルの解説だけでしたが、実際の現場ではシェル化しており、ssh経由で実行することでJMeterのマスタサーバにログを集約させています。 (もっとスマートな方法はありそうですが、今のところこの方法で困ってはいません)

テスト単位にログが分割されていることで、必要な部分だけをダイレクトに確認することが可能です。例えそのときには必要がなかったとしても、後からログを確認したくなるときがあるかもしれません。

負荷テストと結果に関連するデータはしっかりと管理する癖をつけておくといいですね。